Apparent connection leak detected

[kumar-asista]

rule-engine-log-trim.pdf

Environment

HikariCP version: 2.6.1
JDK version     : 1.8.0_111
Database        : PostgreSQL
Driver version  : 9.4-1201-jdbc41

Current Production Tech Stack:

scala - 2.10.4
slick - 2.1.0
hikari - 2.6.1

Datasource Configuration:

val ds = new HikariDataSource()
ds.setDriverClassName("")
ds.setJdbcUrl("jdbc:postgresql://localhost:5432/somedb")
ds.setUsername("dbuser")
ds.setPassword("password")
ds.setMinimumIdle(2)
ds.setMaximumPoolSize(4)
ds.setIdleTimeout(600000)
ds.setLeakDetectionThreshold(30000)
ds.setConnectionTimeout(30000)

We are working multi-tenant model, each tenant has their own DB we are running more than 6 months in production, This month we are facing connection leak problem two times randomly (some connection pool).

Following points noted from log:

1. waiting mode connection keep increasing.
2. Total number of connections equal to active mode connections
3. Total number of connection equal to idle mode connections

I have attached log file. I have marked in red colour.

@brettwooldridge we are expecting your help to solve this problem. should we focus on configuration or code level anything to be done for this permanent solutions.

Thanks @brettwooldridge .

[brettwooldridge]

@kumar-cherry HikariCP v2.6.1 is a bit old, I recommend upgrading to v3.x. More concerning is that Slick v2.1.0 was released in 2014, and has undergone an extensive re-write of the connection handling code.

Many issues like transaction deadlocks, pool exhaustion, async issues, and even connection leaks have been fixed in newer versions of Slick.

[kumar-asista]

@brettwooldridge thanks for Reply. I will upgrade my version,

val ds = new HikariDataSource()
ds.setDriverClassName("")
ds.setJdbcUrl("jdbc:postgresql://localhost:5432/somedb")
ds.setUsername("dbuser")
ds.setPassword("password")
ds.setMinimumIdle(2)
ds.setMaximumPoolSize(4)
ds.setIdleTimeout(600000)
ds.setLeakDetectionThreshold(30000)
ds.setConnectionTimeout(30000)

Regarding pool config above mention is enough, any thing specifically want to consider.

[brettwooldridge]

@kumar-cherry After more log analysis, I have a further conclusion ... with respect to the pool, I do not see any issues.

I do observe a strange pattern in your logs though...

13:37:07 WARN Connection leak detection triggered for org.postgresql.jdbc4.Jdbc4Connection@48c03748
13:37:37 INFO Previously reported leaked connection org.postgresql.jdbc4.Jdbc4Connection@48c03748 was returned to the pool (unleaked)
13:38:07 WARN Connection leak detection triggered for org.postgresql.jdbc4.Jdbc4Connection@48c03748
13:38:37 INFO Previously reported leaked connection org.postgresql.jdbc4.Jdbc4Connection@48c03748 was returned to the pool (unleaked)
13:39:07 WARN Connection leak detection triggered for org.postgresql.jdbc4.Jdbc4Connection@48c03748
13:39:37 INFO Previously reported leaked connection org.postgresql.jdbc4.Jdbc4Connection@48c03748 was returned to the pool (unleaked)
...

Those timestamps are far too regular. Something is borrowing a connection, and holding on to it for one minute. We cannot see the "borrow" action in the log, but we can infer it:

13:36:37 Connection borrowed (inferred)
13:37:07 Leak reported (30 seconds later)
13:37:37 Connection returned, "unleak" reported (30 seconds later)

Do not borrow a connection and hold it for one minute.

[kumar-asista]

@brettwooldridge Sorry for comment closed one.

I have missed some line of log,

2018-07-20 13:36:37 DEBUG HikariPool {com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator call} - HikariPool-4 - Added connection org.postgresql.jdbc4.Jdbc4Connection@470e6501

2018-07-20 13:37:07 WARN ProxyLeakTask {com.zaxxer.hikari.pool.ProxyLeakTask run} - Connection leak detection triggered for org.postgresql.jdbc4.Jdbc4Connection@470e6501, stack trace follows
java.lang.Exception: Apparent connection leak detected
at scala.slick.jdbc.JdbcBackend$DatabaseFactoryDef$$anon$3.createConnection(JdbcBackend.scala:47) ~[rule-engine-sparrowdesk.jar:na]

2018-07-20 13:37:37 INFO ProxyLeakTask {com.zaxxer.hikari.pool.ProxyLeakTask cancel} - Previously reported leaked connection org.postgresql.jdbc4.Jdbc4Connection@470e6501 was returned to the pool (unleaked)

As my understanding, please correct me if anything wrong,

1. Connection getting added to pool

Question: How the Leaked connection added in Pool?

2. try to use the connection got leaked

3. leaked connection not removed from pool?

To solve this what should I do?

Thanks @brettwooldridge ,

[brettwooldridge]

This connection was likely added because a client thread was requesting a connection...

13:36:37 DEBUG Added connection org.postgresql.jdbc4.Jdbc4Connection@470e6501

... so it was borrowed immediately.

Thirty-seconds later, when it was not yet returned, the "leak" was reported.

13:37:07 WARN Connection leak detection triggered for org.postgresql.jdbc4.Jdbc4Connection@470e6501

After another thirty-seconds, the connection is returned ("unleaked"):

13:37:37 INFO Previously reported leaked connection org.postgresql.jdbc4.Jdbc4Connection@470e6501 was returned to the pool (unleaked)

I don't know how I can state this more clearly, somewhere in your code you are borrowing a connection and keeping it out of the pool for exactly one minute, then closing it. Basically it looks like:

Connection con = ds.getConnection();
Thread.sleep(60000);
con.close();

That is the equivalent of what is going on. Because the logs show this occurring every minute ... 13:36:37, 13:37:37, 13:38:37 ... it seems likely this is some kind of timer or schedule.

Don't do that. Do not acquire a Connection, keep it for a minute, and then close it. Instead, acquire a Connection, run a query or queries, and then immediately close it.