MySQL Bugs: #77654: After 5.6.15 innodb_force_recovery greater or equal than 4 is useless

Bug #77654	After 5.6.15 innodb_force_recovery greater or equal than 4 is useless
Submitted:	8 Jul 2015 10:55	Modified:	8 Jul 2015 11:31
Reporter:	Miguel Angel Nieto	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.6.27	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	regression

Description:
If you had a crash and need to start the database to dump the data, after the change done to innodb_force_recovery on 5.6.15 make it useless with values greater or equal than 4.

How to repeat:
Start an instance with latest MySQL 5.6.
Kill it with -9.
Start it with innodb_force_recovery=4
Try to start it and it will fail:

2015-07-08 10:25:25 315 [ERROR] InnoDB: Can't initiate database recovery, running in read-only-mode.
2015-07-08 10:25:25 315 [ERROR] Plugin 'InnoDB' init function returned error.
2015-07-08 10:25:25 315 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2015-07-08 10:25:25 315 [ERROR] Unknown/unsupported storage engine: InnoDB
2015-07-08 10:25:25 315 [ERROR] Aborting

Install a new instance with 5.6.14 and use the same config file and datadir.
Start it and it will work:

2015-07-08 10:45:47 654 [Note] InnoDB: !!! innodb_force_recovery is set to 4 !!!
2015-07-08 10:45:47 654 [Note] /usr/sbin/mysqld: ready for connections.

Hello Miguel,

Thank you for the report.

Thanks,
Umesh

// 5.6.10

rm -rf 77654
scripts/mysql_install_db --basedir=/export/umesh/server/binaries/mysql-5.6.10 --datadir=/export/umesh/server/binaries/mysql-5.6.10/77654
bin/mysqld --no-defaults --basedir=/export/umesh/server/binaries/mysql-5.6.10 --datadir=/export/umesh/server/binaries/mysql-5.6.10/77654 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/server/binaries/mysql-5.6.10/77654/log.err 2>&1 &

[umshastr@hod03]/export/umesh/server/binaries/mysql-5.6.10: ps aux|grep mysqld
umshastr  5488  2.1  0.0 648592 87880 pts/1    Sl   13:26   0:00 bin/mysqld --no-defaults --basedir=/export/umesh/server/binaries/mysql-5.6.10 --datadir=/export/umesh/server/binaries/mysql-5.6.10/77654 --core-file --socket=/tmp/mysql_ushastry.sock --port=15000 --log-error=/export/umesh/server/binaries/mysql-5.6.10/77654/log.err
umshastr  5513  0.0  0.0 112624   972 pts/1    S+   13:26   0:00 grep --color=auto mysqld
[umshastr@hod03]/export/umesh/server/binaries/mysql-5.6.10: kill -9 5488
[umshastr@hod03]/export/umesh/server/binaries/mysql-5.6.10:
[1]+  Killed                  bin/mysqld --no-defaults --basedir=/export/umesh/server/binaries/mysql-5.6.10 --datadir=/export/umesh/server/binaries/mysql-5.6.10/77654 --core-file --socket=/tmp/mysql_ushastry.sock --port=15000 --log-error=/export/umesh/server/binaries/mysql-5.6.10/77654/log.err 2>&1
[umshastr@hod03]/export/umesh/server/binaries/mysql-5.6.10:
[umshastr@hod03]/export/umesh/server/binaries/mysql-5.6.10: bin/mysqld --no-defaults --basedir=/export/umesh/server/binaries/mysql-5.6.10 --datadir=/export/umesh/server/binaries/mysql-5.6.10/77654 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/server/binaries/mysql-5.6.10/77654/log.err --innodb_force_recovery=4 2>&1 &
[1] 5516
[umshastr@hod03]/export/umesh/server/binaries/mysql-5.6.10: 2015-07-08 13:27:29 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).

