[MDEV-25444] mysql --binary-mode is not able to replay some mysqlbinlog outputs Created: 2021-04-18  Updated: 2022-01-04  Resolved: 2021-10-05

Status: Closed
Project: MariaDB Server
Component/s: Scripts & Clients
Affects Version/s: 10.3.16, 10.3.23, 10.3.29, 10.2.40
Fix Version/s: 10.2.41, 10.3.32, 10.4.22, 10.5.13, 10.6.5, 10.7.1

Type: Bug Priority: Critical
Reporter: Valerii Kravchuk Assignee: Brandon Nesterenko
Resolution: Fixed Votes: 2
Labels: None

Attachments: File files.tar    
Issue Links:
Problem/Incident
causes MDEV-26991 CURRENT_TEST: main.mysql_binary_zero_... Closed

 Description   

There are still cases when prepared statements (for example, from Java) generate binary logs that can not be replayed without errors like:

ERROR at line 135: Unknown command '\\'.

while doing point in time recovery with mysqlbinlog ... | mysql --binary-mode=1 ... command lines.

Consider this example:

openxs@ao756:~/dbs/maria10.3$ bin/mysql -uroot --socket=/tmp/mariadb.sock test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A
 
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 536
Server version: 10.3.29-MariaDB-log MariaDB Server
 
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
MariaDB [test]> show create table tb\G
*************************** 1. row ***************************
       Table: tb
Create Table: CREATE TABLE `tb` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `cb` longblob DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=5 DEFAULT CHARSET=latin1
1 row in set (0,000 sec)
 
MariaDB [test]> reset master;
Query OK, 0 rows affected (0,166 sec)
 
MariaDB [test]> truncate table tb;
Query OK, 0 rows affected (0,291 sec)
 
MariaDB [test]> exit
Bye
openxs@ao756:~/dbs/maria10.3$ cd -
/home/openxs
openxs@ao756:~$ for i in `ls ~/Documents`; do java -classpath mariadb-java-client-1.5.4.jar:. blobTest /home/openxs/Documents/$i ; done;
Loading file /home/openxs/Documents/101.bin
Loading file /home/openxs/Documents/102.bin
Loading file /home/openxs/Documents/103.bin
Loading file /home/openxs/Documents/104.bin
Loading file /home/openxs/Documents/all.tgz
Loading file /home/openxs/Documents/gnuplot2.png
Loading file /home/openxs/Documents/gnuplot2.png.zip
Loading file /home/openxs/Documents/gnuplot.png
Loading file /home/openxs/Documents/gnuplot.png.zip
Loading file /home/openxs/Documents/gnuplot.xcf
Loading file /home/openxs/Documents/gnuplot.xcf.zip
Loading file /home/openxs/Documents/psn1.svg
Loading file /home/openxs/Documents/psn1.svg.zip
Loading file /home/openxs/Documents/sysbench
Loading file /home/openxs/Documents/tclsh8.6
Loading file /home/openxs/Documents/zero1.txt
Loading file /home/openxs/Documents/zero2.tgz
openxs@ao756:~$ cd -
/home/openxs/dbs/maria10.3
openxs@ao756:~/dbs/maria10.3$ bin/mysql -uroot --socket=/tmp/mariadb.sock test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A
 
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 577
Server version: 10.3.29-MariaDB-log MariaDB Server
 
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
MariaDB [test]> flush logs;
Query OK, 0 rows affected (0,139 sec)
 
MariaDB [test]> show master status;
+------------------+----------+--------------+------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+------------------+----------+--------------+------------------+
| ao756-bin.000002 |      385 |              |                  |
+------------------+----------+--------------+------------------+
1 row in set (0,000 sec)
 
