mysqlbinlog generates SQL which is not parseable by mysql cmdline tool

[Arturas Moskvinas]

mysqlbinlog outputs SQL (containing nulls) which is not parseable/allowed by mysql cmdline tool, in essence you can't make PITR restore without hacking mysql index file and inserting those log files or using your own written mysql client:

Reproduce (see binlog attached, requires test schema), SBR/mixed replication used:
1. mysqlbinlog mysql-bin.000006 | mysql

Result:
ERROR at line 43: 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 test_replica values(_binary ''.

With option (even worse):
2. mysqlbinlog mysql-bin.000006 | mysql --binary-mode
Result:
ERROR 1046 (3D000) at line 31: No database selected

Expected:
No error, value inserted into test_replica table

Python script to generate binary log entry;
```
import MySQLdb
db = MySQLdb.connect(read_default_file="~/.my.cnf", db='test')
db.query('create table if not exists test_replica(value varchar(256))')
db.query("Insert into test_replica values(_binary '\0')")
db.query("commit")
```

Percona server version: 5.6.31-77.0-1.jessie

[Arturas Moskvinas (arturas-w)]

Python script which generate insert with null value.

[Ovais Tariq (ovais-tariq)]

This should have been fixed as part of https://bugs.mysql.com/bug.php?id=33048 but is apparently not.

Noted in 5.6.3 changelog.

The mysql client program now has a --binary-mode option that helps
when processing mysqlbinlog output that may contain BLOB values. By
default, mysql translates \r\n in statement strings to \n and
interprets \0 as the statement terminator. --binary-mode disables
both features. It also disables all mysql commands except charset and
delimiter in non-interactive mode (for input piped to mysql or loaded
using the source command).

[Sveta Smirnova (svetasmirnova)]

Thank you for the report.

Python script does not create binary log with '\0' character for me.

I also tested with attached mysql-bin.000006 and got following error:

sveta@Thinkie:~/build/ps-5.6/mysql-test$ ../bin/mysqlbinlog /home/sveta/src/bugs/bug1610144/mysql-bin.000006 | mysqlmtr -P13002 test
ERROR at line 43: 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 test_replica values(_binary ''.

However, after I added option --binary-mode to the client import succeed:

sveta@Thinkie:~/build/ps-5.6/mysql-test$ ../bin/mysqlbinlog /home/sveta/src/bugs/bug1610144/mysql-bin.000006 | mysqlmtr -P13002 test --binary-mode
sveta@Thinkie:~/build/ps-5.6/mysql-test$ echo $?
0

Please let us know if you receive same error message when try to import mysql-bin.000006 and if option --binary-mode helps.

[Arturas Moskvinas (arturas-w)]

Regarding python script - server has to be running in SBR or mixed mode otherwise it will probably generate simple row change which will not break, regarding binlog file test case - I'll retest it again. Is mysqlmtr actually using mysql command directly under the hood and not changing anything on the fly?

[Arturas Moskvinas (arturas-w)]

Hmm, tested on one of the server `mysqlbinlog | mysql` worked although it is not the same machine I tested before because it was decommissioned.

[Arturas Moskvinas (arturas-w)]

Ok, found difference:
```
mysqlbinlog mysql-bin.000006 |mysql --binary-mode
ERROR 1046 (3D000) at line 31: No database selected
echo $?
1
```

and
```
mysqlbinlog mysql-bin.000006 |mysql --binary-mode test
echo $?
0
```

If I choose default database - then everything is ok if database is not chosen - import fails.

[Miguel Angel Nieto (miguelangelnieto)]

This is expected. From manual:

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.

So, all mysql commands are ignored. USER DATABASE is listed as a mysql command. Therefore, when --binary-mode is used, the "use `test`/*!*/;" is ignored and then the INSERT fail. That is why by specifying a default database works.

[Miguel Angel Nieto (miguelangelnieto)]

Here the list of all "mysql" client commands:

http://dev.mysql.com/doc/refman/5.6/en/mysql-commands.html

So, all of them except \C and DELIMITER will be ignored.

[Arturas Moskvinas (arturas-w)]

I understand that mysql client behavior is documented and expected nevertheless issue is that `mysqlbinlog | mysql` is PITR story officially presented in documentation: https://dev.mysql.com/doc/refman/5.6/en/point-in-time-recovery.html .
And it fails if any DB users generates such queries as presented in bug report, one of our 3rd party tool is constantly generating such queries because it compress blobs before storing them to DB and compressed data occasionally contains null bytes. To have a reliable PITR we need a new special option for mysql command line or modify documentation to state that if you need PITR - use ROW based replication because Statement/Mixed is not reliable or use 3rd party tool which is probably not optimal solution or at least hacky...

[Sveta Smirnova (svetasmirnova)]

Thank you for the feedback.

I still cannot repeat described behavior:

sveta@Thinkie:~/build/ps-5.6/mysql-test$ ../bin/mysqlbinlog ~/Downloads/mysql-bin.000006 | mysqlmtr -P13001 --binary-mode
sveta@Thinkie:~/build/ps-5.6/mysql-test$ mysqlmtr -P13001
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.6.32-78.0-debug-log Source distribution

Copyright (c) 2009-2016 Percona LLC and/or its affiliates
Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show databases;
+--------------------+
| Database |
+--------------------+
| information_schema |
| mtr |
| mysql |
| performance_schema |
| test |
+--------------------+
5 rows in set (0.00 sec)

mysql> use test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> show tables;
+----------------+
| Tables_in_test |
+----------------+
| test_replica |
+----------------+
1 row in set (0.00 sec)

mysql> select * from test_replica;
+-------+
| value |
+-------+
| |
+-------+
1 row in set (0.00 sec)

mysql> select hex(value) from test_replica;
+------------+
| hex(value) |
+------------+
| 00 |
+------------+
1 row in set (0.00 sec)

mysql> \q
Bye
sveta@Thinkie:~/build/ps-5.6/mysql-test$ alias mysqlmtr
alias mysqlmtr='../bin/mysql -h127.0.0.1 -P13000 -uroot'

Which exact version of Percona or MySQL server do you use?

[Arturas Moskvinas (arturas-w)]

So issue is with mysql command line component. Easily reproducible on 5.6.32-78.1 linux platform, tried debian 8.0/centos 7.X platforms. I even used mysql-test suite to spawn mysqld:
```
./mtr --start --mysqld=--gtid-mode=on --mysqld=--enforce-gtid-consistency --mysqld=--log-bin --mysqld=--log-slave-updates
```
And executed:
```
$ mysqlbinlog mysql-bin.000006 | mysql -S /home/<redacted>/percona/percona-server-5.6.32-78.1/mysql-test/var/tmp/mysqld.1.sock
ERROR at line 43: 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 test_replica values(_binary ''.
$ mysqlbinlog mysql-bin.000006 | mysql -S /home/<redacted>/percona/percona-server-5.6.32-78.1/mysql-test/var/tmp/mysqld.1.sock --binary-mode
ERROR 1046 (3D000) at line 31: No database selected
```

```
$ mysqlbinlog mysql-bin.000006 | mysql -P13001 -h127.0.0.1
ERROR at line 43: 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 test_replica values(_binary ''.
$ mysqlbinlog mysql-bin.000006 | mysql -P13001 -h127.0.0.1 --binary-mode
ERROR 1046 (3D000) at line 31: No database selected

```

Binary log checksum:
```
 md5sum mysql-bin.000006
c0f0fb92bec82c1ae271861ca0a43b51 mysql-bin.000006
```

[Arturas Moskvinas (arturas-w)]

Hmm, it seems like I found why Sveta you can't reproduce issue, here is binary log snippet:
```
#160805 11:50:41 server id 434342760 end_log_pos 239 CRC32 0x4732c8ec GTID [commit=yes]
SET @@SESSION.GTID_NEXT= '0f141c14-5ad9-11e6-a343-2c600ca2324e:7168'/*!*/;
# at 239
#160805 11:50:41 server id 434342760 end_log_pos 377 CRC32 0x1f1acd91 Query thread_id=4625 exec_time=0 error_code=0
use `test`/*!*/;
SET TIMESTAMP=1470387041/*!*/;
SET @@session.pseudo_thread_id=4625/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1073741824/*!*/;
SET @@session.auto_increment_increment=4, @@session.auto_increment_offset=1/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=224/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create table if not exists test_replica(value varchar(256))
/*!*/;
# at 377
#160805 11:50:41 server id 434342760 end_log_pos 425 CRC32 0x9eb0615e GTID [commit=yes]
SET @@SESSION.GTID_NEXT= '0f141c14-5ad9-11e6-a343-2c600ca2324e:7169'/*!*/;
# at 425
#160805 11:50:41 server id 434342760 end_log_pos 509 CRC32 0xd384b73d Query thread_id=4625 exec_time=0 error_code=0
SET TIMESTAMP=1470387041/*!*/;
BEGIN
/*!*/;
# at 509
#160805 11:50:41 server id 434342760 end_log_pos 632 CRC32 0x6e9fbc58 Query thread_id=4625 exec_time=0 error_code=0
SET TIMESTAMP=1470387041/*!*/;
Insert into test_replica values(_binar...
```

I was executing same binary log file twice because server uses gtid it is actually skipping trx (0f141c14-5ad9-11e6-a343-2c600ca2324e:7168) which contains:
```
use test;
create table...
```
and goes straight to insert statement and fails because database is not selected. Probably only https://dev.mysql.com/doc/refman/5.6/en/point-in-time-recovery.html requires update to include --binary-mode for reliable PITR. Our failure was caused because first we were executing changes without --binary-mode and once we hit issue - rerunning was skipping `use database` somewhere in transaction.

[Sveta Smirnova (svetasmirnova)]

Thank you for the update, Arturas!

I will close this bug as !Bg, because last comment.

[Sveta Smirnova (svetasmirnova)]

I opened documentation bug report at http://bugs.mysql.com/bug.php?id=83619

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3508