[umshastr@hod03]/export/umesh/server/binaries/mysql-5.6.10: tail 77654/log.err
2015-07-08 13:27:29 5516 [Note] InnoDB: from the doublewrite buffer...
2015-07-08 13:27:29 5516 [Note] InnoDB: 1.2.10 started; log sequence number 1625997
2015-07-08 13:27:29 5516 [Note] InnoDB: !!! innodb_force_recovery is set to 4 !!!
2015-07-08 13:27:29 5516 [Note] Server hostname (bind-address): '*'; port: 15000
2015-07-08 13:27:29 5516 [Note] IPv6 is available.
2015-07-08 13:27:29 5516 [Note]   - '::' resolves to '::';
2015-07-08 13:27:29 5516 [Note] Server socket created on IP: '::'.
2015-07-08 13:27:29 5516 [Note] Event Scheduler: Loaded 0 events
2015-07-08 13:27:29 5516 [Note] bin/mysqld: ready for connections.
Version: '5.6.10'  socket: '/tmp/mysql_ushastry.sock'  port: 15000  MySQL Community Server (GPL)

##### 5.6.27

rm -rf 77654
scripts/mysql_install_db --basedir=/export/umesh/server/binaries/mysql-5.6.27 --datadir=/export/umesh/server/binaries/mysql-5.6.27/77654
bin/mysqld --no-defaults --basedir=/export/umesh/server/binaries/mysql-5.6.27 --datadir=/export/umesh/server/binaries/mysql-5.6.27/77654 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/server/binaries/mysql-5.6.27/77654/log.err 2>&1 &

kill -9 `pidof mysqld`

// restart with --innodb_force_recovery=4

scripts/mysql_install_db --basedir=/export/umesh/server/binaries/mysql-5.6.27 --datadir=/export/umesh/server/binaries/mysql-5.6.27/77654
bin/mysqld --no-defaults --basedir=/export/umesh/server/binaries/mysql-5.6.27 --datadir=/export/umesh/server/binaries/mysql-5.6.27/77654 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/server/binaries/mysql-5.6.27/77654/log.err --innodb_force_recovery=4 2>&1 &

Version: '5.6.27-enterprise-commercial-advanced'  socket: '/tmp/mysql_ushastry.sock'  port: 15000  MySQL Enterprise Server - Advanced Edition (Commercial)
2015-07-08 13:19:29 4676 [Note] Plugin 'FEDERATED' is disabled.
2015-07-08 13:19:29 4676 [Note] InnoDB: Started in read only mode
2015-07-08 13:19:29 4676 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-07-08 13:19:29 4676 [Note] InnoDB: The InnoDB memory heap is disabled
2015-07-08 13:19:29 4676 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-07-08 13:19:29 4676 [Note] InnoDB: Memory barrier is not used
2015-07-08 13:19:29 4676 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-07-08 13:19:29 4676 [Note] InnoDB: Using Linux native AIO
2015-07-08 13:19:29 4676 [Note] InnoDB: Using CPU crc32 instructions
2015-07-08 13:19:29 4676 [Note] InnoDB: Disabling background IO write threads.
2015-07-08 13:19:29 4676 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2015-07-08 13:19:29 4676 [Note] InnoDB: Completed initialization of buffer pool
2015-07-08 13:19:29 4676 [Note] InnoDB: Highest supported file format is Barracuda.
2015-07-08 13:19:29 4676 [Note] InnoDB: The log sequence numbers 1625987 and 1625987 in ibdata files do not match the log sequence number 1625997 in the ib_logfiles!
2015-07-08 13:19:29 4676 [ERROR] InnoDB: Can't initiate database recovery, running in read-only-mode.
2015-07-08 13:19:29 4676 [ERROR] Plugin 'InnoDB' init function returned error.
2015-07-08 13:19:29 4676 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2015-07-08 13:19:29 4676 [ERROR] Unknown/unsupported storage engine: InnoDB
2015-07-08 13:19:29 4676 [ERROR] Aborting

2015-07-08 13:19:29 4676 [Note] Binlog end