Canal module does not detect row updates in transactions after upgrading MariaDB to 11.4.1

[mefcorvi]

Description

After upgrading our MariaDB database to version 11.4.1, the canal module of the go-mysql library stopped detecting row updates within transactions. This issue seems to be linked to the handling of fake rotate events that I added a few years ago. The problem stems from an incorrect assumption that events with LogPos=0 can be ignored. However, it appears that the new version of MariaDB does not specify LogPos for certain events:

Events written through transaction or statement cache have log_pos set
to 0 so that they can be copied directly to the binlog without having
to compute the real end_log_pos.

Relevant code in MariaDB: MariaDB log_event_server.cc - MariaDB/server@b8f9f79

Steps to Reproduce:

1. Setup MariaDB 10.7.7.
2. Configure the canal module to process binlog events.
3. Execute a transaction that updates rows in the database.
4. Check that the row updates are handled correctly.
5. Upgrade MariaDB to version 11.4.1.
6. Execute a transaction that updates rows in the database.
7. Observe that the canal module does not detect the row updates.

Expected Behavior:
The canal module should detect and process row updates within transactions, regardless of the LogPos value.

Actual Behavior:
The canal module ignores events with LogPos=0, causing it to miss row updates within transactions.

Environment:

• MariaDB version: 11.4.1
• go-mysql version: 1.8.0
• OS: Alpine 3.20

Additional Context

The issue seems to be related to a change in how MariaDB handles LogPos for events written through transaction or statement cache. To resolve this, the canal module needs to be updated to handle events with LogPos=0 appropriately.

Proposed Solution

Consider fake rotate events only for events of type ROTATE_EVENT with timestamp = 0. This aligns with the comment in the MySQL codebase indicating that the timestamp is set to 0 to distinguish FAKE_ROTATE_EVENT from ROTATE_EVENT and conforms to the MariaDB documentation on fake rotate events.

Related

#396 #406 #752

[gaaf]

With this fix row events are dispatched again, but with the position set to 0. For those that rely on the actual binlog position on every row event, use the MariaDB Server option binlog_legacy_event_pos = on. That will restore previous behavior.

[nickchomey]

Hi there, I've discovered this issue via various others. I find it to be unsatisfying to forever force people to manually set a server variable that overrides the now-normal (and more performant) behaviour.

As it turns out, there's more information in the actual PR for this change

Since MariaDB 11.4, writing to the binlog during transaction commit is
optimized to omit (set to 0) the field end_log_pos from binlog events. This
improves the scalability of the binlog. The field is redundant, as the value
can be derived from the position of the event in the file and the event's
length field.

Enabling the --binlog-legacy-event-pos option (which is off by default)
reverts the server to the pre-11.4 behavior and writes the actual
end_log_pos value to every binlog event. This should normally not be needed,
and can hurt binlog performance. The option is provided for backwards
compatibility in case any 3rd-party tools or applications are expecting the
end_log_pos field to be set.

So, perhaps the file position and length field could be used somehow in go-mysql to expose the legacy info.

There's also a new Binlog Indexing mechanism in 11.4. Not sure if that can be helpful or not.

I've asked for guidance in the mariadb Slack, though it seems to be a ghost town...

[mefcorvi]

Hi! We've never relied on intra-transaction positions because we process transactions as a whole. Although transaction events are committed to the binlog and available to replicas, the storage engine's COMMIT process might not be complete, meaning the changes aren't immediately visible to new queries. For example, if you query the database right after an XID_Event, there's a chance you won't see the changes. The longer it takes to persist the data, the larger the gap between the XID_Event and the moment the rows are actually available.

We've encountered issues where parts of our system would receive a change event, immediately query the database for the new data, and fail because it wasn't visible yet. To solve this, we had to implement a workaround: we buffer the events, add a short delay to ensure the COMMIT is fully complete, and only then push the events to our message queue. So we deal with LogPos only on XID_event.

Given this behavior and Canal's nature as a low-level API, I limited the fix to handling only the missing row events.

Theoretically, we could store the last non-zero position and calculate the current one from the event length, but I'm not sure that would be a reliable approach.

[nickchomey]

Thanks for the reply and context!

I had already started looking into solving this in my cdc app by adding the EventSize to the previously-seen event's position. But it doesnt work because we are not currently processing all events that are emitted, so the previously-seen event's position does not align with the EventSize of the next event (as it misses out the intervening events). The only way I could solve this would be to process all events, with most of them simply being to update the previous LogPos.

So, I think it really ought to be solved in go-mysql, and this suggestion seems like the appropriate way to do so:

Theoretically, we could store the last non-zero position and calculate the current one from the event length, but I'm not sure that would be a reliable approach.

This would allow my and any other applications that rely on LogPos to "just work" when used with Mariadb 11.4+. What about this sort of approach do you worry would be unreliable?

For what it is worth, again, Mariadb themselves seem to think that the LogPos field is redundant and could/should be calculated from the last position and the length field (which is what they presumably were doing prior to this breaking change)

Also, I've found various spots in the go-mysql code where the LogPos is relied upon. I'm not sure how that affects any of this, though it seems like such a fix would just allow those lines to remain the same?

go-mysql/canal/sync.go

Line 86 in 84c5e8e

pos.Pos = ev.Header.LogPos

go-mysql/replication/backup.go

Line 210 in 84c5e8e

offset := e.Header.LogPos

go-mysql/replication/binlogsyncer.go

Line 861 in 84c5e8e

if e.Header.LogPos > 0 {

Again, the alternative is simply that applications will forever have to manually use a legacy mode (or figure out the low-level binlog mechanisms that this library typically handles)... Also, if you're hesitant to make it the default behaviour (though I'm not sure why that would be) perhaps such a fix could be hidden behind a config option/flag? This would absolve you of blame/responsibility if it causes people issues.