go-mysqlbinlog: wrong positions for events and Gtid events get decoded as QueryEvent

[dveeden]

Server: MariaDB 11.4.2

From go-mysqlbinlog:

=== RotateEvent ===
Date: 1970-01-01 01:00:00
Log position: 0
Event size: 48
Position: 4
Next log name: mysqld-bin.000002

=== FormatDescriptionEvent ===
Date: 2024-11-08 08:55:18
Log position: 256
Event size: 252
Version: 4
Server version: 11.4.2-MariaDB-ubu2404-log
Checksum algorithm: 1

=== UserVarEvent ===
Date: 2024-11-08 08:55:18
Log position: 285
Event size: 29
Event data: 
00000000  01 00 00 00 21 01                                 |....!.|

=== QueryEvent ===
Date: 2024-11-08 08:55:18
Log position: 329
Event size: 44
Slave proxy ID: 0
Execution time: 0
Error code: 0
Schema: 
Query: # Dummy

=== QueryEvent ===
Date: 2024-11-08 09:24:40
Log position: 371
Event size: 42
Slave proxy ID: 0
Execution time: 0
Error code: 0
Schema: 
Query: # Dum

=== QueryEvent ===
Date: 2024-11-08 09:24:40
Log position: 458
Event size: 87
Slave proxy ID: 11
Execution time: 0
Error code: 0
Schema: test
Query: create database test

=== QueryEvent ===
Date: 2024-11-08 09:27:31
Log position: 500
Event size: 42
Slave proxy ID: 0
Execution time: 0
Error code: 0
Schema: 
Query: # Dum

=== QueryEvent ===
Date: 2024-11-08 09:27:31
Log position: 715
Event size: 215
Slave proxy ID: 11
Execution time: 0
Error code: 0
Schema: test
Query: create table test_time(
           id int(11) primary key, 
         `time_1` time DEFAULT '-838:59:59' COMMENT '-838:59:59 to 838:59:59'
)

From the client:

mysql-11.4.2-MariaDB-ubu2404-log> show binlog events in 'mysqld-bin.000002';
+-------------------+-----+-------------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------------------------------------------------+
| Log_name          | Pos | Event_type        | Server_id | End_log_pos | Info                                                                                                                                                    |
+-------------------+-----+-------------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------------------------------------------------+
| mysqld-bin.000002 |   4 | Format_desc       |         1 |         256 | Server ver: 11.4.2-MariaDB-ubu2404-log, Binlog ver: 4                                                                                                   |
| mysqld-bin.000002 | 256 | Gtid_list         |         1 |         285 | []                                                                                                                                                      |
| mysqld-bin.000002 | 285 | Binlog_checkpoint |         1 |         329 | mysqld-bin.000002                                                                                                                                       |
| mysqld-bin.000002 | 329 | Gtid              |         1 |         371 | GTID 0-1-1                                                                                                                                              |
| mysqld-bin.000002 | 371 | Query             |         1 |         458 | create database test                                                                                                                                    |
| mysqld-bin.000002 | 458 | Gtid              |         1 |         500 | GTID 0-1-2                                                                                                                                              |
| mysqld-bin.000002 | 500 | Query             |         1 |         715 | use `test`; create table test_time(
           id int(11) primary key, 
         `time_1` time DEFAULT '-838:59:59' COMMENT '-838:59:59 to 838:59:59'
) |
+-------------------+-----+-------------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------------------------------------------------+
7 rows in set (0.00 sec)

Note this event:

=== QueryEvent ===
Date: 2024-11-08 09:27:31
Log position: 500
Event size: 42
Slave proxy ID: 0
Execution time: 0
Error code: 0
Schema: 
Query: # Dum

mysql-11.4.2-MariaDB-ubu2404-log> SHOW BINLOG EVENTS IN 'mysqld-bin.000002' FROM 458 LIMIT 1\G
*************************** 1. row ***************************
   Log_name: mysqld-bin.000002
        Pos: 458
 Event_type: Gtid
  Server_id: 1
