MySQL5.0でリレーログが破損した

MySQL5.0でリレーログが破損した。

先日から発生しているエラーのshow slave statusを元にbinlogを調べてみる。


> mysqlbinlog relay-bin.000534

中略

# at 104726037
#110124  8:31:28 server id 84035  end_log_pos 494070847         Query   thread_id=4846316       exec_time=0     error_code=0
SET TIMESTAMP=1295825488/*!*/;
insert into poller_output (local_data_id, rrd_name, time, output) values (533, '', '2011-01-24 08:31:24', 'MySQL: Lost connection to MySQL server at \'reading initial communication packet\', system error: 61')
/*!*/;
# at 104726310
#110124  8:31:28 server id 84035  end_log_pos 494070874         Xid = 121124362
COMMIT/*!*/;
# at 104726337
#110124  8:31:28 server id 84035  end_log_pos 494070943         Query   thread_id=4846316       exec_time=0     error_code=0
SET TIMESTAMP=1295825488/*!*/;
BEGIN
/*!*/;
# at 104726406
#110124  8:31:28 server id 84035  end_log_pos 494071216         Query   thread_id=4846316       exec_time=0     error_code=0
SET TIMESTAMP=1295825488/*!*/;
insert into poller_output (local_data_id, rrd_name, time,
/*!*/;
ERROR: Error in Log_event::read_log_event(): 'Event too small', data_len: 0, event_type: 0
Could not read entry at offset 104726679:Error in log format or read error
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET [email protected]_COMPLETION_TYPE*/;

なんか最後のクエリが尻切れトンボになってる。これじゃあSQL通らないし、この後流すはずのクエリは何なのかわからなくなってる。
さっくり調べたけどmysqlでリレーログの破損を直すような機能はないらしい。
さて困ったけどなんとかしなくてはならない。

今回の目的とか条件とか

  • スレーブを動くようにしたい
  • もっかいスレーブを作り直すのも一つの手だけど、スレーブ立て直すのってかなり大変なのでできればやりたくない。
  • このホストはcpuとかhddとか結構しょっぱくて、途中のデータ復元してchange master toしても追いつくまでにかなり(数日、下手すれば1週間以上)の時間がかかりそう。
  • クエリの漏れは結構許容できる。
  • なのでマスターのログを漁って正常なログの位置を指し示してやることにしようと思い立った。

今回の原因はスレーブの強制シャットダウンが原因のはず。
mysqlが再起動するとリレーログを含めたログ全般がflushされるというか新しい名前をつけられる。
今回原因となったのはrelay-bin.000534なので続きはrelay-bin.000535にあるはず。
それが正しい続きのログなのかを調べて正しければrelay-logの位置をそこへ変えてやる。

上述のrelay-logのdumpをみると、


# at 104726406
#110124  8:31:28 server id 84035  end_log_pos 494071216         Query   thread_id=4846316       exec_time=0     error_code=0

と書いてある。atの後に続くのはbinlogでいうログのポジション。end_log_posは何だろう。今までに見てきたbinlogだとatの値に近いものが記録されていたと思ってた。
それも次のクエリのログポジションな値が入ってる気がしてたんだけど・・・。


at 100
end_log_pos 200
at 200

って具合に。
ここで仮説を立てる。これはリレーログなのでend_log_posはマスターのログのポジションを表しているんじゃないか、と。
ではマスターのログを調べてみる。


master> mysqlbinlog mysql-bin.000075 --start-pos=494071216 | more

/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#110121  2:25:09 server id 84035  end_log_pos 106       Start: binlog v 4, server v 5.1.42-log created 110121  2:25:09
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
9W84TQ9DSAEAZgAAAGoAAAABAAQANS4xLjQyLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
'/*!*/;
# at 494071216
#110124  8:31:28 server id 84035  end_log_pos 494071243         Xid = 121124363
COMMIT/*!*/;
# at 494071243
#110124  8:31:28 server id 84035  end_log_pos 494071312         Query   thread_id=4846316       exec_time=0     error_code=0
SET TIMESTAMP=1295825488/*!*/;
SET @@session.pseudo_thread_id=4846316/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 494071312
#110124  8:31:28 server id 84035  end_log_pos 494071585         Query   thread_id=4846316       exec_time=0     error_code=0
use cacti/*!*/;
SET TIMESTAMP=1295825488/*!*/;
insert into poller_output (local_data_id, rrd_name, time, output) values (535, '', '2011-01-24 08:31:24', 'MySQL: Lost connection to MySQL server at \'reading initial communication packet\', system error: 61')
/*!*/;
# at 494071585
#110124  8:31:28 server id 84035  end_log_pos 494071612         Xid = 121124364
COMMIT/*!*/;
# at 494071612
#110124  8:31:28 server id 84035  end_log_pos 494071681         Query   thread_id=4846316       exec_time=0     error_code=0
SET TIMESTAMP=1295825488/*!*/;
BEGIN
/*!*/;

最初にログの情報が表示されて、次から対象のposのクエリが表示される。おお、ばっちり一致した。
どうやらちょん切れてたクエリは


insert into poller_output (local_data_id, rrd_name, time, output) values (535, '', '2011-01-24 08:31:24', 'MySQL: Lost connection to MySQL server at \'reading initial communication packet\', system error: 61')
/*!*/;

らしい。皮肉にもmysqlのエラーを格納していた様子。
さて気になるのはその後のクエリ。
マスター上では


# at 494071585
#110124  8:31:28 server id 84035  end_log_pos 494071612         Xid = 121124364
COMMIT/*!*/;
# at 494071612
#110124  8:31:28 server id 84035  end_log_pos 494071681         Query   thread_id=4846316       exec_time=0     error_code=0
SET TIMESTAMP=1295825488/*!*/;
BEGIN
/*!*/;

となっている。
これをスレーブ側でも確認してみる。


slave>mysqlbinlog relay-bin.000535 | more
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#110124  8:34:21 server id 84105  end_log_pos 98        Start: binlog v 4, server v 5.0.67-log created 110124  8:34:21
# at 98
#110124  8:34:21 server id 84105  end_log_pos 149       Rotate to relay-bin.000536  pos: 4
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET [email protected]_COMPLETION_TYPE*/;

moreをつけたけど以上で終わり。なんか000536にrotateしたよってのだけが記述されてる。ファイルサイズも149バイトしかなくてどうやらいらない子らしい。


slave>mysqlbinlog relay-bin.000536 | more

/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#110124  8:34:21 server id 84105  end_log_pos 98        Start: binlog v 4, server v 5.0.67-log created 110124  8:34:21
# at 98
#700101  9:00:00 server id 84035  end_log_pos 0         Rotate to mysql-bin.000075  pos: 494172037
# at 141
#110121  2:25:09 server id 84035  end_log_pos 0         Start: binlog v 4, server v 5.1.42-log created 110121  2:25:09
# at 243
#110124  8:31:49 server id 84035  end_log_pos 494172106         Query   thread_id=4846316       exec_time=0     error_code=0
SET TIMESTAMP=1295825509/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1/*!*/;
SET @@session.sql_mode=0/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
BEGIN
/*!*/;
# at 312

000536にはちゃんとクエリがあった。でも見たところ、最初のクエリのpositionは494,172,106 になってる。前のrelay-bin.000534の時には494,071,681だったので100,000(単位不明)もずれてる。

マスターのログを見てもそんなにログのpositionが飛んでいる様子はない。こりゃーこの部分のログをすっ飛ばしたんだろうか。

ここでまとめる

スレーブのrelay logが尻切れトンボで終わってる。これは強制終了のせいだろう。

この途中で切れてしまったクエリは全文をマスター側で確認。手動で実行もできる。

問題のrelay logに続くログがすでに転送されているが、どうやら結構漏れがあるらしい。

ということで、relay logの位置を変えられないか調べることに。

show slave statusを再度確認。


Master_Log_File: mysql-bin.000075 // I/O スレッドが現在読み込んでいるマスタ               バイナリ ログ ファイルの名前
Read_Master_Log_Pos: 773640060 // 現在のマスタ バイナリ ログ内で、I/O               スレッドが読み込んだところまでの位置
Relay_Log_File: relay-bin.000534 // 現在読み込み、実行をしている SQL               スレッドからのリレー ログ               ファイルの名前
Relay_Log_Pos: 104726337 // スレッドが現在のリレー               ログ内で読み込み、実行したところまでの位置
Relay_Master_Log_File: mysql-bin.000075 // SQL               スレッドによって実行された一番最近のイベントを含むマスタ               バイナリ ログ ファイルの名前。

ひとまずI/Oスレッドを止めておく。


slave sql> stop slave io_thread; show slave status\G
Master_Log_File: mysql-bin.000075
Read_Master_Log_Pos: 773640060
Relay_Log_File: relay-bin.000534
Relay_Log_Pos: 104726337
Relay_Master_Log_File: mysql-bin.000075

Slave_IO_Running: No
Slave_SQL_Running: No

その後でchange master toを試す


slave sql> change master to master_log_pos=494071312; show slave status\G

Master_Log_File: mysql-bin.000075
Read_Master_Log_Pos: 494071312
Relay_Log_File: relay-bin.000001
Relay_Log_Pos: 4
Relay_Master_Log_File: mysql-bin.000075
Slave_IO_Running: No
Slave_SQL_Running: No

リレーログのファイル名が1番から振り直しになった。

mysqldirにあったリレーファイルも全部削除されてて、00001番のみ作成されてる。

これでいいのかな。とりあえずi/oスレッドをスタートしてやろう。


slave sql> start slave io_thread;

そのあとでリレーログを確認。なぜか00001にはほとんどデータが書かれてなかった。


slave>mysqlbinlog relay-bin.000001

/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#110126 17:37:11 server id 84105  end_log_pos 98        Start: binlog v 4, server v 5.0.67-log created 110126 17:37:11 at startup
ROLLBACK/*!*/;
# at 98
#110126 17:42:26 server id 84105  end_log_pos 149       Rotate to clinton-relay-bin.000002  pos: 4
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET [email protected]_COMPLETION_TYPE*/;

slave>mysqlbinlog relay-bin.000002 | more

/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#110126 17:42:26 server id 84105  end_log_pos 98        Start: binlog v 4, server v 5.0.67-log created 110126 17:42:26
# at 98
#700101  9:00:00 server id 84035  end_log_pos 0         Rotate to mysql-bin.000075  pos: 494071312
# at 141
#110121  2:25:09 server id 84035  end_log_pos 0         Start: binlog v 4, server v 5.1.42-log created 110121  2:25:09
# at 243
#110124  8:31:28 server id 84035  end_log_pos 494071585         Query   thread_id=4846316       exec_time=0     error_code=0
use cacti/*!*/;
SET TIMESTAMP=1295825488/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1/*!*/;
SET @@session.sql_mode=0/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
insert into poller_output (local_data_id, rrd_name, time, output) values (535, '', '2011-01-24 08:31:24', 'MySQL: Lost connection to MySQL server at \'reading initial communication packet\', system error: 61')
/*!*/;
# at 516
#110124  8:31:28 server id 84035  end_log_pos 494071612         Xid = 121124364
COMMIT/*!*/;
# at 543
#110124  8:31:28 server id 84035  end_log_pos 494071681         Query   thread_id=4846316       exec_time=0     error_code=0
SET TIMESTAMP=1295825488/*!*/;
BEGIN
/*!*/;

おお、しっかりと問題のSQLから記述されてる。

これであとはsqlスレッドを実行してやる。


mysql> start slave; show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: master.l2tp.org
Master_User: repl
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.000075
Read_Master_Log_Pos: 949455645
Relay_Log_File: relay-bin.000002
Relay_Log_Pos: 597375
Relay_Master_Log_File: mysql-bin.000075
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 494668444
Relay_Log_Space: 455384576
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: 205666
1 row in set (0.00 sec)

ばっちり動いたみたい!

この辺で気がついたんだけど、最初の方で途切れちゃってるlogのpositionを調べるに当たって、mysqlbinlogでエラーログを漁り、end_posで合致する箇所をマスターのbinlogと照らし合わせてたけど、それってshow slave statusのexec_master_log_posになるんじゃなかったかな、と。

なので今回のような障害の時にはそこを見ればどこにposをあわせればいいかわかるような気がしなくもない。な!

まとめ

  • リレーログが破損したらchange master toで拾ってきたいデータを指定すればなんとかなる。
  • exec_master_log_posはコレまでに実行したorこれから実行しようとしてるマスターのbinlogの位置。
  • 5.5からは自動でリレーログの修復をやってくれるみたい。
  • mysqlの偉い方々によるとスレーブに変なエラーが出たらとにかく作り直せ、って。うちはスレーブのリソースがあまりなくてそれをやると長期ダウンになっただろうからできませんでした。

コメントを残す