Bug #98840 sql syntax error on replication slave(using prepared statement)
Submitted: 5 Mar 2020 10:32 Modified: 13 Mar 2020 2:21
Reporter: youngjae joe Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:5.7.22 OS:Linux
Assigned to: CPU Architecture:x86
Tags: case expression, prepared statement, replication

[5 Mar 2020 10:32] youngjae joe
Description:
The prepared statement performed on the master causes sql syntax error only on slave, then slave replication stopped.
but, sql syntax error does not occur in Master and is normally commited.

When I look at the binlog and general log, the syntax changes strangely and the binding doesn't work properly on slave.

1. Why does an error occur in Slave although it runs normally on Master?
2. Is it a problem of case expression, or a problem of application, or a problem of prepared statements?
3. What is the solution?

--=========================================================
-- after execution.
--=========================================================
--=========================================================
-- on Master :
--=========================================================

root@localhost:testdatbase 18:48:06>select * from testtable;
+----+----------+----------+
| id | status_a | status_b |
+----+----------+----------+
|  1 | CHECK    | NULL     |
+----+----------+----------+
1 row in set (0.00 sec)
    
-- 1. master binary log
..........
# at 1388
#200305 18:48:00 server id 2  end_log_pos 1388 CRC32 0xa241146c         Intvar
SET INSERT_ID=1/*!*/;
#200305 18:48:00 server id 2  end_log_pos 1654 CRC32 0x78b07b4d         Query   thread_id=34403592      exec_time=0     error_code=0
use `testdatbase`/*!*/;
SET TIMESTAMP=1583401680/*!*/;
insert into testtable (
  `status_a`
, `status_b`
)
values (
  'CHECK',
  case ?
    when 'RESERVATION' then 'IMMEDIATLY'
   'WAITING'when 'PROCESSING' then 'RESERVATION'
  end
)
/*!*/;
# at 1654
#200305 18:48:00 server id 2  end_log_pos 1685 CRC32 0x9c24885f         Xid = 226346305
COMMIT/*!*/;
..........

-- 2. master general_log
2020-03-05T18:47:53.057269+09:00        34403592 Query  PREPARE stmt1 FROM ...
2020-03-05T18:47:53.057496+09:00        34403592 Prepare        insert into testtable (
  `status_a`
, `status_b`
)
values (
  ?,
  case ?
    when ? then ?
    when ? then ?
  end
)
......................
2020-03-05T18:47:56.364371+09:00        34403592 Query  set @var_status_a         = 'CHECK'
2020-03-05T18:47:56.364818+09:00        34403592 Query  set @var_status_b_01      = 'RESERVATION'
2020-03-05T18:47:56.365162+09:00        34403592 Query  set @var_status_b_02      = 'IMMEDIATLY'
2020-03-05T18:47:56.365484+09:00        34403592 Query  set @var_status_b_03      = 'PROCESSING'
2020-03-05T18:47:56.365793+09:00        34403592 Query  set @var_status_b_04      = 'RESERVATION'
2020-03-05T18:47:56.648233+09:00        34403592 Query  set @var_status_b_05      = 'WAITING'
......................
2020-03-05T18:48:00.402209+09:00        34403592 Query  EXECUTE stmt1 USING @var_status_a
,@var_status_b_01
,@var_status_b_02
,@var_status_b_03
,@var_status_b_04
,@var_status_b_05
2020-03-05T18:48:00.402331+09:00        34403592 Execute        insert into testtable (
  `status_a`
, `status_b`
)
values (
  'CHECK',
  case ?
    when 'RESERVATION' then 'IMMEDIATLY'
   'WAITING'when 'PROCESSING' then 'RESERVATION'
  end
)
......................
2020-03-05T18:48:02.994193+09:00        34403592 Query  DEALLOCATE PREPARE stmt1

root@localhost:testdatbase 18:49:46>select * from testtable;
Empty set (0.00 sec)

root@localhost:testdatbase 18:49:25>show slave status\G;
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.127.33.36
                  Master_User: repluser
                  Master_Port: 20306
                Connect_Retry: 60
              Master_Log_File: binary_log.000021
          Read_Master_Log_Pos: 6070
               Relay_Log_File: relay_log.000035
                Relay_Log_Pos: 1413
        Relay_Master_Log_File: binary_log.000020
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 1064
                   Last_Error: Error 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '?
    when 'RESERVATION' then 'IMMEDIATLY'
   'WAITING'when 'PROCESSING' then 'R' at line 7' on query. Default database: 'testdatbase'. Query: 'insert into testtable (
  `status_a`
, `status_b`
)
values (
  'CHECK',
  case ?
    when 'RESERVATION' then 'IMMEDIATLY'
   'WAITING'when 'PROCESSING' then 'RESERVATION'
  end
)'
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 1198
              Relay_Log_Space: 9446
              Until_Condition: None
               Until_Log_File:
                Until_Log_Pos: 0
           Master_SSL_Allowed: Yes
           Master_SSL_CA_File: /mysql/MyHome/ssldir/ca.pem
           Master_SSL_CA_Path:
              Master_SSL_Cert: /mysql/MyHome/ssldir/client-cert.pem
            Master_SSL_Cipher:
               Master_SSL_Key: /mysql/MyHome/ssldir/client-key.pem
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 1064
               Last_SQL_Error: Error 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '?
    when 'RESERVATION' then 'IMMEDIATLY'
   'WAITING'when 'PROCESSING' then 'R' at line 7' on query. Default database: 'testdatbase'. Query: 'insert into testtable (
  `status_a`
, `status_b`
)
values (
  'CHECK',
  case ?
    when 'RESERVATION' then 'IMMEDIATLY'
   'WAITING'when 'PROCESSING' then 'RESERVATION'
  end
)'
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 2
                  Master_UUID: 889e0ea5-7846-11e9-b553-fa163fb75767
             Master_Info_File: /home1/mysql/MyHome/data/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State:
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp: 200305 18:49:10
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set:
            Executed_Gtid_Set:
                Auto_Position: 0
         Replicate_Rewrite_DB:
                 Channel_Name:
           Master_TLS_Version:
1 row in set (0.00 sec)

How to repeat:
-- On Master : 

CREATE DATABASE testdatbase /*!40100 DEFAULT CHARACTER SET utf8mb4 */ ;
use testdatbase;

CREATE TABLE          testtable (                          
   `id`        int(11)                                        NOT NULL AUTO_INCREMENT
 , `status_a`  enum('SUCCESS','CHECK','FAIL','DELETED')
 , `status_b`  enum('WAITING','PROCESSING','SUCCESS','FAIL')  DEFAULT 'WAITING'
 , PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COMMENT='`testtable`';
show create table     `testtable`\G;

PREPARE stmt1 FROM 'insert into testtable (
  `status_a`
, `status_b`
)
values (
  ?,
  case ?
    when ? then ?
    when ? then ?
  end
)';

set @var_status_a         = 'CHECK';
set @var_status_b_01      = 'RESERVATION';
set @var_status_b_02      = 'IMMEDIATLY';
set @var_status_b_03      = 'PROCESSING';
set @var_status_b_04      = 'RESERVATION';
set @var_status_b_05      = 'WAITING';

EXECUTE stmt1 USING @var_status_a   
,@var_status_b_01        
,@var_status_b_02
,@var_status_b_03
,@var_status_b_04
,@var_status_b_05
;

DEALLOCATE PREPARE stmt1;
[5 Mar 2020 10:36] youngjae joe
Master/Slave System Variables
 - Replication : semi-sync replication, no multi thread replication, no GTID
 - binlog_format : MIXED
 - tx_isolation : REPEATABLE-READ
 - character_set_server : utf8mb4
 - collation_server : utf8mb4_general_ci
 - sql_mode : STRICT_TRANS_TABLES,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
[6 Mar 2020 5:05] MySQL Verification Team
Hello youngjae joe,

Thank you for the report and test case.
With the provided test case, issue seen in 5.7.22/23/24/25/26/27(with MIXED binlog format), but it is not observed since 5.7.28+(also, 5.6.47 and 8.0.19 checked but not affected). Please note that we don't fix bugs in old versions, don't backport bug fixes, so you need to check with latest version anyway. So, please, upgrade and inform us if problem still exists. Thank you.

regards,
Umesh
[6 Mar 2020 5:36] youngjae joe
Hello Umesh Shastry,

Is it a bug?
Can you explain exactly what the problem is?
and, If 5.7.28+ does not occur, please let me know the patch (release note link, etc.)?

regards,
youngjae joe
[6 Mar 2020 6:14] MySQL Verification Team
Yes, it is a bug(5.7.22/23/24).
If you see the contents of master's binary log from 5.7.22:

master-bin.000001       837     Anonymous_Gtid  1       902     SET @@SESSION.GTID_NEXT= 'ANONYMOUS'
master-bin.000001       902     Query   1       995     BEGIN
master-bin.000001       995     Intvar  1       1027    INSERT_ID=1
master-bin.000001       1027    Query   1       1289    use `testdatbase`; insert into testtable (
  status_a
, status_b
)
values (
  'CHECK',
  case ?
    when 'RESERVATION' then 'IMMEDIATLY'
   'WAITING'when 'PROCESSING' then 'RESERVATION' <-----
  end
)
master-bin.000001       1289    Xid     1       1320    COMMIT /* xid=187 */

^^ clearly 2 issues, value missing for @var_status_b_01 and rest messed.

master-bin.000001       1027    Query   1       1289    use `testdatbase`; insert into testtable (
  status_a
, status_b
)
values (
  'CHECK',
  case 'RESERVATION'
    when 'IMMEDIATLY' then 'PROCESSING'
    when 'RESERVATION' then 'WAITING'
  end
)
master-bin.000001       1289    Xid     1       1320    COMMIT /* xid=187 */

I'm not able to locate exact bug# from the release notes confirming  on bug# which fixed this issue from 5.7.28+(diff issue altogether in 5.7.25/26/27 than original), will check internally and hope to respond next week.

regards,
Umesh
[13 Mar 2020 2:21] youngjae joe
Hello Umesh Shastry,

The same problem occurs when you change binlog_format to ROW
Wrong parsing from "general log".

binlog_format = 'ROW'
binlog_row_image = 'MINIMAL' or 'FULL'
binlog_rows_query_log_events = 1

Is mysql version upgrade the only solution?

regards,
youngjae joe