End_log_pos: 500
       Info: GTID 0-1-2
1 row in set (0.00 sec)

Issues:

1. Log position: 500: This is not the position of the event as that should be 458. It is the end position of the event.
2. This is a Gtid event and not a QueryEvent
3. Query: # Dum: I think this should have said "Dummy", but that got truncated. But this should probably have had GTID 0-1-2 instead.

Issues with other events:
4. Gtid_list is decoded as UserVarEvent.
5. Binlog_checkpoint is decoded as QueryEvent

[dveeden]

Decoded events from mariadb-binlog from a similar (but not the same as previous messages) binlog:

# mariadb-binlog --hexdump mysqld-bin.000001 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#241108 10:16:07 server id 1  end_log_pos 256 CRC32 0xff52504c 
# Position
#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
#        4  |e7 e4 2d 67 |0f   |01 00 00 00 |fc 00 00 00 |00 01 00 00 |01 00
#
#       17  04 00 31 31 2e 34 2e 32  2d 4d 61 72 69 61 44 42  |..11.4.2-MariaDB|
#       27  2d 75 62 75 32 34 30 34  2d 6c 6f 67 00 00 00 00  |-ubu2404-log....|
#       37  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       47  00 00 00 00 e7 e4 2d 67  13 38 0d 00 08 00 12 00  |......-g.8......|
#       57  04 04 04 04 12 00 00 e4  00 04 1a 08 00 00 00 08  |................|
#       67  08 08 02 00 00 00 0a 0a  0a 00 00 00 00 00 00 00  |................|
#       77  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       87  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       97  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       a7  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       b7  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       c7  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       d7  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
#       e7  00 00 00 00 00 00 00 00  00 04 13 04 00 0d 08 08  |................|
#       f7  08 0a 0a 0a 01 4c 50 52  ff                       |.....LPR.|
#
# Event: 	Start: binlog v 4, server v 11.4.2-MariaDB-ubu2404-log created 241108 10:16:07 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
5+QtZw8BAAAA/AAAAAABAAABAAQAMTEuNC4yLU1hcmlhREItdWJ1MjQwNC1sb2cAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAADn5C1nEzgNAAgAEgAEBAQEEgAA5AAEGggAAAAICAgCAAAACgoKAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQADQgICAoKCgFMUFL/
'/*!*/;
# at 256
#241108 10:16:07 server id 1  end_log_pos 285 CRC32 0xc42ebc3d 
# Position
#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
#      100  |e7 e4 2d 67 |a3   |01 00 00 00 |1d 00 00 00 |1d 01 00 00 |00 00
#
#      113  00 00 00 00 00 00 3d bc  2e c4                    |......=...|
#
# Event: 	Gtid list []
# at 285
#241108 10:16:07 server id 1  end_log_pos 329 CRC32 0xd19db8c1 
# Position
#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
#      11d  |e7 e4 2d 67 |a1   |01 00 00 00 |2c 00 00 00 |49 01 00 00 |00 00
#
#      130  11 00 00 00 6d 79 73 71  6c 64 2d 62 69 6e 2e 30  |....mysqld-bin.0|
#      140  30 30 30 30 31 c1 b8 9d  d1                       |00001....|
#
# Event: 	Binlog checkpoint mysqld-bin.000001
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

And from go-mysqlbinlog:

=== RotateEvent ===
Date: 1970-01-01 01:00:00
Log position: 0
Event size: 44
Position: 4
Next log name: mysqld-bin.000001

=== FormatDescriptionEvent ===
Date: 2024-11-08 11:16:07
Log position: 256
Event size: 252
Version: 4
Server version: 11.4.2-MariaDB-ubu2404-log
Checksum algorithm: 1

=== UserVarEvent ===
Date: 2024-11-08 11:16:07
Log position: 285
Event size: 29
Event data: 
00000000  01 00 00 00 21 01                                 |....!.|

=== QueryEvent ===
Date: 2024-11-08 11:16:07
Log position: 329
Event size: 44
Slave proxy ID: 0
Execution time: 0
Error code: 0
Schema: 
Query: # Dummy

