[MDEV-16273] innodb.alter_kill fails in buildbot with Unknown storage engine 'InnoDB' Created: 2018-05-23  Updated: 2018-10-10  Resolved: 2018-10-10

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Tests
Affects Version/s: 10.3
Fix Version/s: 10.3.11

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

Issue Links:
Duplicate
duplicates MDEV-12905 InnoDB occasionally skips the doublew... Closed
Problem/Incident
is caused by MDEV-12288 Reset DB_TRX_ID when the history is r... Closed
Relates
relates to MDEV-16954 gcol.gcol_rollback failed in buildbot... Closed

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-deb-stretch-ppc64le/builds/2273

innodb.alter_kill 'innodb'               w1 [ fail ]
 
        Test ended at 2018-05-22 23:06:36
 
 
 
CURRENT_TEST: innodb.alter_kill
 
mysqltest: At line 70: query 'SELECT COUNT(*) FROM bug16720368' failed with wrong errno 1286: 'Unknown storage engine 'InnoDB'', instead of 1932...
 
 
 
The result from queries just before the failure was:
 
< snip >
 
SET GLOBAL innodb_file_per_table=1;
 
CREATE TABLE bug16720368_1 (a INT PRIMARY KEY) ENGINE=InnoDB;
 
connect  con1,localhost,root;
 
CREATE TABLE bug16720368 (a INT PRIMARY KEY, b INT) ENGINE=InnoDB;
 
INSERT INTO bug16720368 (a) VALUES (1),(2),(3),(4),(5),(6),(7),(8);
 
connection default;
 
# Cleanly shutdown mysqld
 
disconnect con1;
 
# Corrupt FIL_PAGE_OFFSET in bug16720368.ibd,
 
# and update the checksum to the "don't care" value.
 
# Restart mysqld
 
# This will succeed after a clean shutdown, due to
 
# fil_open_single_table_tablespace(check_space_id=FALSE).
 
SELECT COUNT(*) FROM bug16720368;
 
COUNT(*)
 
8
 
INSERT INTO bug16720368_1 VALUES(1);
 
# The table is unaccessible, because after a crash we will
 
# validate the tablespace header.
 
SELECT COUNT(*) FROM bug16720368;



 Comments   
Comment by Marko Mäkelä [ 2018-05-28 ]

The server error log contains the following, which suggests that this is a duplicate of MDEV-12905 (the doublewrite buffer is not working properly):

2018-05-22 23:06:35 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1649895
 
2018-05-22 23:06:35 0 [ERROR] InnoDB: Header page contains inconsistent data in datafile: ./test/bug16720368.ibd, Space ID:6, Flags: 33. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
 
2018-05-22 23:06:35 0 [Note] InnoDB: Page size:1024. Pages to analyze:64
 
2018-05-22 23:06:35 0 [Note] InnoDB: VALID: space:6 page_no:0 page_size:1024
 
2018-05-22 23:06:35 0 [Note] InnoDB: Page size: 1024. Possible space_id count:1
 
2018-05-22 23:06:35 0 [Note] InnoDB: space_id:6, Number of pages matched: 1/1 (1024)
 
2018-05-22 23:06:35 0 [Note] InnoDB: Chosen space:6
 
2018-05-22 23:06:35 0 [ERROR] InnoDB: Corrupted page [page id: space=6, page number=0] of datafile './test/bug16720368.ibd' could not be found in the doublewrite buffer.
 
2018-05-22 23:06:35 0 [ERROR] InnoDB: Tablespace 6 was not found at ./test/bug16720368.ibd.
 
2018-05-22 23:06:35 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore this and to permanently lose all changes to the tablespace.
 
2018-05-22 23:06:35 0 [ERROR] InnoDB: Plugin initialization aborted with error Tablespace not found
 
2018-05-22 23:06:36 0 [Note] InnoDB: Starting shutdown...

Comment by Marko Mäkelä [ 2018-05-28 ]

thiru did great work with MDEV-15325; I hope this one (and MDEV-12905) can also be fixed soon.

Comment by Marko Mäkelä [ 2018-07-03 ]

I noticed a similar failure and dug up the reason from the server error log mysqld.1.err:

10.3 c3289d27eef39a47fed2ce1ff239013ed6870f39

 
2018-07-03 11:51:39 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1649563
 
2018-07-03 11:51:39 0 [ERROR] InnoDB: Header page contains inconsistent data in datafile: ./test/bug16720368.ibd, Space ID:6, Flags: 33. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
 
2018-07-03 11:51:39 0 [Note] InnoDB: Page size:1024. Pages to analyze:64
 
2018-07-03 11:51:39 0 [Note] InnoDB: VALID: space:6 page_no:0 page_size:1024
 
2018-07-03 11:51:39 0 [Note] InnoDB: Page size: 1024. Possible space_id count:1
 
2018-07-03 11:51:39 0 [Note] InnoDB: space_id:6, Number of pages matched: 1/1 (1024)
 
2018-07-03 11:51:39 0 [Note] InnoDB: Chosen space:6
 
2018-07-03 11:51:39 0 [ERROR] InnoDB: Corrupted page [page id: space=6, page number=0] of datafile './test/bug16720368.ibd' could not be found in the doublewrite buffer.
 
2018-07-03 11:51:39 0 [ERROR] InnoDB: Tablespace 6 was not found at ./test/bug16720368.ibd.
 
2018-07-03 11:51:39 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore this and to permanently lose all changes to the tablespace.
 
2018-07-03 11:51:39 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[2006] with error Tablespace not found
 
2018-07-03 11:51:40 0 [Note] InnoDB: Starting shutdown...

The failure in the mysql-test log looked exactly the same as in the Description:

CURRENT_TEST: innodb.alter_kill
 
mysqltest: At line 70: query 'SELECT COUNT(*) FROM bug16720368' failed with wrong errno 1286: 'Unknown storage engine 'InnoDB'', instead of 1932...

This may be a duplicate of MDEV-12905.

Comment by Marko Mäkelä [ 2018-10-10 ]

I believe that the test simply needs to be updated after MDEV-12288.

The test is shutting down InnoDB, corrupting a file, and finally restarting InnoDB. Before the shutdown, the test created the table and inserted some records. Before MDEV-12288, there would be no access to the table after server restart, but after MDEV-12288 we would reset the transaction identifier after the INSERT.

To make the test deterministic again, we must wait for purge to complete before the shutdown.

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