Debugging "Communications link failure"

[Nadav Samet]

Hi,

We are seeing a lot of "Communications link failure" exceptions in production. We have tried to change the maxLifetime of a connection down to 10 minutes from the default of 30 minutes. The wait timeout on MySQL is 28800 minutes.

The thing that is consistent about this problem is that the timeout message always specifies a number between 930,000ms to 935,000ms (see example below). However, since it is strictly larger than the 10 minute maxLifetime I am not sure why a connection that is 930 seconds old is still kept around. 

Any advice will be appreciated.

Thanks,

Nadav

08:56:48.560 [HikariCP connection filler (pool HikariPool-0)] DEBUG com.zaxxer.hikari.pool.HikariPool - After fill pool stats HikariPool-0 (total=10, inUse=8, avail=2, waiting=0)
Exception in thread "main" com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 931,092 milliseconds ago.  The last packet sent successfully to the server was 931,092 milliseconds ago.
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:422)
	at com.mysql.jdbc.Util.handleNewInstance(Util.java:389)
	at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1038)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3422)
	at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3322)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3762)
	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:870)
	at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1928)
	at com.mysql.jdbc.MysqlIO.fetchRowsViaCursor(MysqlIO.java:4790)
	at com.mysql.jdbc.RowDataCursor.fetchMoreRows(RowDataCursor.java:394)
	at com.mysql.jdbc.RowDataCursor.hasNext(RowDataCursor.java:313)
	at com.mysql.jdbc.RowDataCursor.next(RowDataCursor.java:343)
	at com.mysql.jdbc.ResultSetImpl.next(ResultSetImpl.java:6338)
	at com.zaxxer.hikari.proxy.ResultSetJavassistProxy.next(ResultSetJavassistProxy.java)
	at slick.jdbc.PositionedResult.nextRow(PositionedResult.scala:26)
	at slick.jdbc.PositionedResultIterator.fetchNext(PositionedResult.scala:175)
	at slick.util.ReadAheadIterator$class.slick$util$ReadAheadIterator$$update(ReadAheadIterator.scala:34)
	at slick.util.ReadAheadIterator$class.hasNext(ReadAheadIterator.scala:40)
	at slick.jdbc.PositionedResultIterator.hasNext(PositionedResult.scala:167)
	at scala.collection.Iterator$class.foreach(Iterator.scala:750)
	at slick.jdbc.PositionedResultIterator.foreach(PositionedResult.scala:167)
	at slick.jdbc.Invoker$class.foreach(Invoker.scala:70)
	at slick.jdbc.StatementInvoker.foreach(StatementInvoker.scala:16)
	at slick.jdbc.StreamingInvokerAction$class.run(StreamingInvokerAction.scala:22)

Variable dump:

08:08:48.466 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - HikariCP pool HikariPool-0 configuration:
08:08:48.476 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - allowPoolSuspension.............false
08:08:48.476 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - autoCommit......................true
08:08:48.477 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - catalog.........................
08:08:48.477 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - connectionCustomizer............com.zaxxer.hikari.AbstractHikariConfig$1@f10de66
08:08:48.477 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - connectionCustomizerClassName...
08:08:48.477 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - connectionInitSql...............
08:08:48.478 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - connectionTestQuery.............
08:08:48.478 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - connectionTimeout...............30000
08:08:48.478 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - dataSource......................
08:08:48.479 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceClassName.............com.mysql.jdbc.jdbc2.optional.MysqlDataSource
08:08:48.479 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceJNDI..................
08:08:48.479 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - dataSourceProperties............{password=<masked>, serverTimezone=UTC, useServerPrepStmts=true, cachePrepStmts=true, verifyServerCertificate=false, defaultFetchSize=5000, serverName=db2, requireSSL=true, useCursorFetch=true, useJDBCCompliantTimezoneShift=true, useTimezone=true, prepStmtCacheSize=250, useLegacyDatetimeCode=false, useGmtMillisForDatetimes=true, databaseName=prod, characterEncoding=utf8, useSSL=true, prepStmtCacheSqlLimit=2048, user=prod}
08:08:48.480 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - driverClassName.................
08:08:48.480 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - healthCheckProperties...........{}
08:08:48.480 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - healthCheckRegistry.............
08:08:48.481 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - idleTimeout.....................600000
08:08:48.481 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - initializationFailFast..........true
08:08:48.481 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - isolateInternalQueries..........false
08:08:48.481 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - jdbc4ConnectionTest.............false
08:08:48.482 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - jdbcUrl.........................
08:08:48.482 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - leakDetectionThreshold..........0
08:08:48.482 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - maxLifetime.....................600000
08:08:48.482 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - maximumPoolSize.................10
08:08:48.483 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - metricRegistry..................
08:08:48.483 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - minimumIdle.....................10
08:08:48.483 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - password........................<masked>
08:08:48.484 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - poolName........................HikariPool-0
08:08:48.484 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - readOnly........................false
08:08:48.484 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - registerMbeans..................false
08:08:48.484 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - threadFactory...................
08:08:48.485 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - transactionIsolation............
08:08:48.485 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - username........................prod
08:08:48.485 [ForkJoinPool-3-worker-7] DEBUG com.zaxxer.hikari.HikariConfig - validationTimeout...............5000

[Brett Wooldridge]

I'm not sure that I trust MySQL's logged "last packet sent successfully to the server was X milliseconds ago" messages anymore.  We had a user reporting similar issues, and despite the fact that the server was only up for a day or two the messages were indicating that the packet successfuly sent was +900 hours ago.

I suggest first enabling debug logging for the com.zaxxer.hikari package, as well as configuring the leakDetectionThreshold.

Brett