[MDEV-30676] rpl.parallel_backup* tests sometimes fail with Result length mismatch - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.5, 10.6, 10.8(EOL), 10.9(EOL), 10.10(EOL), 10.11, 11.0(EOL), 11.1(EOL)
Fix Version/s: 10.5.25, 10.11.8, 10.6.18, 11.0.6, 11.1.5, 11.2.4
Component/s: Replication, Tests
Labels:
None

Description

https://buildbot.mariadb.org/#/builders/236/builds/8645

10.6 67a6ad0a4
rpl.parallel_backup_lsu_off 'innodb,mix' w14 [ fail ]
Test ended at 2023-02-16 09:31:38

CURRENT_TEST: rpl.parallel_backup_lsu_off
--- /home/buildbot/amd64-ubuntu-2004-fulltest/build/mysql-test/suite/rpl/r/parallel_backup_lsu_off.result 2023-02-16 08:50:33.000000000 +0000
+++ /home/buildbot/amd64-ubuntu-2004-fulltest/build/mysql-test/suite/rpl/r/parallel_backup_lsu_off.reject 2023-02-16 09:31:37.703046027 +0000
@@ -187,6 +187,18 @@
BACKUP STAGE START;
BACKUP STAGE BLOCK_COMMIT;
connection aux_slave;
+Timeout in wait_condition.inc for SELECT COUNT(*) = 0 FROM information_schema.processlist WHERE state = "Waiting for prior transaction to commit"
+Id User Host db Command Time State Info Progress
+5 root localhost:56620 test Sleep 36 NULL 0.000
+6 root localhost:56626 test Sleep 37 NULL 0.000
+9 root localhost:56628 test Sleep 32 NULL 0.000
+10 root localhost:56636 test Sleep 36 NULL 0.000
+11 root localhost:56640 test Execute 0 starting show full processlist 0.000
+16 root localhost:56656 test Sleep 32 NULL 0.000
+33 system user NULL Slave_IO 32 Waiting for master to send event NULL 0.000
+35 system user NULL Slave_worker 32 Waiting for backup lock NULL 0.000
+36 system user test Slave_worker 32 Waiting for prior transaction to commit XA COMMIT X'31',X'',1 0.000
+34 system user NULL Slave_SQL 32 Slave has read all relay log; waiting for more updates NULL 0.000
ROLLBACK;
connection backup_slave;
BACKUP STAGE END;

mysqltest: Result length mismatch

Tests affected
rpl.parallel_backup_lsu_off
rpl.parallel_backup
rpl.parallel_backup_slave_binlog_off

Seems to mostly happen on s390x.

Attachments

Issue Links

is part of

MDEV-33073 always green buildbot

Stalled

Activity

Ascending order - Click to sort in descending order

Angelique Sklavounos (Inactive) added a comment - 2023-02-17 22:00

Output can vary:
https://buildbot.mariadb.org/#/builders/192/builds/16121

rpl.parallel_backup 'innodb,mix'         w29 [ fail ]

        Test ended at 2023-01-31 14:55:24

CURRENT_TEST: rpl.parallel_backup

--- /buildbot/amd64-ubuntu-1804-valgrind/build/mysql-test/suite/rpl/r/parallel_backup.result	2023-01-31 14:43:00.000000000 +0000

+++ /buildbot/amd64-ubuntu-1804-valgrind/build/mysql-test/suite/rpl/r/parallel_backup.reject	2023-01-31 14:55:20.151212882 +0000

@@ -176,6 +176,15 @@

 SET @@global.slave_transaction_retries=0;

 include/start_slave.inc

 connection aux_slave;

+Timeout in wait_condition.inc for SELECT COUNT(*) = 1 FROM information_schema.processlist WHERE state = "Waiting for prior transaction to commit"

+Id	User	Host	db	Command	Time	State	Info	Progress

+5	root	localhost:37062	test	Sleep	62		NULL	0.000

+6	root	localhost:37070	test	Sleep	63		NULL	0.000

+9	root	localhost:37072	test	Sleep	41		NULL	0.000

+10	root	localhost:37080	test	Sleep	61		NULL	0.000

+11	root	localhost:43078	test	Query	0	starting	show full processlist	0.000

+16	root	localhost:43086	test	Sleep	46		NULL	0.000

+33	system user		NULL	Slave_IO	44	Waiting for master to send event	NULL	0.000

 # Xid '1' must be in the output:

 XA RECOVER;

 formatID	gtrid_length	bqual_length	data

@@ -185,6 +194,15 @@

 BACKUP STAGE BLOCK_COMMIT;

 connection aux_slave;

 ROLLBACK;

