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に表示されるんじゃないかと。
上から読んでいくと、
- SQLスレッドが初期化された。マスターのログファイルはmysql-bin.000032でログポジションは61352894、リレーログファイルはmysql-relay.000787でログポジションが21485832。
- I/Oスレッドがマスターに接続して、mysql-bin.000032のポジション61352894のログを要求した。
- サーバーからerrno= 1236 を受け取った。メッセージは「クライアントのリクエストしたレプリケーションの開始位置がアリエナイ!」
- 大事なので(かどうかは知らんけど)2回言った
- 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ごとクラッシュした時にこんな状況が起こりがちで、
- マスターがバイナリーログをwrite
- Binlog dump threadがwriteされたバイナリーログを読み出してスレーブに送信
- マスターのバイナリーログがフラッシュされる前にOSクラッシュ
CHANGE MASTER TO master_log_file= 'mysql-bin.000033', master_log_pos= 1; で仮復旧はできるものの、その後マスター/スレーブのデータの整合性確認しないといけないのが面倒とか、バイナリーログの保全ができてない(log-slave-updatesしているならそっちから抽出すれば大丈夫だろうけど)ので、この時間近辺のPITRは危ないとか色々あるので、5.6のmysqlbinlog使ったリアルタイムバックアップももう一度考えようかなぁ。。
0 件のコメント :
コメントを投稿