[MDEV-32184] rpl.rpl_gtid_until_before_after_gtids regularly times out - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 11.3(EOL)
Fix Version/s: 11.3.1
Component/s: Replication
Labels:
- timeout

Description

Using:

MTR_MEM=/dev/shm ./mysql-test-run --repeat=99999 --parallel=30 --mem --force --retry=99999 --retry-failure=99999 rpl_gtid_until_before_after_gtids | tee mtr_output.txt

We see regular timeouts in rpl_gtid_until_before_after_gtids on both optimized and debug builds:

preview-11.3-preview aefddd9319864bad87b4679355e216b5663768d0 (debug)
...
rpl.rpl_gtid_until_before_after_gtids 'innodb,stmt' w4 [ 144 pass ] 3206
rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w28 [ 146 pass ] 2617
rpl.rpl_gtid_until_before_after_gtids 'innodb,stmt' w4 [ 145 pass ] 3344
rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w28 [ 147 pass ] 3260
rpl.rpl_gtid_until_before_after_gtids 'innodb,row' w15 [ 72 fail ]
Test ended at 2023-09-12 16:15:58

CURRENT_TEST: rpl.rpl_gtid_until_before_after_gtids
mysqltest: In included file "./include/wait_for_slave_param.inc":
included from ./include/wait_for_slave_io_to_start.inc at line 40:
included from ./include/wait_for_slave_to_start.inc at line 26:
included from ./include/start_slave.inc at line 35:
included from /test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/suite/rpl/include/rpl_gtid_until_before_after_gtids.test at line 161:
included from /test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/suite/rpl/t/rpl_gtid_until_before_after_gtids.test at line 26:
At line 119: Timeout in include/wait_for_slave_param.inc

The result from queries just before the failure was:
< snip >
master-bin.000001 1397 Annotate_rows 1 1447 INSERT INTO t1 VALUES (103)
master-bin.000001 1447 Table_map 1 1492 table_id: 459 (test.t1)
master-bin.000001 1492 Write_rows_v1 1 1530 table_id: 459 flags: STMT_END_F
master-bin.000001 1530 Query 1 1603 COMMIT
master-bin.000001 1603 Gtid 1 1645 BEGIN GTID 0-1-7
master-bin.000001 1645 Annotate_rows 1 1695 INSERT INTO t1 VALUES (104)
master-bin.000001 1695 Table_map 1 1740 table_id: 459 (test.t1)
master-bin.000001 1740 Write_rows_v1 1 1778 table_id: 459 flags: STMT_END_F
master-bin.000001 1778 Query 1 1851 COMMIT
master-bin.000001 1851 Gtid 1 1893 BEGIN GTID 0-1-9
master-bin.000001 1893 Annotate_rows 1 1943 INSERT INTO t1 VALUES (105)
master-bin.000001 1943 Table_map 1 1988 table_id: 459 (test.t1)
master-bin.000001 1988 Write_rows_v1 1 2026 table_id: 459 flags: STMT_END_F
master-bin.000001 2026 Query 1 2099 COMMIT

** SHOW RELAYLOG EVENTS on server_1 **
relaylog_name = 'No such row'
SHOW RELAYLOG EVENTS IN 'No such row';
Log_name Pos Event_type Server_id End_log_pos Info
connection slave;

More results from queries before failure can be found in /test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/15/log/rpl_gtid_until_before_after_gtids.log

- saving '/test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/15/log/rpl.rpl_gtid_until_before_after_gtids-innodb,row/' to '/test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/log/rpl.rpl_gtid_until_before_after_gtids-innodb,row/'

preview-11.3-preview aefddd9319864bad87b4679355e216b5663768d0 (optimized)
...
rpl.rpl_gtid_until_before_after_gtids 'innodb,stmt' w17 [ 238 pass ] 2614
rpl.rpl_gtid_until_before_after_gtids 'innodb,stmt' w17 [ 239 pass ] 2393
rpl.rpl_gtid_until_before_after_gtids 'innodb,stmt' w17 [ 240 pass ] 2891
rpl.rpl_gtid_until_before_after_gtids 'innodb,row' w9 [ 157 fail ]
Test ended at 2023-09-12 16:20:16

