Improve By Learning

Troubleshooting Unable to Convert Binlog Coordinate

Posted on Mar 30, 2024

At work I got assigned to a bug, the MySQL Replication setup failing with error Unable to convert binlog coordinate (mysql-binlog.000002:430106631) to GTID when we tried to fetch the GTID using below command.

MariaDB [(none)]> SELECT BINLOG_GTID_POS('mysql-binlog.000002', 430106631) AS gtid;
+------+
| gtid |
+------+
| NULL |
+------+
1 row in set (0.002 sec)

MariaDB [(none)]>

After investing time and effort, I thought like, what’s the gaurentee that 430106631 is presented in the mysql-binlog.000002.

Reading binlog file

Though we have in-house library to read mysql binlog files, which uses mysqlbinlog internally, we can see basic usage of the command as below

mysqlbinlog \
    --read-from-remote-server \
    --host=MySQL56Instance1.cg034hpkmmjt.region.rds.amazonaws.com \
    --port=3306  \
    --user ReplUser \
    --password \
    --raw \
    --result-file=/tmp/ \
    Binlog.00098

If your setup of MySQL uses Socket based authentication, then you can use option --socket=.

Now, using mysqlbinlog I read starting lines and ending line of the file. These are the lines from my binlog file mysql-binlog.000002 Starting lines


DELIMITER /*!*/;
# at 4
#240328  2:48:05 server id 2446197621  end_log_pos 256 CRC32 0x09a51ea7         Start: binlog v 4, server v 10.4.20-MariaDB-log created 240328  2:48:05 at startup
# at 256
#240328  2:48:05 server id 2446197621  end_log_pos 299 CRC32 0xd97bfa97         Gtid list [0-2446197621-57]
# at 299
#240328  2:48:05 server id 2446197621  end_log_pos 345 CRC32 0xe13d2787         Binlog checkpoint mysql-binlog.000002
# at 345
#240328  2:48:06 server id 2446197621  end_log_pos 387 CRC32 0xb3d835ef         GTID 0-2446197621-58 ddl
#240328  2:48:06 server id 2446197621  end_log_pos 482 CRC32 0x13c5f51c         Query   thread_id=11    exec_time=0     error_code=0
SET TIMESTAMP=1711619286/*!*/;

Ending lines

#240328  2:48:07 server id 2446197621  end_log_pos 6804 CRC32 0x1b2bd5ec        GTID 0-2446197621-79 ddl
# at 6804
#240328  2:48:07 server id 2446197621  end_log_pos 7238 CRC32 0x4d21cf94        Query   thread_id=17    exec_time=0     error_code=0
SET TIMESTAMP=1711619287/*!*/;
# at 7238
#240328  2:48:07 server id 2446197621  end_log_pos 7280 CRC32 0xa65f8415        GTID 0-2446197621-80 ddl
# at 7280
#240328  2:48:07 server id 2446197621  end_log_pos 7359 CRC32 0x3ac22477        Query   thread_id=17    exec_time=0     error_code=0
SET TIMESTAMP=1711619287/*!*/;
FLUSH PRIVILEGES
# at 7359
#240328  2:56:00 server id 2446197621  end_log_pos 7382 CRC32 0x461b434a        Stop
DELIMITER ;
# End of log file
ROLLBACK

You see the # at 4, # at 256 from above lines, those are the binlog positions. The binlog files used to be big, so I inspected both starting and ending lines of the file to make sure 430106631 is there or not.

The last binlog event id/position is as 7359 as you can see. So it is obvious that I do not have 430106631 and the cordiniates are wrong.

Is there any other way instead of doing all this ?

Yes, I came across SHOW BINLOG EVENTS later. I know a position and a file, that’s all I needed.

MariaDB [(none)]> SHOW BINLOG EVENTS IN 'mysql-binlog.000002' FROM 430106631 LIMIT 5;
ERROR 1220 (HY000): Error when executing command SHOW BINLOG EVENTS: Invalid pos specified. Requested from pos:430106631 is greater than actual file size:7382

If you want to see sample data how SHOW BINLOG EVENTS prints

MariaDB [(none)]> SHOW BINLOG EVENTS IN 'mysql-binlog.000002'  LIMIT 5;
+---------------------+-----+-------------------+------------+-------------+------------------------------------------------+
| Log_name            | Pos | Event_type        | Server_id  | End_log_pos | Info                                           |
+---------------------+-----+-------------------+------------+-------------+------------------------------------------------+
| mysql-binlog.000002 |   4 | Format_desc       | 2446197621 |         256 | Server ver: 10.4.20-MariaDB-log, Binlog ver: 4 |
| mysql-binlog.000002 | 256 | Gtid_list         | 2446197621 |         299 | [0-2446197621-57]                              |
| mysql-binlog.000002 | 299 | Binlog_checkpoint | 2446197621 |         345 | mysql-binlog.000002                            |
| mysql-binlog.000002 | 345 | Gtid              | 2446197621 |         387 | GTID 0-2446197621-58                           |
| mysql-binlog.000002 | 387 | Query             | 2446197621 |         482 | DROP DATABASE IF EXISTS test                   |
+---------------------+-----+-------------------+------------+-------------+------------------------------------------------+
5 rows in set (0.002 sec)

So it is obvious that coordinator given was wrong. I know this is not the only reason but this is a good starting point.

Hope it helps.