explaining pgbouncer log entries in django project

Question

I'm using pgbouncer in a Django web app of mine. The application server and the database server are two separate VMs. pgbouncer is installed on the application server. Pertinent settings in pgbouncer.ini are:

[databases]
dbname = host=80.211.128.113 port=5432 dbname=dbname

pool_mode = transaction
max_client_conn = 250
default_pool_size = 100

Once pgbouncer took over, I checked pgbouncer.log and found lots of entries as follows:

2016-11-15 12:26:27.514 582 LOG S-0x1192740: dbname/[email protected]:5432 new connection to server
2016-11-15 12:26:27.517 582 LOG C-0x11afcb8: dbname/[email protected]:42262 login attempt: db=dbname user=myuser
2016-11-15 12:26:27.523 582 LOG S-0x1192a10: dbname/[email protected]:5432 new connection to server
2016-11-15 12:26:27.528 582 LOG C-0x11af880: dbname/[email protected]:42250 closing because: client close request (age=0)
2016-11-15 12:26:27.528 582 LOG S-0x1191a98: dbname/[email protected]:5432 closing because: unclean server (age=0)
2016-11-15 12:26:27.548 582 LOG C-0x11afb50: dbname/[email protected]:42258 closing because: client close request (age=0)
2016-11-15 12:26:27.556 582 LOG C-0x11aff88: dbname/[email protected]:42256 closing because: client close request (age=0)
2016-11-15 12:26:27.556 582 LOG S-0x1191c00: dbname/[email protected]:5432 closing because: unclean server (age=0)
2016-11-15 12:26:27.564 582 LOG C-0x11aff88: dbname/[email protected]:42264 login attempt: db=dbname user=myuser
2016-11-15 12:26:27.569 582 LOG C-0x11afb50: dbname/[email protected]:42265 login attempt: db=dbname user=myuser
2016-11-15 12:26:27.570 582 LOG S-0x1191c00: dbname/[email protected]:5432 new connection to server
2016-11-15 12:26:27.593 582 LOG C-0x11af448: dbname/[email protected]:42255 closing because: client close request (age=0)
2016-11-15 12:26:27.593 582 LOG C-0x11afcb8: dbname/[email protected]:42262 closing because: client close request (age=0)
2016-11-15 12:26:27.593 582 LOG S-0x1191c00: dbname/[email protected]:5432 closing because: unclean server (age=0)
2016-11-15 12:26:27.597 582 LOG C-0x11afb50: dbname/[email protected]:42265 closing because: client close request (age=0)
2016-11-15 12:26:27.603 582 LOG C-0x11afb50: dbname/[email protected]:42267 login attempt: db=dbname user=myuser
2016-11-15 12:26:27.604 582 LOG C-0x11afcb8: dbname/[email protected]:42268 login attempt: db=dbname user=myuser

If analyzed closely, many instances of closing because: unclean server and closing because: client close request are found in the log file. Can anyone explain what these are? Perhaps I'm doing something wrong. On the surface, my application seems to be running correctly so far. But I need to understand what I'm seeing in my log files so I can be sure what's what. Thanks in advance.

Answer 1

• LOG C - logs with this headers are related to a client connecting to pgbouncer (not the postgresql server).
• LOG S - are about communication between pgbouncer and server (the real connection to posgres server).
• age=0 - tells the usage time i.e. a LOG C with age=0, means client used the connection for less than a second.

---

The answer:

closing because: client close request

Is nothing to worry about, totally normal. It logs that client has quite i.e. client no more has a live connection to pgbouncer.

Usually the logs are like:

On first attempt to connect to pgbouncer

Line 1 - connection attempt to pgbouncer.

Line 2 - pgbouncer making connection attempt to postgresql server.

Line 3 - Client request is completed and client-pgbouncer connection is closed

2016-11-15 12:26:27.517 582 LOG C-0x11afcb8: dbname/[email protected]:42262 login attempt: db=dbname user=myuser
2016-11-15 12:26:27.523 582 LOG S-0x1192a10: dbname/[email protected]:5432 new connection to server
2016-11-15 12:26:27.528 582 LOG C-0x11af880: dbname/[email protected]:42250 closing because: client close request (age=0)

Line 1 - connection attempt to pgbouncer by a new client. It'll re-use the already opened connection to the postgresql server (opened for last client)

Line 2 - Client request is completed and client-pgbouncer connection is closed

2016-11-15 12:26:27.569 582 LOG C-0x11afb50: dbname/[email protected]:42265 login attempt: db=dbname user=myuser
2016-11-15 12:26:27.593 582 LOG C-0x11af448: dbname/[email protected]:42255 closing because: client close request (age=0)

Line 1 & 2 - 2 concurrent clients attempting connection to pgbouncer

Line 3 - pgbouncer making a second connection attempt to postgresql server, for second client (first one will re-use the already opened one)

Line 4 & 5 - Client requests are completed and client-pgbouncer connections are closed

2016-11-15 12:26:27.564 582 LOG C-0x11aff88: dbname/[email protected]:42264 login attempt: db=dbname user=myuser
2016-11-15 12:26:27.569 582 LOG C-0x11afb50: dbname/[email protected]:42265 login attempt: db=dbname user=myuser
2016-11-15 12:26:27.570 582 LOG S-0x1191c00: dbname/[email protected]:5432 new connection to server
2016-11-15 12:26:27.593 582 LOG C-0x11af448: dbname/[email protected]:42255 closing because: client close request (age=0)
2016-11-15 12:26:27.593 582 LOG C-0x11afcb8: dbname/[email protected]:42262 closing because: client close request (age=0)

---

closing because: unclean server

Can be an issue, as it seems like pgbouncer is getting and closing a new connection to postgres server with every new client connecting to it (pgbouncer).

Possible solution/way-out - may have something to do with how the Django works by default.

As with normal pooling pgbouncer must not close it's connections to postgres server (at the time of closing client connection) - You may get this server connection close messages/logs when the connection may reach server_lifetime or server_idle_timeout when idle, otherwise not.

---