binlog应用过程中的一个报错信息

//binlog应用过程中的一个报错信息//

今天在测试线上的一个基于binlog的恢复的功能的时候，发现了一个报错信息，差了半天，最后定位到问题所在，分析过程贴在这里，供大家参考。

案例中，我需要应用的binlog有以下三个：

mysql-bin.000289

mysql-bin.000290

mysql-bin.000291

需要解析的start position是184097370,存在于第一个binlog中，需要解析的stop datetime是'2020-06-29 10:00:00'存在于第三个binlog中。

使用同样的语句进行binlog重放，第二个binlog和第三个binlog都报错，报错信息如下：

mysqlbinlog mysql-bin.000290 --start-position=184097370 --stop-datetime='2020-06-29 10:00:00' 
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 322900992, event_type: 0

关于这个重放的命令，解释下：

从标准使用上看，

参数start-position和stop-position是一对，

参数start-datetime和stop-datetime是一对，

这里我使用start-position配合stop-datetime这两个组成一对范围，这种方法不常用，但是经过实际测试是可行的。

我们可以看到，报错信息是binlog中有不合法的event，为了定位这个问题，我采用了控制变量法，如下：

#报错，start-position和stop-datetime都在
[root ]#mysqlbinlog mysql-bin.000290 --start-position=184097370 --stop-datetime='2020-06-29 10:00:00'  > /data1/tmp1.txt
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 322900992, event_type: 0
#报错，仅包含start-position
[root ]#mysqlbinlog mysql-bin.000290 --start-position=184097370 > /data1/tmp1.txt                                       
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 322900992, event_type: 0
#正确
[root ]#mysqlbinlog mysql-bin.000290 --stop-datetime='2020-06-29 10:00:00'  > /data1/tmp1.txt

可以看到：

1、对于mysql-bin.000290这个binlog，只要使用了stop-position的这个参数，执行的结果就会报错。

2、经过测试，mysql-bin.000291的执行结果和mysql-bin.000290的执行结果一致。

3、mysql-bin.000289在以上三种语法的执行过程中，都没有报错。

接下来的事情，就是定位这个start-position的位置是否存在于这三个binlog中了，经过确认：

start-position的位置184097370存在于mysql-bin.000289中，其他两个binlog文件没有。

stop-datetime的值'2020-06-29 10:00:00'在mysql-bin.000291中，其他两个没有。

到这里，可以得出结论：

1、如果只使用stop-datetime指定的参数，如果binlog中包含的时间都比这个值小，那么整个binlog都会被应用，如果binlog中不包含这个时间点，不会发生报错。

2、如果只使用start-position指定的参数，则binlog中必须包含这个位置点，否则binlog重放的过程中就会报错。

3、start-position和stop-datetime可以组合起来用，它用来定位那些偏移量在start-position之后，而时间在stop-datetime之前的binlog内容。