fix(replication): calculate LogPos for non-artificial events in MariaDB 11.4+

[mefcorvi]

In MariaDB 11.4+, some legitimate binlog events may have LogPos=0 in their header, particularly inter-transaction events. The current code in BinlogSyncer.handleEventAndACK() unconditionally ignores all events with LogPos=0:

if e.Header.LogPos > 0 {
    // Some events like FormatDescriptionEvent return 0, ignore.
    b.nextPos.Pos = e.Header.LogPos
}

This can cause issues when replicating from MariaDB 11.4+ because valid events are being ignored for position tracking.

Proposed solution

Add a configuration parameter in binlogsyncer that enables dynamic calculation of LogPos for those events where we received 0. For this to work, the BINLOG_SEND_ANNOTATE_ROWS_EVENT flag must be set when connecting to the database. This flag will cause the database to start sending ANNOTATE_ROWS_EVENT to the replica. This is necessary to correctly calculate the position of events because if ANNOTATE_ROWS_EVENTS are present in the binlog of the primary, they affect the position of other events. The flag itself will increase the traffic between the replica and the database, but otherwise, there should be no difference; MariadbAnnotateRowsEvent should be handled normally in go-mysql.

References

• https://jira.mariadb.org/browse/MDEV-31273
• MariaDB source: sql/log_event_server.cc - Log_event::net_send() method
• MariaDB source: sql/sql_repl.cc - mysql_show_binlog_events() function
• MariaDB documentation on artificial events and the 0x20 flag
• https://mariadb.com/docs/server/clients-and-utilities/logging-tools/mariadb-binlog/annotate_rows_log_event
• https://mariadb.com/docs/server/ha-and-performance/standard-replication/replication-and-binary-log-system-variables#binlog_annotate_row_events

Fixes

#1035

Related

#893

[nickchomey]

Thanks very much for giving this such prompt attention!

I briefly tested this out with the cdc tool, and it didnt quite work. At a superficial glance, the positions just weren't accurate - perhaps some artificial events were sneaking through.

More importantly, the OnRow handler was not triggering at all.

I'll look into it all more deeply tomorrow and report back

[nickchomey]

Perhaps, at the very least, the LOG_EVENT_IGNORABLE_F flag should be added?

Though, I wonder if flags are the right approach? Why not create a sort of whitelist of transaction-eligible event types instead? It would avoid the guessing game of which flags are associated with transaction events (which are the only events that have LogPos of 0).

I don't know which event types should truly be eligible, but what about something like this?

Or is it also somewhat ambiguous which event types are eligible for transactions?

func isMariaDbTxEventType(t EventType) bool {
	switch t {
	case
		MARIADB_GTID_EVENT,
		XID_EVENT,
		QUERY_EVENT,
		TABLE_MAP_EVENT,
		WRITE_ROWS_EVENTv0,
		UPDATE_ROWS_EVENTv0,
		DELETE_ROWS_EVENTv0,
		WRITE_ROWS_EVENTv1,
		UPDATE_ROWS_EVENTv1,
		DELETE_ROWS_EVENTv1,
		WRITE_ROWS_EVENTv2,
		UPDATE_ROWS_EVENTv2,
		DELETE_ROWS_EVENTv2,
		MARIADB_WRITE_ROWS_COMPRESSED_EVENT_V1,
		MARIADB_UPDATE_ROWS_COMPRESSED_EVENT_V1,
		MARIADB_DELETE_ROWS_COMPRESSED_EVENT_V1,
		MARIADB_ANNOTATE_ROWS_EVENT:
		return true
	default:
		return false
	}
}

