PostgreSQL Log Entries: CDTLOG: statement: SHOW client_min_messages

I was troubleshooting an issue at work the other day regarding some PostgreSQL connections that were not closing. They were left IDLE, never closed, and eventually used up all of the possible connections (which totaled 100) configured in the  postgresql.conf configuration file. In the process of troubleshooting I noticed a bunch of Postgres log entries that I was unable to immediately pin down to what was causing the entries. Below I describe the view of the idle Postgres connections, the PostgreSQL log entries that were unfamiliar, and the cause of both.

Linux ps Command Displaying IDLE PostgreSQL Connections:

[root@dev ~]# ps -ef | grep postgres | grep idle
postgres 28499 25890  0 18:03 ?        00:00:00 postgres: postgres somedb 10.2.128.20(51292) idle
postgres 28513 25890  0 18:03 ?        00:00:00 postgres: postgres somedb 10.2.128.10(40069) idle
postgres 28616 25890  0 18:04 ?        00:00:00 postgres: postgres somedb 10.2.128.20(55198) idle
postgres 28630 25890  0 18:04 ?        00:00:00 postgres: postgres somedb 10.2.128.10(40099) idle
postgres 28808 25890  0 18:05 ?        00:00:00 postgres: postgres somedb 10.2.128.20(55202) idle
postgres 28822 25890  0 18:05 ?        00:00:00 postgres: postgres somedb 10.2.128.10(40129) idle
postgres 28904 25890  0 18:06 ?        00:00:00 postgres: postgres somedb 10.2.128.20(55206) idle
postgres 28917 25890  0 18:06 ?        00:00:00 postgres: postgres somedb 10.2.128.10(40152) idle
postgres 29017 25890  0 18:07 ?        00:00:00 postgres: postgres somedb 10.2.128.20(55210) idle
postgres 29031 25890  0 18:07 ?        00:00:00 postgres: postgres somedb 10.2.128.10(40176) idle
postgres 29159 25890  0 18:08 ?        00:00:00 postgres: postgres somedb 10.2.128.20(55214) idle
postgres 29176 25890  0 18:08 ?        00:00:00 postgres: postgres somedb 10.2.128.10(40207) idle
postgres 29263 25890  0 18:09 ?        00:00:00 postgres: postgres somedb 10.2.128.20(55219) idle
postgres 29287 25890  0 18:09 ?        00:00:00 postgres: postgres somedb 10.2.128.10(33814) idle
postgres 29386 25890  0 18:10 ?        00:00:00 postgres: postgres somedb 10.2.128.20(53187) idle
postgres 29398 25890  0 18:10 ?        00:00:00 postgres: postgres somedb 10.2.128.10(33840) idle
postgres 29592 25890  0 18:11 ?        00:00:00 postgres: postgres somedb 10.2.128.20(53191) idle
postgres 29604 25890  0 18:11 ?        00:00:00 postgres: postgres somedb 10.2.128.10(33866) idle
postgres 29655 25890  0 18:11 ?        00:00:00 postgres: postgres somedb 10.2.128.20(53195) idle
postgres 29699 25890  0 18:12 ?        00:00:00 postgres: postgres somedb 10.2.128.10(33892) idle

As you can see above the idle connections are being created by two different servers that both use this database server. Now below are the PostgreSQL log entries that appeared to be related to the idle Postgres connections.

Unknown PostgreSQL Log Entries:

2010-03-24 12:26:06.673 CDTLOG:  duration: 3.337 ms
2010-03-24 12:26:06.935 CDTLOG:  statement: SHOW client_min_messages
2010-03-24 12:26:06.935 CDTLOG:  duration: 0.343 ms
2010-03-24 12:26:06.935 CDTLOG:  statement: SET client_min_messages TO 'panic'
2010-03-24 12:26:06.936 CDTLOG:  duration: 0.072 ms
2010-03-24 12:26:06.936 CDTLOG:  statement: SHOW standard_conforming_strings
2010-03-24 12:26:06.936 CDTLOG:  duration: 0.047 ms
2010-03-24 12:26:06.936 CDTLOG:  statement: SET client_min_messages TO 'notice'
2010-03-24 12:26:06.936 CDTLOG:  duration: 0.043 ms
2010-03-24 12:26:06.937 CDTLOG:  statement: SELECT version()
2010-03-24 12:26:06.937 CDTLOG:  duration: 0.438 ms
2010-03-24 12:26:06.938 CDTLOG:  statement: BEGIN
2010-03-24 12:26:06.938 CDTLOG:  duration: 0.038 ms

After some troubleshooting I was able to locate the issue which I wanted to explain in some more detail as others could have this issue as well. The issue ended up being a Rufus job that was running for the Ruby project. This particular Rufus job did not even use PostgreSQL at all and really all it did was make a simple TCP connection to a remote server and then disconnect. The issue here was that the postgres-pr gem is being used and every time that the Rufus job was executing it was loading the entire Rails environment which in turn loaded postgres-pr. Since the job was not finishing properly ( the far end server was down) and the exception wasn’t caught properly the PostgreSQL connection was staying open.

So if you are using Rufus to schedule tasks from within a Ruby project it is possible to run into a similar scenario if the postgres-pr gem is being loaded. The issue could be noticed by looking in the psql logs for client_min_messages entries.

See larger image PostgreSQL 8.4 Official Documentation - Volume III. Server Programming (Paperback) By (author) The PostgreSQL Global Development Group List Price: $30.99 USD New From: $25.45 In Stock Used from: $4.40 In Stock

See larger image Rails Cookbook (Cookbooks (O'Reilly)) (Paperback) By (author) Rob Orsini List Price: $39.99 USD New From: $7.96 In Stock Used from: $0.01 In Stock

This entry was posted on Friday, March 26th, 2010 at 3:26 PM and is filed under Insights. You can follow any responses to this entry through the RSS 2.0 feed. You can skip to the end and leave a response. Pinging is currently not allowed.