CURRENT_TEST: rpl.rpl_gtid_until_before_after_gtids
mysqltest: In included file "./include/wait_for_slave_param.inc":
included from ./include/wait_for_slave_io_to_start.inc at line 40:
included from ./include/wait_for_slave_to_start.inc at line 26:
included from ./include/start_slave.inc at line 35:
included from /test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-opt/mariadb-test/suite/rpl/include/rpl_gtid_until_before_after_gtids.test at line 161:
included from /test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-opt/mariadb-test/suite/rpl/t/rpl_gtid_until_before_after_gtids.test at line 29:
At line 119: Timeout in include/wait_for_slave_param.inc

The result from queries just before the failure was:
< snip >
master-bin.000001 1397 Annotate_rows 1 1447 INSERT INTO t1 VALUES (114)
master-bin.000001 1447 Table_map 1 1492 table_id: 971 (test.t1)
master-bin.000001 1492 Write_rows_v1 1 1530 table_id: 971 flags: STMT_END_F
master-bin.000001 1530 Query 1 1603 COMMIT
master-bin.000001 1603 Gtid 1 1645 BEGIN GTID 0-1-7
master-bin.000001 1645 Annotate_rows 1 1695 INSERT INTO t1 VALUES (115)
master-bin.000001 1695 Table_map 1 1740 table_id: 971 (test.t1)
master-bin.000001 1740 Write_rows_v1 1 1778 table_id: 971 flags: STMT_END_F
master-bin.000001 1778 Query 1 1851 COMMIT
master-bin.000001 1851 Gtid 1 1893 BEGIN GTID 0-1-9
master-bin.000001 1893 Annotate_rows 1 1943 INSERT INTO t1 VALUES (116)
master-bin.000001 1943 Table_map 1 1988 table_id: 971 (test.t1)
master-bin.000001 1988 Write_rows_v1 1 2026 table_id: 971 flags: STMT_END_F
master-bin.000001 2026 Query 1 2099 COMMIT

** SHOW RELAYLOG EVENTS on server_1 **
relaylog_name = 'No such row'
SHOW RELAYLOG EVENTS IN 'No such row';
Log_name Pos Event_type Server_id End_log_pos Info
connection slave;

More results from queries before failure can be found in /test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-opt/mariadb-test/var/9/log/rpl_gtid_until_before_after_gtids.log

- saving '/test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-opt/mariadb-test/var/9/log/rpl.rpl_gtid_until_before_after_gtids-innodb,row/' to '/test/preview-11.3-preview_MD120923-mariadb-11.3.0-linux-x86_64-opt/mariadb-test/var/log/rpl.rpl_gtid_until_before_after_gtids-innodb,row/'

Issues are somewhat regular:

preview-11.3-preview aefddd9319864bad87b4679355e216b5663768d0 (debug)
rpl.rpl_gtid_until_before_after_gtids 'innodb,row' w15 [ 72 fail ]
rpl.rpl_gtid_until_before_after_gtids 'innodb,stmt' w4 [ 176 fail ]
rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w28 [ 1000 fail ]

preview-11.3-preview aefddd9319864bad87b4679355e216b5663768d0 (optimized)
rpl.rpl_gtid_until_before_after_gtids 'innodb,row' w9 [ 157 fail ]
rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w4 [ 167 fail ]
rpl.rpl_gtid_until_before_after_gtids 'innodb,stmt' w17 [ 242 fail ]

And we also see regular retry failures (38 out of 5536 on debug, 49 out of 6361 on optimized). Note the test suite will timeout around 5-6K execs depending on system performance.

Attachments

Issue Links

blocks

