MySQL · 答疑解惑 · binlog event 中的 error code · 數據庫內核月報

## 問題描述 RDS 有個任務叫做恢復到任意時間點，相當于一個數據時光機，可以將數據恢復到過去任意一個時間點，在用戶出現誤操作需要將數據找回時非常有用。這個功能主要是通過備份集恢復 + binlog回放實現，在用備份集恢復出的實例上應用 binlog 到指定時間點。然而最近線上重放binlog時遇到了這樣一個錯誤： ~~~ Table xxxx already exists ~~~ 查看對應 binlog 的，發現這是一個 CREATE VIEW 語句，而備份集恢復出來的實例上確實已經有了這個view，再往前翻看binlog，并沒有發現 DROP 這個 view 的記錄，倒是找到了CREATE 這個 view 的記錄，仔細比較2處 CREATE VIEW 的binlog event，會發現后者多了個 error_code=1050，這個是什么錯呢： ~~~ $perror 1050 MySQL error code 1050 (ER_TABLE_EXISTS_ERROR): Table '%-.192s' already exists ~~~ 1050 對應的錯就是 Table already exists 就是說 CREATE VIEW 失敗了，仍然記入 binlog 了，但是當時備庫并沒有這個錯誤中斷掉。 ## 復現步驟復現非常簡單，連著執行同一個create view語句即可。 ~~~ mysql> create table t1(id int, name varchar(30)) engine=innodb; Query OK, 0 rows affected (0.02 sec) mysql> create view t1_v as select id from t1; Query OK, 0 rows affected (0.01 sec) mysql> create view t1_v as select id from t1; ERROR 1050 (42S01): Table 't1_v' already exists ~~~ 查看binlog event ~~~ #150614 23:15:02 server id 36302 end_log_pos 2651 CRC32 0x8f8b6c61 GTID [commit=yes] SET @@SESSION.GTID_NEXT= '94cdda9b-a2d0-11e4-ade1-a0d3c1f20ae4:68157343'/*!*/; # at 2651 #150614 23:15:02 server id 36302 end_log_pos 2856 CRC32 0x703fbe6d Query thread_id=21475 exec_time=0 error_code=0 SET TIMESTAMP=1434294902/*!*/; CREATE ALGORITHM=UNDEFINED DEFINER=`root`@`127.0.0.1` SQL SECURITY DEFINER VIEW `t1_v` AS select id from t1 /*!*/; # at 2856 #150614 23:15:02 server id 36302 end_log_pos 2904 CRC32 0xfc2ef7cb GTID [commit=yes] SET @@SESSION.GTID_NEXT= '94cdda9b-a2d0-11e4-ade1-a0d3c1f20ae4:68157344'/*!*/; # at 2904 #150614 23:15:02 server id 36302 end_log_pos 3109 CRC32 0x0e807965 Query thread_id=21475 exec_time=0 error_code=1050 SET TIMESTAMP=1434294902/*!*/; CREATE ALGORITHM=UNDEFINED DEFINER=`root`@`127.0.0.1` SQL SECURITY DEFINER VIEW `t1_v` AS select id from t1 /*!*/; ~~~ 可以清楚的看到，第二次 CREATE VIEW 時error_code 為 1050。 ## 分析查看 binlog 對應的代碼，發現 error_code 這個字段是?`Query_log_event`?的專屬，其它的如 row_event、gtid event等都沒有這個字段。而備庫在執行`Query_log_event`?時會檢查event 的 error_code(存入expected_error），如果非0的話，就和當前SQL線程執行出錯（存入actual_error）比較，看是否一致，如果一致的話就算執行成功，如果不一致的話，就再檢查這個錯是否能夠忽略，如配置了 slave_skip_errors，代碼片段如下（在`Query_log_event::do_apply_event`中）: ~~~ /* If we expected a non-zero error code, and we don't get the same error code, and it should be ignored or is related to a concurrency issue. */ actual_error= thd->is_error() ? thd->get_stmt_da()->sql_errno() : 0; DBUG_PRINT("info",("expected_error: %d sql_errno: %d", expected_error, actual_error)); if ((expected_error && expected_error != actual_error && !concurrency_error_code(expected_error)) && !ignored_error_code(actual_error) && !ignored_error_code(expected_error)) { rli->report(ERROR_LEVEL, 0, "\ Query caused different errors on master and slave. \ Error on master: message (format)='%s' error code=%d ; \ Error on slave: actual message='%s', error code=%d. \ Default database: '%s'. Query: '%s'", ER_SAFE(expected_error), expected_error, actual_error ? thd->get_stmt_da()->message() : "no error", actual_error, print_slave_db_safe(db), query_arg); thd->is_slave_error= 1; } ~~~ 正常的想法應該是執行出錯，就不應該記binlog，為什么會有這樣的設計呢，主庫錯，記binlog，然后備庫要求同樣的錯。因為DDL是不能回滾的，如果DDL執行到一半報錯，主庫又不能回滾，那么應該如何通知備庫它做了一半呢？就是把錯記下去，期待備庫也報同樣的錯。挖一下黑歷史，`Query_log_event`?中的?`error_code`?字段最早是在這個[commit](https://github.com/mysql/mysql-server/commit/204ae8473262f37d40f27aa35505b0492128cb7d)中加入的，目的是將主庫上執行出錯的信息傳給備庫，備庫執行的時候會檢測實際的出錯信息和主庫傳過來的binlog中記錄的是否是一樣的，不一樣就報錯。在此之前，備庫對于?`Query_log_event`?執行出錯是這樣處理的，先檢查SQL線程執行出錯是不是因為表不存在，如果是的話，就單獨再開個連接，從主庫把不存在的表導過來(`fetch_nx_table`)，然后再重試執行失敗的event，如果還有不存在的表，就再拉，再重復執行；對于其它的錯就直接報錯。現在看起來是不是很奇葩，2000年的時候，MySQL還是很年青的哇 =_= ## 總結我們在回放binlog的時候用的是mysql client，不是SQL線程，mysql client中并沒有對error_cocd的處理邏輯，因此遇到執行出錯就直接報錯了。所以如果腳本或者代碼里有這種重放binlog邏輯的，需要注意處理這種場景。