{"action":"created","issue":{"url":"https://api.github.com/repos/github/gh-ost/issues/259","repository_url":"https://api.github.com/repos/github/gh-ost","labels_url":"https://api.github.com/repos/github/gh-ost/issues/259/labels{/name}","comments_url":"https://api.github.com/repos/github/gh-ost/issues/259/comments","events_url":"https://api.github.com/repos/github/gh-ost/issues/259/events","html_url":"https://github.com/github/gh-ost/issues/259","id":180957710,"number":259,"title":"Binlog streamer does not reconnect at expected position on error","user":{"login":"mignaulo","id":1916624,"avatar_url":"https://avatars.githubusercontent.com/u/1916624?v=3","gravatar_id":"","url":"https://api.github.com/users/mignaulo","html_url":"https://github.com/mignaulo","followers_url":"https://api.github.com/users/mignaulo/followers","following_url":"https://api.github.com/users/mignaulo/following{/other_user}","gists_url":"https://api.github.com/users/mignaulo/gists{/gist_id}","starred_url":"https://api.github.com/users/mignaulo/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mignaulo/subscriptions","organizations_url":"https://api.github.com/users/mignaulo/orgs","repos_url":"https://api.github.com/users/mignaulo/repos","events_url":"https://api.github.com/users/mignaulo/events{/privacy}","received_events_url":"https://api.github.com/users/mignaulo/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/github/gh-ost/labels/documentation","name":"documentation","color":"bfd4f2"},{"url":"https://api.github.com/repos/github/gh-ost/labels/question","name":"question","color":"c2e0c6"}],"state":"closed","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":1,"created_at":"2016-10-04T17:39:12Z","updated_at":"2016-10-04T18:50:11Z","closed_at":"2016-10-04T18:50:11Z","body":"When running an alter (at that point I was postponing cut-over, so it was only applying the binlog), the binlog streamer's connection to the replica server died. When it reconnected, it resumed at an unexpected position:\r\n\r\nLog:\r\n```\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9219887; Backlog: 100/100; Time: 96h24m26s(total), 92h46m31s(copy); streamer: bin.000243:1026801556; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9219887; Backlog: 100/100; Time: 96h24m30s(total), 92h46m31s(copy); streamer: bin.000243:1026801556; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9219887; Backlog: 100/100; Time: 96h25m0s(total), 92h46m31s(copy); streamer: bin.000243:1026801556; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9219887; Backlog: 100/100; Time: 96h25m30s(total), 92h46m31s(copy); streamer: bin.000243:1026801556; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9219887; Backlog: 100/100; Time: 96h26m0s(total), 92h46m31s(copy); streamer: bin.000243:1026801556; State: postponing cut-over; ETA: due\r\n2016-10-04 10:23:27 INFO StreamEvents encountered unexpected error: connection was bad\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9220920; Backlog: 0/100; Time: 96h26m20s(total), 92h46m31s(copy); streamer: bin.000243:1033923198; State: postponing cut-over; ETA: due\r\n2016-10-04 10:23:32 INFO Reconnecting... Will resume at bin.000243:1033923198\r\n2016-10-04 10:23:32 INFO Registering replica at nr-db1:3306\r\n2016-10-04 10:23:32 INFO Connecting binlog streamer at bin.000243:4\r\n2016-10-04 10:23:32 INFO rotate to next log name: bin.000243\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9220920; Backlog: 0/100; Time: 96h26m25s(total), 92h46m31s(copy); streamer: bin.000243:810464; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9220920; Backlog: 0/100; Time: 96h26m26s(total), 92h46m31s(copy); streamer: bin.000243:4099431; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9220920; Backlog: 0/100; Time: 96h26m30s(total), 92h46m31s(copy); streamer: bin.000243:17466841; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9220920; Backlog: 0/100; Time: 96h26m32s(total), 92h46m31s(copy); streamer: bin.000243:22221511; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9220920; Backlog: 0/100; Time: 96h26m32s(total), 92h46m31s(copy); streamer: bin.000243:24645916; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9220920; Backlog: 0/100; Time: 96h26m33s(total), 92h46m31s(copy); streamer: bin.000243:27418253; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9220920; Backlog: 0/100; Time: 96h26m35s(total), 92h46m31s(copy); streamer: bin.000243:34486024; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9220920; Backlog: 0/100; Time: 96h26m40s(total), 92h46m31s(copy); streamer: bin.000243:52740540; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9220920; Backlog: 0/100; Time: 96h26m45s(total), 92h46m31s(copy); streamer: bin.000243:73128764; State: postponing cut-over; ETA: due\r\n...\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9220920; Backlog: 0/100; Time: 96h32m30s(total), 92h46m31s(copy); streamer: bin.000243:900969265; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9220920; Backlog: 0/100; Time: 96h33m0s(total), 92h46m31s(copy); streamer: bin.000243:1010245529; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9223178; Backlog: 82/100; Time: 96h33m30s(total), 92h46m31s(copy); streamer: bin.000243:1056641399; State: postponing cut-over; ETA: due\r\n2016-10-04 10:30:47 INFO rotate to next log name: bin.000244\r\n2016-10-04 10:30:47 INFO rotate to next log name: bin.000244\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9228495; Backlog: 100/100; Time: 96h34m0s(total), 92h46m31s(copy); streamer: bin.000244:28818123; State: postponing cut-over; ETA: due\r\nCopy: 1800140389/1800140389 100.0%; Applied: 9234276; Backlog: 100/100; Time: 96h34m30s(total), 92h46m31s(copy); streamer: bin.000244:73697075; State: postponing cut-over; ETA: due\r\n```\r\n\r\nI would have expected the streamer to resume at  `bin.000243:1033923198` but it actually resumed at `bin.000243:4`. \r\n\r\nI'll note that this did not cause any problems, as replaying RBR is idempotent, but it looks like a potential bug."},"comment":{"url":"https://api.github.com/repos/github/gh-ost/issues/comments/251478227","html_url":"https://github.com/github/gh-ost/issues/259#issuecomment-251478227","issue_url":"https://api.github.com/repos/github/gh-ost/issues/259","id":251478227,"user":{"login":"shlomi-noach","id":2607934,"avatar_url":"https://avatars.githubusercontent.com/u/2607934?v=3","gravatar_id":"","url":"https://api.github.com/users/shlomi-noach","html_url":"https://github.com/shlomi-noach","followers_url":"https://api.github.com/users/shlomi-noach/followers","following_url":"https://api.github.com/users/shlomi-noach/following{/other_user}","gists_url":"https://api.github.com/users/shlomi-noach/gists{/gist_id}","starred_url":"https://api.github.com/users/shlomi-noach/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/shlomi-noach/subscriptions","organizations_url":"https://api.github.com/users/shlomi-noach/orgs","repos_url":"https://api.github.com/users/shlomi-noach/repos","events_url":"https://api.github.com/users/shlomi-noach/events{/privacy}","received_events_url":"https://api.github.com/users/shlomi-noach/received_events","type":"User","site_admin":true},"created_at":"2016-10-04T18:50:11Z","updated_at":"2016-10-04T18:50:11Z","body":"@mignaulo, the binlog stream does not actually rework statements.\r\n\r\nThat is, it is true there is idempotency, but the streamer does not even attempt that. It just skips handled statements and proceeds to only execute unhandled statements.\r\n\r\nWhy is the behavior this way and not just resume from last known coordinates? Because a binlog entry is not isolated. A RBR DML entry is preceeded by an entry which maps table name to internal Id. If we break replication in between those, I need to know to go back to a point where everything starts taking place. For multi-table statements that is even more complicated.\r\n\r\nThe _one place_ where I trust there is no prior setup is the beginning of the binary log. This is why, in the occasion of losing the connection, I feels it's OK to waste some time iterating the binary log from start, and make sure we don't lose information."}}
{"actor":{"display_login":"shlomi-noach"}}