Failed to validate connection com.mysql.jdbc.JDBC4Connection@xxxxx (No operations allowed after connection closed.)

[kutchar]

Environment

HikariCP version: 2.7.4
JDK version     : 1.8.0_144
Database        : MySQL
Driver version  : 5.1.42

---

We keep seeing Failed to validate connection com.mysql.jdbc.JDBC4Connection@xxxxx (No operations allowed after connection closed.) warnings in the logs at a high frequency. The interval between the logs seems rather random. What could be the cause of this? I have checked the relevant GitHub issues and StackOverflow but none of those cases seemed similar to our issue. What could possibly be closing the connections?

A bit context:
We are using sqlest library in Scala, I've checked the relevant parts of the code and sqlest is not really doing anything out of ordinary (https://github.com/jhc-systems/sqlest/blob/master/sqlest/src/main/scala/sqlest/executor/Database.scala#L191)
The database calls happen asynchronously using's Scala's Future class.

Here's the Hikari config:

jdbc-url     = "jdbc:mysql://x.x.x.x:3306/database"
username     = "XXXX"
password     = "XXXX"
auto-commit  = false
pool-name    = "core"
data-source-properties {
  cachePrepStmts           = true
  prepStmtCacheSize        = 250
  prepStmtCacheSqlLimit    = 2048
  useServerPrepStmts       = true
  useLocalSessionState     = true
  useLocalTransactionState = true
  rewriteBatchedStatements = true
  cacheResultSetMetadata   = true
  cacheServerConfiguration = true
  elideSetAutoCommits      = true
  maintainTimeStats        = false
  useUnicode               = true
  characterEncoding        = UTF-8
}

What's strange is that I see in the logs that right after the failed validation (in 5ms) there is an executed SQL.

2017-12-01T07:01:24.281Z WARN  [application-akka.actor.default-dispatcher-5] [com.zaxxer.hikari.pool.PoolBase] [] [] Failed to validate connection com.mysql.jdbc.JDBC4Connection@30fd6802 (No operations allowed after connection closed.)
2017-12-01T07:01:24.286Z INFO  [application-akka.actor.default-dispatcher-5] [sqlest.executor.Transaction] [] [] Ran sql in 2ms: sql [update xxxxxx]

Thanks in advance

[brettwooldridge]

Two things I can think of to check. 1) MySQL may be closing idle connections in a shorter period than HikariCP (default 10 minutes). 2) Some code (somewhere) is unwrapping the HikariCP connection to access the underlying MySQL connection, and then closing that instead of (or in addition to) the HikariCP Connection.

[brettwooldridge]

Regarding the query closely following the validation error, that is to be expected. The thread wanted a connection, the one HikariCP wanted to give it failed validation, so HikariCP immediately gave it another. At which point the thread ran the query.

[kutchar]

It appears that the issue was with the HA Proxy timeout (that's between the app servers & the MySql servers) since I don't see the issue when I connect directly. For future readers, I set the HA Proxy timeout to the same value as MySql's wait_timeout and so far I haven't seen the issue again. Still monitoring...

[kutchar]

Still no warnings, so the problem was caused by HAProxy terminating connections. @brettwooldridge thanks for the hint.

[chainyu]

We used Microsoft azure database, the maximum value of interactive_timeout in its server configuration is 240s, so the configuration 228800 in the database does not take effect. see https://docs.azure.cn/zh-cn/articles/azure-operations-guide/mysql/aog-mysql-connections-faq

[eggplantbr]

I had the same issue on a MySql Server 5.7.24 running on Azure. The issue is that the pool has the default idle timeout of 10 minutes, whilst the mysql server on azure has the idle timeout (mysql server variable is called wait_timeout) configured by default to 120 seconds.
So the server times out every 2 minutes and the pools tries to reconnect and generates that warning.
I fixed it by setting the wait_timeout on mysql to 660 seconds.

Hope that helps someone.

[kanuku]

We were encountering similar problems!
At first it looked like this happened because of having a ha-proxy between the service and the database!
However, later it became obvious that it was a configuration problem because the error was being logged before connecting to the database via the proxy! We decided to step away from the default configuration!

Possible solution:

We managed to get rid of those problem by using the following configuration:

      #Hikari related configuration
      SPRING_DATASOURCE_HIKARI_LEAKDETECTIONTHRESHOLD: 2000
      SPRING_DATASOURCE_HIKARI_MAXIMUMPOOLSIZE: 10
      SPRING_DATASOURCE_HIKARI_MINIMUMIDLE: 9
      SPRING_DATASOURCE_HIKARI_ISOLATEINTERNALQUERIES: true
      SPRING_DATASOURCE_HIKARI_IDLETIMEOUT: 30000
      SPRING_DATASOURCE_HIKARI_MAXLIFETIME: 60000

Take into account that the the maxlifetime and idletimeout will not work if they have the exact same value (or if you use the default configuration)!