Leaking: org.apache.http.impl.conn.PoolingHttpClientConnectionManager

[abedali]

Describe the bug

HikariCP: 4.0.3
aws-mysql-jdbc: 1.1.1
Hikari DataSource maxLifetime is set to 2mins,

As per our observations in JVM runtime, PoolingHttpClientConnectionManager is leaking connections and the number of instances spiking in the heap is based on Hikari's maxLifetime.

This is a serious problem.

As an alternative, we would like to explore (UrlConnectionHttpClient)
https://docs.aws.amazon.com/sdk-for-java/latest/developer-guide/http-configuration-url.html
How do we configure this in the connection?

Expected Behavior

Reuse org.apache.http.impl.conn.PoolingHttpClientConnectionManager instance
instead of re-creating

Current Behavior

Driver creates org.apache.http.impl.conn.PoolingHttpClientConnectionManager instance everytime a new connection is established and the number of instances is 5 at minimum.

Reproduction Steps

HikariCP: 4.0.3
aws-mysql-jdbc: 1.1.1
Hikari DataSource maxLifetime is set to 2mins and monitor the number of instances of
org.apache.http.impl.conn.PoolingHttpClientConnectionManager

Possible Solution

Reuse org.apache.http.impl.conn.PoolingHttpClientConnectionManager instance
instead of re-creating

Additional Information/Context

No response

The AWS JDBC Driver for MySQL version used

1.1.1

JDK version used

OpenJDK Runtime Environment Corretto-8.352.08.1 (build 1.8.0_352-b08)

Operating System and version

Linux amzn2 x86_64 GNU/Linux

[karenc-bq]

Hi @abedali, thank you for raising this. To help us investigate the issue, would you be able to answer the following questions?

1. Can you please provide us with some logs? See here on how to enable driver logs.
2. How did you configure your Hikari DataSource? What are the values for maximum pool size and the minimum idle connections?
3. Are you using the driver with JBoss or Spring?

Thank you.

[abedali]

@karenc-bq thanks for your response.

Its a spring boot application
Here are the Hikari configurations

driverClassName: software.aws.rds.jdbc.mysql.Driver
hikari:
minimum-idle: 15
maximum-pool-size: 25
pool-name: HikariPool
auto-commit: true
connection-timeout: 10000
allowPoolSuspension: true
validation-timeout: 5000
max-lifetime: 120000 #2mins
register-mbeans: true
keepalive-time: 60000
connection-init-sql: SELECT 1
leak-detection-threshold: 5000
idle-timeout: 20000
data-source-properties:
useServerPrepStmts: true

I've enabled logging, by supplying 'logger=Slf4JLogger' in the connection string properties, but didn't help much interms of logging. Its outputting sql statements.

Please help!

[karenc-bq]

Hi @abedali, thank you for providing the configurations.

Based on the configuration you have provided, the connections are not leaking and this is the expected behaviour of Hikari. HikariCP keeps a number of idle connections in the background to satisfy the minimum-idle setting, and will keep creating new connections until this values is met.

As a quick verification, do you still see the same issue if you set minimum-idle to 0?

[abedali]

@karenc-bq
The title of this bug is 'PoolingHttpClientConnectionManager' which is HTTP Pool connection manager, but not JDBC connection. My concern is related to leaks in http connection pool with-in each JDBC connection.

I've put logging.level.org.apache.http: DEBUG, and min jdbc idle connections are set to 5.

Those many instaces of PoolingHttpClientConnectionManager are created and left idle.
These objects are leaking http connections.
Likewise when new JDBC connections are added, PoolingHttpClientConnectionManager is also created along with them.

The screenshot explains the increase in the number of instances of the PoolingHttpClientConnectionManager objects in heap.

Hope the following logs would help in better understanding. Thank you and please help!

