断电导致MySQL数据库无法启动

一、情况描述

因为断电，MySQL数据库无法启动。报错如下：

2022-07-25T03:18:39.998156938Z 2022-07-25T03:18:39.998047Z 0 [ERROR] InnoDB: Ignoring the redo log due to missing MLOG_CHECKPOINT between the chec                 kpoint 10560650382 and the end 10560650240. 
2022-07-25T03:18:39.998162317Z 2022-07-25T03:18:39.998077Z 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error 
2022-07-25T03:18:40.602294432Z 2022-07-25T03:18:40.602077Z 0 [ERROR] Plugin 'InnoDB' init function returned error. 
2022-07-25T03:18:40.602316541Z 2022-07-25T03:18:40.602107Z 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. 
2022-07-25T03:18:40.602318529Z 2022-07-25T03:18:40.602115Z 0 [ERROR] Failed to initialize builtin plugins. 
2022-07-25T03:18:40.602320373Z 2022-07-25T03:18:40.602117Z 0 [ERROR] Aborting

2022-07-25 06:39:54+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.34-1debian10 started.
2022-07-25T06:39:54.976401Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2022-07-25T06:39:54.977381Z 0 [Note] mysqld (mysqld 5.7.34) starting as process 1 ...
2022-07-25T06:39:54.979176Z 0 [Note] InnoDB: PUNCH HOLE support available
2022-07-25T06:39:54.979197Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2022-07-25T06:39:54.979201Z 0 [Note] InnoDB: Uses event mutexes
2022-07-25T06:39:54.979203Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2022-07-25T06:39:54.979206Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2022-07-25T06:39:54.979208Z 0 [Note] InnoDB: Using Linux native AIO
2022-07-25T06:39:54.979426Z 0 [Note] InnoDB: Number of pools: 1
2022-07-25T06:39:54.979526Z 0 [Note] InnoDB: Using CPU crc32 instructions
2022-07-25T06:39:54.980794Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2022-07-25T06:39:54.985079Z 0 [Note] InnoDB: Completed initialization of buffer pool
2022-07-25T06:39:54.986435Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2022-07-25T06:39:54.998211Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2022-07-25T06:39:54.999041Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 6862152204
2022-07-25T06:39:54.999060Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 6862152213
2022-07-25T06:39:54.999064Z 0 [Note] InnoDB: Database was not shutdown normally!
2022-07-25T06:39:54.999066Z 0 [Note] InnoDB: Starting crash recovery.
2022-07-25T06:39:55.000798Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=7] log sequence number 10437217739 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.000821Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.000908Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=2] log sequence number 10559379158 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.000916Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.000943Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=11] log sequence number 10234442969 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.000953Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.000989Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=5] log sequence number 10560701216 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.000992Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.001002Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=6] log sequence number 10560721737 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.001004Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.001012Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=269] log sequence number 10560635345 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.001017Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.001029Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=319] log sequence number 10560604027 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.001031Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.001051Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=45] log sequence number 10560652720 is in the future! Current system log sequence number 6862152222.
。。。。。。。。。。。。。。
2022-07-25T06:39:55.006044Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.006067Z 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 0 row operations to undo
2022-07-25T06:39:55.006070Z 0 [Note] InnoDB: Trx id counter is 28929024
2022-07-25T06:39:55.106864Z 0 [Note] InnoDB: Cleaning up trx with id 28921967
2022-07-25T06:39:55.107014Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=10] log sequence number 8810837119 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.107021Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.107049Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=12] log sequence number 10234443193 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.107067Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.107142Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=275] log sequence number 10234443033 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.107158Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.107172Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=474] log sequence number 10234443033 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.107174Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.107233Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=475] log sequence number 10234443033 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.107238Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.107272Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=276] log sequence number 10234442662 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.107275Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.107282Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=472] log sequence number 10234442662 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.107284Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.108099Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=473] log sequence number 10234442662 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.108116Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.111555Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=385] log sequence number 10437220745 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.111581Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.115001Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=419] log sequence number 10234441666 is in the future! Current system log sequence number 6862152222.
2022-07-25T06:39:55.115018Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.119373Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=306] log sequence number 10234442969 is in the future! Current system log sequence number 6862152232.
2022-07-25T06:39:55.119393Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.119424Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=312] log sequence number 10234442969 is in the future! Current system log sequence number 6862152232.
2022-07-25T06:39:55.119426Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.119442Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=314] log sequence number 10437257184 is in the future! Current system log sequence number 6862152232.
2022-07-25T06:39:55.119444Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.119470Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=316] log sequence number 10437221909 is in the future! Current system log sequence number 6862152232.
2022-07-25T06:39:55.119479Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2022-07-25T06:39:55.121114Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2022-07-25T06:39:55.121132Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-07-25T06:39:55.121220Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-07-25T06:39:55.142416Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2022-07-25T06:39:55.142828Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2022-07-25T06:39:55.142846Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2022-07-25T06:39:55.143463Z 0 [Note] InnoDB: Waiting for purge to start
2022-07-25 06:39:55 0x7f77ba7fc700  InnoDB: Assertion failure in thread 140152206771968 in file fut0lst.ic line 93
InnoDB: Failing assertion: addr.page == FIL_NULL || addr.boffset >= FIL_PAGE_DATA
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
06:39:55 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=0
max_threads=151
thread_count=0
connection_count=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68197 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f77b4000b60
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7f77ba7fbdd8 thread_stack 0x40000
mysqld(my_print_stacktrace+0x2c)[0x555d6178e4fc]
mysqld(handle_fatal_signal+0x501)[0x555d610abff1]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x12730)[0x7f77df97f730]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x10b)[0x7f77df45a7bb]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x121)[0x7f77df445535]
mysqld(+0x6c1f13)[0x555d61072f13]
mysqld(+0x6bee4b)[0x555d6106fe4b]
mysqld(+0x10ca0e8)[0x555d61a7b0e8]
mysqld(_Z9trx_purgemmb+0x563)[0x555d61a7ee23]
mysqld(srv_purge_coordinator_thread+0xab5)[0x555d61a551f5]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7fa3)[0x7f77df974fa3]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f77df51c4cf]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0): Connection ID (thread ID): 0
Status: NOT_KILLED