MDEV-27247 Add keywords "SQL_BEFORE_GTIDS" and "SQL_AFTER_GTIDS" for START SLAVE UNTIL

Closed

is caused by

MDEV-27247 Add keywords "SQL_BEFORE_GTIDS" and "SQL_AFTER_GTIDS" for START SLAVE UNTIL

Closed

Activity

Ascending order - Click to sort in descending order

Roel Van de Paar added a comment - 2023-09-19 02:51

Testing bugfix branch bb-11.3-MDEV-32184 provided by bnestere

Roel Van de Paar added a comment - 2023-09-19 02:51 Testing bugfix branch bb-11.3- MDEV-32184 provided by bnestere

Roel Van de Paar added a comment - 2023-09-20 04:17

bnestere Thank you for your work on this. I am still getting errors on the new branch, however the output has changed.
Firstly, here is a better testcase (true parallel):

MTR_MEM=/dev/shm ./mysql-test-run --repeat=99999 --parallel=30 --mem --force --retry=99999 --retry-failure=99999 rpl_gtid_until_before_after_gtids{,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,} | tee mtr_output.txt

We now get output like this:

bb-11.3-MDEV-32184 f99f1a8d76aa0f9f561965247da147593ee2012b
...
rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w4 [ 8 pass ] 9300
rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w29 [ 8 pass ] 9182
rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w23 [ 9 fail ]
Test ended at 2023-09-20 14:02:54

CURRENT_TEST: rpl.rpl_gtid_until_before_after_gtids


Server [mysqld.1 - pid: 343661, winpid: 343661, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2023-09-20 14:02:47 254 [Note] Deleted Master_info file '/dev/shm/var_auto_i67M/23/mysqld.1/data/master.info'.
2023-09-20 14:02:47 254 [Note] Deleted Master_info file '/dev/shm/var_auto_i67M/23/mysqld.1/data/relay-log.info'.
2023-09-20 14:02:48 256 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('')
2023-09-20 14:02:48 259 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 329), using_gtid(1), gtid(''
)
2023-09-20 14:02:48 260 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('')
2023-09-20 14:02:48 260 [Warning] Aborted connection 260 to db: 'unconnected' user: 'root' host: 'localhost' (Got an err
or writing communication packets)
2023-09-20 14:02:49 261 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 611), using_gtid(1), gtid('0
-1-2')
2023-09-20 14:02:49 262 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1029), using_gtid(1), gtid('0-1-3')
2023-09-20 14:02:49 262 [Warning] Aborted connection 262 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets)
2023-09-20 14:02:50 263 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1238), using_gtid(1), gtid('0-1-5')
2023-09-20 14:02:50 264 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1865), using_gtid(1), gtid('0-1-7')
2023-09-20 14:02:50 264 [Warning] Aborted connection 264 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets)
2023-09-20 14:02:50 265 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1865), using_gtid(1), gtid('0-1-9')
2023-09-20 14:02:51 266 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 2701), using_gtid(1), gtid('1-1-2,0-1-10')
2023-09-20 14:02:51 266 [Warning] Aborted connection 266 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets)
2023-09-20 14:02:51 267 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 2910), using_gtid(1), gtid('1-1-3,0-1-11')
2023-09-20 14:02:51 268 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 3642), using_gtid(1), gtid('1-1-4,0-1-12')
2023-09-20 14:02:52 269 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 4374), using_gtid(1), gtid('1-1-6,0-1-14')
2023-09-20 14:02:52 270 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 4538), using_gtid(1), gtid('1-1-6,0-1-15')
2023-09-20 14:02:53 271 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('')
2023-09-20 14:02:53 271 [Warning] Aborted connection 271 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets)
2023-09-20 14:02:53 272 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 611), using_gtid(1), gtid('0-1-2')
----------SERVER LOG END-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
create table t1 (a int);
create table t2 (a int);
connection slave;
#
# Test Case 1 (SQL_AFTER_GTIDS): For a single-dimensional binlog state and a
# STOP SLAVE UNTIL gtid position with one GTID, the replica should
# execute events up until the GTID is encountered, finish replicating
# that event group, and then stop
connection slave;
connection master;
set session gtid_domain_id=0;
INSERT INTO t1 VALUES (111);
INSERT INTO t1 VALUES (112);
INSERT INTO t1 VALUES (113);
connection slave;
START SLAVE UNTIL SQL_AFTER_GTIDS="0-1-4";
# Ensure the slave started
# Clean replica state
connection master;
connection slave;