+Timeout in wait_condition.inc for SELECT COUNT(*) = 1 FROM information_schema.processlist WHERE state = "Waiting for backup lock"

+Id	User	Host	db	Command	Time	State	Info	Progress

+5	root	localhost:37062	test	Sleep	104		NULL	0.000

+6	root	localhost:37070	test	Sleep	105		NULL	0.000

+9	root	localhost:37072	test	Sleep	83		NULL	0.000

+10	root	localhost:37080	test	Sleep	103		NULL	0.000

+11	root	localhost:43078	test	Query	0	starting	show full processlist	0.000

+16	root	localhost:43086	test	Sleep	41		NULL	0.000

+33	system user		NULL	Slave_IO	85	Waiting for master to send event	NULL	0.000

 connection backup_slave;

 BACKUP STAGE END;

 connection slave;

mysqltest: Result length mismatch

Angelique Sklavounos (Inactive) added a comment - 2023-02-17 22:00 Output can vary: https://buildbot.mariadb.org/#/builders/192/builds/16121 rpl.parallel_backup 'innodb,mix' w29 [ fail ] Test ended at 2023-01-31 14:55:24 CURRENT_TEST: rpl.parallel_backup --- /buildbot/amd64-ubuntu-1804-valgrind/build/mysql-test/suite/rpl/r/parallel_backup.result 2023-01-31 14:43:00.000000000 +0000 +++ /buildbot/amd64-ubuntu-1804-valgrind/build/mysql-test/suite/rpl/r/parallel_backup.reject 2023-01-31 14:55:20.151212882 +0000 @@ -176,6 +176,15 @@ SET @@global.slave_transaction_retries=0; include/start_slave.inc connection aux_slave; +Timeout in wait_condition.inc for SELECT COUNT(*) = 1 FROM information_schema.processlist WHERE state = "Waiting for prior transaction to commit" +Id User Host db Command Time State Info Progress +5 root localhost:37062 test Sleep 62 NULL 0.000 +6 root localhost:37070 test Sleep 63 NULL 0.000 +9 root localhost:37072 test Sleep 41 NULL 0.000 +10 root localhost:37080 test Sleep 61 NULL 0.000 +11 root localhost:43078 test Query 0 starting show full processlist 0.000 +16 root localhost:43086 test Sleep 46 NULL 0.000 +33 system user NULL Slave_IO 44 Waiting for master to send event NULL 0.000 # Xid '1' must be in the output: XA RECOVER; formatID gtrid_length bqual_length data @@ -185,6 +194,15 @@ BACKUP STAGE BLOCK_COMMIT; connection aux_slave; ROLLBACK; +Timeout in wait_condition.inc for SELECT COUNT(*) = 1 FROM information_schema.processlist WHERE state = "Waiting for backup lock" +Id User Host db Command Time State Info Progress +5 root localhost:37062 test Sleep 104 NULL 0.000 +6 root localhost:37070 test Sleep 105 NULL 0.000 +9 root localhost:37072 test Sleep 83 NULL 0.000 +10 root localhost:37080 test Sleep 103 NULL 0.000 +11 root localhost:43078 test Query 0 starting show full processlist 0.000 +16 root localhost:43086 test Sleep 41 NULL 0.000 +33 system user NULL Slave_IO 85 Waiting for master to send event NULL 0.000 connection backup_slave; BACKUP STAGE END; connection slave; mysqltest: Result length mismatch

Otto Kekäläinen added a comment - 2023-10-09 18:18

Seen in https://launchpadlibrarian.net/691101423/buildlog_ubuntu-mantic-riscv64.mariadb_1%3A10.11.5-3~bpo23.10.1~1696830433.49186426d72+feature.re.enable.all.tests_BUILDING.txt.gz for MariaDB 10.11.5 on riscv64

rpl.parallel_backup_slave_binlog_off 'innodb,mix' w5 [ fail ]

        Test ended at 2023-10-09 11:21:39

CURRENT_TEST: rpl.parallel_backup_slave_binlog_off

--- /<<PKGBUILDDIR>>/mysql-test/suite/rpl/r/parallel_backup_slave_binlog_off.result	2023-08-11 06:35:40.000000000 +0000

+++ /<<PKGBUILDDIR>>/mysql-test/suite/rpl/r/parallel_backup_slave_binlog_off.reject	2023-10-09 11:21:35.273185963 +0000

@@ -145,6 +145,15 @@

 BACKUP STAGE BLOCK_COMMIT;

 connection aux_slave;

 ROLLBACK;

+Timeout in wait_condition.inc for SELECT COUNT(*) = 1 FROM information_schema.processlist WHERE state = "Waiting for backup lock"

