[MDEV-12306] The main.auth_rpl 'row' test fail in i386 Created: 2017-03-20  Updated: 2023-11-29  Resolved: 2023-11-29

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Tests
Affects Version/s: 10.1.22
Fix Version/s: N/A

Type: Bug Priority: Minor
Reporter: Ondřej Surý (Inactive) Assignee: Marko Mäkelä
Resolution: Cannot Reproduce Votes: 0
Labels: Debian


 Description   

The Debian unstable i386 fails with:

main.auth_rpl 'row'                      w3 [ fail ]  Found warnings/errors in server log file!
 
        Test ended at 2017-03-20 10:13:07
 
line
 
2017-03-20 10:13:06 f5940800 InnoDB: Error: page 5 log sequence number 1629826
 
^ Found warnings in /«PKGBUILDDIR»/builddir/mysql-test/var/3/log/mysqld.2.err
 
ok
 
 
 
 - saving '/«PKGBUILDDIR»/builddir/mysql-test/var/3/log/main.auth_rpl-row/' to '/«PKGBUILDDIR»/builddir/mysql-test/var/log/main.auth_rpl-row/'
 
 
 
Retrying test main.auth_rpl, attempt(2/3)...
 
[...]
 
main.auth_rpl 'row'                      w3 [ retry-pass ]    437
 
 
 
Retrying test main.auth_rpl, attempt(3/3)...
 
[...]
 
main.auth_rpl 'row'                      w3 [ retry-fail ]
 
        Test ended at 2017-03-20 10:18:13
 
 
 
CURRENT_TEST: main.auth_rpl
 
mysqltest: In included file "/«PKGBUILDDIR»/mysql-test/include/wait_for_slave_param.inc": 
included from /«PKGBUILDDIR»/mysql-test/include/wait_for_slave_io_to_start.inc at line 40:
 
included from /«PKGBUILDDIR»/mysql-test/include/wait_for_slave_to_start.inc at line 26:
 
included from /«PKGBUILDDIR»/mysql-test/include/start_slave.inc at line 35:
 
included from /«PKGBUILDDIR»/mysql-test/include/rpl_for_each_slave.inc at line 33:
 
included from /«PKGBUILDDIR»/mysql-test/include/rpl_start_slaves.inc at line 30:
 
included from /«PKGBUILDDIR»/mysql-test/include/rpl_init.inc at line 210:
 
included from /«PKGBUILDDIR»/mysql-test/include/master-slave.inc at line 38:
 
included from /«PKGBUILDDIR»/mysql-test/t/auth_rpl.test at line 4:
 
At line 119: Timeout in include/wait_for_slave_param.inc
 
 
 
The result from queries just before the failure was:
 
< snip >
 
15	root	localhost:42277	test	Query	0	init	SHOW PROCESSLIST	0.000
 
16	root	localhost:42278	test	Sleep	303		NULL	0.000
 
 
 
**** SHOW BINARY LOGS on server_1 ****
 
SHOW BINARY LOGS;
 
Log_name	File_size
 
master-bin.000001	314
 
 
 
**** SHOW BINLOG EVENTS on server_1 ****
 
binlog_name = 'master-bin.000001'
 
SHOW BINLOG EVENTS IN 'master-bin.000001';
 
Log_name	Pos	Event_type	Server_id	End_log_pos	Info
 
master-bin.000001	4	Format_desc	1	249	Server ver: 10.1.22-MariaDB-, Binlog ver: 4
 
master-bin.000001	249	Gtid_list	1	274	[]
 
master-bin.000001	274	Binlog_checkpoint	1	314	master-bin.000001
 
 
 
**** 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
 
 
 
More results from queries before failure can be found in /«PKGBUILDDIR»/builddir/mysql-test/var/3/log/auth_rpl.log
 
 
 
 - saving '/«PKGBUILDDIR»/builddir/mysql-test/var/3/log/main.auth_rpl-row/' to '/«PKGBUILDDIR»/builddir/mysql-test/var/log/main.auth_rpl-row/'
 
--------------------------------------------------------------------------
 
The servers were restarted 1032 times
 
Spent 3868.127 of 1987 seconds executing testcases
 
 
 
Completed: Failed 1/4450 tests, 99.98% were successful.
 
 
 
Failing test(s): main.auth_rpl

A full build log can be found here: https://buildd.debian.org/status/fetch.php?pkg=mariadb-10.1&arch=i386&ver=10.1.22-1&stamp=1490005100&raw=0

 Comments   
Comment by Ondřej Surý (Inactive) [ 2017-03-20 ]

Strangely enough, I can't reproduce the issue when building the package locally within i386 chroot (pbuilder). I could ask Debian buildd admins for triggering the build again to see if the issue persists on the buildd machine.

Comment by Ondřej Surý (Inactive) [ 2017-03-22 ]

And the second rebuild on the Debian i386 infrastructure went well. I would however appreciate if there's some insight why this might have failed, but I understand that a bug not reproducible is not very useful.

Comment by Marko Mäkelä [ 2023-11-29 ]

A relevant part of the error message is missing in the output, because InnoDB used to split error messages into several lines. I believe that the message wanted to say that the log sequence number is in the future. The explanation could be that replication tests used to (or maybe still do) kill the replica servers (see the mysqld.2.err below) instead of waiting for a graceful shutdown. Maybe the log checkpoints were seriously lagging behind. Ultimately, this could have been fixed by MDEV-28415 (2022-04-27).

The latest such failure for a main branch is the following:

10.2 99945d77d748470fbb3939be5f7d0e36d24d8097

 
main.auth_rpl 'row'                      w28 [ fail ]  Found warnings/errors in server log file!
 
        Test ended at 2021-03-30 23:59:17
 
line
 
2021-03-30 23:59:15 140603632383936 [ERROR] InnoDB: Page [page id: space=0, page number=5] log sequence number 1628272 is in the future! Current system log sequence number 1628262.
 
2021-03-30 23:59:15 140603632383936 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
 
^ Found warnings in /buildbot/amd64-ubuntu-1804-clang6/build/mysql-test/var/28/log/mysqld.2.err

The latest failure for a non-main branch was 2021-05-25 23 on a 10.2 based branch.

Generated at Thu Feb 08 07:56:41 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.