In one of my latest database restore jobs, I was helping a MySQL client with issues related to mysqlbinlog and I wanted to share it here. In case you didn’t know, MySQL is a simple SQL shell with input line editing capabilities, while mysqlbinlog is a utility for processing binary logs a MySQL server. In this case, the server was MariaDB, but the utilities are the same. The database version was 10.1.38-MariaDB.
So, why use mysqlbinlog?
There are many reasons for using mysqlbinlog to process binary log files, but in this case, it was used for point-in-time recovery. Let's say you have an erroneous transaction that you run at 3:05 p.m. and your last full backup was run at 12 p.m. To be able to restore your database up to 3:05 p.m., you will need to restore the full backup that you took at 12 p.m. and then apply the events from your binary logs up to the time before you ran the erroneous transaction. This procedure is only possible if you still have the binary logs generated between 12 p.m. and 3:05 p.m. on the server. Applying the events to the database can be done by using MySQL client. Let's say you have restored the full backup and it’s time to apply the missing events after 12 p.m., but before the erroneous transaction. Using mysqlbinlog, you can parse the binlog and confirm the position that is just before your erroneous transaction. After you find the position, your command to generate SQL from the binary log will look something like this:mysqlbinlog mysql-bin.000072 --stop-position=16208282 --result-file=binlog72.sql Now that you have the SQL file that will apply all missing events since your last backup, you will want to run this on the MySQL server. We use MySQL client for the same. Typically, it is something like:
mysql -uadmin -p < binlog72.sql But in our case, there were errors after running this command. The error is shown below:
Enter **************** at line 66848: ASCII '\0' appeared in the statement, but this is not allowed unless option --binary-mode is enabled and mysql is run in non-interactive mode. Set --binary-mode to 1 if ASCII '\0' is expected. Query: 'INSERT into pythian_msq(ID, KEY, REGION, CREATED_DATE, PRIORITY, BYTES) values ('b67d8bd1-f8f7-8ffb-d2a4-88da8cf14b21', 'd4d0a754-019b-39af-b568-2f2bf93b2845', '2.8.0', 1553862137605, NULL, _binary '??. Obviously, something was wrong with binary data as the error message was showing "--binary-mode is not enabled" but the other message was also confusing - "unless MySQL is run in non-interactive mode". In our case, per my understanding, we were running MySQL in non-interactive mode. Still, the error message was not easy to understand.
ASCII '\0' appeared in the statement, but this is not allowed unless option --binary-mode is enabled and mysql is run in non-interactive mode From the
manual on --binary-mode
By default, ASCII '\0' is disallowed and '\r\n' is translated to '\n'. This switch turns off both features, and also turns off parsing of all client commands except \C and DELIMITER, in non-interactive mode (for input piped to MySQL or loaded using the 'source' command). This is necessary when processing output from mysqlbinlog that may contain blobs.The table was showing an error with the below design:
CREATE TABLE `pythian_msq` ( `ID` char(36) COLLATE utf8_unicode_ci NOT NULL, `KEY` char(36) COLLATE utf8_unicode_ci NOT NULL, `CREATED_DATE` bigint(20) NOT NULL, `PRIORITY` int(11) DEFAULT NULL, `SEQUENCE` bigint(20) NOT NULL AUTO_INCREMENT, `BYTES` blob, `REGION` varchar(100) COLLATE utf8_unicode_ci NOT NULL, PRIMARY KEY (`KEY`,`ID`,`REGION`) ) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci; The column that was failing in the insert is defined as "blob". According to quick research on this and based on the error message, the next command we used was with --binary-mode=1
mysql -uadmin -p --binary-mode=1 < binlog72.sql Again, there was an error when trying to execute the SQL file with MySQL client. The error is now showing bad SQL syntax:
Enter **************** 1064 (42000) at line 66849: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near 'VJKF3BY7', 'solution-center', 0, NULL, 'idPrefixPersist', '44a6a325-d17d-4ce9-b7' at line 1 In another try for the same restore, we used the command where we pipe the output from mysqlbinlog to MySQL client:
mysqlbinlog mysql-bin.000072 --stop-position=16208282 | mysql -uadmin -p --binary-mode=1 After some more tries on this, we were not able to make this SQL file run. We did some checks to see if the binary log was corrupted, in case there was some corruption in the blob column, but none of that was the case. Our next try was to source the file after we connect to MySQL as client.
mysql -uadmin -p MariaDB [test]> source binlog72.sql The server starts processing the events from the SQL file and then it errors again:
...... Query OK, 1 row affected (0.00 sec) Rows matched: 1 Changed: 1 Warnings: 0 Query OK, 0 rows affected (0.01 sec) Query OK, 0 rows affected (0.00 sec) Query OK, 0 rows affected (0.00 sec) Query OK, 0 rows affected (0.00 sec) Query OK, 0 rows affected (0.00 sec) ERROR at line 66848 in file: 'binlog72.sql': ASCII '\0' appeared in the statement, but this is not allowed unless option --binary-mode is enabled and mysql is run in non-interactive mode. Set --binary-mode to 1 if ASCII '\0' is expected. Query: 'INSERT into pythian_msq(ID, KEY, REGION, CREATED_DATE, PRIORITY, BYTES) values ('b67d8bd1-f8f7-8ffb-d2a4-88da8cf14b21', 'd4d0a754-019b-39af-b568-2f2bf93b2845', '2.8.0', 1553862137605, NULL, _binary '??. In between each of these tests, we had to restore the latest backup and try again. Our next try was to start the MySQL client with --binary-mode=1 and then source the SQL file. The commands are:
mysql -uadmin -p --binary-mode=1 MariaDB [test]> source binlog72.sql With the last command, the database does not produce any errors and we were able to restore the database up to the point of time before an erroneous transaction was run.