+Id	User	Host	db	Command	Time	State	Info	Progress

+4	root	localhost:59878	test	Sleep	59		NULL	0.000

+5	root	localhost:59880	test	Sleep	61		NULL	0.000

+8	root	localhost:59882	test	Sleep	46		NULL	0.000

+9	root	localhost:59884	test	Sleep	59		NULL	0.000

+10	root	localhost:59886	test	Query	0	starting	show full processlist	0.000

+15	root	localhost:59888	test	Sleep	46		NULL	0.000

+24	system user		NULL	Slave_IO	47	Waiting for master to send event	NULL	0.000

 connection backup_slave;

 BACKUP STAGE END;

 connection slave;

mysqltest: Result length mismatch

 - saving '/<<PKGBUILDDIR>>/builddir/mysql-test/var/5/log/rpl.parallel_backup_slave_binlog_off-innodb,mix/' to '/<<PKGBUILDDIR>>/builddir/mysql-test/var/log/rpl.parallel_backup_slave_binlog_off-innodb,mix/'

Retrying test rpl.parallel_backup_slave_binlog_off, attempt(2/3)...

worker[5] > Restart  - not started

worker[5] > Restart  - not started

***Warnings generated in error logs during shutdown after running tests: rpl.parallel_backup_slave_binlog_off

2023-10-09 11:20:36 26 [Warning] Slave: Lock wait timeout exceeded; try restarting transaction Error_code: 1205

2023-10-09 11:20:36 26 [Warning] Slave: Deadlock found when trying to get lock; try restarting transaction Error_code: 1213

2023-10-09 11:20:36 27 [Warning] Slave: Commit failed due to failure of an earlier commit on which this one depends Error_code: 1964

2023-10-09 11:21:26 34 [Warning] Slave: Lock wait timeout exceeded; try restarting transaction Error_code: 1205

2023-10-09 11:21:26 34 [Warning] Slave: Deadlock found when trying to get lock; try restarting transaction Error_code: 1213

2023-10-09 11:21:27 35 [Warning] Slave: Commit failed due to failure of an earlier commit on which this one depends Error_code: 1964

It didn't repeat, seems like a sporadic issue.

Otto Kekäläinen added a comment - 2023-10-09 18:18 Seen in https://launchpadlibrarian.net/691101423/buildlog_ubuntu-mantic-riscv64.mariadb_1%3A10.11.5-3~bpo23.10.1~1696830433.49186426d72+feature.re.enable.all.tests_BUILDING.txt.gz for MariaDB 10.11.5 on riscv64 rpl.parallel_backup_slave_binlog_off 'innodb,mix' w5 [ fail ] Test ended at 2023-10-09 11:21:39 CURRENT_TEST: rpl.parallel_backup_slave_binlog_off --- /<<PKGBUILDDIR>>/mysql-test/suite/rpl/r/parallel_backup_slave_binlog_off.result 2023-08-11 06:35:40.000000000 +0000 +++ /<<PKGBUILDDIR>>/mysql-test/suite/rpl/r/parallel_backup_slave_binlog_off.reject 2023-10-09 11:21:35.273185963 +0000 @@ -145,6 +145,15 @@ BACKUP STAGE BLOCK_COMMIT; connection aux_slave; ROLLBACK; +Timeout in wait_condition.inc for SELECT COUNT(*) = 1 FROM information_schema.processlist WHERE state = "Waiting for backup lock" +Id User Host db Command Time State Info Progress +4 root localhost:59878 test Sleep 59 NULL 0.000 +5 root localhost:59880 test Sleep 61 NULL 0.000 +8 root localhost:59882 test Sleep 46 NULL 0.000 +9 root localhost:59884 test Sleep 59 NULL 0.000 +10 root localhost:59886 test Query 0 starting show full processlist 0.000 +15 root localhost:59888 test Sleep 46 NULL 0.000 +24 system user NULL Slave_IO 47 Waiting for master to send event NULL 0.000 connection backup_slave; BACKUP STAGE END; connection slave; mysqltest: Result length mismatch - saving '/<<PKGBUILDDIR>>/builddir/mysql-test/var/5/log/rpl.parallel_backup_slave_binlog_off-innodb,mix/' to '/<<PKGBUILDDIR>>/builddir/mysql-test/var/log/rpl.parallel_backup_slave_binlog_off-innodb,mix/' Retrying test rpl.parallel_backup_slave_binlog_off, attempt(2/3)... worker[5] > Restart - not started worker[5] > Restart - not started ***Warnings generated in error logs during shutdown after running tests: rpl.parallel_backup_slave_binlog_off 2023-10-09 11:20:36 26 [Warning] Slave: Lock wait timeout exceeded; try restarting transaction Error_code: 1205 2023-10-09 11:20:36 26 [Warning] Slave: Deadlock found when trying to get lock; try restarting transaction Error_code: 1213 2023-10-09 11:20:36 27 [Warning] Slave: Commit failed due to failure of an earlier commit on which this one depends Error_code: 1964 2023-10-09 11:21:26 34 [Warning] Slave: Lock wait timeout exceeded; try restarting transaction Error_code: 1205 2023-10-09 11:21:26 34 [Warning] Slave: Deadlock found when trying to get lock; try restarting transaction Error_code: 1213 2023-10-09 11:21:27 35 [Warning] Slave: Commit failed due to failure of an earlier commit on which this one depends Error_code: 1964 It didn't repeat, seems like a sporadic issue.

