Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. 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'

    XMLWordPrintable

    Details

      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

            Activity

              People

              Assignee:
              bar Alexander Barkov
              Reporter:
              valerii Valerii Kravchuk
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved: