Canal服务运行一段时间后日志会落后很多，MySQL服务超出保留binlog最大期限删除后，导致C

版本信息：

Canal server version : 1.1.3 Canal client version: 1.1.3 - Java MySQL version：5.7+

问题描述：

如题，MySQL配置了的binlog日志文件的最大保存期限，超期文件自动删除，Canal服务运行一段时间后总是会落后很多，由于MySQL服务器将超期binlog文件删除，导致Canal服务读取不到文件。

错误日志：

2020-11-21 00:23:06.224 [destination = example , address = 'xxx' , EventParser] WARN c.a.o.c.p.inbound.mysql.rds.RdsBinlogEventParserProxy - ---> begin to find start position, it will be long time for reset or first position 2020-11-21 00:23:06.225 [destination = example , address = 'xxx' , EventParser] WARN c.a.o.c.p.inbound.mysql.rds.RdsBinlogEventParserProxy - prepare to find start position just last position {"identity":{"slaveId":-1,"sourceAddress":{"address":"ga.offline-data.mysqlp.jhops.club","port":7306}},"postion":{"gtid":"","included":false,"journalName":"mysql-bin.001556","position":132716536,"serverId":194,"timestamp":1605101347000}} 2020-11-21 00:23:06.225 [destination = example , address = 'xxx' , EventParser] WARN c.a.o.c.p.inbound.mysql.rds.RdsBinlogEventParserProxy - ---> find start position successfully, EntryPosition[included=false,journalName=mysql-bin.001556,position=132716536,serverId=194,gtid=,timestamp=1605101347000] cost : 1ms , the next step is binlog dump 2020-11-21 00:23:06.241 [destination = example , address = 'xxx' , EventParser] ERROR c.a.o.canal.parse.inbound.mysql.dbsync.DirectLogFetcher - I/O error while reading from client socket java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = Could not find first log file name in binary log index file at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102) ~[canal.parse-1.1.3.jar:na] at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:235) [canal.parse-1.1.3.jar:na] at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:257) [canal.parse-1.1.3.jar:na] at java.lang.Thread.run(Thread.java:748) [na:1.8.0_222] 2020-11-21 00:23:06.241 [destination = example , address = 'xxx' , EventParser] ERROR c.a.o.c.p.inbound.mysql.rds.RdsBinlogEventParserProxy - dump address 'xxx' has an error, retrying. caused by java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = Could not find first log file name in binary log index file at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102) ~[canal.parse-1.1.3.jar:na] at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:235) ~[canal.parse-1.1.3.jar:na] at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:257) ~[canal.parse-1.1.3.jar:na] at java.lang.Thread.run(Thread.java:748) [na:1.8.0_222] 2020-11-21 00:23:06.242 [destination = example , address = 'xxx' , EventParser] ERROR com.alibaba.otter.canal.common.alarm.LogAlarmHandler - destination:example[java.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = Could not find first log file name in binary log index file at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:102) at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:235) at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:257) at java.lang.Thread.run(Thread.java:748) ]

meta.log 2020-11-21 00:06:08.345 - clientId:1001 cursor:[mysql-bin.001556,128799707,1605101295000,194,] address['xxx'] 2020-11-21 00:18:58.345 - clientId:1001 cursor:[mysql-bin.001556,130046215,1605101303000,194,] address['xxx'] 2020-11-21 00:31:48.345 - clientId:1001 cursor:[mysql-bin.001556,131293135,1605101309000,194,] address['xxx'] 2020-11-21 00:43:48.345 - clientId:1001 cursor:[mysql-bin.001556,132531393,1605101345000,194,] address['xxx'] 2020-11-21 00:43:58.345 - clientId:1001 cursor:[mysql-bin.001556,132589815,1605101345000,194,] address['xxx'] 2020-11-21 00:44:08.345 - clientId:1001 cursor:[mysql-bin.001556,132636636,1605101346000,194,] address['xxx'] 2020-11-21 00:44:18.345 - clientId:1001 cursor:[mysql-bin.001556,132685727,1605101347000,194,] address['xxx'] 2020-11-21 00:44:28.345 - clientId:1001 cursor:[mysql-bin.001556,132716536,1605101347000,194,] address['xxx']

从以上的日志可以看出，日志输出时间和timestamp时间相差甚远，以meta.log的最后一条记录为例，日志记录时间为：2020-11-21 00:44:28，但只同步到binlog文件的时间为1605101347000 - 2020-11-11 21:29:07

客户端代码示例： 每次拉取处理后，休眠10秒中再拉取数据？落后是不是和这个有关系呢？

while (true) { // 服务停止时，不再读取消息 if (SHUTDOWN) { break; } // 获取指定最大数量的消息数（以非阻塞的方式运行） Message message = null; try { message = canalConnector.getWithoutAck(batchSize); } catch (CanalClientException exception) { reconnectCanalConnector(); message = canalConnector.getWithoutAck(batchSize); } long batchId = message.getId(); try { int size = message.getEntries().size(); if (batchId == -1 || size == 0) { } else { processMessageEntries(message.getEntries()); } } catch (Exception e){ log.error("Handler canal binlog failed:{}", e.getMessage(), e); } finally { try { // 提交确认 canalConnector.ack(batchId); Thread.sleep(pullPeriod); // 这里休眠时间为10秒中 } catch (Exception e) { } } }

原提问者GitHub用户yuxiao97