[MDEV-35157] wrong binlog timestamps on secondary nodes of a galera cluster - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.5.25, 10.6.18, 10.5.26, 10.6.19
Fix Version/s: 10.5.28, 10.6.21, 10.11.11, 11.4.5, 11.7.2
Component/s: Binary Protocol, Galera
Labels:
- binlog
- galera

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

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

- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

galrep9.zip
5 kB
2024-10-30 09:02

Issue Links

relates to

MDEV-31413 Node has been dropped from the cluster on Startup / Shutdown with async replica

Closed

MDEV-34211 Seconds_Behind_Master gives impossible values

Closed

Activity

Ascending order - Click to sort in descending order

Richard Stracke added a comment - 2024-10-24 10:19

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

Richard Stracke added a comment - 2024-10-24 10:19 For clarification. The issues starts with 10.5.25, 10.6.18, 10.5.26, 10.6.19 , previous versions works fine.

Richard Stracke added a comment - 2024-10-30 09:02 - 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 Stracke added a comment - 2024-10-30 09:02 - 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

Jan Lindström added a comment - 2024-10-30 11:20

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

Jan Lindström added a comment - 2024-10-30 11:20 Richard I do not think those timestamps should be identical, they should be timestamp when they were written to binlog.

Jan Lindström added a comment - 2024-10-30 11:29

https://github.com/MariaDB/server/pull/3601

Jan Lindström added a comment - 2024-10-30 11:29 https://github.com/MariaDB/server/pull/3601

Richard Stracke added a comment - 2024-11-06 05:58

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 Stracke added a comment - 2024-11-06 05:58 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

Julius Goryavsky added a comment - 2024-11-06 12:48

The fix has been merged with the main branch: https://github.com/MariaDB/server/commit/4b38af06a4b762f7cd55fa0292fb5e1e9a4f6b98

Julius Goryavsky added a comment - 2024-11-06 12:48 The fix has been merged with the main branch: https://github.com/MariaDB/server/commit/4b38af06a4b762f7cd55fa0292fb5e1e9a4f6b98

People

Assignee:: Julius Goryavsky

Reporter:: Richard Stracke

Votes:: 1 Vote for this issue

Watchers:: 5 Start watching this issue

Dates

Created:: 2024-10-15 11:07

Updated:: 2025-04-15 17:51

Resolved:: 2024-11-06 12:48

Git Integration

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

MariaDB Server

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates

Git Integration