embulk-input-mysqlでのSSL通信にCommunications link failureが出た時の対処法

経緯

1. ある時期からSSLExceptionを見かけるようになり、何か対処が必要そうだと思い始める

• インスタンスローテーションのため、インスタンス再作成を行った後からエラーが発生し接続不可となった
• 応急的にSSL: true (SSL: enableと同義)から、 SSL: false と変更することで動作を確認
• 2020年からTLS v1.0/1.1の無効化が決定したのでその影響を疑う
• twitterで助けてもらう https://twitter.com/yoshi_ken/status/1398119709732610049
• 提案された設定を追加することで解決に至る

結論

embulkに渡す設定ファイルにoptions: {"enabledTLSProtocols":"TLSv1.2"} を指定しましょう。

もし複数のoptionを渡したい時には、次のように複数行表記が良いでしょう。

  options:
    enabledTLSProtocols: TLSv1.2
    sessionVariables: group_concat_max_len=10*1024

JDBC Optionを渡したことによるパラメータの変化

enabledTLSProtocols=TLSv1.2, が増えていることが分かります。

変更前
Connecting to jdbc:mysql://****.rds.amazonaws.com:3306/abc_db options {useCompression=true, socketTimeout=1800000, useSSL=true, user=test, useLegacyDatetimeCode=false, requireSSL=true, tcpKeepAlive=true, verifyServerCertificate=false, connectTimeout=300000, password=***, zeroDateTimeBehavior=convertToNull}

変更後
Connecting to jdbc:mysql://****.rds.amazonaws.com:3306/abc_db options {useCompression=true, enabledTLSProtocols=TLSv1.2, socketTimeout=1800000, useSSL=true, user=test, useLegacyDatetimeCode=false, requireSSL=true, verifyServerCertificate=false, tcpKeepAlive=true, connectTimeout=300000, password=***, zeroDateTimeBehavior=convertToNull}

前兆

次のSSLException が出始めていました

Wed Feb 24 00:08:16 UTC 2021 WARN: Caught while disconnecting...

EXCEPTION STACK TRACE:



** BEGIN NESTED EXCEPTION ** 

javax.net.ssl.SSLException
MESSAGE: closing inbound before receiving peer's close_notify

STACKTRACE:

javax.net.ssl.SSLException: closing inbound before receiving peer's close_notify
	at sun.security.ssl.Alert.createSSLException(Alert.java:133)
	at sun.security.ssl.Alert.createSSLException(Alert.java:117)
	at sun.security.ssl.TransportContext.fatal(TransportContext.java:311)
	at sun.security.ssl.TransportContext.fatal(TransportContext.java:267)
	at sun.security.ssl.TransportContext.fatal(TransportContext.java:258)
	at sun.security.ssl.SSLSocketImpl.shutdownInput(SSLSocketImpl.java:637)
	at sun.security.ssl.SSLSocketImpl.shutdownInput(SSLSocketImpl.java:616)
	at com.mysql.jdbc.MysqlIO.quit(MysqlIO.java:2246)
	at com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4237)
	at com.mysql.jdbc.ConnectionImpl.close(ConnectionImpl.java:1465)
	at org.embulk.input.jdbc.JdbcInputConnection.close(JdbcInputConnection.java:208)
	at org.embulk.input.jdbc.AbstractJdbcInputPlugin.transaction(AbstractJdbcInputPlugin.java:215)
	at org.embulk.exec.BulkLoader.doRun(BulkLoader.java:507)
	at org.embulk.exec.BulkLoader.access$000(BulkLoader.java:35)
	at org.embulk.exec.BulkLoader$1.run(BulkLoader.java:353)
	at org.embulk.exec.BulkLoader$1.run(BulkLoader.java:350)
	at org.embulk.spi.Exec.doWith(Exec.java:22)
	at org.embulk.exec.BulkLoader.run(BulkLoader.java:350)
	at org.embulk.EmbulkEmbed.run(EmbulkEmbed.java:178)
	at org.embulk.EmbulkRunner.runInternal(EmbulkRunner.java:292)
	at org.embulk.EmbulkRunner.run(EmbulkRunner.java:156)
	at org.embulk.cli.EmbulkRun.runSubcommand(EmbulkRun.java:433)
	at org.embulk.cli.EmbulkRun.run(EmbulkRun.java:90)
	at org.embulk.cli.Main.main(Main.java:64)


** END NESTED EXCEPTION **

後日、Communications link failureというエラーが発生しSSL通信に失敗していました。

2021-05-25 06:22:00.934 +0000 [INFO] (0001:transaction): Connecting to jdbc:mysql://****.rds.amazonaws.com:3306/abc_db options {useCompression=true, socketTimeout=1800000, useSSL=true, user=test, useLegacyDatetimeCode=false, requireSSL=true, tcpKeepAlive=true, verifyServerCertificate=false, connectTimeout=300000, password=***, zeroDateTimeBehavior=convertToNull}
org.embulk.exec.PartialExecutionException: java.lang.RuntimeException: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 222 milliseconds ago.  The last packet sent successfully to the server was 217 milliseconds ago.
	at org.embulk.exec.BulkLoader$LoaderState.buildPartialExecuteException(BulkLoader.java:340)
	at org.embulk.exec.BulkLoader.doRun(BulkLoader.java:566)
	at org.embulk.exec.BulkLoader.access$000(BulkLoader.java:35)
	at org.embulk.exec.BulkLoader$1.run(BulkLoader.java:353)
	at org.embulk.exec.BulkLoader$1.run(BulkLoader.java:350)
	at org.embulk.spi.Exec.doWith(Exec.java:22)
	at org.embulk.exec.BulkLoader.run(BulkLoader.java:350)
	at org.embulk.EmbulkEmbed.run(EmbulkEmbed.java:178)
	at org.embulk.EmbulkRunner.runInternal(EmbulkRunner.java:292)
	at org.embulk.EmbulkRunner.run(EmbulkRunner.java:156)
	at org.embulk.cli.EmbulkRun.runSubcommand(EmbulkRun.java:433)
	at org.embulk.cli.EmbulkRun.run(EmbulkRun.java:90)
	at org.embulk.cli.Main.main(Main.java:64)
	Suppressed: java.lang.NullPointerException
		at org.embulk.exec.BulkLoader.doCleanup(BulkLoader.java:463)
		at org.embulk.exec.BulkLoader$3.run(BulkLoader.java:397)
		at org.embulk.exec.BulkLoader$3.run(BulkLoader.java:394)
		at org.embulk.spi.Exec.doWith(Exec.java:22)
		at org.embulk.exec.BulkLoader.cleanup(BulkLoader.java:394)
		at org.embulk.EmbulkEmbed.run(EmbulkEmbed.java:181)
		... 5 more
Caused by: java.lang.RuntimeException: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

参考記事