{"action":"created","issue":{"url":"https://api.github.com/repos/alibaba/otter/issues/200","repository_url":"https://api.github.com/repos/alibaba/otter","labels_url":"https://api.github.com/repos/alibaba/otter/issues/200/labels{/name}","comments_url":"https://api.github.com/repos/alibaba/otter/issues/200/comments","events_url":"https://api.github.com/repos/alibaba/otter/issues/200/events","html_url":"https://github.com/alibaba/otter/issues/200","id":175017233,"number":200,"title":"Node节点网络闪断后报异常","user":{"login":"dusonchen","id":109661,"avatar_url":"https://avatars.githubusercontent.com/u/109661?v=3","gravatar_id":"","url":"https://api.github.com/users/dusonchen","html_url":"https://github.com/dusonchen","followers_url":"https://api.github.com/users/dusonchen/followers","following_url":"https://api.github.com/users/dusonchen/following{/other_user}","gists_url":"https://api.github.com/users/dusonchen/gists{/gist_id}","starred_url":"https://api.github.com/users/dusonchen/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/dusonchen/subscriptions","organizations_url":"https://api.github.com/users/dusonchen/orgs","repos_url":"https://api.github.com/users/dusonchen/repos","events_url":"https://api.github.com/users/dusonchen/events{/privacy}","received_events_url":"https://api.github.com/users/dusonchen/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":2,"created_at":"2016-09-05T08:10:55Z","updated_at":"2016-09-08T03:29:28Z","closed_at":null,"body":"如果节点的网络短暂（如10秒 - 1分钟）与源数据库的机器连不上，就会重试3次连接网络，然后Kill掉连接。接着网络连接上了，但报错：Could not find first log file name in binary log index file，报3次这样的错后，又Kill掉连接，如此kill掉3次后，最后不停地报：NullPointerException。最后只用停止Channel，删除最后同步位置信息，然后设置canal的“位点自定义设置”，最后启动 Channel 才恢复正常。这种异常非常常见，隔一段时间就发生。使用命令：show binlog events in 'bin-log.00000x' from xxx; 查日志又是存在的。\r\n\r\n背景：1个数据源，6个异构的Node节点分布在不同的内网机器，同步3张表，每张表数量在1W左右。上面的异常有2个节点发生了，报错的日志几乎是一模一样的，其它4个正常。\r\n\r\n开始的3次网络连接不上日志：\r\n\r\n2016-09-05 08:12:45.180 [destination = canal-xmg , address = /172.30.248.148:3306 , EventParser] ERROR c.a.o.canal.parse.inbound.mysql.dbsync.DirectLogFetcher - I/O error while reading from client socket\r\njava.io.IOException: Connection reset by peer\r\n\tat sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[na:1.7.0_79]\r\n\tat sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[na:1.7.0_79]\r\n\tat sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223) ~[na:1.7.0_79]\r\n\tat sun.nio.ch.IOUtil.read(IOUtil.java:197) ~[na:1.7.0_79]\r\n\tat sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:379) ~[na:1.7.0_79]\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch0(DirectLogFetcher.java:154) ~[canal.parse-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:70) ~[canal.parse-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:113) [canal.parse-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:210) [canal.parse-1.0.22.jar:na]\r\n\tat java.lang.Thread.run(Thread.java:745) [na:1.7.0_79]\r\n2016-09-05 08:12:45.181 [destination = canal-xmg , address = /172.30.248.148:3306 , EventParser] ERROR c.a.otter.canal.parse.inbound.mysql.MysqlEventParser - dump address /172.30.248.148:3306 has an error, retrying. caused by \r\njava.io.IOException: Connection reset by peer\r\n\tat sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[na:1.7.0_79]\r\n\tat sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[na:1.7.0_79]\r\n\tat sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223) ~[na:1.7.0_79]\r\n\tat sun.nio.ch.IOUtil.read(IOUtil.java:197) ~[na:1.7.0_79]\r\n\tat sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:379) ~[na:1.7.0_79]\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch0(DirectLogFetcher.java:154) ~[canal.parse-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:70) ~[canal.parse-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:113) ~[canal.parse-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:210) ~[canal.parse-1.0.22.jar:na]\r\n\tat java.lang.Thread.run(Thread.java:745) [na:1.7.0_79]\r\n2016-09-05 08:12:45.183 [destination = canal-xmg , address = /172.30.248.148:3306 , EventParser] WARN  c.a.o.s.a.i.setl.zookeeper.termin.WarningTerminProcess - nid:8[8:canal:canal-xmg:java.io.IOException: Connection reset by peer\r\n\tat sun.nio.ch.FileDispatcherImpl.read0(Native Method)\r\n\tat sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)\r\n\tat sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)\r\n\tat sun.nio.ch.IOUtil.read(IOUtil.java:197)\r\n\tat sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:379)\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch0(DirectLogFetcher.java:154)\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:70)\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:113)\r\n\tat com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:210)\r\n\tat java.lang.Thread.run(Thread.java:745)\r\n]\r\n2016-09-05 08:12:45.185 [destination = canal-xmg , address = /172.30.248.148:3306 , EventParser] ERROR c.a.otter.canal.parse.inbound.mysql.MysqlEventParser - disconnect address /172.30.248.148:3306 has an error, retrying., caused by \r\njava.io.IOException: KILL DUMP 4408478 failure:java.io.IOException: ErrorPacket [errorNumber=1094, fieldCount=-1, message=Unknown thread id: 4408478, sqlState=HY000, sqlStateMarker=#]\r\n with command: KILL CONNECTION 4408478\r\n\tat com.alibaba.otter.canal.parse.driver.mysql.MysqlUpdateExecutor.update(MysqlUpdateExecutor.java:49)\r\n\tat com.alibaba.otter.canal.parse.driver.mysql.MysqlConnector.disconnect(MysqlConnector.java:104)\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.disconnect(MysqlConnection.java:60)\r\n\tat com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:242)\r\n\tat java.lang.Thread.run(Thread.java:745)\r\n\r\n\tat com.alibaba.otter.canal.parse.driver.mysql.MysqlConnector.disconnect(MysqlConnector.java:106) ~[canal.parse.driver-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.disconnect(MysqlConnection.java:60) ~[canal.parse-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:242) ~[canal.parse-1.0.22.jar:na]\r\n\tat java.lang.Thread.run(Thread.java:745) [na:1.7.0_79]\r\n\r\n网络连接成功后，就重试了3次查找Bin-log位置失败和杀死连接：\r\n\r\n2016-09-05 08:12:58.989 [destination = canal-xmg , address = /172.30.248.148:3306 , EventParser] WARN  c.a.otter.canal.parse.inbound.mysql.MysqlEventParser - prepare to find start position just last position\r\n2016-09-05 08:12:58.993 [destination = canal-xmg , address = /172.30.248.148:3306 , EventParser] ERROR c.a.o.canal.parse.inbound.mysql.dbsync.DirectLogFetcher - I/O error while reading from client socket\r\njava.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = Could not find first log file name in binary log index file\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:95) ~[canal.parse-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:113) [canal.parse-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:210) [canal.parse-1.0.22.jar:na]\r\n\tat java.lang.Thread.run(Thread.java:745) [na:1.7.0_79]\r\n2016-09-05 08:12:58.993 [destination = canal-xmg , address = /172.30.248.148:3306 , EventParser] ERROR c.a.otter.canal.parse.inbound.mysql.MysqlEventParser - dump address /172.30.248.148:3306 has an error, retrying. caused by \r\njava.io.IOException: Received error packet: errno = 1236, sqlstate = HY000 errmsg = Could not find first log file name in binary log index file\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.dbsync.DirectLogFetcher.fetch(DirectLogFetcher.java:95) ~[canal.parse-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.dump(MysqlConnection.java:113) ~[canal.parse-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:210) ~[canal.parse-1.0.22.jar:na]\r\n\tat java.lang.Thread.run(Thread.java:745) [na:1.7.0_79]\r\n\r\n2016-09-05 08:12:58.995 [destination = canal-xmg , address = /172.30.248.148:3306 , EventParser] ERROR c.a.otter.canal.parse.inbound.mysql.MysqlEventParser - disconnect address /172.30.248.148:3306 has an error, retrying., caused by \r\njava.io.IOException: KILL DUMP 4657772 failure:java.io.IOException: ErrorPacket [errorNumber=1094, fieldCount=-1, message=Unknown thread id: 4657772, sqlState=HY000, sqlStateMarker=#]\r\n with command: KILL CONNECTION 4657772\r\n\tat com.alibaba.otter.canal.parse.driver.mysql.MysqlUpdateExecutor.update(MysqlUpdateExecutor.java:49)\r\n\tat com.alibaba.otter.canal.parse.driver.mysql.MysqlConnector.disconnect(MysqlConnector.java:104)\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.disconnect(MysqlConnection.java:60)\r\n\tat com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:242)\r\n\tat java.lang.Thread.run(Thread.java:745)\r\n\r\n\tat com.alibaba.otter.canal.parse.driver.mysql.MysqlConnector.disconnect(MysqlConnector.java:106) ~[canal.parse.driver-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.disconnect(MysqlConnection.java:60) ~[canal.parse-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:242) ~[canal.parse-1.0.22.jar:na]\r\n\tat java.lang.Thread.run(Thread.java:745) [na:1.7.0_79]\r\n\r\n最后间隔10多秒不停地报下面的错：\r\n\r\n2016-09-05 08:13:37.585 [destination = canal-xmg , address = /172.30.248.148:3306 , EventParser] ERROR c.a.otter.canal.parse.inbound.mysql.MysqlEventParser - dump address /172.30.248.148:3306 has an error, retrying. caused by \r\njava.lang.NullPointerException: null\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.MysqlEventParser.findStartPositionInternal(MysqlEventParser.java:398) ~[canal.parse-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.MysqlEventParser.findStartPosition(MysqlEventParser.java:313) ~[canal.parse-1.0.22.jar:na]\r\n\tat com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:162) ~[canal.parse-1.0.22.jar:na]\r\n\tat java.lang.Thread.run(Thread.java:745) [na:1.7.0_79]\r\n2016-09-05 08:13:37.585 [destination = canal-xmg , address = /172.30.248.148:3306 , EventParser] WARN  c.a.o.s.a.i.setl.zookeeper.termin.WarningTerminProcess - nid:8[8:canal:canal-xmg:java.lang.NullPointerException\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.MysqlEventParser.findStartPositionInternal(MysqlEventParser.java:398)\r\n\tat com.alibaba.otter.canal.parse.inbound.mysql.MysqlEventParser.findStartPosition(MysqlEventParser.java:313)\r\n\tat com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:162)\r\n\tat java.lang.Thread.run(Thread.java:745)\r\n]"},"comment":{"url":"https://api.github.com/repos/alibaba/otter/issues/comments/245483917","html_url":"https://github.com/alibaba/otter/issues/200#issuecomment-245483917","issue_url":"https://api.github.com/repos/alibaba/otter/issues/200","id":245483917,"user":{"login":"theseusyang","id":863136,"avatar_url":"https://avatars.githubusercontent.com/u/863136?v=3","gravatar_id":"","url":"https://api.github.com/users/theseusyang","html_url":"https://github.com/theseusyang","followers_url":"https://api.github.com/users/theseusyang/followers","following_url":"https://api.github.com/users/theseusyang/following{/other_user}","gists_url":"https://api.github.com/users/theseusyang/gists{/gist_id}","starred_url":"https://api.github.com/users/theseusyang/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/theseusyang/subscriptions","organizations_url":"https://api.github.com/users/theseusyang/orgs","repos_url":"https://api.github.com/users/theseusyang/repos","events_url":"https://api.github.com/users/theseusyang/events{/privacy}","received_events_url":"https://api.github.com/users/theseusyang/received_events","type":"User","site_admin":false},"created_at":"2016-09-08T03:29:28Z","updated_at":"2016-09-08T03:29:28Z","body":"2016-09-08 11:23:26.142 [destination = canal2 , address = /xxx.xxx.xxx.xxx:3308 , EventParser] WARN  c.a.otter.canal.parse.inbound.mysql.MysqlEventParser - prepare to find start position by switch ::1473303427000\r\n2016-09-08 11:23:33.286 [destination = canal2 , address = /xxx.xxx.xxx.xxx:3308 , EventParser] ERROR c.a.otter.canal.parse.inbound.mysql.MysqlEventParser - dump address /xx.xxx.xxx.xxx:3308 has an error, retrying. caused by\r\njava.io.IOException: KILL DUMP 334 failure:java.io.IOException: ErrorPacket [errorNumber=1094, fieldCount=-1, message=Unknown thread id: 334, sqlState=HY000, sqlStateMarker=#]\r\n with command: KILL CONNECTION 334\r\n        at com.alibaba.otter.canal.parse.driver.mysql.MysqlUpdateExecutor.update(MysqlUpdateExecutor.java:49)\r\n        at com.alibaba.otter.canal.parse.driver.mysql.MysqlConnector.disconnect(MysqlConnector.java:104)\r\n        at com.alibaba.otter.canal.parse.driver.mysql.MysqlConnector.reconnect(MysqlConnector.java:82)\r\n        at com.alibaba.otter.canal.parse.inbound.mysql.MysqlConnection.reconnect(MysqlConnection.java:56)\r\n        at com.alibaba.otter.canal.parse.inbound.AbstractEventParser$3.run(AbstractEventParser.java:169)\r\n        at java.lang.Thread.run(Thread.java:745)"}}
{"actor":{"display_login":"theseusyang"}}