2019-09-12 11:12:31.463 [destination = example2 , address = /60.205.164.108:3307 , EventParser] ERROR c.a.o.c.p.inbound.mysql.rds.RdsBinlogEventParserProxy - dump address 60.205.164.108/60.205.164.108:3307 has an error, retrying. caused by java.net.SocketTimeoutException: Timeout occurred, failed to read total 4 bytes in 25000 milliseconds, actual read only 0 bytes at com.alibaba.otter.canal.parse.driver.mysql.socket.BioSocketChannel.read(BioSocketChannel.java:124) ~[canal.parse.driver-1.1.4.jar:na] at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch0(DirectLogFetcher.java:174) ~[canal.parse-1.1.4.jar:na] at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:77) ~[canal.parse-1.1.4.jar:na] at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:235) ~[canal.parse-1.1.4.jar:na] at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:265) ~[canal.parse-1.1.4.jar:na] at java.lang.Thread.run(Thread.java:748) [na:1.8.0_191] 2019-09-12 11:12:31.463 [destination = example2 , address = /60.205.164.108:3307 , EventParser] ERROR com.alibaba.otter.canal.common.alarm.LogAlarmHandler - destination:example2[java.net.SocketTimeoutException: Timeout occurred, failed to read total 4 bytes in 25000 milliseconds, actual read only 0 bytes at com.alibaba.otter.canal.parse.driver.mysql.socket.BioSocketChannel.read(BioSocketChannel.java:124) at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch0(DirectLogFetcher.java:174) at com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:77) 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:265) at java.lang.Thread.run(Thread.java:748)
2019-09-12 14:22:46.858 [destination = example2 , address = /60.205.164.108:3307 , 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 2019-09-12 14:22:46.859 [destination = example2 , address = /60.205.164.108:3307 , EventParser] WARN c.a.o.c.p.inbound.mysql.rds.RdsBinlogEventParserProxy - prepare to find start position just last position {"identity":{"slaveId":-1,"sourceAddress":{"address":"60.205.164.108","port":3307}},"postion":{"gtid":"","included":false,"journalName":"mysql-bin.000008","position":1851264,"serverId":3307,"timestamp":1568269294000}} 2019-09-12 14:22:46.877 [destination = example2 , address = /60.205.164.108:3307 , EventParser] WARN c.a.o.c.p.inbound.mysql.rds.RdsBinlogEventParserProxy - ---> find start position successfully, EntryPosition[included=false,journalName=mysql-bin.000008,position=1851264,serverId=3307,gtid=,timestamp=1568269294000] cost : 19ms , the next step is binlog dump
查询之前issue有提到这个问题的根源是mysql在25秒内都没有任何binlog事件,canal等了25秒没有任何消息就会出现类似的错误。目前已添加了mysql定时事件每10s更新一次数据,下面是meta.log中的记录:
`2019-09-12 11:10:57.519 - clientId:1001 cursor:[mysql-bin.000008,1665932,1568257856000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:11:07.519 - clientId:1001 cursor:[mysql-bin.000008,1666143,1568257866000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:11:14.520 - clientId:1001 cursor:[mysql-bin.000008,1666411,1568257873000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:11:15.520 - clientId:1001 cursor:[mysql-bin.000008,1666679,1568257873000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:11:17.520 - clientId:1001 cursor:[mysql-bin.000008,1666890,1568257876000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:11:27.520 - clientId:1001 cursor:[mysql-bin.000008,1667101,1568257886000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:11:37.520 - clientId:1001 cursor:[mysql-bin.000008,1667312,1568257896000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:11:47.520 - clientId:1001 cursor:[mysql-bin.000008,1667523,1568257906000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:11:57.520 - clientId:1001 cursor:[mysql-bin.000008,1667734,1568257916000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:12:07.520 - clientId:1001 cursor:[mysql-bin.000008,1667945,1568257926000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:12:45.521 - clientId:1001 cursor:[mysql-bin.000008,1668156,1568257956000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:12:47.521 - clientId:1001 cursor:[mysql-bin.000008,1668367,1568257966000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:12:57.521 - clientId:1001 cursor:[mysql-bin.000008,1668578,1568257976000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:13:07.520 - clientId:1001 cursor:[mysql-bin.000008,1668789,1568257986000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:13:17.520 - clientId:1001 cursor:[mysql-bin.000008,1669000,1568257996000,3307,] address[60.205.164.108/60.205.164.108:3307]
2019-09-12 11:13:27.520 - clientId:1001 cursor:[mysql-bin.000008,1669211,1568258006000,3307,] address[60.205.164.108/60.205.164.108:3307]`
可以看到在11点12分07秒至45秒处确实有超时25s的情况,请问是否还有其他方法可以根除此问题?
canal版本1.1.4 mysql版本5.6
原提问者GitHub用户enclairfarron
版权声明:本文内容由阿里云实名注册用户自发贡献,版权归原作者所有,阿里云开发者社区不拥有其著作权,亦不承担相应法律责任。具体规则请查看《阿里云开发者社区用户服务协议》和《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容,填写侵权投诉表单进行举报,一经查实,本社区将立刻删除涉嫌侵权内容。