18-01-2023 12:28:31.705 LOGINHikariPool housekeeper [DEBUG] HikariPool - LOGINHikariPool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
18-01-2023 12:28:31.705 LOGINHikariPool housekeeper [DEBUG] HikariPool - LOGINHikariPool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
18-01-2023 12:28:31.705 LOGINHikariPool housekeeper [DEBUG] HikariPool - LOGINHikariPool - Fill pool skipped, pool is at sufficient level.
18-01-2023 12:28:05.841 java-sdk-http-connection-reaper [DEBUG] PoolingHttpClientConnectionManager - Closing connections idle longer than 60000 MILLISECONDS
18-01-2023 12:28:05.841 java-sdk-http-connection-reaper [DEBUG] PoolingHttpClientConnectionManager - Closing connections idle longer than 60000 MILLISECONDS
18-01-2023 12:28:05.841 java-sdk-http-connection-reaper [DEBUG] PoolingHttpClientConnectionManager - Closing connections idle longer than 60000 MILLISECONDS
18-01-2023 12:28:01.786 LOGINHikariPool connection adder [DEBUG] HikariPool$PoolEntryCreator - LOGINHikariPool - Added connection software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ConnectionImpl@687d64ee
18-01-2023 12:28:01.760 LOGINHikariPool connection closer [DEBUG] PoolBase - LOGINHikariPool - Closing connection software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ConnectionImpl@2c3ae1d9: (connection has passed maxLifetime)
18-01-2023 12:28:01.704 LOGINHikariPool housekeeper [DEBUG] HikariPool - LOGINHikariPool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
18-01-2023 12:28:01.704 LOGINHikariPool housekeeper [DEBUG] HikariPool - LOGINHikariPool - Fill pool skipped, pool is at sufficient level.
18-01-2023 12:28:01.704 LOGINHikariPool housekeeper [DEBUG] HikariPool - LOGINHikariPool - Before cleanup stats (total=5, active=0, idle=5, waiting=0)
18-01-2023 12:28:01.538 LOGINHikariPool connection adder [DEBUG] HikariPool$PoolEntryCreator - LOGINHikariPool - Added connection software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ConnectionImpl@1359c40b
18-01-2023 12:28:01.509 LOGINHikariPool connection closer [DEBUG] PoolBase - LOGINHikariPool - Closing connection software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ConnectionImpl@7a135dd5: (connection has passed maxLifetime)
18-01-2023 12:28:00.962 LOGINHikariPool connection adder [DEBUG] HikariPool$PoolEntryCreator - LOGINHikariPool - Added connection software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ConnectionImpl@68b99784
18-01-2023 12:28:00.933 LOGINHikariPool connection closer [DEBUG] PoolBase - LOGINHikariPool - Closing connection software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ConnectionImpl@79d743e6: (connection has passed maxLifetime)
18-01-2023 12:28:00.884 LOGINHikariPool connection adder [DEBUG] HikariPool$PoolEntryCreator - LOGINHikariPool - Added connection software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ConnectionImpl@3ee0abe2
18-01-2023 12:28:00.856 LOGINHikariPool connection closer [DEBUG] PoolBase - LOGINHikariPool - Closing connection software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ConnectionImpl@2ca85602: (connection has passed maxLifetime)
18-01-2023 12:28:00.819 LOGINHikariPool connection adder [DEBUG] HikariPool$PoolEntryCreator - LOGINHikariPool - Added connection software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ConnectionImpl@7fb233f8
18-01-2023 12:28:00.774 LOGINHikariPool connection closer [DEBUG] PoolBase - LOGINHikariPool - Closing connection software.aws.rds.jdbc.mysql.shading.com.mysql.cj.jdbc.ConnectionImpl@25267139: (connection has passed maxLifetime)
18-01-2023 12:27:59.966 idle-connection-reaper [DEBUG] PoolingHttpClientConnectionManager - Closing connections idle longer than 60000 MILLISECONDS
18-01-2023 12:27:59.966 idle-connection-reaper [DEBUG] PoolingHttpClientConnectionManager - Closing connections idle longer than 60000 MILLISECONDS
18-01-2023 12:27:59.966 idle-connection-reaper [DEBUG] PoolingHttpClientConnectionManager - Closing connections idle longer than 60000 MILLISECONDS
18-01-2023 12:27:59.966 idle-connection-reaper [DEBUG] PoolingHttpClientConnectionManager - Closing connections idle longer than 60000 MILLISECONDS
18-01-2023 12:27:59.966 idle-connection-reaper [DEBUG] PoolingHttpClientConnectionManager - Closing connections idle longer than 60000 MILLISECONDS
18-01-2023 12:27:59.966 idle-connection-reaper [DEBUG] PoolingHttpClientConnectionManager - Closing connections idle longer than 60000 MILLISECONDS
18-01-2023 12:27:31.705 LOGINHikariPool connection closer [DEBUG] HikariPool - LOGINHikariPool - Fill pool skipped, pool is at sufficient level.
18-01-2023 12:27:31.703 LOGINHikariPool housekeeper [DEBUG] HikariPool - LOGINHikariPool - After cleanup stats (total=5, active=0, idle=5, waiting=0)
18-01-2023 12:27:31.704 LOGINHikariPool housekeeper [DEBUG] HikariPool - LOGINHikariPool - Fill pool skipped, pool is at sufficient level.

[Michael-S-Smith]

Just want to see if I can add some clarity to this issue. We have noticed a slow memory leak in services using the driver. Heap dumps show an enormous number of PoolingHttpClientConnectionManager instances on the heap. We have now demonstrated that the event of closing expired connections and opening new ones adds an instance of PoolingHttpClientConnectionManager and these do not seem to ever be cleaned up. The number of additional instances is exactly the same as the minimum pool size and they grow at a time defined by the idle timeout.
We suspect the AWSSecretsManagerPlugin is creating a client that is not being closed.

[testereg]

@Michael-S-Smith

By disabling AWSSecretsManagerPluginFactory, the PoolingHttpClientConnectionManager instances are not increasing now

[testereg]

[Michael-S-Smith]

The disabling of the AWSSecretsManagerPluginFactory was done as a test to prove our guess, but it is not a solution for us as we really need the secrets manager approach to work properly. It seems the AWSSecretsManagerPluginFactory is the problem.

[aaronchung-bitquill]

Hello @abedali
Wanted to let you know that we're still actively looking this.
We'll provide an update here when we have a solution ready.
Thanks

[karenc-bq]

Hi @abedali, thank you for raising this issue.

The fix has been merged, can you please kindly checkout our snapshot build and let us know if the issue persists? Thank you.

[abedali]

@karenc-bq Appreciate your quick turnaround. I don't see the issue anymore using snapshot version of the library 'aws-mysql-jdbc-1.1.4-20230126.000534-6'.

[karenc-bq]

We've released a new version of the driver that resolves this issue. Please download the latest 1.1.4 version of the driver. We'll be closing this ticket. Thank you