[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' - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
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
Component/s: Character Sets, Replication, Stored routines
Labels:
- upstream

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.

Attachments

Issue Links

relates to

MDEV-11815 SP variables of temporal data types do not replicate correctly

Closed

Can not replay binary log due to Illegal mix of collations (latin1_swedish_ci,IMPLICIT) and (utf8mb4_general_ci,COERCIBLE) for operation 'concat'

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration