MySQL Bugs: #85307: The server refuses to restart if turn off innodb_log

Bug #85307	The server refuses to restart if turn off innodb_log_checksums
Submitted:	4 Mar 2017 13:53	Modified:	14 Mar 2017 9:59
Reporter:	zhai weixiang (OCA)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.7	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	Contribution

Description:
if innodb_log_checksums is turned off on fly, then make some data changes and kill the server. it will refuse to startup because the checksum validation fails.

Related error log:

2017-03-04T13:35:46.956050Z 0 [ERROR] InnoDB: Log block 2483 at lsn 1270784 has valid header, but checksum field contains 3735928559, should be 2104295489
2017-03-04T13:35:46.956096Z 0 [ERROR] InnoDB: Ignoring the redo log due to missing MLOG_CHECKPOINT between the checkpoint 1270828 and the end 1270784.
2017-03-04T13:35:46.956116Z 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
2017-03-04T13:35:47.256381Z 0 [ERROR] Plugin 'InnoDB' init function returned error.
2017-03-04T13:35:47.256399Z 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2017-03-04T13:35:47.256408Z 0 [ERROR] Failed to initialize plugins.
2017-03-04T13:35:47.256414Z 0 [ERROR] Aborting

How to repeat:
1. create a innodb table;
2. set global innodb_log_checksums= 0
3. insert something into the table and then kill the server immediately.
4. restart the server.

Suggested fix:
During crash recovery, the function log_block_checksum_is_ok is invoked to check if the log block is valid. but it only checks:
1. if innodb_log_checksums is turned off, always return true
2. else the calculated crc32 value should match the value stored in block header. 

But since we can change innodb_log_checksums on fly, it should also check if the stored checksum equals to LOG_NO_CHECKSUM_MAGIC

A simpe patch based on 5.7.17 (*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: checksum-fail.diff (application/octet-stream, text), 587 bytes.

Hello Zhai,

Thank you for the report and contribution.

Thanks,
Umesh

Hi,

i've got this issue on docker when one of my containers shutdown suddenly. can you please assist?

2017-03-14T09:11:07.744122Z 0 [Note] mysqld (mysqld 5.7.17) starting as process 1 ...
2017-03-14T09:11:07.771153Z 0 [Note] InnoDB: PUNCH HOLE support available
2017-03-14T09:11:07.771177Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2017-03-14T09:11:07.771180Z 0 [Note] InnoDB: Uses event mutexes
2017-03-14T09:11:07.771183Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2017-03-14T09:11:07.771185Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-03-14T09:11:07.771188Z 0 [Note] InnoDB: Using Linux native AIO
2017-03-14T09:11:07.771390Z 0 [Note] InnoDB: Number of pools: 1
2017-03-14T09:11:07.771484Z 0 [Note] InnoDB: Using CPU crc32 instructions
2017-03-14T09:11:07.773122Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2017-03-14T09:11:07.779132Z 0 [Note] InnoDB: Completed initialization of buffer pool
2017-03-14T09:11:07.781476Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2017-03-14T09:11:07.802409Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2017-03-14T09:11:07.816944Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 221455645196
2017-03-14T09:11:07.932078Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 221457847952
2017-03-14T09:11:07.933827Z 0 [ERROR] InnoDB: Ignoring the redo log due to missing MLOG_CHECKPOINT between the checkpoint 221455645196 and the end 221457847952.
2017-03-14T09:11:07.933859Z 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
2017-03-14T09:11:08.436002Z 0 [ERROR] Plugin 'InnoDB' init function returned error.
2017-03-14T09:11:08.436035Z 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2017-03-14T09:11:08.436041Z 0 [ERROR] Failed to initialize plugins.
2017-03-14T09:11:08.436043Z 0 [ERROR] Aborting
2017-03-14T09:11:08.436052Z 0 [Note] Binlog end
2017-03-14T09:11:08.436099Z 0 [Note] Shutting down plugin 'MyISAM'
2017-03-14T09:11:08.436118Z 0 [Note] Shutting down plugin 'CSV'
2017-03-14T09:11:08.436545Z 0 [Note] mysqld: Shutdown complete

Hi, Nico, 

You can turn off innodb_log_checksums via command line or set innodb_log_checksums = 0 in configure file. and then restart  the server to workaround this problem.

The proposed solution with innodb_log_checksums doesn't work, my local server is down, I am adding this option but the error is the same:

➜  mysql mysqld --datadir=/usr/local/var/mysql --defaults-filesss=/etc/my.cnf
2018-11-07T12:55:58.878480Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-11-07T12:55:58.878823Z 0 [Note] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled
2018-11-07T12:55:58.878915Z 0 [Note] mysqld (mysqld 5.7.24) starting as process 12334 ...
2018-11-07T12:55:58.883278Z 0 [Warning] Setting lower_case_table_names=2 because file system for /usr/local/var/mysql/ is case insensitive
2018-11-07T12:55:58.885284Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-11-07T12:55:58.885304Z 0 [Note] InnoDB: Uses event mutexes
2018-11-07T12:55:58.885310Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2018-11-07T12:55:58.885315Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2018-11-07T12:55:58.885766Z 0 [Note] InnoDB: Number of pools: 1
2018-11-07T12:55:58.885920Z 0 [Note] InnoDB: Using CPU crc32 instructions
2018-11-07T12:55:58.887831Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-11-07T12:55:58.903006Z 0 [Note] InnoDB: Completed initialization of buffer pool
2018-11-07T12:55:58.919879Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2018-11-07T12:55:58.920718Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 296078826124
2018-11-07T12:55:58.936663Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 296079027200
2018-11-07T12:55:58.936898Z 0 [ERROR] InnoDB: Ignoring the redo log due to missing MLOG_CHECKPOINT between the checkpoint 296078826124 and the end 296079027200.
2018-11-07T12:55:58.936927Z 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
2018-11-07T12:55:59.242340Z 0 [ERROR] Plugin 'InnoDB' init function returned error.
2018-11-07T12:55:59.242366Z 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2018-11-07T12:55:59.242375Z 0 [ERROR] Failed to initialize builtin plugins.
2018-11-07T12:55:59.242387Z 0 [ERROR] Aborting

2018-11-07T12:55:59.242402Z 0 [Note] Binlog end
2018-11-07T12:55:59.242520Z 0 [Note] Shutting down plugin 'CSV'
2018-11-07T12:55:59.242693Z 0 [Note] mysqld: Shutdown complete

How do I recover?