[MDEV-13685] Can not replay binary log due to Illegal mix of collations (latin1_swedish_ci,IMPLICIT) and (utf8mb4_general_ci,COERCIBLE) for operation 'concat' Created: 2017-08-31  Updated: 2020-08-25  Resolved: 2017-09-15

Status: Closed
Project: MariaDB Server
Component/s: Character Sets, Replication, Stored routines
Affects Version/s: 10.0, 10.1.23, 10.1.26, 10.2.9
Fix Version/s: 10.0.33, 10.1.27, 10.2.9, 10.3.2

Type: Bug Priority: Critical
Reporter: Valerii Kravchuk Assignee: Alexander Barkov
Resolution: Fixed Votes: 0
Labels: upstream

Issue Links:
Relates
relates to MDEV-11815 SP variables of temporal data types d... Closed

 Description   

It seems there is a serious problem with STATEMENT or MIXED mode binary logging in many (all?) versions of MariaDB Server (and ColumnStore that is based on them) in case when we do INSERT ... SELECT from some stored procedure and CONCAT() is used in SELECT part on number and utf8mb4 character string.

Consider the following case:

openxs@ao756:~/dbs/maria10.2$ bin/mysql -uroot --port=3308 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 10
 
Server version: 10.2.9-MariaDB-log Source distribution
 
 
 
Copyright (c) 2000, 2017, Oracle, MariaDB Corporation Ab and others.
 
 
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
 
 
MariaDB [test]> show master status;
 
+------------------+----------+--------------+------------------+
 
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB |
 
+------------------+----------+--------------+------------------+
 
| ao756-bin.000003 |      328 |              |                  |
 
+------------------+----------+--------------+------------------+
 
1 row in set (0.02 sec)
 
 
 
MariaDB [test]> show variables like 'char%';
 
+--------------------------+--------------------------------------------+
 
| Variable_name            | Value                                      |
 
+--------------------------+--------------------------------------------+
 
| character_set_client     | utf8                                       |
 
| character_set_connection | utf8                                       |
 
| character_set_database   | latin1                                     |
 
| character_set_filesystem | binary                                     |
 
| character_set_results    | utf8                                       |
 
| character_set_server     | latin1                                     |
 
| character_set_system     | utf8                                       |
 
| character_sets_dir       | /home/openxs/dbs/maria10.2/share/charsets/ |
 
+--------------------------+--------------------------------------------+
 
8 rows in set (0.01 sec)
 
 
 
MariaDB [test]> drop table if exists t1;
 
Query OK, 0 rows affected (0.22 sec)
 
 
 
MariaDB [test]> drop table if exists t11;
 
Query OK, 0 rows affected, 1 warning (0.00 sec)
 
 
 
MariaDB [test]>  CREATE TABLE `t1` (
 
    -> `id` int(11) DEFAULT NULL,
 
    -> `nm` varchar(10) DEFAULT NULL
 
    -> ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
 
Query OK, 0 rows affected (0.23 sec)
 
 
 
MariaDB [test]>  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.25 sec)
 
 
 
MariaDB [test]> set names utf8mb4;
 
Query OK, 0 rows affected (0.00 sec)
 
 
 
MariaDB [test]> delimiter //
 
MariaDB [test]> 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.04 sec)
 
 
 
MariaDB [test]> delimiter ;
 
MariaDB [test]> CALL test.sp_test_t11_ins();
 
Query OK, 0 rows affected (0.01 sec)
 
 
 
MariaDB [test]> show master status;
 
+------------------+----------+--------------+------------------+
 
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB |
 
+------------------+----------+--------------+------------------+
 
| ao756-bin.000003 |     1768 |              |                  |
 
+------------------+----------+--------------+------------------+
 
1 row in set (0.00 sec)

This is what we get with mysqlbinlog:

openxs@ao756:~/dbs/maria10.2$ bin/mysqlbinlog -vv -uroot --start-position=328 data/ao756-bin.000003
 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
 
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
 
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
 
DELIMITER /*!*/;
 
# at 4
 
#170831 11:05:04 server id 1  end_log_pos 256 CRC32 0x3d96a2c6  Start: binlog v 4, server v 10.2.9-MariaDB-log created 170831 11:05:04 at startup
 
