PGAgent Connection Pool Leaking

Hiya,

We run postgresql-9.5 (9.5.5-1.pgdg80+1) on debian jessie (using the
postgres apt repo) with replication between two servers. We have pgagent
running on both the master and the slave using:
/usr/bin/pgagent -f host=pgserver dbname=postgres user=username
password=password -l 2 -s /home/robertemery/test/pgagent.log
where pgserver is a CNAME that we use to direct traffic to the current
master.

We are finding that over-time, the pgagent user ends up with hundreds of
connections into the postgresql cluster from both pgagents. If we kill and
restart the pgagent process, it returns to 1.

When we run a job the number of connections goes from 1 -> 3 then back to 1
again; however this morning (for example) one of the servers has ended up
with 2 connections for the pgagent user:

SELECT * FROM pg_stat_activity WHERE usename LIKE '%pgagent%'; looks like :

12379;"postgres";14853;22872466;"pgagent_login_role";"";"192.168.1.1";"";58223;"2017-10-18
08:20:29.481096+01";"";"2017-10-19 09:16:25.656794+01";"2017-10-19
09:16:25.657219+01";f;"idle";;;"SELECT J.jobid FROM pgagent.pga_job J
WHERE jobenabled AND jobagentid IS NULL AND jobnextrun <= now()
AND (jobhostagent = '' OR jobhostagent = 'pgsqla02') ORDER BY jobnextrun"
12379;"postgres";10184;22872466;"pgagent_login_role";"";"192.168.1.2";"";34501;"2017-10-18
15:20:53.282212+01";"";"2017-10-19 09:16:29.061761+01";"2017-10-19
09:16:29.062225+01";f;"idle";;;"SELECT J.jobid FROM pgagent.pga_job J
WHERE jobenabled AND jobagentid IS NULL AND jobnextrun <= now()
AND (jobhostagent = '' OR jobhostagent = 'pgsqla01') ORDER BY jobnextrun"
12379;"postgres";13060;22872466;"pgagent_login_role";"";"192.168.1.2";"";34518;"2017-10-19
07:20:02.680711+01";"";"2017-10-19 07:20:02.70995+01";"2017-10-19
07:20:02.723907+01";f;"idle";;;"UPDATE pgagent.pga_job SET
jobagentid=10184, joblastrun=now() WHERE jobagentid IS NULL AND jobid=2"

It looks like the UPDATE statement is the new connection that's leaking.

Looking at the pgagent log for 07:20 (we have a job that runs at 07:10,
07:20, 07:30, 07:40) I can see:

Thu Oct 19 07:19:57 2017 : DEBUG: Clearing inactive connections
Thu Oct 19 07:19:57 2017 : DEBUG: Connection stats: total - 1, free - 0,
deleted - 0
Thu Oct 19 07:19:57 2017 : DEBUG: Checking for jobs to run
Thu Oct 19 07:19:57 2017 : DEBUG: Sleeping...
Thu Oct 19 07:20:02 2017 : DEBUG: Clearing inactive connections
Thu Oct 19 07:20:02 2017 : DEBUG: Connection stats: total - 1, free - 0,
deleted - 0
Thu Oct 19 07:20:02 2017 : DEBUG: Checking for jobs to run
Thu Oct 19 07:20:02 2017 : DEBUG: Creating job thread for job 2
Thu Oct 19 07:20:02 2017 : DEBUG: Creating DB connection:
user=pgagent_login_role host=pgserver password=password dbname=postgres
Thu Oct 19 07:20:02 2017 : DEBUG: Allocating new connection to database
postgres
Thu Oct 19 07:20:02 2017 : DEBUG: Starting job: 2
Thu Oct 19 07:20:02 2017 : DEBUG: Destroying job thread for job 2
Thu Oct 19 07:20:02 2017 : DEBUG: Sleeping...
Thu Oct 19 07:20:07 2017 : DEBUG: Clearing inactive connections
Thu Oct 19 07:20:07 2017 : DEBUG: Connection stats: total - 2, free - 0,
deleted - 0
Thu Oct 19 07:20:07 2017 : DEBUG: Checking for jobs to run
Thu Oct 19 07:20:07 2017 : DEBUG: Sleeping...

