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

        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.