- saving '/test/bb-11.3-MDEV-32184_MD190923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/23/log/rpl.rpl_gtid_until_before_after_gtids-innodb,mix/' to '/test/bb-11.3-MDEV-32184_MD190923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/log/rpl.rpl_gtid_until_before_after_gtids-innodb,mix/'

Retrying test rpl.rpl_gtid_until_before_after_gtids, attempt(2/99999)...

rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w20 [ 9 fail ]
Test ended at 2023-09-20 14:02:54

CURRENT_TEST: rpl.rpl_gtid_until_before_after_gtids


Server [mysqld.1 - pid: 343351, winpid: 343351, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2023-09-20 14:02:50 254 [Note] Deleted Master_info file '/dev/shm/var_auto_i67M/20/mysqld.1/data/master.info'.
2023-09-20 14:02:50 254 [Note] Deleted Master_info file '/dev/shm/var_auto_i67M/20/mysqld.1/data/relay-log.info'.
2023-09-20 14:02:51 256 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('')
2023-09-20 14:02:51 259 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 329), using_gtid(1), gtid('')
2023-09-20 14:02:52 260 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('')
2023-09-20 14:02:52 260 [Warning] Aborted connection 260 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets)
2023-09-20 14:02:52 261 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 611), using_gtid(1), gtid('0-1-2')
2023-09-20 14:02:52 262 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1029), using_gtid(1), gtid('0-1-3')
2023-09-20 14:02:53 262 [Warning] Aborted connection 262 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets)
2023-09-20 14:02:53 263 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1238), using_gtid(1), gtid('0-1-5')
2023-09-20 14:02:53 264 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1865), using_gtid(1), gtid('0-1-7')
2023-09-20 14:02:53 264 [Warning] Aborted connection 264 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets)
----------SERVER LOG END-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
#
# Test Case 3 (SQL_BEFORE_GTIDS): For a multi-dimensional binlog state and a
# STOP SLAVE UNTIL gtid position with one GTID, the replica should
# execute events from all domains (including unspecified ones) until the
# provided GTID is encountered, and immediately stop
connection slave;
connection master;
set session gtid_domain_id=0;
INSERT INTO t1 VALUES (106);
set session gtid_domain_id=1;
INSERT INTO t2 VALUES (200);
INSERT INTO t2 VALUES (201);
set session gtid_domain_id=0;
INSERT INTO t1 VALUES (107);
set session gtid_domain_id=1;
INSERT INTO t2 VALUES (202);
set session gtid_domain_id=0;
connection slave;
START SLAVE UNTIL SQL_BEFORE_GTIDS="0-1-11";
# Ensure the slave started
...

This was a debug build of bb-11.3-MDEV-32184.
The above failed in 8 passes. Retesting failed after 35 passes, but in another area:

bb-11.3-MDEV-32184 f99f1a8d76aa0f9f561965247da147593ee2012b
...
rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w7 [ 35 pass ] 7367
rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w16 [ 35 pass ] 8545
rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w11 [ 36 fail ]
Test ended at 2023-09-20 14:13:11

CURRENT_TEST: rpl.rpl_gtid_until_before_after_gtids


