Skip to content

application need to handle some fake rotate events #752

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
gaojijun opened this issue Dec 12, 2022 · 6 comments · Fixed by #753
Closed

application need to handle some fake rotate events #752

gaojijun opened this issue Dec 12, 2022 · 6 comments · Fixed by #753

Comments

@gaojijun
Copy link
Contributor

Story:

  1. Mysql stopped at 2022/11/27 20:00:00, and the host machine restarted.
  2. Mysql started after the host booted, and a new binlog file was used: mysql-bin.000837
  3. My application began to sync binlog from mysql, start at (mysql-bin.000836, 68115791)
  4. fake rotate event (mysql-bin.000837, 4) was not handle by my application, so the Pos.Name is still mysql-bin.000836 when the applicaiton handle row event at (mysql-bin.000837, 1073)
  5. The application compare the postion of 68122877 and 1073, and decide to ignore it, since application couldn't know the binlog filename in row events.

Expected:

The application will handle fake rotate event (mysql-bin.000837, 4)

Actual:

The application didn't handle fake rotate event (mysql-bin.000837, 4)

Logs:

[2022/11/27 20:16:16] [info] binlogsyncer.go:148 create BinlogSyncer with config {1352 mysql 172.19.0.250 3306 hpcctrl   utf8 false false <nil> false UTC false 0 0s 0s 0 false false 0 <nil>}
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000836, 68115791)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669551376
[2022/11/27 20:16:16] [info] dump.go:199 skip dump, use last binlog replication pos (mysql-bin.000836, 68115791) or GTID set <nil>
[2022/11/27 20:16:16] [info] binlogsyncer.go:374 begin to sync binlog from position (mysql-bin.000836, 68115791)
[2022/11/27 20:16:16] [info] sync.go:25 start sync binlog at binlog file (mysql-bin.000836, 68115791)
[2022/11/27 20:16:16] [info] binlogsyncer.go:791 rotate to (mysql-bin.000836, 68115791)
[2022/11/27 20:16:16] [info] sync.go:68 received fake rotate event, next log name is mysql-bin.000836
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000836, 68115818)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669549804
[2022/11/27 20:16:16] [info] binlogsyncer.go:791 rotate to (mysql-bin.000837, 4)
[2022/11/27 20:16:16] [info] binlogsyncer.go:791 rotate to (mysql-bin.000838, 4)
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000836, 68122652)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550400
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000836, 68122877)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550400
[2022/11/27 20:16:16] [info] sync.go:68 received fake rotate event, next log name is mysql-bin.000837
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 1073)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 1885)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 2715)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 3652)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 5307)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 6151)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 7086)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 8747)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 9656)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 10470)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 12109)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 13742)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 14554)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 15519)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 17154)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 17962)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832
[2022/11/27 20:16:16] [debug] master.go:21 update master position (mysql-bin.000837, 18929)
[2022/11/27 20:16:16] [debug] master.go:29 update master timestamp 1669550832

####Environment:
Server version: 10.1.48-MariaDB-0

I have read the following issues about fake rotate events:
#396
#406

In issue #396: the application handled the fake rorate event, and restarted, canal may restart sync in the middle of a transaction, which will result in the error of "no corresponding table map even"
In issue #406: since all fake rotate events are ignored, canal failed to keep the correct Pos.Name, and the application got the wrong Pos.Name

So, I get the following conclustion:
The application should ignore some fake rotate events while should not ignore others. Especially the following ones:
The fake roate events whose binlog filename changed exactly.
Actually, the fake rotate event (mysql-bin.000837, 4) has nothing different with real roate events.

@mefcorvi
@lintanghui
@csuzhangxc
@gaojijun gaojijun mentioned this issue Dec 12, 2022
Merged
@mefcorvi
Copy link
Contributor

I think you're right but I'm not entirely sure that it's possible to start syncing from a position from a fake rotate event in all cases. For example, when client requests position at the end of a binlog file then the database sends fake rotate event with a position in new binlog file and I don't know if this new file really exists (assuming that nobody actually writes into the database so there are no "real" events to write into this file) and if we can actually save this position and use it to reconnect.

The application compare the postion of 68122877 and 1073, and decide to ignore it, since application couldn't know the binlog filename in row events.

BTW, why has the application decided to ignore it?

@gaojijun
Copy link
Contributor Author

I think you're right but I'm not entirely sure that it's possible to start syncing from a position from a fake rotate event in all cases. For example, when client requests position at the end of a binlog file then the database sends fake rotate event with a position in new binlog file and I don't know if this new file really exists (assuming that nobody actually writes into the database so there are no "real" events to write into this file) and if we can actually save this position and use it to reconnect.

I have never seen a fake rotate event with a non-exist binglog file name. If there is one, can you show me? Let's assume mysql is using a binlog file A. When the slave sync binlog from A, and arrives at the end, the syncing should block and wait.

The application compare the postion of 68122877 and 1073, and decide to ignore it, since application couldn't know the binlog filename in row events.

BTW, why has the application decided to ignore it?

My application will sync mulitiple dababases via a single canal, and each database is synced independently, and to a different position. The positions are persisted independently for each databases. When the application begin to sync, it finds the oldest position from all databases, and start at that position. When a row event is handled, the event's position will be compared with each database's position. If the event's position is older, it will be ignored by that database.

@mefcorvi
Copy link
Contributor

I have never seen a fake rotate event with a non-exist binglog file name.

Yes, looks like it is impossible case. After sending fake rotate event, MySQL always opens this file.

https://github.com/mysql/mysql-server/blob/a246bad76b9271cb4333634e954040a970222e0a/sql/rpl_binlog_sender.cc#L405-L410

@gaojijun
Copy link
Contributor Author

There is another resolution: canal pass all fake rotate events to applications, and applications decide to ignore or not. But this change may broke existing applications.

@lance6716
Copy link
Collaborator

lance6716 commented Dec 13, 2022 •
edited
Loading

I don't use canal so please correct me if you find something wrong (maybe break some expected API behaviour). In

go-mysql/canal/sync.go

Lines 87 to 89 in 8206ccd

// We only save position with RotateEvent and XIDEvent.
// For RowsEvent, we can't save the position until meeting XIDEvent
// which tells the whole transaction is over.
, can we also let rotate events trigger the savePos and OnPosSynced? (nextBinlogFile, 4) should be a valid position to start a binlog stream

@gaojijun
Copy link
Contributor Author

, can we also let rotate events trigger the savePos and OnPosSynced? (nextBinlogFile, 4) should be a valid position to start a binlog stream

Yes, I think it's OK. And if fake rotate events are handled as real ones in #753, both of savePos and OnPosSynced will be triggered.

@mefcorvi mefcorvi mentioned this issue Jun 24, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

handle fake rotate event as real if binlog filename changed gaojijun/go-mysql
3 participants
@mefcorvi @gaojijun @lance6716