// / handleEventAndACK processes an event and sends an ACK if necessary.
func (b *BinlogSyncer) handleEventAndACK(s *BinlogStreamer, e *BinlogEvent, needACK bool) error {
	// Update the next position based on the event's LogPos
	if e.Header.LogPos > 0 {
		// Some events like FormatDescriptionEvent return 0, ignore.
		b.nextPos.Pos = e.Header.LogPos
	} else if b.cfg.Flavor == mysql.MariaDBFlavor &&
		isMariaDbTxEventType(e.Header.EventType) {
		// For MariaDB 11.4+, some events may have LogPos=0 but are still valid position updates
		// if they are not artificial events (marked with LOG_EVENT_ARTIFICIAL_F flag).
		// For such events, we calculate the next position dynamically.
		calculatedPos := b.nextPos.Pos + e.Header.EventSize
		e.Header.LogPos = calculatedPos
		b.nextPos.Pos = calculatedPos
		b.cfg.Logger.Debug("MariaDB event with LogPos=0 but not artificial, calculated position",
			slog.String("eventType", e.Header.EventType.String()),
			slog.Uint64("logPos", uint64(calculatedPos)))
	}

https://mariadb.com/docs/server/reference/clientserver-protocol/replication-protocol/rows_event_v1v2-rows_compressed_event_v1

This says that write/delete/updatev2 is mysql only. and v0 doesnt even show up - probably not used/relevant, especially since this is for 11.4+ only.

[nickchomey]

As it turns out, OnRow is actually triggering with your code (as well as what I suggested above). The issue I was having was probably from something else.

However, either way, I have issues with regards to the calculated LogPos.

At least of the problem seems to be that MARIADB_ANNOTATE_ROWS_EVENT events are seemingly completely ignored/disappear. I don't see them ever get processed by binlogsyner.onStream() and subsequent functions/methods.

When I inspect the binlog with mariadb-binlog, GTID is the first event in a transaction, and it has an end_log_pos field. The next event is Annotate_rows, followed by Table_map, Write_rows and Xid. So, because Annotate_rows doesn't seem to exist as far as go-mysql is concerned, when Table_map gets processed, the previous position is from GTID rather than Annotate_rows, and the subsequent events in the transaction are out of sync.

Now, perhaps none of this really matters much for tracking the LogPos in go-mysql - Xid runs at the end of a transaction, and includes end_log_pos. So, b.nextPos.Pos would get set to the proper value even if it was messed up within the transaction.

But, it becomes an issue for applications that rely on LogPos, because they are probably not processing all events - we only use OnRow, and we store the LogPos in order to know where to signal to go-mysql to restart from. I suppose that we could also add an event handler for OnXID simply to update our LogPos. However, the point of this effort, it seems to me, is to obviate the need for anyone else from having to even know, let alone think about and fix, any of this.

So, I'm back to thinking that we should figure out why the Annotate_rows event is seemingly invisible to go-mysql, regardless of whether flags or event types are used to filter the events for this mechanism

ps. If I set binlog_annotate_row_events=0, then the Anotate_rows event is, of course, no longer in the binlog and everything syncs up properly.

[mefcorvi]

@nickchomey Thanks for looking into this! I noticed the https://mariadb.com/docs/server/reference/clientserver-protocol/replication-protocol/annotate_rows_event has the following note:

Note: The master server sends ANNOTATE_ROWS_EVENT events only if the slave server connects with the BINLOG_SEND_ANNOTATE_ROWS_EVENT flag (value is 2) in the COM_BINLOG_DUMP Slave Registration phase.

I also see that BinlogSyncerConfig contains a DumpCommandFlag, which is 0 by default. So, I assume it's possible to set it to BINLOG_SEND_ANNOTATE_ROWS_EVENT to start receiving these events.

While this BINLOG_SEND_ANNOTATE_ROWS_EVENT flag probably shouldn't be mandatory for everyone, the entire fix doesn't make much sense without it. Perhaps we could add a new configuration parameter that enables dynamic LogPos calculation in MariaDB and also sets the BINLOG_SEND_ANNOTATE_ROWS_EVENT flag.

[mefcorvi]

Perhaps, at the very least, the LOG_EVENT_IGNORABLE_F flag should be added?

As I understand it, the main purpose of this flag is to provide forward compatibility, allowing a replica to ignore an event if it doesn't understand it. However, I suspect that such events could still be written to the binlog and affect subsequent event positions.

[nickchomey]

Ah, great. I didn't dig too much deeper because I figured you folks would have some idea of what to do. Yes, that sounds like a reasonable solution! Though, if there's some way to just handle it all without having to set a config param, that would be ideal. So that applications that are already using go-mysql will just automatically work if connected to mariadb 11.4+

What do you think of using flags vs specific whitelisted events?

[mefcorvi]

What do you think of using flags vs specific whitelisted events?

In my opinion, flags are a more reliable solution. New event types can be added to the database engine, and everything should remain stable as long as the primary database continues to send these events to the replicas.

[mefcorvi]

@lance6716 @dveeden What do you think? I can add a new configuration parameter and update the documentation if you think it's a good idea. Also, I'd like to add some functional tests using snapshots of real network communications with the database.

[dveeden]

How do the flags that are send to the MySQL/MariaDB server affect applications that use go-mysql?

I think events that were previously ignored or not send to the client or had less data should be fine as either the application is already for specific events or should be made to accept many events (e.g. by logging it or throwing a warning).

For compatibility I'm more concerned by flags that are not accepted by certain server versions or server vendors.

I hope to have time to review this in more detail soon-ish, but I can't guarantee anything.

[nickchomey]

If I understand correctly, the proposed fix for annotate_rows would either be opt-in via a config param, or done automatically IF you are using mariadb 11.4+. So I don't see any compatibility issues arising from it.

[mefcorvi]

@dveeden Currently, MariaDB 11.4+ returns 0 as the end_log_pos (i.e., LogPos) for a number of events from the binlog, which may seem non-obvious to library users. I propose to add a configuration parameter in binlogsyncer that enables dynamic calculation of LogPos for those events where we received 0. For this to work, the BINLOG_SEND_ANNOTATE_ROWS_EVENT flag must be set when connecting to the database. This flag will cause the database to start sending ANNOTATE_ROWS_EVENT to the replica. The flag itself will increase the traffic between the replica and the database, but otherwise, there should be no difference; MariadbAnnotateRowsEvent should be handled normally in go-mysql.

Considering that all this logic will be hidden under a configuration flag, it should not affect those library users who do not need it.

I don't think this mode should be enabled automatically for MariaDB 11.4+. I would prefer to make it manual for those users who understand what they are doing. They can enable it at their discretion based on their own requirements.

Of course, this should also be reflected in the documentation.

[mefcorvi]

I've added a configuration parameter and have updated the README.md. I'm still waiting on any feedback or opinions here.

[nickchomey]

Looks good to me. My only thoughts are:

1. What happens if you have turned off annotations via the server variables? Nothing?
2. Again, are any necessary flags missing?

I'll test it out tomorrow and follow up.

[mefcorvi]

What happens if you have turned off annotations via the server variables? Nothing?

As far as I can see, there are several server variables in MariaDB related to ANNOTATE_ROWS_EVENTS:

• binlog_annotate_row_events, indicates to the primary whether to record ANNOTATE_ROWS_EVENTS in the binlog. If disabled, there will be no issues, events will not be in the primary, and they should not be sent to the replica.
• replicate_annotate_row_events, indicates that the replica should copy ANNOTATE_ROWS_EVENTS to its binlog. If I understand correctly, this flag tells the replica whether it should send the BINLOG_SEND_ANNOTATE_ROWS_EVENT flag when connecting to the primary. In the case of go-mysql, this setting should not affect anything.

However, this all needs to be tested thoroughly, and I currently do not have the opportunity to do so.

[lance6716]

Thanks for contributing, I'll start review about 1~2 days later.

[lance6716]

in NewBinlogSyncer we can check the flavor and MariaDBDynamicLogPos match, and print warning log if mismatch.

[lance6716]

How about MariaDBFillZeroLogPos? Dynamic makes me think more LogPos will be computed on-the-fly other than zero positions. And maybe the value is changeable, not the same one as upstream binlog position.

[lance6716]

Do you have some manual test result to make sure only this flag is enough? Please add some explanation in PR description.

[nickchomey]

This has been my ongoing concern and feedback - that this might not be the only necessary flag, and likewise that perhaps using event types explicitly would be a better approach. It is too "hand wavey" to just use this flag without a more thorough rationale. I don't have much to contribute to resolving this, however.