# Warning: this binlog is either in use or was not closed properly.
 
ROLLBACK/*!*/;
 
BINLOG '
 
MMOnWQ8BAAAA/AAAAAABAAABAAQAMTAuMi45LU1hcmlhREItbG9nAAAAAAAAAAAAAAAAAAAAAAAA
 
AAAAAAAAAAAAAAAAAAAww6dZEzgNAAgAEgAEBAQEEgAA5AAEGggAAAAICAgCAAAACgoKAAAAAAAA
 
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
 
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
 
AAAAAAAAAAAEEwQADQgICAoKCgHGopY9
 
'/*!*/;
 
# at 328
 
#170831 11:06:17 server id 1  end_log_pos 370 CRC32 0xa8300017  GTID 0-1-1 ddl
 
/*!100101 SET @@session.skip_parallel_replication=0*//*!*/;
 
/*!100001 SET @@session.gtid_domain_id=0*//*!*/;
 
/*!100001 SET @@session.server_id=1*//*!*/;
 
/*!100001 SET @@session.gtid_seq_no=1*//*!*/;
 
# at 370
 
#170831 11:06:17 server id 1  end_log_pos 488 CRC32 0x6ff21ca6  Query   thread_id=10    exec_time=0     error_code=0
 
use `test`/*!*/;
 
SET TIMESTAMP=1504166777/*!*/;
 
SET @@session.pseudo_thread_id=10/*!*/;
 
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1, @@session.check_constraint_checks=1/*!*/;
 
SET @@session.sql_mode=1411383296/*!*/;
 
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
 
/*!\C utf8 *//*!*/;
 
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
 
SET @@session.lc_time_names=0/*!*/;
 
SET @@session.collation_database=DEFAULT/*!*/;
 
DROP TABLE IF EXISTS `t1` /* generated by server */
 
/*!*/;
 
# at 488
 
#170831 11:06:19 server id 1  end_log_pos 530 CRC32 0x981b0736  GTID 0-1-2 ddl
 
/*!100001 SET @@session.gtid_seq_no=2*//*!*/;
 
# at 530
 
#170831 11:06:19 server id 1  end_log_pos 649 CRC32 0x4633eef8  Query   thread_id=10    exec_time=0     error_code=0
 
SET TIMESTAMP=1504166779/*!*/;
 
DROP TABLE IF EXISTS `t11` /* generated by server */
 
/*!*/;
 
# at 649
 
#170831 11:06:34 server id 1  end_log_pos 691 CRC32 0x69c0c9c3  GTID 0-1-3 ddl
 
/*!100001 SET @@session.gtid_seq_no=3*//*!*/;
 
# at 691
 
#170831 11:06:34 server id 1  end_log_pos 874 CRC32 0x2b0f0812  Query   thread_id=10    exec_time=1     error_code=0
 
SET TIMESTAMP=1504166794/*!*/;
 