MariaDB [test]> select id, length(cb) from tb;
+----+------------+
| id | length(cb) |
+----+------------+
|  1 |        560 |
|  2 |        560 |
|  3 |        560 |
|  4 |        560 |
|  5 |    2484981 |
|  6 |      66204 |
|  7 |      64308 |
|  8 |      34859 |
|  9 |      34040 |
| 10 |      86976 |
| 11 |      42593 |
| 12 |      25999 |
| 13 |       6072 |
| 14 |    1454472 |
| 15 |       8824 |
| 16 |      10000 |
| 17 |    2484981 |
+----+------------+
17 rows in set (0,004 sec)
 
MariaDB [test]> exit
Bye
openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog data/ao756-bin.000001 | bin/mysql -uroot --socket=/tmp/mariadb.sock --binary-mode=1 test
ERROR at line 135: Unknown command '\\'.
openxs@ao756:~/dbs/maria10.3$

Java code is:

openxs@ao756:~/dbs/maria10.3$ cd -
/home/openxs
openxs@ao756:~$ cat blobTest.java
import java.sql.DriverManager;
import java.sql.Connection;
import java.sql.SQLException;
import java.sql.Statement;
import java.sql.PreparedStatement;
import java.sql.ResultSet;
import java.sql.ResultSetMetaData;
import java.io.File;
import java.io.FileInputStream;
 
public class blobTest {
    public static void main(String ... args) {
        try {
            Class.forName("org.mariadb.jdbc.Driver");
        } catch (ClassNotFoundException e) {
            e.printStackTrace();
            return;
        }
 
        Connection conn = null;
 
        try {
            conn = DriverManager.getConnection("jdbc:mariadb://127.0.0.1:3309/test?user=root");
        } catch (SQLException e) {
            e.printStackTrace();
            return;
        }
 
        if (conn != null) {
//          Statement stmt = conn.createStatement();
//          stmt.execute("create table tb(id int primary key, cb longblob)");   
          try {
            PreparedStatement ps = conn.prepareStatement("INSERT INTO tb(cb) VALUES(_binary ?)");
            File file = new File(args[0]);
            System.out.println("Loading file "+args[0]);
            ps.setBlob(1, new FileInputStream(file));
            ps.execute();
          } catch (Exception e) {
              e.printStackTrace();
              return;
          }
 
        } else {
            System.out.println("Failed to make connection!");
        }
    }
}

It was built this way:

openxs@ao756:~$ javac -version
javac 1.8.0_282
openxs@ao756:~$ javac blobTest.java
openxs@ao756:~$

The content of my ~/Documents that matters is attached. Nothe *.bin files (they all have the same content, but I can not reproduce easily without other files so far).



 Comments   
Comment by Valerii Kravchuk [ 2021-04-18 ]

MariaDB server was started with mostly default options:

openxs@ao756:~/Documents$ ps aux | grep maria
openxs   11668  0.0  0.0   4500  1716 pts/3    S    12:39   0:00 /bin/sh bin/mysqld_safe --no-defaults --port=3309 --socket=/tmp/mariadb.sock --log-bin
openxs   11758  0.9  7.3 1843332 282948 pts/3  Sl   12:39   1:32 /home/openxs/dbs/maria10.3/bin/mysqld --no-defaults --basedir=/home/openxs/dbs/maria10.3 --datadir=/home/openxs/dbs/maria10.3/data --plugin-dir=/home/openxs/dbs/maria10.3/lib/plugin --log-bin --log-error=/home/openxs/dbs/maria10.3/data/ao756.err --pid-file=ao756.pid --socket=/tmp/mariadb.sock --port=3309
openxs   21637  0.0  0.0  15720  1020 pts/3    S+   15:15   0:00 grep --color=auto maria

Comment by Sergei Golubchik [ 2021-04-19 ]

valerii, and if you add -vvv to the mysql command line — what command causes the error?

Comment by Valerii Kravchuk [ 2021-04-19 ]

I've executed:

openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog data/ao756-bin.000001 | bin/mysql -vvv -uroot --socket=/tmp/mariadb.sock --binary-mode=1 test

