mysql 重放binlog_【MySQL】老版本重放binlog的罕见报错

在重放binlog时，报错1050。

起初将问题定位为未找准position，解析了对应binlog之后，才知如此：

现象

在通过binlog增量恢复数据时，报错1050，表已存在

版本

MySQL 5.5.x

及以下和部分低版本的MySQL 5.6.x

原因

binlog记录了执行出错的DDL语句，此处，具体DDL是CREATE VIEW $view_name AS ...

有点奇怪，难道执行错误了的DDL也会被记录到binlog中么？

复现

* 此处可横屏并可拖动↓[17:52:45] root@localhost [a]> FLUSH BINARY LOGS;

Query OK, 0 rows affected (0.01 sec)

[17:52:47] root@localhost [a]> SHOW BINLOG EVENTS IN 'mysql55-bin.000006';

+--------------------+-----+-------------+-----------+-------------+---------------------------------------+

| Log_name           | Pos | Event_type  | Server_id | End_log_pos | Info                                  |

+--------------------+-----+-------------+-----------+-------------+---------------------------------------+

| mysql55-bin.000006 | 4   | Format_desc | 55        | 107         | Server ver: 5.5.57-log, Binlog ver: 4 |

+--------------------+-----+-------------+-----------+-------------+---------------------------------------+

1 row in set (0.00 sec)

[17:53:13] root@localhost [a]> CREATE TABLE t(id int);

Query OK, 0 rows affected (0.01 sec)

[17:53:18] root@localhost [a]> CREATE VIEW v_t AS SELECT * from t;

Query OK, 0 rows affected (0.00 sec)

[17:53:21] root@localhost [a]> CREATE VIEW v_t AS SELECT * from t;

ERROR 1050 (42S01): Table 'v_t' already exists

再创建一次视图，产生报错

此时，再次检查binlog：[17:53:24] root@localhost [a]> SHOW BINLOG EVENTS IN 'mysql55-bin.000006'\G

*************************** 1. row ***************************

Log_name: mysql55-bin.000006

Pos: 4

Event_type: Format_desc

Server_id: 55

End_log_pos: 107

Info: Server ver: 5.5.57-log, Binlog ver: 4

*************************** 2. row ***************************

Log_name: mysql55-bin.000006

Pos: 107

Event_type: Query

Server_id: 55

End_log_pos: 189

Info: use `a`; CREATE TABLE t(id int)

*************************** 3. row ***************************

Log_name: mysql55-bin.000006

Pos: 189

Event_type: Query

Server_id: 55

End_log_pos: 369

Info: use `a`; CREATE ALGORITHM=UNDEFINED DEFINER=`root`@`localhost` SQL SECURITY DEFINER VIEW `v_t` AS SELECT * from t

*************************** 4. row ***************************

Log_name: mysql55-bin.000006

Pos: 369

Event_type: Query

Server_id: 55

End_log_pos: 549

Info: use `a`; CREATE ALGORITHM=UNDEFINED DEFINER=`root`@`localhost` SQL SECURITY DEFINER VIEW `v_t` AS SELECT * from t

4 rows in set (0.00 sec)

可以发现，第二次执行CREATE VIEW，即便在执行时报错，但也被记录到binlog中。自然，在通过mysqlbinlog重放binlog时，也会报错。

重新通过mysqlbinlog解析日志得到(可滑动看右侧的内容)：…………………………

# at 189

#180206 17:53:21 server id 55 end_log_pos 369 Query thread_id=13 exec_time=0 error_code=0

SET TIMESTAMP=1517910801/*!*/;

CREATE ALGORITHM=UNDEFINED DEFINER=`root`@`localhost` SQL SECURITY DEFINER VIEW `v_t` AS SELECT * from t

/*!*/;

# at 369

#180206 17:53:22 server id 55 end_log_pos 549 Query thread_id=13 exec_time=0 error_code=1050

SET TIMESTAMP=1517910802/*!*/;

CREATE ALGORITHM=UNDEFINED DEFINER=`root`@`localhost` SQL SECURITY DEFINER VIEW `v_t` AS SELECT * from t

/*!*/;

可以发现第二次报错的语句，虽然被记录到binlog中，但error_code标识为1050。(个人觉得虽记录了error_code=1050，但也不应该记录binlog)

此处顺带检查了一下从库，没有报错。至于为何从库不报错，大概是因为sql thread会特殊处理这种error_code。

而mysqlbinlog mysql-binlog.00000x | mysql -u -p

重放binlog的方式会报错。(——大概是因为mysql这个client工具没有做对mysqlbinlog解析出来的error_code的特殊处理？)

暂时不知道是否为bug，但高版本的MySQL 5.6.x已经修正了该问题，5.7更如此。虽出现概率极低，但仍有可能在这些版本出现问题(如重复create view必现)。

通过binlog增量恢复数据时，可能需要特殊处理。(如删掉这个events)

btw，快升级到更高版本的MySQL吧。