[MDEV-18224] MTR's internal check of the test case 'innodb.recovery_shutdown' failed due to extra #sql-ib*.ibd files Created: 2019-01-14  Updated: 2019-03-22  Resolved: 2019-01-14

Status: Closed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 10.3, 10.4
Fix Version/s: 10.4.2, 10.2.23, 10.3.13

Type: Bug Priority: Major
Reporter: Marko Mäkelä Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-14705 systemd: EXTEND_TIMEOUT_USEC= to avoi... Closed

 Description   

The test innodb.recovery_shutdown often fails like this:

10.3 82490a97dbbe1dfdf88ed6b9fee8974cf58c63e3

innodb.recovery_shutdown 'innodb'        [ pass ]   5680
 
MTR's internal check of the test case 'innodb.recovery_shutdown' failed.
This means that the test case does not preserve the state that existed
before the test case was executed.  Most likely the test case did not
do a proper clean-up. It could also be caused by the previous test run
by this thread, if the server wasn't restarted.
This is the diff of the states of the servers before and after the
test case was executed:
mysqltest: Logging to '/dev/shm/10.3/mysql-test/var/tmp/check-mysqld_1.log'.
mysqltest: Results saved in '/dev/shm/10.3/mysql-test/var/tmp/check-mysqld_1.result'.
mysqltest: Connecting to server localhost:16000 (socket /dev/shm/10.3/mysql-test/var/tmp/mysqld.1.sock) as 'root', connection 'default', attempt 0 ...
mysqltest: ... Connected.
mysqltest: Start processing test commands from './include/check-testcase.test' ...
mysqltest: ... Done processing test commands.
--- /dev/shm/10.3/mysql-test/var/tmp/check-mysqld_1.result	2019-01-14 09:00:35.439659687 +0200
+++ /dev/shm/10.3/mysql-test/var/tmp/check-mysqld_1.reject	2019-01-14 09:00:41.279817227 +0200
@@ -1059,3 +1059,4 @@
 partition	1.0	DISABLED	STORAGE ENGINE	100313.0	NULL	NULL	Mikael Ronstrom, MySQL AB	Partition Storage Engine Helper	GPL	OFF	Stable	1.0
 VARIABLE_NAME	VARIABLE_VALUE
 DEBUG_SYNC	ON - current signal: ''
+#sql-ib28.ibd

The reason would be visible in the server error log:

Version: '10.3.13-MariaDB-debug-log'  socket: '/dev/shm/10.3/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
2019-01-14  9:00:40 0 [Note] InnoDB: Rolled back recovered transaction 49
2019-01-14  9:00:41 8 [Note] InnoDB: Deferring DROP TABLE `test`.`t1`; renaming to test/#sql-ib28
2019-01-14  9:00:41 0 [Note] /dev/shm/10.3/sql/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown

It is a mystery why this only started failing recently. Nothing has changed since this fix of MDEV-14705: Do not rollback on InnoDB shutdown
and there has been no relevant change to mysql-test/include/check-testcase.test since this adjustment.
That is, only a shutdown with innodb_fast_shutdown=0 would wait for the rollback of recovered transactions to complete.
With this simple fix, the test will stop failing, because no locks would be held by recovered not-yet-rolled-back transactions when the DROP TABLE is executing:

diff --git a/mysql-test/suite/innodb/t/recovery_shutdown.test b/mysql-test/suite/innodb/t/recovery_shutdown.test
index d796189c724..9b4a5f337d4 100644
--- a/mysql-test/suite/innodb/t/recovery_shutdown.test
+++ b/mysql-test/suite/innodb/t/recovery_shutdown.test
@@ -51,6 +51,10 @@ FLUSH TABLES;
 --let $shutdown_timeout=60
 --source include/restart_mysqld.inc
 
+--disable_query_log
+SET GLOBAL innodb_fast_shutdown=0;
+--source include/restart_mysqld.inc
+
 --disable_query_log
 let $c = $trx;
 while ($c)


Generated at Thu Feb 08 08:42:26 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.