and got this:

...
--------------
START TRANSACTION
--------------
 
Query OK, 0 rows affected (0,000 sec)
 
--------------
SET INSERT_ID=5
--------------
 
Query OK, 0 rows affected (0,000 sec)
 
--------------
SET TIMESTAMP=1618744173
--------------
 
Query OK, 0 rows affected (0,000 sec)
 
ERROR at line 135: Unknown command '\\'.
Bye
openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog data/ao756-bin.000001 | head -135 |  tail -1 | hexdump -C
00000000  49 4e 53 45 52 54 20 49  4e 54 4f 20 74 62 28 63  |INSERT INTO tb(c|
00000010  62 29 20 56 41 4c 55 45  53 28 5f 62 69 6e 61 72  |b) VALUES(_binar|
00000020  79 20 27 1f 8b 08 5c 00  da 02 7c 60 5c 00 03 ec  |y '...\...|`\...|
00000030  fb 07 54 93 db f6 3e 0a                           |..T...>.|
00000038

Comment by Sachin Setiya (Inactive) [ 2021-05-11 ]

I am able to hit the bug

Comment by Sachin Setiya (Inactive) [ 2021-05-11 ]

Issue is with all.tgz file, If i only insert all.tgz I get this error

╭─sachin@p51 ~/10.3/mysql-test ‹bb-10.3-25444*› 
╰─$ ../client/mysqlbinlog -vvv  var/mysqld.1/data/master-bin.000001| mysql -uroot -S ~/10.3/mysql-test/var/tmp/mysqld.1.sock --binary-mode=1 test
ERROR 1064 (42000) at line 42: 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 ''?
?? ?????\"EzoB轇?UzG???.Mz@:?4i??)RD??_غ???????{??~???e(???5...' at line 1

Comment by Sachin Setiya (Inactive) [ 2021-05-12 ]

So the end of insert query shown by mysqlbinlog

^@\^@IEND?B`?')                                                                                                                                                                       
  209 /*!*/;                                                                                                                                                                                                                                                  
  210 # at 36478                                                                                                                                                                                                                                              
  211 #210511 11:06:45 server id 1  end_log_pos 36509 CRC32 0x35101f4a  Xid = 669 

But when it goes to mariadb end of insert query

\347\016\\'\016p\342\n/*!*/;\n# at 36478\n#210511 11:33:09 server id 1  end_log_pos 36509 CRC32 0xf7d4d586 \tXid = 11\nCOMMIT/*!*/;\n# at 36509\n#210511 11:33:18 ser
ver id 1  end_log_pos 36551 CRC32 0x40ba7558 \tGTID 0-1-2 ddl\n/*!100001 SET @@session.gtid

We can see some later query gets concatenated into the insert query, That is why we are getting syntax error

Comment by Sachin Setiya (Inactive) [ 2021-05-18 ]

There is one common bytes in all the files where we are getting syntax error. (0x5c00)

So If I do insert binary file into table `tb` with the data 5c00

And dump the binary logs and read from the binary logs , I am getting the same error

Comment by Sachin Setiya (Inactive) [ 2021-05-19 ]

Branch bb-10.3-25444

Comment by Brandon Nesterenko [ 2021-09-17 ]

I agree with Sachin's findings, his patch is ready for review.

Commit: 39599f3

Buildbot: bb-10.3-25444

Comment by Andrei Elkin [ 2021-09-27 ]

diego dupin: thank you for the tip! We're adding a test for that as well.

Comment by Andrei Elkin [ 2021-10-05 ]

Thanks for this work including in-depth analysis.
I left couple of notes to extend the test, after that it must be fully ready.

Comment by Brandon Nesterenko [ 2021-10-05 ]

Manual cherry-picking of these changes (commits 10cd281 from Sachin, and 1755ea4 as my refinements) resulted in no merge conflicts to any later version branches.

Generated at Thu Feb 08 09:37:44 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.