Server [mysqld.1 - pid: 891354, winpid: 891354, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2023-09-20 14:13:06 1091 [Note] Deleted Master_info file '/dev/shm/var_auto_qVTY/11/mysqld.1/data/master.info'.
2023-09-20 14:13:06 1091 [Note] Deleted Master_info file '/dev/shm/var_auto_qVTY/11/mysqld.1/data/relay-log.info'.
2023-09-20 14:13:06 1093 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('')
2023-09-20 14:13:07 1096 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 329), using_gtid(1), gtid('')
2023-09-20 14:13:07 1097 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('')
2023-09-20 14:13:07 1097 [Warning] Aborted connection 1097 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets)
2023-09-20 14:13:07 1098 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 611), using_gtid(1), gtid('0-1-2')
2023-09-20 14:13:08 1099 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1029), using_gtid(1), gtid('0-1-3')
2023-09-20 14:13:08 1099 [Warning] Aborted connection 1099 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets)
2023-09-20 14:13:08 1100 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1238), using_gtid(1), gtid('0-1-5')
2023-09-20 14:13:09 1101 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1865), using_gtid(1), gtid('0-1-7')
2023-09-20 14:13:09 1101 [Warning] Aborted connection 1101 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets)
2023-09-20 14:13:09 1102 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1865), using_gtid(1), gtid('0-1-9')
2023-09-20 14:13:09 1103 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 2701), using_gtid(1), gtid('1-1-2,0-1-10')
2023-09-20 14:13:09 1103 [Warning] Aborted connection 1103 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets)
2023-09-20 14:13:10 1104 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 2910), using_gtid(1), gtid('1-1-3,0-1-11')
2023-09-20 14:13:10 1105 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 3642), using_gtid(1), gtid('1-1-4,0-1-12')
2023-09-20 14:13:10 1106 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 4374), using_gtid(1), gtid('1-1-6,0-1-14')
----------SERVER LOG END-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
ERROR HY000: Could not parse GTID list
START SLAVE UNTIL SQL_BEFORE_GTIDS="0";
ERROR HY000: Could not parse GTID list
START SLAVE UNTIL SQL_BEFORE_GTIDS="0-1";
ERROR HY000: Could not parse GTID list
START SLAVE UNTIL SQL_BEFORE_GTIDS="0-1-";
ERROR HY000: Could not parse GTID list
START SLAVE UNTIL SQL_BEFORE_GTIDS="a-b-c";
ERROR HY000: Could not parse GTID list
#
# Cleanup test data
connection master;
DROP TABLE t1, t2;
connection slave;
include/rpl_gtid_until_before_after_gtids.inc
#
# Test Setup (SQL_AFTER_GTIDS)
# Clean primary and replica states
connection master;
connection slave;



- saving '/test/bb-11.3-MDEV-32184_MD190923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/11/log/rpl.rpl_gtid_until_before_after_gtids-innodb,mix/' to '/test/bb-11.3-MDEV-32184_MD190923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/log/rpl.rpl_gtid_until_before_after_gtids-innodb,mix/'

Retrying test rpl.rpl_gtid_until_before_after_gtids, attempt(2/99999)...

rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w4 [ 36 fail ]
Test ended at 2023-09-20 14:13:11

CURRENT_TEST: rpl.rpl_gtid_until_before_after_gtids


Server [mysqld.1 - pid: 891449, winpid: 891449, exit: 256] failed during test run
...

