Canal: Wrong binlog position after MariaDB is restarted

[mefcorvi]

STR

1. Start syncing
2. Stop MariaDB
3. Start MariaDB
4. Ensure that canal is reconnected.
5. Commit some transaction in the database.

Expected

Binlog position is correct in the OnXID handler.

Actual

pos.Pos is updated to the new position, but pos.Name is wrong.

Environment

MariaDB 10.3.14

MariaDB creates a new binlog file on start and sends fake rotate events with a new binlog filename and position. These events are ignored in canal as a consequence of the #397 so Pos is updated with LogPos from headers of the received events but Name stays the same as before reconnection.

I believe that issue should be reproducible with MySQL but I don't have one to verify this.

Logs

[info] sync.go:57 MariadbGTIDEvent: 1841
[info] sync.go:66 CurPos: (mysql-bin.000017, 1841)
[info] sync.go:57 QueryEvent: 2201
[info] sync.go:66 CurPos: (mysql-bin.000017, 2201)
[info] binlogsyncer.go:698 receive EOF packet, retry ReadPacket
[error] binlogsyncer.go:639 connection was bad
[info] binlogsyncer.go:581 begin to re-sync from (mysql-bin.000017, 2201)
...
[info] binlogsyncer.go:211 register slave for master server mysql:3306
[error] binlogsyncer.go:239 kill connection 17 error ERROR 1094 (HY000): Unknown thread id: 17
[info] binlogsyncer.go:245 kill last connection id 17
[info] binlogsyncer.go:731 rotate to (mysql-bin.000017, 2201)
[info] binlogsyncer.go:731 rotate to (mysql-bin.000018, 4)
[info] sync.go:57 RotateEvent: 0
[info] sync.go:57 FormatDescriptionEvent: 0
[info] sync.go:57 StopEvent: 2224
[info] sync.go:66 CurPos: (mysql-bin.000017, 2224)
[info] sync.go:57 RotateEvent: 0
[info] sync.go:57 FormatDescriptionEvent: 256
[info] sync.go:66 CurPos: (mysql-bin.000017, 256)
[info] sync.go:57 MariadbGTIDListEvent: 299
[info] sync.go:66 CurPos: (mysql-bin.000017, 299)
[info] sync.go:57 MariadbBinLogCheckPointEvent: 342
[info] sync.go:66 CurPos: (mysql-bin.000017, 342)
[info] sync.go:57 MariadbGTIDEvent: 384
[info] sync.go:66 CurPos: (mysql-bin.000017, 384)
[info] sync.go:57 TableMapEvent: 502
[info] sync.go:66 CurPos: (mysql-bin.000017, 502)
[info] sync.go:57 DeleteRowsEventV1: 616
[info] sync.go:66 CurPos: (mysql-bin.000017, 616)
[info] sync.go:57 XIDEvent: 647
[info] sync.go:66 CurPos: (mysql-bin.000017, 647)

CurPos must be (mysql-bin.000018, 647) for XIDEvent.

Events and log pos are written by log.Infof("%v: %v", ev.Header.EventType, ev.Header.LogPos) before checking for header's LogPos and log.Infof("CurPos: %v", pos) before the switch.

To be honest I'm not sure how ignoring fake rotate events helps to mitigate issue in #396
Probably @csuzhangxc or @lintanghui can shed some light on this.

[lintanghui]

it may be a bug, we set pos.Pos = ev.header.Pos. but when receive a XIDEvent, savePos=true. so pos would be update at https://github.com/siddontang/go-mysql/blob/master/canal/sync.go#L153-L158 but without update fileName. then we would get a wrong pos file name.

[mefcorvi]

Yeap, basically fileName can only be updated when RotateEvent is received, that's why I'm wondering about this fix in #396. I'm afraid I didn't understand the original issue.

[lintanghui]

no, you may mistake what i mean, the issue in #396 is to fix fake rotate event, when you reconnect to mysql ,mysql will send a fake rotate ,but you should not save
this pos, if you save this pos and canal shutdown , next time canal would begin from a wrong pos.
it seem when header.pos ==0 may also be a real rotate event. maybe we should add a timestamp to distinguish real and fake rotate event @csuzhangxc

[mefcorvi]

Looking at https://github.com/mysql/mysql-server/blob/8e797a5d6eb3a87f16498edcb7261a75897babae/sql/rpl_binlog_sender.h#L235 I can guess that although position received from such events must be ignored it's still required to use the filename.

[gaaf]

When starting from a GTID, this regression bug also causes the binlog.name to be empty on all events that get a position parameter until a non-faked RotateEvent is received. I really need the current binlog filename asap after starting, not only after the next file is opened.

[mefcorvi]

If we agree to use the filename of the fake RotateEvent I can make PR.

[gaaf]

Well, from your earlier comment it seems that the filename in the fake RotateEvent is guaranteed to be the correct filename. That should at least be stored so that when the correct position gets known, a full Position (name and pos) can be constructed to pass in the event channel.

On a faked RotateEvent, maybe the onRotate event can be passed a Position with the correct filename but a recognizable faked position, like 0 (IIRC, 4 is minimum for a real position).