# 查看容器日志位置及详情，定位最早的报错
docker inspect --format='{{.LogPath}}' mysql

二、问题分析

数据文件的LSN比redo log的LSN要大，当系统尝试使用Redo Log去修复数据页面的时候，发现Redo Log LSN比数据页面还小，所以导致错误。数据页的LSN在一般情况下，都是小于Redo Log的，因为在事物提交或按照 innodb_trx_commit 设置的方式提交时，先将事物顺序写入Redo Log ， 然后后台线程按照 max_prt_dirty_page 参数设置的比例刷新或当系统检测到当10秒内系统会执行刷新脏页操作，所以，数据页的LSN正常情况下永远会比Redo Log 的LSN 小。此次问题是由于系统断电，数据库非正常关闭，数据库回滚操作未执行完毕。来电后数据库容器重启，数据库回滚崩溃。

三、解决办法

需要设置innodb_force_recovery=3或者4 ，每次都需删除MySQL数据目录下的所有ib开头的文件，逐个尝试，直到数据库能启动，导出重要的数据，重建数据库，恢复重要业务数据。

# 1、innodb_force_recovery参数介绍
innodb_force_recovery：可以设置为1-6,大的数字包含前面所有数字的影响。
1(SRV_FORCE_IGNORE_CORRUPT)：使服务器即使检测到损坏的页面也可以运行。尝试跳过损坏的索引记录和页，这有助于转储表。SELECT * FROM tbl_name
2(SRV_FORCE_NO_BACKGROUND)：阻止主线程和任何清除线程运行。如果在清除操作期间发生崩溃，则此恢复值可防止崩溃。
3(SRV_FORCE_NO_TRX_UNDO)：崩溃恢复后不执行事务回滚操作。 
4(SRV_FORCE_NO_IBUF_MERGE)：防止插入缓冲区合并操作。如果它们会导致崩溃，请不要这样做。不计算表统计信息。此值可能会永久损坏数据文件。使用此值后，准备删除并重新创建所有二级索引。设置InnoDB为只读。 
5(SRV_FORCE_NO_UNDO_LOG_SCAN)：启动数据库时 不查看撤消日志InnoDB：甚至将不完整的事务视为已提交。此值可能会永久损坏数据文件。设置InnoDB为只读。
6(SRV_FORCE_NO_LOG_REDO)：不执行与恢复相关的重做日志前滚。此值可能会永久损坏数据文件。使数据库页面处于过时状态，这反过来可能会给 B 树和其他数据库结构带来更多损坏。设置 InnoDB为只读。
当设置参数值大于0后，可以对表进行select,create,drop操作,但insert,update或者delete这类操作是不允许的。即使innodb_force_recovery>0 ，也可以DROP或CREATE表。如果某个表正在回滚而导致数据库崩溃，设置innodb_force_recovery为3,重启db后,使得数据库被挂起而不需要回滚，然后舍弃导致失控回滚的表。