Roel Van de Paar added a comment - 2023-09-20 04:17 bnestere Thank you for your work on this. I am still getting errors on the new branch, however the output has changed. Firstly, here is a better testcase (true parallel): MTR_MEM= /dev/shm . /mysql-test-run --repeat=99999 --parallel=30 --mem --force --retry=99999 --retry-failure=99999 rpl_gtid_until_before_after_gtids{,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,} | tee mtr_output.txt We now get output like this: bb-11.3-MDEV-32184 f99f1a8d76aa0f9f561965247da147593ee2012b ... rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w4 [ 8 pass ] 9300 rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w29 [ 8 pass ] 9182 rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w23 [ 9 fail ] Test ended at 2023-09-20 14:02:54 CURRENT_TEST: rpl.rpl_gtid_until_before_after_gtids Server [mysqld.1 - pid: 343661, winpid: 343661, exit: 256] failed during test run Server log from this test: ----------SERVER LOG START----------- 2023-09-20 14:02:47 254 [Note] Deleted Master_info file '/dev/shm/var_auto_i67M/23/mysqld.1/data/master.info'. 2023-09-20 14:02:47 254 [Note] Deleted Master_info file '/dev/shm/var_auto_i67M/23/mysqld.1/data/relay-log.info'. 2023-09-20 14:02:48 256 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('') 2023-09-20 14:02:48 259 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 329), using_gtid(1), gtid('' ) 2023-09-20 14:02:48 260 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('') 2023-09-20 14:02:48 260 [Warning] Aborted connection 260 to db: 'unconnected' user: 'root' host: 'localhost' (Got an err or writing communication packets) 2023-09-20 14:02:49 261 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 611), using_gtid(1), gtid('0 -1-2') 2023-09-20 14:02:49 262 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1029), using_gtid(1), gtid('0-1-3') 2023-09-20 14:02:49 262 [Warning] Aborted connection 262 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets) 2023-09-20 14:02:50 263 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1238), using_gtid(1), gtid('0-1-5') 2023-09-20 14:02:50 264 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1865), using_gtid(1), gtid('0-1-7') 2023-09-20 14:02:50 264 [Warning] Aborted connection 264 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets) 2023-09-20 14:02:50 265 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1865), using_gtid(1), gtid('0-1-9') 2023-09-20 14:02:51 266 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 2701), using_gtid(1), gtid('1-1-2,0-1-10') 2023-09-20 14:02:51 266 [Warning] Aborted connection 266 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets) 2023-09-20 14:02:51 267 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 2910), using_gtid(1), gtid('1-1-3,0-1-11') 2023-09-20 14:02:51 268 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 3642), using_gtid(1), gtid('1-1-4,0-1-12') 2023-09-20 14:02:52 269 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 4374), using_gtid(1), gtid('1-1-6,0-1-14') 2023-09-20 14:02:52 270 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 4538), using_gtid(1), gtid('1-1-6,0-1-15') 2023-09-20 14:02:53 271 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('') 2023-09-20 14:02:53 271 [Warning] Aborted connection 271 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets) 2023-09-20 14:02:53 272 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 611), using_gtid(1), gtid('0-1-2') ----------SERVER LOG END------------- mysqltest failed but provided no output The result from queries just before the failure was: < snip > create table t1 (a int); create table t2 (a int); connection slave; # # Test Case 1 (SQL_AFTER_GTIDS): For a single-dimensional binlog state and a # STOP SLAVE UNTIL gtid position with one GTID, the replica should # execute events up until the GTID is encountered, finish replicating # that event group, and then stop connection slave; connection master; set session gtid_domain_id=0; INSERT INTO t1 VALUES (111); INSERT INTO t1 VALUES (112); INSERT INTO t1 VALUES (113); connection slave; START SLAVE UNTIL SQL_AFTER_GTIDS="0-1-4"; # Ensure the slave started # Clean replica state connection master; connection slave; - saving '/test/bb-11.3-MDEV-32184_MD190923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/23/log/rpl.rpl_gtid_until_before_after_gtids-innodb,mix/' to '/test/bb-11.3-MDEV-32184_MD190923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/log/rpl.rpl_gtid_until_before_after_gtids-innodb,mix/' Retrying test rpl.rpl_gtid_until_before_after_gtids, attempt(2/99999)... rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w20 [ 9 fail ] Test ended at 2023-09-20 14:02:54 CURRENT_TEST: rpl.rpl_gtid_until_before_after_gtids Server [mysqld.1 - pid: 343351, winpid: 343351, exit: 256] failed during test run Server log from this test: ----------SERVER LOG START----------- 2023-09-20 14:02:50 254 [Note] Deleted Master_info file '/dev/shm/var_auto_i67M/20/mysqld.1/data/master.info'. 2023-09-20 14:02:50 254 [Note] Deleted Master_info file '/dev/shm/var_auto_i67M/20/mysqld.1/data/relay-log.info'. 2023-09-20 14:02:51 256 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('') 2023-09-20 14:02:51 259 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 329), using_gtid(1), gtid('') 2023-09-20 14:02:52 260 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('') 2023-09-20 14:02:52 260 [Warning] Aborted connection 260 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets) 2023-09-20 14:02:52 261 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 611), using_gtid(1), gtid('0-1-2') 2023-09-20 14:02:52 262 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1029), using_gtid(1), gtid('0-1-3') 2023-09-20 14:02:53 262 [Warning] Aborted connection 262 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets) 2023-09-20 14:02:53 263 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1238), using_gtid(1), gtid('0-1-5') 2023-09-20 14:02:53 264 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1865), using_gtid(1), gtid('0-1-7') 2023-09-20 14:02:53 264 [Warning] Aborted connection 264 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets) ----------SERVER LOG END------------- mysqltest failed but provided no output The result from queries just before the failure was: < snip > # # Test Case 3 (SQL_BEFORE_GTIDS): For a multi-dimensional binlog state and a # STOP SLAVE UNTIL gtid position with one GTID, the replica should # execute events from all domains (including unspecified ones) until the # provided GTID is encountered, and immediately stop connection slave; connection master; set session gtid_domain_id=0; INSERT INTO t1 VALUES (106); set session gtid_domain_id=1; INSERT INTO t2 VALUES (200); INSERT INTO t2 VALUES (201); set session gtid_domain_id=0; INSERT INTO t1 VALUES (107); set session gtid_domain_id=1; INSERT INTO t2 VALUES (202); set session gtid_domain_id=0; connection slave; START SLAVE UNTIL SQL_BEFORE_GTIDS="0-1-11"; # Ensure the slave started ... This was a debug build of bb-11.3- MDEV-32184 . The above failed in 8 passes. Retesting failed after 35 passes, but in another area: bb-11.3-MDEV-32184 f99f1a8d76aa0f9f561965247da147593ee2012b ... rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w7 [ 35 pass ] 7367 rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w16 [ 35 pass ] 8545 rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w11 [ 36 fail ] Test ended at 2023-09-20 14:13:11 CURRENT_TEST: rpl.rpl_gtid_until_before_after_gtids Server [mysqld.1 - pid: 891354, winpid: 891354, exit: 256] failed during test run Server log from this test: ----------SERVER LOG START----------- 2023-09-20 14:13:06 1091 [Note] Deleted Master_info file '/dev/shm/var_auto_qVTY/11/mysqld.1/data/master.info'. 2023-09-20 14:13:06 1091 [Note] Deleted Master_info file '/dev/shm/var_auto_qVTY/11/mysqld.1/data/relay-log.info'. 2023-09-20 14:13:06 1093 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('') 2023-09-20 14:13:07 1096 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 329), using_gtid(1), gtid('') 2023-09-20 14:13:07 1097 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('') 2023-09-20 14:13:07 1097 [Warning] Aborted connection 1097 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets) 2023-09-20 14:13:07 1098 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 611), using_gtid(1), gtid('0-1-2') 2023-09-20 14:13:08 1099 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1029), using_gtid(1), gtid('0-1-3') 2023-09-20 14:13:08 1099 [Warning] Aborted connection 1099 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets) 2023-09-20 14:13:08 1100 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1238), using_gtid(1), gtid('0-1-5') 2023-09-20 14:13:09 1101 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1865), using_gtid(1), gtid('0-1-7') 2023-09-20 14:13:09 1101 [Warning] Aborted connection 1101 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets) 2023-09-20 14:13:09 1102 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 1865), using_gtid(1), gtid('0-1-9') 2023-09-20 14:13:09 1103 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 2701), using_gtid(1), gtid('1-1-2,0-1-10') 2023-09-20 14:13:09 1103 [Warning] Aborted connection 1103 to db: 'unconnected' user: 'root' host: 'localhost' (Got an error writing communication packets) 2023-09-20 14:13:10 1104 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 2910), using_gtid(1), gtid('1-1-3,0-1-11') 2023-09-20 14:13:10 1105 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 3642), using_gtid(1), gtid('1-1-4,0-1-12') 2023-09-20 14:13:10 1106 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 4374), using_gtid(1), gtid('1-1-6,0-1-14') ----------SERVER LOG END------------- mysqltest failed but provided no output The result from queries just before the failure was: < snip > ERROR HY000: Could not parse GTID list START SLAVE UNTIL SQL_BEFORE_GTIDS="0"; ERROR HY000: Could not parse GTID list START SLAVE UNTIL SQL_BEFORE_GTIDS="0-1"; ERROR HY000: Could not parse GTID list START SLAVE UNTIL SQL_BEFORE_GTIDS="0-1-"; ERROR HY000: Could not parse GTID list START SLAVE UNTIL SQL_BEFORE_GTIDS="a-b-c"; ERROR HY000: Could not parse GTID list # # Cleanup test data connection master; DROP TABLE t1, t2; connection slave; include/rpl_gtid_until_before_after_gtids.inc # # Test Setup (SQL_AFTER_GTIDS) # Clean primary and replica states connection master; connection slave; - saving '/test/bb-11.3-MDEV-32184_MD190923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/11/log/rpl.rpl_gtid_until_before_after_gtids-innodb,mix/' to '/test/bb-11.3-MDEV-32184_MD190923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/log/rpl.rpl_gtid_until_before_after_gtids-innodb,mix/' Retrying test rpl.rpl_gtid_until_before_after_gtids, attempt(2/99999)... rpl.rpl_gtid_until_before_after_gtids 'innodb,mix' w4 [ 36 fail ] Test ended at 2023-09-20 14:13:11 CURRENT_TEST: rpl.rpl_gtid_until_before_after_gtids Server [mysqld.1 - pid: 891449, winpid: 891449, exit: 256] failed during test run ...

