Bug #87624 Wrong statement-based binary logging for CONCAT() in stored procedure
Submitted: 31 Aug 2017 11:04 Modified: 1 Sep 2017 7:26
Reporter: Valeriy Kravchuk Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.6, 8.0.2, any?, 5.6.37 OS:Any
Assigned to: CPU Architecture:Any
Tags: collation, mixed, replication, statement, stored, variable

[31 Aug 2017 11:04] Valeriy Kravchuk 
Description:
It seems while writing statements with local variables from stored procedure to the STATEMENT-based binary log something wrong happens that end up with incompatible collations while replaying the statement. 

This code works on master:

mysql> delimiter //
mysql> CREATE DEFINER=`root`@`localhost` PROCEDURE `sp_test_t11_ins`()
    -> BEGIN
    -> DECLARE v_id INT;
    -> SET v_id=2017;
    -> INSERT INTO test.t11 (id,nm, cmt)
    -> SELECT
    -> id
    -> ,nm
    -> ,CONCAT( v_id, ' 오뉴이노베이션') AS cmt
    -> FROM test.t1;
    -> END//
Query OK, 0 rows affected (0,10 sec)

mysql> delimiter ;
mysql> insert into t1 values(1,'aaa');
Query OK, 1 row affected (0,07 sec)

mysql> CALL test.sp_test_t11_ins();
Query OK, 1 row affected (0,07 sec)

mysql> select * from t11;
+------+------+----------------------------+
| id   | nm   | cmt                        |
+------+------+----------------------------+
|    1 | aaa  | 2017 오뉴이노베이션        |
+------+------+----------------------------+
1 row in set (0,00 sec)

mysql> show master status;
+------------------+----------+--------------+------------------+-------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+----------+--------------+------------------+-------------------+
| ao756-bin.000001 |     1793 |              |                  |                   |
+------------------+----------+--------------+------------------+-------------------+
1 row in set (0,00 sec)

But can not be replicated by slaves or even replayed on the same master:

openxs@ao756:~/dbs/8.0$ bin/mysqlbinlog -vv -uroot --stop-position=1793 data/ao756-bin.000001 | bin/mysql -uroot --port=3308 test
ERROR 1267 (HY000) at line 108: Illegal mix of collations (latin1_swedish_ci,IMPLICIT) and (utf8mb4_0900_ai_ci,COERCIBLE) for operation 'concat'