[dveeden]

So looks like MariaDB server sends an event with type 162 / 0xa3 to mariadb-dump --read-from-remote-server ... but for the same event sends a type 14 / 0x0e to go-mysqldump.

[dveeden]

The reason for MariaDB server to send different events is probably that go-mysqlbinlog didn't send SET @mariadb_slave_capability=4. However go-mysqlbinlog should do this for MariaDBFlavor.

It turns out that I didn't use go-mysqlbinlog -flavor mariadb ..., which caused it to default to MySQLFlavor.

What we could/should do is;

1. Validate the value passed by -flavor as it accepts anything now.
2. Detect mismatch between Flavor and server.
3. Auto detect Flavor (e.g. if the version contains MariaDB)

[dveeden]

$ ./bin/go-mysqlbinlog -port 3307 -flavor mariadb
[2024/11/08 12:51:39] [info] binlogsyncer.go:189 create BinlogSyncer with config {ServerID:101 Flavor:mariadb Host:127.0.0.1 Port:3307 User:root Password: Localhost: Charset: SemiSyncEnabled:false RawModeEnabled:false TLSConfig:<nil> ParseTime:false TimestampStringLocation:UTC UseDecimal:true RecvBufferSize:0 HeartbeatPeriod:0s ReadTimeout:0s MaxReconnectAttempts:0 DisableRetrySync:false VerifyChecksum:false DumpCommandFlag:0 Option:<nil> Logger:0xc0001b6240 Dialer:0x6d0d00 RowsEventDecodeFunc:<nil> TableMapOptionalMetaDecodeFunc:<nil> DiscardGTIDSet:false EventCacheCount:10240 SynchronousEventHandler:<nil>}
[2024/11/08 12:51:39] [info] binlogsyncer.go:429 begin to sync binlog from position (, 4)
[2024/11/08 12:51:39] [info] binlogsyncer.go:407 Connected to mariadb 11.4.2-MariaDB-ubu2404-log server
[2024/11/08 12:51:39] [info] binlogsyncer.go:846 rotate to (mysqld-bin.000001, 4)
=== RotateEvent ===
Date: 1970-01-01 01:00:00
Log position: 0
Event size: 44
Position: 4
Next log name: mysqld-bin.000001

=== FormatDescriptionEvent ===
Date: 2024-11-08 11:16:07
Log position: 256
Event size: 252
Version: 4
Server version: 11.4.2-MariaDB-ubu2404-log
Checksum algorithm: 1

=== MariadbGTIDListEvent ===
Date: 2024-11-08 11:16:07
Log position: 285
Event size: 29
Lists: []

=== MariadbBinLogCheckPointEvent ===
Date: 2024-11-08 11:16:07
Log position: 329
Event size: 44
Info: mysqld-bin.000001

^C

mysql-11.4.2-MariaDB-ubu2404-log> show master status;
+-------------------+----------+--------------+------------------+
| File              | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+-------------------+----------+--------------+------------------+
| mysqld-bin.000001 |      329 |              |                  |
+-------------------+----------+--------------+------------------+
1 row in set (0.00 sec)

mysql-11.4.2-MariaDB-ubu2404-log> show binlog events;
+-------------------+-----+-------------------+-----------+-------------+-------------------------------------------------------+
| Log_name          | Pos | Event_type        | Server_id | End_log_pos | Info                                                  |
+-------------------+-----+-------------------+-----------+-------------+-------------------------------------------------------+
| mysqld-bin.000001 |   4 | Format_desc       |         1 |         256 | Server ver: 11.4.2-MariaDB-ubu2404-log, Binlog ver: 4 |
| mysqld-bin.000001 | 256 | Gtid_list         |         1 |         285 | []                                                    |
| mysqld-bin.000001 | 285 | Binlog_checkpoint |         1 |         329 | mysqld-bin.000001                                     |
+-------------------+-----+-------------------+-----------+-------------+-------------------------------------------------------+
3 rows in set (0.00 sec)

This also now has the corrects log positions