Slick(HikariCP) で「Communications link failure」が出た時の対応

はじめに

MySQLの「Communications link failure」が出る要因はいくつかあり ¹、原因によってアプローチが異なるますが、Slick　の「HikariCP」を使っている時にアプリケーションで以下のエラーに遭遇した際の対応方法について記載します。　

• Version
  • slick:3.3.3
  • slick-hikaricp:3.3.3

slick-mysql.db - Connection com.mysql.cj.jdbc.ConnectionImpl@6f588eb5 marked as broken because of SQLSTATE(08S01), ErrorCode(0)
	
com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure

The last packet successfully received from the server was 10,016 milliseconds ago. The last packet sent successfully to the server was 10,106 milliseconds ago.
	at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174)
	at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64)
	at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:953)
	at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1098)
	at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1046)
	at com.mysql.cj.jdbc.ClientPreparedStatement.executeLargeUpdate(ClientPreparedStatement.java:1371)
	at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdate(ClientPreparedStatement.java:1031)
	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)
	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java)
	at biz.taketora.application.infrastructure.database.HogeWriteRepositoryImpl.$anonfun$save$3(HogeWriteRepositoryImpl.scala:58)
	at biz.taketora.application.infrastructure.database.HogeWriteRepositoryImpl.$anonfun$save$3$adapted(HogeWriteRepositoryImpl.scala:45)
	at slick.jdbc.SimpleJdbcAction.run(StreamingInvokerAction.scala:70)
	at slick.jdbc.SimpleJdbcAction.run(StreamingInvokerAction.scala:69)
	at slick.basic.BasicBackend$DatabaseDef$$anon$3.liftedTree1$1(BasicBackend.scala:276)
	at slick.basic.BasicBackend$DatabaseDef$$anon$3.run(BasicBackend.scala:276)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: com.mysql.cj.exceptions.CJCommunicationsException: Communications link failure

The last packet successfully received from the server was 10,016 milliseconds ago. The last packet sent successfully to the server was 10,106 milliseconds ago.
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61)
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)
	at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151)
	at com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167)
	at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:520)
	at com.mysql.cj.protocol.a.NativeProtocol.checkErrorMessage(NativeProtocol.java:700)
	at com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:639)
	at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:987)
	at com.mysql.cj.NativeSession.execSQL(NativeSession.java:666)
	at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:930)
	... 15 common frames omitted
Caused by: java.net.SocketTimeoutException: Read timed out
	at java.base/java.net.SocketInputStream.socketRead0(Native Method)
	at java.base/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
	at java.base/java.net.SocketInputStream.read(SocketInputStream.java:168)
	at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
	at com.mysql.cj.protocol.ReadAheadInputStream.fill(ReadAheadInputStream.java:107)
	at com.mysql.cj.protocol.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:150)
	at com.mysql.cj.protocol.ReadAheadInputStream.read(ReadAheadInputStream.java:180)
	at java.base/java.io.FilterInputStream.read(FilterInputStream.java:133)
	at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:64)
	at com.mysql.cj.protocol.a.SimplePacketReader.readHeaderLocal(SimplePacketReader.java:81)
	at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63)
	at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45)
	at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:52)
	at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:41)
	at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:54)
	at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:44)
	at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:514)
	... 20 common frames omitted

原因

SocketTimeoutExceptionは、タイムアウトのために発生しています。

Caused by: java.net.SocketTimeoutException: Read timed out

アプリケーション側でタイムアウトにならないようにDBの処理を軽くするか、またはこのタイムアウトの期間を伸ばします。

対応方法

タイムアウトの期間を伸ばすためにはslick の validationTimeoutの値を設定します。

validationTimeoutは接続が有効かどうかテストされる最大時間です。²

• validationTimeout

validationTimeout (Duration, optional, default: 5s): The maximum amount of time that a connection will be tested for aliveness. This value must be less than the connectionTimeout. Lowest acceptable validation timeout is 250 ms.

application.conf

mydb {
  profile = "slick.jdbc.MySQLProfile$"
  db {
    dataSourceClass = "slick.jdbc.DriverDataSource"
    properties = {
      driver = "com.mysql.cj.jdbc.Driver"
      url = "jdbc:mysql://127.0.0.1:3306/my_database?useSSL=false"
      user = "user"
      password = "pass"
    }
    validationTimeout = 10000 // 追加
    numThreads = 10
  }
}

val databaseConfig = Database.forConfig("mydb")

databaseConfig.db.run(query)

これでアプリケーションの操作で5秒以上DBから応答がなくても、コネクションが切られません。

補足

デフォルトの設定値

• HikariCPJdbcDataSource.scala

HikariCPJdbcDataSource.scala

hconf.setValidationTimeout(c.getMillisecondsOr("validationTimeout", 5000))

• PoolBase.java

PoolBase.java

setNetworkTimeout(connection, validationTimeout);

参考

• 今更ながらの、HttpURLConnection 障害処理編
• HikariPool-1 - Connection marked as broken because of SQLSTATE(08S01), ErrorCode(-99999)

1. MySQLの「Communications link failure...」の解決方法を調べていて、よく見つけるヤツ
   ↩

2. 実行しているSQLに5秒以上時間がかかっているとレスポンスがないとみなされてコネクションが切られるのではないかと推測しています。 ↩