How to repeat:
Start any version (I've used 8.0.2 here) with utf8mb4 support, make sure you use MIXED or STATEMENT binlog_format and the create the following simple setup:

mysql> set session binlog_format=STATEMENT;
Query OK, 0 rows affected (0,01 sec)

mysql>  CREATE TABLE `t1` (
    -> `id` int(11) DEFAULT NULL,
    -> `nm` varchar(10) DEFAULT NULL
    -> ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
Query OK, 0 rows affected (0,34 sec)

mysql> CREATE TABLE `t11` (
    -> `id` int(11) DEFAULT NULL,
    -> `nm` varchar(10) DEFAULT NULL,
    -> `cmt` varchar(300) DEFAULT NULL
    -> ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
Query OK, 0 rows affected (0,41 sec)

mysql> delimiter //
mysql> CREATE DEFINER=`root`@`localhost` PROCEDURE `sp_test_t11_ins`()
    -> BEGIN
    -> DECLARE v_id INT;
    -> SET v_id=2017;
    -> INSERT INTO test.t11 (id,nm, cmt)
    -> SELECT
    -> id
    -> ,nm
    -> ,CONCAT( v_id, ' 오뉴이노베이션') AS cmt
    -> FROM test.t1;
    -> END//
Query OK, 0 rows affected (0,10 sec)

mysql> delimiter ;
mysql> insert into t1 values(1,'aaa');
Query OK, 1 row affected (0,07 sec)

mysql> CALL test.sp_test_t11_ins();
Query OK, 1 row affected (0,07 sec)

mysql> select * from t11;
+------+------+----------------------------+
| id   | nm   | cmt                        |
+------+------+----------------------------+
|    1 | aaa  | 2017 오뉴이노베이션        |
+------+------+----------------------------+
1 row in set (0,00 sec)

mysql> show master status;
+------------------+----------+--------------+------------------+-------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+------------------+----------+--------------+------------------+-------------------+
| ao756-bin.000001 |     1793 |              |                  |                   |
+------------------+----------+--------------+------------------+-------------------+
1 row in set (0,00 sec)

mysql> exit

As you can see, everything worked as expected, no errors. 

In the binary log we see:

openxs@ao756:~/dbs/8.0$ bin/mysqlbinlog -vv -uroot data/ao756-bin.000001
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#170831 13:43:20 server id 1  end_log_pos 123 CRC32 0xadff738a  Start: binlog v 4, server v 8.0.2-dmr-log created 170831 13:43:20 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
SOinWQ8BAAAAdwAAAHsAAAABAAQAOC4wLjItZG1yLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAABI6KdZEwANAAgAAAAABAAEAAAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AYpz/60=
'/*!*/;
# at 123
#170831 13:43:20 server id 1  end_log_pos 154 CRC32 0x8574ebd2  Previous-GTIDs
# [empty]
# at 154
#170831 13:46:30 server id 1  end_log_pos 229 CRC32 0x45c74adf  Anonymous_GTID last_committed=0 sequence_number=1       rbr_only=no     original_committed_timestamp=1504176391067504   immediate_commit_timestamp=1504176391067504     transaction_length=274
# original_commit_timestamp=1504176391067504 (2017-08-31 13:46:31.067504 EEST)
# immediate_commit_timestamp=1504176391067504 (2017-08-31 13:46:31.067504 EEST)
/*!80001 SET @@session.original_commit_timestamp=1504176391067504*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 229
#170831 13:46:30 server id 1  end_log_pos 428 CRC32 0x47eb7fa8  Query   thread_id=5     exec_time=1     error_code=0    Xid = 10
use `test`/*!*/;
SET TIMESTAMP=1504176390/*!*/;
SET @@session.pseudo_thread_id=5/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
CREATE TABLE `t1` (
`id` int(11) DEFAULT NULL,
`nm` varchar(10) DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4
/*!*/;
# at 428
#170831 13:46:43 server id 1  end_log_pos 503 CRC32 0x2a199ae8  Anonymous_GTID last_committed=1 sequence_number=2       rbr_only=no     original_committed_timestamp=1504176403537133   immediate_commit_timestamp=1504176403537133     transaction_length=308
# original_commit_timestamp=1504176403537133 (2017-08-31 13:46:43.537133 EEST)
# immediate_commit_timestamp=1504176403537133 (2017-08-31 13:46:43.537133 EEST)
/*!80001 SET @@session.original_commit_timestamp=1504176403537133*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 503
#170831 13:46:43 server id 1  end_log_pos 736 CRC32 0x7d8d5770  Query   thread_id=5     exec_time=0     error_code=0    Xid = 11
SET TIMESTAMP=1504176403/*!*/;
CREATE TABLE `t11` (
`id` int(11) DEFAULT NULL,
`nm` varchar(10) DEFAULT NULL,
`cmt` varchar(300) DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4
/*!*/;
# at 736
#170831 13:47:02 server id 1  end_log_pos 811 CRC32 0x9889743f  Anonymous_GTID last_committed=2 sequence_number=3       rbr_only=no     original_committed_timestamp=1504176422180287   immediate_commit_timestamp=1504176422180287     transaction_length=381
# original_commit_timestamp=1504176422180287 (2017-08-31 13:47:02.180287 EEST)
# immediate_commit_timestamp=1504176422180287 (2017-08-31 13:47:02.180287 EEST)
/*!80001 SET @@session.original_commit_timestamp=1504176422180287*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 811
#170831 13:47:02 server id 1  end_log_pos 1117 CRC32 0xcc831877         Query  thread_id=5      exec_time=0     error_code=0
SET TIMESTAMP=1504176422/*!*/;
CREATE DEFINER=`root`@`localhost` PROCEDURE `sp_test_t11_ins`()
BEGIN
DECLARE v_id INT;
SET v_id=2017;
INSERT INTO test.t11 (id,nm, cmt)
SELECT
id
,nm
,CONCAT( v_id, ' 오뉴이노베이션') AS cmt
FROM test.t1;
END
/*!*/;
# at 1117
#170831 13:47:34 server id 1  end_log_pos 1192 CRC32 0xfee61968         Anonymous_GTID  last_committed=3        sequence_number=4       rbr_only=no     original_committed_timestamp=1504176454140282   immediate_commit_timestamp=1504176454140282     transaction_length=289
# original_commit_timestamp=1504176454140282 (2017-08-31 13:47:34.140282 EEST)
# immediate_commit_timestamp=1504176454140282 (2017-08-31 13:47:34.140282 EEST)
/*!80001 SET @@session.original_commit_timestamp=1504176454140282*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 1192
#170831 13:47:34 server id 1  end_log_pos 1271 CRC32 0x9c33d4c2         Query  thread_id=5      exec_time=0     error_code=0
SET TIMESTAMP=1504176454/*!*/;
BEGIN
/*!*/;
# at 1271
#170831 13:47:34 server id 1  end_log_pos 1375 CRC32 0xe6634c38         Query  thread_id=5      exec_time=0     error_code=0
SET TIMESTAMP=1504176454/*!*/;
insert into t1 values(1,'aaa')
/*!*/;
# at 1375
#170831 13:47:34 server id 1  end_log_pos 1406 CRC32 0x1fed35f2         Xid = 13
COMMIT/*!*/;
# at 1406
#170831 13:47:38 server id 1  end_log_pos 1481 CRC32 0x1bebf313         Anonymous_GTID  last_committed=4        sequence_number=5       rbr_only=no     original_committed_timestamp=1504176458237077   immediate_commit_timestamp=1504176458237077     transaction_length=387
# original_commit_timestamp=1504176458237077 (2017-08-31 13:47:38.237077 EEST)
# immediate_commit_timestamp=1504176458237077 (2017-08-31 13:47:38.237077 EEST)
/*!80001 SET @@session.original_commit_timestamp=1504176458237077*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 1481
#170831 13:47:38 server id 1  end_log_pos 1560 CRC32 0x53d13bac         Query  thread_id=5      exec_time=0     error_code=0
SET TIMESTAMP=1504176458/*!*/;
BEGIN
/*!*/;
# at 1560
#170831 13:47:38 server id 1  end_log_pos 1762 CRC32 0x42600eb7         Query  thread_id=5      exec_time=0     error_code=0
SET TIMESTAMP=1504176458/*!*/;
INSERT INTO test.t11 (id,nm, cmt)
SELECT
id
,nm
,CONCAT(  NAME_CONST('v_id',2017), ' 오뉴이노베이션') AS cmt
FROM test.t1
/*!*/;
# at 1762
#170831 13:47:38 server id 1  end_log_pos 1793 CRC32 0x4b9d1ea1         Xid = 17
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

Now, if we clear up things and try to replay this binary log:

openxs@ao756:~/dbs/8.0$ bin/mysql -uroot --port=3308 test -e'drop table t1, t11'
openxs@ao756:~/dbs/8.0$ bin/mysql -uroot --port=3308 test -e'drop procedure sp_test_t11_ins'
openxs@ao756:~/dbs/8.0$ bin/mysqlbinlog -vv -uroot --stop-position=1793 data/ao756-bin.000001 | bin/mysql -uroot --port=3308 test
ERROR 1267 (HY000) at line 108: Illegal mix of collations (latin1_swedish_ci,IMPLICIT) and (utf8mb4_0900_ai_ci,COERCIBLE) for operation 'concat'

we get the error:

Illegal mix of collations (latin1_swedish_ci,IMPLICIT) and (utf8mb4_0900_ai_ci,COERCIBLE) for operation 'concat'

as a result, point in time recovery and replication is impossible.

As a workaround, use ROW-based binlog_format.

Suggested fix:
Do something differently so that INT local variables can be used in CONCAT() with utf8mb4 strings without such an error while replayed from the binary log:

Illegal mix of collations (latin1_swedish_ci,IMPLICIT) and (utf8mb4_0900_ai_ci,COERCIBLE) for operation 'concat'
[31 Aug 2017 11:05] Valeriy Kravchuk 
Fixed typo.
[1 Sep 2017 7:26] MySQL Verification Team 
Hello Valeriy,

Thank you for the report and test case.
Verified as described with 5.6.37.

Thanks,
Umesh
[1 Sep 2017 7:27] MySQL Verification Team 
5.6.37 results

Attachment: 87624_5.6.37.results (application/octet-stream, text), 7.07 KiB.
[1 Sep 2017 7:47] MySQL Verification Team 
5.7.19 results

Attachment: 87624_5.7.19.results (application/octet-stream, text), 9.04 KiB.