'Client requested master to start replication from impossible position'の原因

たとえばこんなエラーログ。

140603 10:05:58 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000032' at position 61352894, relay log './mysql-relay.000787' position: 21485832
140603 10:05:58 [Note] Slave I/O thread: connected to master 'replicator@xxx.xxx.xxx.xxx:3306',  replication started in log 'mysql-bin.000032' at position 61352894
140603 10:05:58 [ERROR] Error reading packet from server: Client requested master to start replication from impossible position ( server_errno=1236)
140603 10:05:58 [ERROR] Got fatal error 1236: 'Client requested master to start replication from impossible position' from master when reading data from binary log
140603 10:05:58 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.000032', position 61352894

START SLAVEしたタイミングでこんなんが出ることがあります。
そしてI/Oスレッドのみが止まる。SHOW SLAVE STATUSで見るとSlave_IO_Running: No, Slave_SQL_Running: Yes な状態です。

ゆえあってMySQL 5.0なので(というか2014年にもなってTritonnです)、SHOW SLAVE STATUSには何も表示されてないですが、5.1 以降なら↑のログの内容がLast_IO_Errorに表示されるんじゃないかと。

上から読んでいくと、

1. SQLスレッドが初期化された。マスターのログファイルはmysql-bin.000032でログポジションは61352894、リレーログファイルはmysql-relay.000787でログポジションが21485832。
2. I/Oスレッドがマスターに接続して、mysql-bin.000032のポジション61352894のログを要求した。
3. サーバーからerrno= 1236 を受け取った。メッセージは「クライアントのリクエストしたレプリケーションの開始位置がアリエナイ！」
4. 大事なので(かどうかは知らんけど)2回言った
5. I/Oスレッドが動作を停止した。最後に読んだマスターのログファイルは..(略)

errno= 1236は「バイナリーログをもらおうとしたら致命的な(=リトライしても成功する見込みのない)エラーが発生した」というI/Oスレッドの(わりと)汎用エラーなので、大事なのはエラーメッセージの方。

$ perror 1236
MySQL error code 1236 (ER_MASTER_FATAL_ERROR_READING_BINLOG): Got fatal error %d from master when reading data from binary log: '%-.320s'

そしてマスター上のバイナリーログファイルはこんなんになっており、

$ ll mysql-bin.*
-rw-rw---- 1 mysql mysql 268436192 May 31 21:26 mysql-bin.000031
-rw-rw---- 1 mysql mysql  61341696 Jun  3 05:35 mysql-bin.000032
-rw-rw---- 1 mysql mysql        98 Jun  3 05:53 mysql-bin.000033
-rw-rw---- 1 mysql mysql       117 Jun  3 06:15 mysql-bin.000034
-rw-rw---- 1 mysql mysql   4630804 Jun  3 11:35 mysql-bin.000035
-rw-rw---- 1 mysql mysql        95 Jun  3 06:29 mysql-bin.index

確かにmysql-bin.000032に61352894バイト目は存在しない(master_log_posはバイナリーログファイルの先頭からのバイトオフセット)
だけど、スレーブは61352894バイト目までは終わってるから次をよこせと言っている状況。

マスターがsync-binlog= 0 でOSごとクラッシュした時にこんな状況が起こりがちで、

1. マスターがバイナリーログをwrite
2. Binlog dump threadがwriteされたバイナリーログを読み出してスレーブに送信
3. マスターのバイナリーログがフラッシュされる前にOSクラッシュ

とまあ、書き込みワークロードをかけながらOSをクラッシュさせるなり電源を落とすなりで比較的簡単に再現できる。

CHANGE MASTER TO master_log_file= 'mysql-bin.000033', master_log_pos= 1; で仮復旧はできるものの、その後マスター/スレーブのデータの整合性確認しないといけないのが面倒とか、バイナリーログの保全ができてない(log-slave-updatesしているならそっちから抽出すれば大丈夫だろうけど)ので、この時間近辺のPITRは危ないとか色々あるので、5.6のmysqlbinlog使ったリアルタイムバックアップももう一度考えようかなぁ。。