CREATE TABLE `t1` (
 
`id` int(11) DEFAULT NULL,
 
`nm` varchar(10) DEFAULT NULL
 
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4
 
/*!*/;
 
# at 874
 
#170831 11:06:49 server id 1  end_log_pos 916 CRC32 0x24ff66d1  GTID 0-1-4 ddl
 
/*!100001 SET @@session.gtid_seq_no=4*//*!*/;
 
# at 916
 
#170831 11:06:49 server id 1  end_log_pos 1133 CRC32 0x763b3b16         Query  thread_id=10     exec_time=1     error_code=0
 
SET TIMESTAMP=1504166809/*!*/;
 
CREATE TABLE `t11` (
 
`id` int(11) DEFAULT NULL,
 
`nm` varchar(10) DEFAULT NULL,
 
`cmt` varchar(300) DEFAULT NULL
 
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4
 
/*!*/;
 
# at 1133
 
#170831 11:07:17 server id 1  end_log_pos 1175 CRC32 0xab2d80eb         GTID 0-1-5 ddl
 
/*!100001 SET @@session.gtid_seq_no=5*//*!*/;
 
# at 1175
 
#170831 11:07:17 server id 1  end_log_pos 1458 CRC32 0xd7c01347         Query  thread_id=10     exec_time=0     error_code=0
 
SET TIMESTAMP=1504166837/*!*/;
 
/*!\C utf8mb4 *//*!*/;
 
SET @@session.character_set_client=45,@@session.collation_connection=45,@@session.collation_server=8/*!*/;
 
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 1458
 
#170831 11:07:31 server id 1  end_log_pos 1500 CRC32 0x933e1f0c         GTID 0-1-6 trans
 
/*!100001 SET @@session.gtid_seq_no=6*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 1500
 
#170831 11:07:31 server id 1  end_log_pos 1695 CRC32 0x5547c5c6         Query  thread_id=10     exec_time=0     error_code=0
 
SET TIMESTAMP=1504166851/*!*/;
 
INSERT INTO test.t11 (id,nm, cmt)
 
SELECT
 
id
 
,nm
 
,CONCAT(  NAME_CONST('v_id',2017), ' 오뉴이노베이션') AS cmt
 
FROM test.t1
 
/*!*/;
 
# at 1695
 
#170831 11:07:31 server id 1  end_log_pos 1768 CRC32 0xb9c38de0         Query  thread_id=10     exec_time=0     error_code=0
 
SET TIMESTAMP=1504166851/*!*/;
 
COMMIT
 
/*!*/;
 
DELIMITER ;
 
# End of log file
 
ROLLBACK /* added by mysqlbinlog */;
 
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
 
openxs@ao756:~/dbs/maria10.2$

So, there was no errors and everything is logged, including INSERT ... SELECT from stored procedure that uses INT variable. Now, if we drop procedure and try to replay the binary log again, we get:

openxs@ao756:~/dbs/maria10.2$ bin/mysql -uroot --port=3308 test -e"drop procedure sp_test_t11_ins"
 
openxs@ao756:~/dbs/maria10.2$ bin/mysqlbinlog -vv -uroot --start-position=328 data/ao756-bin.000003 | bin/mysql -uroot --port=3308 test
 
ERROR 1267 (HY000) at line 95: Illegal mix of collations (latin1_swedish_ci,IMPLICIT) and (utf8mb4_general_ci,COERCIBLE) for operation 'concat'

As a result, we can not replay changes from the binary log for point in time recovery and all slaves also fail and get out of sync.

Setting binlog_format to ROW surely allows to workaround this.

 Comments   
Comment by Valerii Kravchuk [ 2017-08-31 ]

See upstream https://bugs.mysql.com/bug.php?id=87624 also

Comment by Alexander Barkov [ 2017-09-15 ]

It seems the NAME_CONST() function sets it derivation in a wrong way in case of a numeric argument.
This short script demonstates the problem:

SET NAMES utf8;
 
SELECT CONCAT(NAME_CONST('name',15),'오');


ERROR 1267 (HY000): Illegal mix of collations (latin1_swedish_ci,IMPLICIT) and (utf8_general_ci,COERCIBLE) for operation 'concat'

IMPLICIT is a wrong derivation for a numeric expression.

Comment by Alexander Barkov [ 2017-09-15 ]

This mtr test case fails with the 'Illegal mix of collations...' error.

source include/master-slave.inc;
 
 
 
connection master;
 
 
 
SET NAMES utf8;
 
CREATE TABLE t1 (a VARCHAR(10) CHARACTER SET utf8);
 
DELIMITER $$;
 
CREATE PROCEDURE p1()
 
BEGIN
 
  DECLARE v_id INT DEFAULT 2017;
 
  INSERT INTO test.t1 SELECT CONCAT(v_id, '오');
 
END;
 
$$
 
DELIMITER ;$$
 
CALL p1;
 
SELECT * FROM t1;
 
sync_slave_with_master;
 
SET NAMES utf8;
 
SELECT * FROM t1;
 
connection master;
 
DROP PROCEDURE p1;
 
DROP TABLE t1;
 
sync_slave_with_master;
 
 
 
--source include/rpl_end.inc

Comment by Alexander Barkov [ 2017-09-15 ]

Pushed to 10.0.

Generated at Thu Feb 08 08:07:32 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.