# 2、问题解决步骤
# 2.1、更新配置文件,启动mysql容器
su - rpa
docker-compose stop mysql
cd /data/cyclone/rpaplatform/data/middleware/mysql
rm -rf ib*
cat >> /data/cyclone/rpaplatform/data/middleware/mysql-conf/mysql.cnf <<EOF
innodb_force_recovery=3
EOF

cd /data/cyclone/rpaplatform/
docker-compose up -d mysql
docker logs -f --tail=50 mysql

如果此时数据库已启动，直接执行2.3，否则执行2.2

# 2.2、再次更新配置文件,启动mysql容器
su - rpa
docker stop mysql
cd /data/cyclone/rpaplatform/data/middleware/mysql
rm -rf ib*
sed -i 's/innodb_force_recovery=3/innodb_force_recovery=4/g' /data/cyclone/rpaplatform/data/middleware/mysql-conf/mysql.cnf

cd /data/cyclone/rpaplatform/
docker-compose up -d mysql
docker logs -f --tail=50 mysql

# 2.3、进入容器验证数据，mysqldump备份重要业务数据
docker exec -it mysql bash
mysql -uroot -proot -e'select * from rpa_cs.alert limit 1;'
mysqldump -uroot -proot -B rpa_cs rpa_lic rpa_orc_serv rpa_orc_trig rpa_orc_wf>/tmp/dball.sql

# 2.4、宿主机获取mysqldump的文件，备份有问题的数据库数据目录
docker cp mysql:/tmp/dball.sql /data
cp -rf /data/cyclone/rpaplatform/data/middleware/mysql /data/cyclone/rpaplatform/data/middleware/mysqlbak

# 2.5、重建mysql容器
su - rpa
cd /data/cyclone/rpaplatform/
docker-compose stop mysql
docker-compose rm -f mysql
rm -rf /data/cyclone/rpaplatform/data/middleware/mysql/*

# 更新配置文件
sed -i 's/innodb_force_recovery=4/#innodb_force_recovery=4/g' /data/cyclone/rpaplatform/data/middleware/mysql-conf/mysql.cnf

# 查看日志无报错
docker-compose up -d mysql
docker logs -f --tail=50 mysql

# 2.6、恢复备份的业务数据
docker cp /data/dball.sql mysql:/tmp
docker exec -it mysql bash
# mysql容器操作
mysql -uroot -proot </tmp/dball.sql

# 2.7、数据恢复后，验证业务