Roel Van de Paar added a comment - 2023-10-05 04:44 - edited

bnestere Provided an updated patch branch bb-11.3-MDEV-32184 with thanks. Retesting that one on the server which showed the previous random issues. Reproduction attempts on another instance did not produce any failures.

Roel Van de Paar added a comment - 2023-10-05 04:44 - edited bnestere Provided an updated patch branch bb-11.3-MDEV- 32184 with thanks. Retesting that one on the server which showed the previous random issues. Reproduction attempts on another instance did not produce any failures.

Roel Van de Paar added a comment - 2023-10-14 05:38

The random failures seem to have been the result of a monitoring script issue. However, the final patch updates from Brandon will remain in place. Closing as fixed.

Roel Van de Paar added a comment - 2023-10-14 05:38 The random failures seem to have been the result of a monitoring script issue. However, the final patch updates from Brandon will remain in place. Closing as fixed.

Roel Van de Paar added a comment - 2023-10-18 04:26

In the lastest test branch (bb-11.3-~~MDEV-27247~~) at revision 3ef2c8009b2f6147d3861cc8003cda1ecc9b6747, the test looks to be very stable.

Roel Van de Paar added a comment - 2023-10-18 04:26 In the lastest test branch (bb-11.3- MDEV-27247 ) at revision 3ef2c8009b2f6147d3861cc8003cda1ecc9b6747, the test looks to be very stable.

MariaDB Server

rpl.rpl_gtid_until_before_after_gtids regularly times out

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration