Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-35157

wrong binlog timestamps on secondary nodes of a galera cluster

Details

    Description

      Testcase to reproduce

      Create a 3 node testcluster.

      On all nodes

      wsrep_gtid_mode=1
      wsrep_gtid_domain_id=100
      server_id=100

      CREATE TABLE `t1` (`id` INT NOT NULL AUTO_INCREMENT,`c1` INT NOT NULL DEFAULT '0',`t1` DATETIME NOT NULL DEFAULT now() ON UPDATE NOW(),PRIMARY KEY (`id`));
       
      insert into t1 (c1) values (1);
      update t1 set c1 = 2 where c1 = 1;
      select sleep (61);
      insert into t1 (c1) values (3);
      update t1 set c1 = 4 where c1 = 3; 
      

      Node1:

      #241015  6:26:55 server id 100  end_log_pos 2014 CRC32 0xb2ffc8eb 	GTID 100-100-26 trans
      ### INSERT INTO `d1`.`t1`
      ### SET
      ###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
      ###   @2=1 /* INT meta=0 nullable=0 is_null=0 */
      ###   @3='2024-10-15 06:26:55' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
       
      #241015  6:26:55 server id 100  end_log_pos 2233 CRC32 0x435b6af7 	GTID 100-100-27 trans
      ### UPDATE `d1`.`t1`
       
      #241015  6:27:56 server id 100  end_log_pos 2470 CRC32 0xc4bc0bfa 	GTID 100-100-28 trans
      #Q> insert into t1 (c1) values (3)
       
      #241015  6:27:58 server id 100  end_log_pos 2689 CRC32 0xf55e6d7b 	GTID 100-100-29 trans
      ### UPDATE `d1`.`t1`
      

      binlog timestamps are fine as expected.

      Node2:

      #241015  6:18:52 server id 100  end_log_pos 1970 CRC32 0xf27fcb76 	GTID 100-100-26 trans
      #Q> insert into t1 (c1) values (1)
       
       
      #241015  6:23:33 server id 100  end_log_pos 2189 CRC32 0x1c769ec5 	GTID 100-100-27 trans
      #Q> update t1 set c1 = 2 where c1 = 1
       
      #241015  6:27:56 server id 100  end_log_pos 2426 CRC32 0x5d1a5f92 	GTID 100-100-28 trans
      #Q> insert into t1 (c1) values (3)
       
      #241015  6:26:53 server id 100  end_log_pos 2645 CRC32 0xb6436db4 	GTID 100-100-29 trans
      #Q> update t1 set c1 = 4 where c1 = 3
      

      So

      Example:
      Node1:

      #241015  6:26:55  GTID 100-100-26
      ###   @3='2024-10-15 06:26:55' /* DATETIME(0) meta=0 nullable=0 is_null=0 */
      

      Node2:

      #241015 6:18:52 server id 100 end_log_pos 1970 CRC32 0xf27fcb76 GTID 100-100-26

      Attachments

        Issue Links

          Activity

            For clarification. The issues starts with 10.5.25, 10.6.18, 10.5.26, 10.6.19 , previous versions works fine.

            Richard Richard Stracke added a comment - For clarification. The issues starts with 10.5.25, 10.6.18, 10.5.26, 10.6.19 , previous versions works fine.
            Richard Richard Stracke added a comment - - edited

            janlindstrom

            It tested different configs, it popped up for every config.

            I cut the set lines, binlogs are identical apart the timestamps.

            simply testsetup with docker-compose.

            deflate galrep9

             
             
            cd galrep9
             
            docker compose up -d
             
            docker ps
            

            waiting until

            (health: starting)

            for all nodes switched to

            (healthy)

            execute

            mysql -h127.0.0.1 -uroot -ppassword123 -P4131
            

            create database d1;
             
            use d1;
             
            select sleep (61);
             
            CREATE TABLE `t1` (`id` INT NOT NULL AUTO_INCREMENT,`c1` INT NOT NULL DEFAULT '0',`t1` DATETIME NOT NULL DEFAULT now() ON UPDATE NOW(),PRIMARY KEY (`id`));
             
             
             
            insert into t1 (c1) values (1);
             
            update t1 set c1 = 2 where c1 = 1;
             
            select sleep (61);
             
            insert into t1 (c1) values (3);
             
            update t1 set c1 = 4 where c1 = 3; 
            
            

            execute show binary logs and remember the last log_name

            MariaDB [(none)]> show binary logs;
            +-------------------+-----------+
            | Log_name          | File_size |
            +-------------------+-----------+
            | mysqld-bin.000001 |      3754 |
            | mysqld-bin.000002 |       407 |
            | mysqld-bin.000003 |       451 |
            | mysqld-bin.000004 |      1710 |
            +-------------------+-----------+
            4 rows in set (0,000 sec)
            

            exit

            execute:

             
            docker cp galrep9-galera-1-1-1:/bitnami/mariadb/data/mysqld-bin.000004 binlognode1
            docker cp galrep9-galera-1-2-1:/bitnami/mariadb/data/mysqld-bin.000004 binlognode2
            

             
            (base) richard@amarna:~/docker/galrep9$ mysqlbinlog --no-defaults -vvv binlognode1 | grep GTID
            #241016  9:35:59 server id 100  end_log_pos 445 CRC32 0x8d8cded8 	GTID 100-100-18 ddl
            #241016  9:37:00 server id 100  end_log_pos 570 CRC32 0xba8a6213 	GTID 100-100-19 ddl
            #241016  9:37:01 server id 100  end_log_pos 840 CRC32 0xa2eeb3b0 	GTID 100-100-20 trans
            #241016  9:37:01 server id 100  end_log_pos 1059 CRC32 0x56f1f45e 	GTID 100-100-21 trans
            #241016  9:38:02 server id 100  end_log_pos 1296 CRC32 0x0456f26a 	GTID 100-100-22 trans
            #241016  9:38:02 server id 100  end_log_pos 1515 CRC32 0x346c942e 	GTID 100-100-23 trans
            
            

             
            (base) richard@amarna:~/docker/galrep9$ mysqlbinlog --no-defaults -vvv binlognode2 | grep GTID
            #241016  9:35:59 server id 100  end_log_pos 401 CRC32 0xea144948 	GTID 100-100-18 ddl
            #241016  9:37:00 server id 100  end_log_pos 526 CRC32 0xa90e415a 	GTID 100-100-19 ddl
            #241016  9:37:01 server id 100  end_log_pos 796 CRC32 0xba6945dc 	GTID 100-100-20 trans
            #241016  9:37:01 server id 100  end_log_pos 1015 CRC32 0xd24404f6 	GTID 100-100-21 trans
            #241016  9:35:59 server id 100  end_log_pos 1252 CRC32 0x7bf88157 	GTID 100-100-22 trans
            #241016  9:37:00 server id 100  end_log_pos 1471 CRC32 0x0c63a5fb 	GTID 100-100-23 trans
            
            

            attach galrep9.zip

            Richard Richard Stracke added a comment - - edited janlindstrom It tested different configs, it popped up for every config. I cut the set lines, binlogs are identical apart the timestamps. simply testsetup with docker-compose. deflate galrep9     cd galrep9   docker compose up -d   docker ps waiting until (health: starting) for all nodes switched to (healthy) execute mysql -h127. 0.0 . 1 -uroot -ppassword123 -P4131 create database d1;   use d1;   select sleep ( 61 );   CREATE TABLE `t1` (`id` INT NOT NULL AUTO_INCREMENT,`c1` INT NOT NULL DEFAULT '0' ,`t1` DATETIME NOT NULL DEFAULT now() ON UPDATE NOW(),PRIMARY KEY (`id`));     insert into t1 (c1) values ( 1 );   update t1 set c1 = 2 where c1 = 1 ;   select sleep ( 61 );   insert into t1 (c1) values ( 3 );   update t1 set c1 = 4 where c1 = 3 ; execute show binary logs and remember the last log_name MariaDB [(none)]> show binary logs; +-------------------+-----------+ | Log_name | File_size | +-------------------+-----------+ | mysqld-bin. 000001 | 3754 | | mysqld-bin. 000002 | 407 | | mysqld-bin. 000003 | 451 | | mysqld-bin. 000004 | 1710 | +-------------------+-----------+ 4 rows in set ( 0 , 000 sec) exit execute: docker cp galrep9-galera- 1 - 1 - 1 :/bitnami/mariadb/data/mysqld-bin. 000004 binlognode1 docker cp galrep9-galera- 1 - 2 - 1 :/bitnami/mariadb/data/mysqld-bin. 000004 binlognode2   (base) richard @amarna :~/docker/galrep9$ mysqlbinlog --no-defaults -vvv binlognode1 | grep GTID # 241016 9 : 35 : 59 server id 100 end_log_pos 445 CRC32 0x8d8cded8 GTID 100 - 100 - 18 ddl # 241016 9 : 37 : 00 server id 100 end_log_pos 570 CRC32 0xba8a6213 GTID 100 - 100 - 19 ddl # 241016 9 : 37 : 01 server id 100 end_log_pos 840 CRC32 0xa2eeb3b0 GTID 100 - 100 - 20 trans # 241016 9 : 37 : 01 server id 100 end_log_pos 1059 CRC32 0x56f1f45e GTID 100 - 100 - 21 trans # 241016 9 : 38 : 02 server id 100 end_log_pos 1296 CRC32 0x0456f26a GTID 100 - 100 - 22 trans # 241016 9 : 38 : 02 server id 100 end_log_pos 1515 CRC32 0x346c942e GTID 100 - 100 - 23 trans   (base) richard @amarna :~/docker/galrep9$ mysqlbinlog --no-defaults -vvv binlognode2 | grep GTID # 241016 9 : 35 : 59 server id 100 end_log_pos 401 CRC32 0xea144948 GTID 100 - 100 - 18 ddl # 241016 9 : 37 : 00 server id 100 end_log_pos 526 CRC32 0xa90e415a GTID 100 - 100 - 19 ddl # 241016 9 : 37 : 01 server id 100 end_log_pos 796 CRC32 0xba6945dc GTID 100 - 100 - 20 trans # 241016 9 : 37 : 01 server id 100 end_log_pos 1015 CRC32 0xd24404f6 GTID 100 - 100 - 21 trans # 241016 9 : 35 : 59 server id 100 end_log_pos 1252 CRC32 0x7bf88157 GTID 100 - 100 - 22 trans # 241016 9 : 37 : 00 server id 100 end_log_pos 1471 CRC32 0x0c63a5fb GTID 100 - 100 - 23 trans attach galrep9.zip

            Richard I do not think those timestamps should be identical, they should be timestamp when they were written to binlog.

            janlindstrom Jan Lindström added a comment - Richard I do not think those timestamps should be identical, they should be timestamp when they were written to binlog.
            janlindstrom Jan Lindström added a comment - https://github.com/MariaDB/server/pull/3601

            janlindstrom

            >Richard Stracke I do not think those timestamps should be identical, they should be timestamp when they were written to binlog.

            Would be sufficient, but later written gtid can never be in the past.

            #241016  9:37:01 server id 100  end_log_pos 1015 CRC32 0xd24404f6 	GTID 100-100-21 trans
            #241016  9:35:59 server id 100  end_log_pos 1252 CRC32 0x7bf88157 	GTID 100-100-22 trans
            

            Richard Richard Stracke added a comment - janlindstrom >Richard Stracke I do not think those timestamps should be identical, they should be timestamp when they were written to binlog. Would be sufficient, but later written gtid can never be in the past. # 241016 9 : 37 : 01 server id 100 end_log_pos 1015 CRC32 0xd24404f6 GTID 100 - 100 - 21 trans # 241016 9 : 35 : 59 server id 100 end_log_pos 1252 CRC32 0x7bf88157 GTID 100 - 100 - 22 trans
            sysprg Julius Goryavsky added a comment - The fix has been merged with the main branch: https://github.com/MariaDB/server/commit/4b38af06a4b762f7cd55fa0292fb5e1e9a4f6b98

            People

              sysprg Julius Goryavsky
              Richard Richard Stracke
              Votes:
              1 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.