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

[4 Mar 2017 13:53] zhai weixiang
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
[4 Mar 2017 13:56] zhai weixiang
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.

[6 Mar 2017 5:26] Umesh Shastry
Hello Zhai,

Thank you for the report and contribution.

Thanks,
Umesh
[14 Mar 2017 9:16] Nico Razon
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
[14 Mar 2017 9:59] zhai weixiang
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.
[7 Nov 2018 13:01] Alexander S
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?