読者です 読者をやめる 読者になる 読者になる

Gobble up pudding

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

MENU

MySQLでハマる Communications link failure

スポンサードリンク

f:id:fa11enprince:20150730081021j:plain
開発環境でSpring Batchを動かすと今まで動いていたはずのところでエラーが出てしまいました。
Java + Spring + iBatisを使用していて、Spring Batchを動かすとエラーが……
iBatisとか古いのはお察しください……
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
ここあたりが参考になるかも
とりあえずぼくは約2日がかりで問題解決しました(´・ω・`)。

教訓

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