which looks like it allocates a connection but never gives it up again.
From this point on DEBUG: Connection stats: total - 2, free - 0, deleted -
0 always shows 2.

Looking at the run at 07:10 it looks different:

Thu Oct 19 07:09:55 2017 : DEBUG: Clearing inactive connections
Thu Oct 19 07:09:55 2017 : DEBUG: Connection stats: total - 1, free - 0,
deleted - 0
Thu Oct 19 07:09:55 2017 : DEBUG: Checking for jobs to run
Thu Oct 19 07:09:55 2017 : DEBUG: Sleeping...
Thu Oct 19 07:10:00 2017 : DEBUG: Clearing inactive connections
Thu Oct 19 07:10:00 2017 : DEBUG: Connection stats: total - 1, free - 0,
deleted - 0
Thu Oct 19 07:10:00 2017 : DEBUG: Checking for jobs to run
Thu Oct 19 07:10:00 2017 : DEBUG: Creating job thread for job 2
Thu Oct 19 07:10:01 2017 : DEBUG: Creating DB connection:
user=pgagent_login_role host=pgserver password=password dbname=postgres
Thu Oct 19 07:10:01 2017 : DEBUG: Allocating new connection to database
postgres
Thu Oct 19 07:10:01 2017 : DEBUG: Starting job: 2
Thu Oct 19 07:10:01 2017 : DEBUG: Sleeping...
Thu Oct 19 07:10:01 2017 : DEBUG: Creating DB connection:
user=pgagent_login_role host=pgserver password=password dbname=postgres
dbname=ourdatabasename
Thu Oct 19 07:10:01 2017 : DEBUG: Allocating new connection to database
ourdatabasename
Thu Oct 19 07:10:01 2017 : DEBUG: Executing SQL step 3 (part of job 2)
Thu Oct 19 07:10:01 2017 : DEBUG: Returning connection to database
ourdatabasename
Thu Oct 19 07:10:01 2017 : DEBUG: Returning connection to database postgres
Thu Oct 19 07:10:01 2017 : DEBUG: Completed job: 2
Thu Oct 19 07:10:01 2017 : DEBUG: Destroying job thread for job 2
Thu Oct 19 07:10:06 2017 : DEBUG: Checking for jobs to run
Thu Oct 19 07:10:06 2017 : DEBUG: Sleeping...

I'm at a bit of a loss to debug this further now, it looks like a bug in
the connection pooling to me?

Many Thanks,
Rob

--
Robert Emery

--
<https://codeweavers.net>

<http://us15.campaign-archive1.com/?u=fcb361cfa194cf70551bc5169&id=f556b0bf09>
Codeweavers
October
Newsletter
<http://us15.campaign-archive1.com/?u=fcb361cfa194cf70551bc5169&id=f556b0bf09>
*l *Auto Trader extends partnership with Codeweavers
<https://codeweavers.net/company-blog/auto-trader-extends-partnership-with-codeweavers-to-power-finance-on-auto-trader-websites>

<https://codeweavers.net/automotive-vision-conference-agenda>

*What are Codeweavers doing to gear up for GDPR?
<https://codeweavers.net/company-blog/what-are-codeweavers-doing-to-gear-up-for-gdpr>*

*Phone:* 0800 021 0888 * Email: *contactus(at)codeweavers(dot)net
*Codeweavers Ltd* | Barn 4 | Dunston Business Village | Dunston | ST18 9AB
Registered in England and Wales No. 04092394 | VAT registration no. 974
9705 63

<https://www.linkedin.com/company/codeweavers-limited>
<https://vimeo.com/codeweaversltd> [image:
https://plus.google.com/b/105942302039373248738/+CodeweaversNet]
<https://plus.google.com/b/105942302039373248738/+CodeweaversNet> [image:
https://twitter.com/CodeweaversTeam] <https://twitter.com/CodeweaversTeam>