"Communications link failure"でアプリ起動できない問題

Communications link failure Java エラー 環境構築

SpringBootで作ったアプリを起動すると、以下のエラーが起こり起動に失敗する現象に遭遇しました。

Caused by: com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure

この現象の原因と解決策についてメモします。

環境

言語: Java8
FW: SpringBoot
DB: MySQL5.7
ビルドツール: Maven

現象

application.propertiesにdb接続の設定を以下のように記述し、

spring.datasource.url=jdbc:mysql://localhost:3306/sample_app
spring.datasource.username=testuser
spring.datasource.password=testuser
spring.jpa.database=MYSQL

mvn spring-boot:run とターミナルで叩きアプリを起動します。

すると以下のようにエラーが発生しました。

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.5.RELEASE)

2021-07-05 18:57:34.756  INFO 10112 --- [  restartedMain] com.example.demo.DemoApplication         : Starting DemoApplication on N0128.local with PID 10112 (/Users/akiyoshi.tokiya/develop/iTICKET/app_in_app/springbootsample/target/classes started by akiyoshi.tokiya in /Users/akiyoshi.tokiya/develop/iTICKET/app_in_app/springbootsample)
2021-07-05 18:57:34.758  INFO 10112 --- [  restartedMain] com.example.demo.DemoApplication         : No active profile set, falling back to default profiles: default
2021-07-05 18:57:34.788  INFO 10112 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : Devtools property defaults active! Set 'spring.devtools.add-properties' to 'false' to disable
2021-07-05 18:57:34.789  INFO 10112 --- [  restartedMain] .e.DevToolsPropertyDefaultsPostProcessor : For additional web related logging consider setting the 'logging.level.web' property to 'DEBUG'
2021-07-05 18:57:35.631  INFO 10112 --- [  restartedMain] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2021-07-05 18:57:35.651  INFO 10112 --- [  restartedMain] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2021-07-05 18:57:35.651  INFO 10112 --- [  restartedMain] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.19]
2021-07-05 18:57:35.718  INFO 10112 --- [  restartedMain] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2021-07-05 18:57:35.718  INFO 10112 --- [  restartedMain] o.s.web.context.ContextLoader            : Root WebApplicationContext: initialization completed in 929 ms
2021-07-05 18:57:35.806  INFO 10112 --- [  restartedMain] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Starting...
2021-07-05 18:57:37.040 ERROR 10112 --- [  restartedMain] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Exception during pool initialization.

com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
    at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:835) ~[mysql-connector-java-8.0.16.jar:8.0.16]
...
    at com.mysql.cj.NativeSession.connect(NativeSession.java:165) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    at com.mysql.cj.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:955) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:825) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    ... 104 common frames omitted
Caused by: javax.net.ssl.SSLHandshakeException: No appropriate protocol (protocol is disabled or cipher suites are inappropriate)
    at java.base/sun.security.ssl.HandshakeContext.(HandshakeContext.java:172) ~[na:na]
    at java.base/sun.security.ssl.ClientHandshakeContext.(ClientHandshakeContext.java:98) ~[na:na]
    at java.base/sun.security.ssl.TransportContext.kickstart(TransportContext.java:238) ~[na:na]
    at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:434) ~[na:na]
    at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:412) ~[na:na]
    at com.mysql.cj.protocol.ExportControlled.performTlsHandshake(ExportControlled.java:316) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    at com.mysql.cj.protocol.StandardSocketFactory.performTlsHandshake(StandardSocketFactory.java:188) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    at com.mysql.cj.protocol.a.NativeSocketConnection.performTlsHandshake(NativeSocketConnection.java:99) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    at com.mysql.cj.protocol.a.NativeProtocol.negotiateSSLConnection(NativeProtocol.java:352) ~[mysql-connector-java-8.0.16.jar:8.0.16]
    ... 111 common frames omitted

結論

application.propertiesのspring.datasource.url=jdbc:mysql://localhost:3306/sample_appの末尾に?enabledTLSProtocols=TLSv1.2をつけることで解決しました。

spring.datasource.url=jdbc:mysql://localhost:3306/sample_app?enabledTLSProtocols=TLSv1.2

原因

ログを詳しく見ると、Caused by: javax.net.ssl.SSLHandshakeException: No appropriate protocol (protocol is disabled or cipher suites are inappropriate) というエラーに起因しています。これはRHEL 7 から RHEL 8 でサポートされる最新の TLS プロトコルバージョンが異なるために発生するようで、これにより、TLSハンドシェイクのネゴシエーション中にアプリケーションとT LSプロトコルの不一致が発生し接続が失敗してしまいます。

これの回避策として、データベース接続URLにTLSプロトコルバージョンを手動で指定すると接続できるようになるようです。

また、Communications link failureというエラーに関してですが、これはアプリケーションがdbにアクセスできていないために起こるエラーで、原因としては以下が考えられるようです。

  1. JDBC URLで指定しているIPアドレスやホストアドレスが間違っている
  2. JDBC URLで指定しているホスト名がローカルDNSに認識されていない
  3. JDBC URLで指定しているポート番号が間違っている
  4. DBサーバが起動していない
  5. DBサーバがTCP/IPコネクションを受け付けない
  6. DBサーバのコネクションが足りていない
  7. ファイアウォールやプロキシなどによってアプリケーションとDBの接続がブロックされている

上記の対策、調査方法としては以下があります。

  1. pingを試す
  2. DNSをリフレッシュ、またはJDBC URLに指定しているIPアドレスを指定する
  3. MySQLの場合、my.cnfのポート番号と一致するか確認
  4. DBを起動する
  5. mysqldが--skip-networking optionの指定なしで動いているか確認
  6. DBを再起動し、DB接続後にコネクションをしっかり閉じているか確認
  7. ファイアウォールやプロキシの設定を確認

今回の場合は5が当てはまりますね。

参考
・https://access.redhat.com/documentation/ja-jp/red_hat_build_of_thorntail/2.7/html/release_notes_for_thorntail_2.7/connection-between-a-rhel-8-based-application-and-a-rhel-7-based-mysql-5-7-database-fails-due-to-tls-protocol-version-mismatch
・https://stackoverflow.com/questions/2983248/com-mysql-jdbc-exceptions-jdbc4-communicationsexception-communications-link-fai