Gobble up pudding

プログラミングの記事がメインのブログです。

MENU
トップ > Java > MySQLでハマる Communications link failure

MySQLでハマる Communications link failure

Java データベース
スポンサードリンク



2020/05/18 追記 いまだにアクセスがあるのでコメントを書きます。
これは古い記事ですが、今でも通用する内容かと思われます。
かなり怪しい記憶ですが、当時のバージョンは

Java 6
Struts 1.2
Spring 1
MySQL 5.5
iBatis(バージョン不明だが、すくなくともMyBatisではない)

だったかと思います。なんでもそうですが、下位レイヤーから疑えというのは何についても大事でいつの時代も変わらないと思います。
よく言われていたSSHパターンの変則系(Hibernateの代わりにiBatis)の構成でした。

開発環境でSpring Batchを動かすと今まで動いていたはずのところでエラーが出てしまいました。
Spring Batchを動かすとエラーが……
java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
とか
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
とかでググると見事にハマった。

エラー内容

長いのでところどころ端折っています。

... [WARN ] [...] [...] [...] [main] Error while extracting database product name - falling back to empty error codes
org.springframework.jdbc.support.MetaDataAccessException: Error while extracting DatabaseMetaData;
        nested exception is com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException:
        No operations allowed after connection closed.Connection was implicitly closed by the driver.
        at org.springframework.jdbc.support.JdbcUtils.extractDatabaseMetaData(JdbcUtils.java:296)
        at org.springframework.jdbc.support.JdbcUtils.extractDatabaseMetaData(JdbcUtils.java:320)
        at org.springframework.jdbc.support.SQLErrorCodesFactory.getErrorCodes(SQLErrorCodesFactory.java:216)
        at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.setDataSource(SQLErrorCodeSQLExceptionTranslator.java:140)
        at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.<init>(SQLErrorCodeSQLExceptionTranslator.java:103)
        at org.springframework.jdbc.support.JdbcAccessor.getExceptionTranslator(JdbcAccessor.java:99)
        at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:407)
        at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:522)
		...
       at org.springframework.batch.core.launch.support.CommandLineJobRunner.main(CommandLineJobRunner.java:525)
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed.Connection was implicitly closed by the driver.
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:409)
        at com.mysql.jdbc.Util.getInstance(Util.java:384)
        ...
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 52,995 milliseconds ago.  The last packet sent successfully to the server was 52,995 milliseconds ago.
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:409)
        ...
        ... 49 more
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes,
        read 0 bytes before connection was unexpectedly lost.
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2502)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2952)
        ... 59 more
org.springframework.dao.RecoverableDataAccessException: StatementCallback;
        SQL [INSERT INTO ...]; Communications link failure
The last packet successfully received from the server was 52,995 milliseconds ago.
The last packet sent successfully to the server was 52,995 milliseconds ago.;
        nested exception is com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
The last packet successfully received from the server was 52,995 milliseconds ago.
The last packet sent successfully to the server was 52,995 milliseconds ago.
        at org.springframework.jdbc.support.SQLExceptionSubclassTranslator.doTranslate(SQLExceptionSubclassTranslator.java:97)
        at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
        at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:80)
        at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:407)
        at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:522)
		...
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 52,995 milliseconds ago.  The last packet sent successfully to the server was 52,995 milliseconds ago.
        ... 
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2502)
        at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2952)
        ... 59 more

タイムアウトを疑う

設定ファイル群からタイムアウトを根こそぎ探す。
だけど、設定値より短い時間で落ちている……。

MySQLのタイムアウト設定ではなさそう
iBatisが8時間で切れるっていうのはデフォルトの設定値であるみたい。
とりあえずググった結果からそのあたりの記事に書いてある対策をやってみる

とりあえず接続切れない対策をする

コネクションはりすぎたかなー…コネクションプールきいてないのかなー
とかいろいろ妄想しつつ…
http://yyhayashi303.hatenablog.com/entry/20120911/1347322683

<bean id="dataSource" class="org.apache.commons.dbcp.BasicDataSource"
    destroy-method="close">
    <property name="driverClassName" value="com.mysql.jdbc.Driver" />
    <property name="url"
                  value="jdbc:mysql://localhost:3306/test_db?characterEncoding=utf8" />
    <property name="username" value="xxxxxxxx" />
    <property name="password" value="xxxxxxxx" />
</bean>