Brandon Nesterenko added a comment - 2024-01-22 13:42 - edited

Also can occur with Slave connection was killed (seen on Ubuntu 20.04)

rpl.parallel_backup 'innodb,mix'         w4 [ fail ]  Found warnings/errors in server log file!

        Test ended at 2024-01-22 13:24:46

line

2024-01-22 13:24:45 35 [Warning] Slave: Connection was killed Error_code: 1927

2024-01-22 13:24:45 35 [Warning] Slave: Connection was killed Error_code: 1927

^ Found warnings in /home/buildbot/amd64-ubuntu-2004/build/mysql-test/var/4/log/mysqld.2.err

Brandon Nesterenko added a comment - 2024-01-22 13:42 - edited Also can occur with Slave connection was killed (seen on Ubuntu 20.04) rpl.parallel_backup 'innodb,mix' w4 [ fail ] Found warnings/errors in server log file! Test ended at 2024-01-22 13:24:46 line 2024-01-22 13:24:45 35 [Warning] Slave: Connection was killed Error_code: 1927 2024-01-22 13:24:45 35 [Warning] Slave: Connection was killed Error_code: 1927 ^ Found warnings in /home/buildbot/amd64-ubuntu-2004/build/mysql-test/var/4/log/mysqld.2.err

Daniel Black added a comment - 2024-03-06 05:02

Did lazy bump from 30 seconds to 60 in https://github.com/MariaDB/server/pull/3106

Daniel Black added a comment - 2024-03-06 05:02 Did lazy bump from 30 seconds to 60 in https://github.com/MariaDB/server/pull/3106

Brandon Nesterenko added a comment - 2024-03-26 16:51 - edited

Thanks danblack! I left a suggestion on the PR.

Brandon Nesterenko added a comment - 2024-03-26 16:51 - edited Thanks danblack ! I left a suggestion on the PR.

Daniel Black added a comment - 2024-03-27 07:46

Thank you. Updated as suggested.

Lets see how it goes.

Daniel Black added a comment - 2024-03-27 07:46 Thank you. Updated as suggested. Lets see how it goes .

Daniel Black added a comment - 2024-04-01 23:38

Ok. Passing on builders it didn't previous. FreeBSD builder appears out to lunch.

Good to merge?

Daniel Black added a comment - 2024-04-01 23:38 Ok. Passing on builders it didn't previous. FreeBSD builder appears out to lunch. Good to merge?

Otto Kekäläinen added a comment - 4 days ago

I confirm this is passing now at e.g. https://launchpadlibrarian.net/786072298/buildlog_ubuntu-plucky-amd64.mariadb_1%3A11.8.1-2~bpo25.04.1~1743619672.b7bf6d3ee70+feature.extend.mtr.to.big_BUILDING.txt.gz

rpl.parallel_backup_slave_binlog_off 'mix' w3 [ pass ]  14356

Thus I am re-enabling this and many other tests I have re-tested now in https://salsa.debian.org/mariadb-team/mariadb-server/-/merge_requests/112

Otto Kekäläinen added a comment - 4 days ago I confirm this is passing now at e.g. https://launchpadlibrarian.net/786072298/buildlog_ubuntu-plucky-amd64.mariadb_1%3A11.8.1-2~bpo25.04.1~1743619672.b7bf6d3ee70+feature.extend.mtr.to.big_BUILDING.txt.gz rpl.parallel_backup_slave_binlog_off 'mix' w3 [ pass ] 14356 Thus I am re-enabling this and many other tests I have re-tested now in https://salsa.debian.org/mariadb-team/mariadb-server/-/merge_requests/112

People

Assignee:: Brandon Nesterenko

Reporter:: Angelique Sklavounos (Inactive)

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Dates

Created:: 2023-02-17 13:54

Updated:: 5 days ago 21:17

Resolved:: 2024-04-15 04:36

Git Integration

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

MariaDB Server