[MDEV-11814] Refuse innodb_read_only startup if crash recovery is needed Created: 2017-01-16  Updated: 2018-02-05  Resolved: 2017-01-26

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.0, 10.1, 10.2
Fix Version/s: 10.0.30, 10.1.22, 10.2.4

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

Issue Links:
Relates
relates to MDEV-12700 Allow innodb_read_only startup withou... Closed
relates to MDEV-15202 innodb.log_file_size failed in buildb... Closed
Sprint: 10.2.4-1, 10.2.4-2

 Description   

I am starting 10.1 server (7e3f3deb41a87, but it was happening with previous builds as well) on a datadir produced by a relatively old 10.0 server (tried 10.0.10 and 10.0.13). The old server was fed some test flow, then normally restarted, then killed.

When the 10.1 server is started on this datadir in innodb-read-only mode, it notices that crash recovery is needed, but does not refuse to start up as it would usually do; instead, it says that recovery would be skipped, proceeds, and later produces an error message.

2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Initializing buffer pool, size = 128.0M
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Completed initialization of buffer pool
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 0 name ./ibdata1 key_id 1 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 4294967280 name ./ib_logfile0 key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 4294967281 name arch_log_space key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-01-16 15:52:51 139938701260672 [Warning] InnoDB: Recovery skipped, --innodb-read-only set!
 
2017-01-16 15:52:51 139938701260672 [ERROR] InnoDB: We scanned the log up to 0. A checkpoint was at 4239494 and the maximum LSN on a database page was 0. It is possible that the database is now corrupt!
 
2017-01-16 15:52:51 7f4604943780 InnoDB: Error: page 5 log sequence number 4239504
 
InnoDB: is in the future! Current system log sequence number 4239494.
 
InnoDB: Your database may be corrupt or you may have copied the InnoDB
 
InnoDB: tablespace but not the InnoDB log files. See
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
 
InnoDB: for more information.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 3 name mysql/gtid_slave_pos key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 2 name mysql/innodb_index_stats key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 1 name mysql/innodb_table_stats key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 15 name test/oltp1 key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 16 name test/oltp2 key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 17 name test/oltp3 key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 18 name test/oltp4 key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 6 name test/t1 key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 7 name test/t2 key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 8 name test/t3 key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 9 name test/t4 key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 10 name test/t5 key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 11 name test/t6 key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 12 name test/t7 key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 13 name test/t8 key_id 0 encryption 0.
 
2017-01-16 15:52:51 139938701260672 [Note] InnoDB: Created tablespace for space 14 name test/t9 key_id 0 encryption 0.
 
2017-01-16 15:52:52 139938701260672 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.34-79.1 started; log sequence number 4239494
 
2017-01-16 15:52:52 139938701260672 [Note] Plugin 'FEEDBACK' is disabled.
 
2017-01-16 15:52:53 139938701260672 [Note] Server socket created on IP: '::'.
 
2017-01-16 15:52:53 7f46048f0b00 InnoDB: Error: Column last_update in table "mysql"."innodb_table_stats" is INT UNSIGNED NOT NULL but should be BINARY(4) NOT NULL (type mismatch).
 
2017-01-16 15:52:53 7f46048f0b00 InnoDB: Error: Fetch of persistent statistics requested for table "mysql"."gtid_slave_pos" but the required system tables mysql.innodb_table_stats and mysql.innodb_index_stats are not present or have unexpected structure. Using transient stats instead.
 
2017-01-16 15:52:53 139938700921600 [Note] InnoDB: Read page 0 from tablespace for space 3 name mysql/gtid_slave_pos key_id 0 encryption 0 handle 32.
 
2017-01-16 15:52:53 139938701260672 [Note] /data/bld/10.1/bin/mysqld: ready for connections.
 
Version: '10.1.21-MariaDB-debug'  socket: '/data/bld/10.1/data/tmp/mysql.sock'  port: 3306  Source distribution

If the same server is started on the same datadir in a non-read-only-mode, it performs the recovery and starts without the error:

2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Initializing buffer pool, size = 128.0M
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Completed initialization of buffer pool
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 0 name ./ibdata1 key_id 1 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 4294967280 name ./ib_logfile0 key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 4294967281 name arch_log_space key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Log scan progressed past the checkpoint lsn 4239494
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Database was not shutdown normally!
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Starting crash recovery.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Reading tablespace information from the .ibd files...
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 6 name test/t1 key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 10 name test/t5 key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 9 name test/t4 key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 13 name test/t8 key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 7 name test/t2 key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 17 name test/oltp3 key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 16 name test/oltp2 key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 14 name test/t9 key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 11 name test/t6 key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 12 name test/t7 key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 18 name test/oltp4 key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 15 name test/oltp1 key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 8 name test/t3 key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 2 name mysql/innodb_index_stats key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 3 name mysql/gtid_slave_pos key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Created tablespace for space 1 name mysql/innodb_table_stats key_id 0 encryption 0.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Restoring possible half-written data pages 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: from the doublewrite buffer...
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 16 name test/oltp2 key_id 0 encryption 0 handle 13.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 17 name test/oltp3 key_id 0 encryption 0 handle 14.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 18 name test/oltp4 key_id 0 encryption 0 handle 15.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 14 name test/t9 key_id 0 encryption 0 handle 16.
 
2017-01-16 15:57:40 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 15 name test/oltp1 key_id 0 encryption 0 handle 17.
 
InnoDB: Doing recovery: scanned up to log sequence number 4239504
 
2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 3 name mysql/gtid_slave_pos key_id 0 encryption 0 handle 18.
 
2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 2 name mysql/innodb_index_stats key_id 0 encryption 0 handle 20.
 
2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 1 name mysql/innodb_table_stats key_id 0 encryption 0 handle 21.
 
2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 6 name test/t1 key_id 0 encryption 0 handle 22.
 
2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 7 name test/t2 key_id 0 encryption 0 handle 23.
 
2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 8 name test/t3 key_id 0 encryption 0 handle 24.
 
2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 9 name test/t4 key_id 0 encryption 0 handle 25.
 
2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 10 name test/t5 key_id 0 encryption 0 handle 26.
 
2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 11 name test/t6 key_id 0 encryption 0 handle 27.
 
2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 12 name test/t7 key_id 0 encryption 0 handle 28.
 
2017-01-16 15:57:41 140552159930240 [Note] InnoDB: Read page 0 from tablespace for space 13 name test/t8 key_id 0 encryption 0 handle 29.
 
2017-01-16 15:57:42 140552159930240 [Note] InnoDB: 128 rollback segment(s) are active.
 
2017-01-16 15:57:42 140552159930240 [Note] InnoDB: Waiting for purge to start
 
2017-01-16 15:57:42 140552159930240 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.34-79.1 started; log sequence number 4239504
 
2017-01-16 15:57:43 140551395473152 [Note] InnoDB: Dumping buffer pool(s) not yet started



 Comments   
Comment by Marko Mäkelä [ 2017-01-26 ]

Sometimes the startup is prevented by another check, checking the redo log checkpoint LSN against the FIL_PAGE_FILE_FLUSH_LSN in the first page of each InnoDB system tablespace file. When I tested 10.0, that check seemed to be effective more often in innodb_plugin than xtradb. It seems to me that that mismatch can only be triggered if there was a log checkpoint since the last shutdown. And that is definitely not the case if the server is killed soon enough after startup.

This problem exists in MySQL as well, starting with the first 5.6 version that introduced the parameter innodb_read_only.

Comment by Marko Mäkelä [ 2017-01-26 ]

http://lists.askmonty.org/pipermail/commits/2017-January/010531.html

Comment by Jan Lindström (Inactive) [ 2017-01-26 ]

ok to push.

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