追加してみる。

<bean id="dataSource" class="org.apache.commons.dbcp.BasicDataSource"
    destroy-method="close">
    <property name="driverClassName" value="com.mysql.jdbc.Driver" />
    <property name="url"
                  value="jdbc:mysql://localhost:3306/test_db?characterEncoding=utf8" />
    <property name="username" value="xxxxxxxx" />
    <property name="password" value="xxxxxxxx" />
	<property name="validationQuery" value="SELECT 1 FROM DUAL" />
	<property name="testOnBorrow" value="true" />
	<property name="testWhileIdle" value="true" />
	<property name="timeBetweenEvictionRunsMillis" value="60000" />
</bean>

うーん症状変わらず。
iBatisのタイムアウトも関係なかった。
結局ここは関係ないのでもとに戻す。

エラーでひたすらググる

Welcome to 泥沼でした。
java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
http://stackoverflow.com/questions/10048296/error-in-mysql-connection-when-accessing-a-remote-server
http://stackoverflow.com/questions/9687153/can-not-read-response-from-server

com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
http://stackoverflow.com/questions/2983248/com-mysql-jdbc-exceptions-jdbc4-communicationsexception-communications-link-fai
http://stackoverflow.com/questions/2121829/com-mysql-jdbc-exceptions-jdbc4-communicationsexceptioncommunications-link-fail
http://stackoverflow.com/questions/9687153/can-not-read-response-from-server
この辺も見てみたが助けにならない…

あれ、MySQLのエラーログが出てない！！！

そうだMySQLのエラーログ見よう！！普通はそっちが先に見るべきだよね！
あれ…ログの設定してない。

log-error=/var/log/mysql/error.log

などとしてmy.cnfを編集してmysql再起動

エラーを見るとmysqlが死んでいる…

Java側で捕捉しているエラーは上記のCommunications link failureでしたが、、
mysqlのエラーログを見ると、当初はInnoDBのログファイルのサイズが小さすぎてエラーを出しており
mysqldが死んで勝手に再起動というようなことになっていた。
一方Java側はmysqlが生きているものだと思って接続しようとするが失敗し結果上記のエラーになっていた模様。

真の原因

ログファイルサイズが小さすぎた

InnoDB: ERROR: the age of the last checkpoint is 90608129,
InnoDB: which exceeds the log group capacity 90593280.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the
InnoDB: largest such row.

エラーログにこんなん出てきた。そうか……BLOB使ってたよな。
ということでinnodb_log_file_sizeを拡大しなければということに至る。

と、ここで気軽にmysqlのログファイルサイズを拡張したらDBがぶっ壊れたり
mysqlが起動しなくなりました。
とりあえず復元して(バックアップは重要だね！！)、
mysqldumpでデータのバックアップを取ります。

そのあとログファイルサイズを変更します。
http://blog.flatlabs.net/20100727_212649/
に書いてある手順をやって慎重に変更します。
手軽に変えると死にます。
んで、結局ログファイルサイズを変更するとDBがうまいこと読み込めないので
DBごとDROPしてしまってmysqldumpで取ったものを投入します。
開発環境だからこそ通用する手段ですねw
そうすると元通りに！運用環境だとどうするんだろ。。。
実際には何も考えずにinnodb_buffer_pool_sizeを積んでいるメモリ以上にでかくして
アロケート失敗なんてエラーも出して四苦八苦していましたが……。

今回変更したmy.cnfの内容の抜粋

# デフォルト値
#max_allowed_packet = 1M
#read_buffer_size = 128k
#read_rnd_buffer_size = 256k
#innodb_buffer_pool_size = 8M
#innodb_log_file_size = 5M
#innodb_log_buffer_size = 1M
max_allowed_packet = 16M
read_buffer_size = 16M
read_rnd_buffer_size = 16M
innodb_buffer_pool_size = 1024M
innodb_log_file_size = 128M
innodb_log_buffer_size = 1M

ここら辺のパラメータの値はなかなか難しいところがあって
いろいろ算出する流儀があるそうですが、
開発環境のスペックや処理対象のモノが動くかどうかあたりを検討して
きめちゃいます。
http://tetsuyai.hatenablog.com/entry/20111006/1317873012
ここあたりが参考になるかも。また、

というのもあるので参考にするとよいかもしれません。

教訓

DBがらみのエラーが出たら真っ先にmysqlのエラーログを見ましょう。