[MDEV-26343] InnoDB prevents database to start anymore on 10.6.4 Created: 2021-08-11  Updated: 2021-09-24  Resolved: 2021-09-24

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, wsrep
Affects Version/s: 10.6.4, 10.6
Fix Version/s: N/A

Type: Bug Priority: Critical
Reporter: Jaroslav Assignee: Jan Lindström (Inactive)
Resolution: Incomplete Votes: 0
Labels: None


 Description   

We upgraded from 10.5.11 to 10.6.4 recently and after cluster run for few hours it crashed after a while and we are unable to bring it up again. It always fails with following

2021/08/11 13:29:20 Peer list updated
 
was []
 
now [mysql-0.mysql.default.svc.cluster.local]
 
2021/08/11 13:29:20 execing: /opt/galera/on-start.sh with stdin: mysql-0.mysql.default.svc.cluster.local
 
2021/08/11 13:29:20 *** [Galera] Starting new cluster!
 
2021/08/11 13:29:21 Peer finder exiting
 
Galera - Determining recovery position...
 
galera-recovery.sh: Attempting to recover GTID positon...
 
2021-08-11 13:29:21 0 [Note] mysqld (server 10.6.4-MariaDB-1:10.6.4+maria~focal) starting as process 48 ...
 
galera-recovery.sh: Failed to start mysqld for wsrep recovery: '2021-08-11 13:29:21 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2021-08-11 13:29:21 0 [Note] InnoDB: Number of pools: 1
 
2021-08-11 13:29:21 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
 
2021-08-11 13:29:21 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
 
2021-08-11 13:29:21 0 [Note] InnoDB: Using Linux native AIO
 
2021-08-11 13:29:21 0 [Note] InnoDB: Initializing buffer pool, total size = 8858370048, chunk size = 134217728
 
2021-08-11 13:29:21 0 [Note] InnoDB: Completed initialization of buffer pool
 
2021-08-11 13:29:21 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1533931390429,1533931390429
 
2021-08-11 13:29:22 0 [Note] InnoDB: Starting final batch to recover 4330 pages from redo log.
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Not applying DELETE_ROW_FORMAT_DYNAMIC due to corruption on [page id: space=14079, page number=78]
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Not applying INSERT_REUSE_DYNAMIC due to corruption on [page id: space=14079, page number=78]
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
 
2021-08-11 13:29:22 0 [Warning] InnoDB: The last skipped log record LSN 1533931681138 is not equal to page LSN 1533931712960
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Not applying DELETE_ROW_FORMAT_DYNAMIC due to corruption on [page id: space=14079, page number=79]
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
 
2021-08-11 13:29:22 0 [Warning] InnoDB: The last skipped log record LSN 1533931662627 is not equal to page LSN 1533931682005
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Not applying INSERT_HEAP_DYNAMIC due to corruption on [page id: space=14079, page number=79]
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Not applying DELETE_ROW_FORMAT_DYNAMIC due to corruption on [page id: space=14079, page number=82]
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
 
2021-08-11 13:29:22 0 [Warning] InnoDB: The last skipped log record LSN 1533931658204 is not equal to page LSN 1533931773729
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Not applying INSERT_REUSE_DYNAMIC due to corruption on [page id: space=14079, page number=82]
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Not applying DELETE_ROW_FORMAT_DYNAMIC due to corruption on [page id: space=14079, page number=94]
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Not applying INSERT_HEAP_DYNAMIC due to corruption on [page id: space=14079, page number=94]
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore corruption.
 
2021-08-11 13:29:22 0 [Warning] InnoDB: The last skipped log record LSN 1533931662825 is not equal to page LSN 1533931799000
 
2021-08-11 13:29:22 0 [Warning] InnoDB: The last skipped log record LSN 1533931640049 is not equal to page LSN 1533931730786
 
2021-08-11 13:29:22 0 [Warning] InnoDB: The last skipped log record LSN 1533931565000 is not equal to page LSN 1533931729834
 
2021-08-11 13:29:22 0 [Warning] InnoDB: The last skipped log record LSN 1533931482936 is not equal to page LSN 1533931483333
 
2021-08-11 13:29:22 0 [ERROR] InnoDB: Plugin initialization aborted with error Data structure corruption
 
2021-08-11 13:29:22 0 [Note] InnoDB: Starting shutdown...
 
2021-08-11 13:29:23 0 [ERROR] Plugin 'InnoDB' init function returned error.
 
2021-08-11 13:29:23 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
 
2021-08-11 13:29:23 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2021-08-11 13:29:23 0 [Note] Plugin 'unix_socket' is disabled.
 
2021-08-11 13:29:23 0 [ERROR] Unknown/unsupported storage engine: InnoDB
 
2021-08-11 13:29:23 0 [ERROR] Aborting'
 
Galera recovery position:
 
2021-08-11 13:29:23 0 [Note] mysqld (server 10.6.4-MariaDB-1:10.6.4+maria~focal) starting as process 1 ...
 
2021-08-11 13:29:23 0 [Note] WSREP: Loading provider /usr/lib/galera/libgalera_smm.so initial position: 00000000-0000-0000-0000-000000000000:-1
 
2021-08-11 13:29:23 0 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'
 
2021-08-11 13:29:23 0 [Note] WSREP: wsrep_load(): Galera 26.4.9(r819f29cb) by Codership Oy <info@codership.com> loaded successfully.
 
2021-08-11 13:29:23 0 [Note] WSREP: CRC-32C: using 64-bit x86 acceleration.
 
2021-08-11 13:29:23 0 [Note] WSREP: Found saved state: a5925485-fa9e-11eb-b6f8-3ec6336b487c:-1, safe_to_bootstrap: 0
 
2021-08-11 13:29:23 0 [Note] WSREP: GCache DEBUG: opened preamble:
 
Version: 2
 
UUID: a5925485-fa9e-11eb-b6f8-3ec6336b487c
 
Seqno: 1 - 50408
 
Offset: 1280
 
Synced: 1
 
2021-08-11 13:29:23 0 [Note] WSREP: Recovering GCache ring buffer: version: 2, UUID: a5925485-fa9e-11eb-b6f8-3ec6336b487c, offset: 1280
 
2021-08-11 13:29:23 0 [Note] WSREP: GCache::RingBuffer initial scan...  0.0% (        0/134217752 bytes) complete.
 
2021-08-11 13:29:23 0 [Note] WSREP: GCache::RingBuffer initial scan...100.0% (134217752/134217752 bytes) complete.
 
2021-08-11 13:29:23 0 [Note] WSREP: Recovering GCache ring buffer: found gapless sequence 1-50408
 
2021-08-11 13:29:23 0 [Note] WSREP: GCache::RingBuffer unused buffers scan...  0.0% (        0/104510296 bytes) complete.
 
2021-08-11 13:29:23 0 [Note] WSREP: GCache::RingBuffer unused buffers scan...100.0% (104510296/104510296 bytes) complete.
 
2021-08-11 13:29:23 0 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): found 13/50421 locked buffers
 
2021-08-11 13:29:23 0 [Note] WSREP: GCache DEBUG: RingBuffer::recover(): free space: 29718624/134217728
 
2021-08-11 13:29:23 0 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = mysql-0.mysql.default.svc.cluster.local; base_port = 4567; cert.log_conflicts = no; cert.optimistic_pa = yes; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = galera.cache; gcache.page_size = 128M; gcache.recover = yes; gcache.size = 128M; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announce_tim
 
2021-08-11 13:29:23 0 [Note] WSREP: Start replication
 
2021-08-11 13:29:23 0 [Note] WSREP: Connecting with bootstrap option: 1
 
2021-08-11 13:29:23 0 [Note] WSREP: Setting GCS initial position to 00000000-0000-0000-0000-000000000000:-1
 
2021-08-11 13:29:23 0 [ERROR] WSREP: It may not be safe to bootstrap the cluster from this node. It was not the last one to leave the cluster and may not contain all the updates. To force cluster bootstrap with this node, edit the grastate.dat file manually and set safe_to_bootstrap to 1 .
 
2021-08-11 13:29:23 0 [ERROR] WSREP: wsrep::connect(gcomm://) failed: 7
 
2021-08-11 13:29:23 0 [ERROR] Aborting

is there some workaround how to force this node to go up?

Before it got to this state it was throwing these errors on all 3 mariadb nodes

2021/08/11 11:54:49 Peer list updated
 
was []
 
now [mysql-0.mysql.default.svc.cluster.local mysql-1.mysql.default.svc.cluster.local mysql-2.mysql.default.svc.cluster.local]
 
2021/08/11 11:54:49 execing: /opt/galera/on-start.sh with stdin: mysql-0.mysql.default.svc.cluster.local
 
mysql-1.mysql.default.svc.cluster.local
 
mysql-2.mysql.default.svc.cluster.local
 
2021/08/11 11:54:49 *** [Galera] Joining cluster: mysql-0.mysql.default.svc.cluster.local,mysql-1.mysql.default.svc.cluster.local
 
2021/08/11 11:54:50 Peer finder exiting
 
Galera - Determining recovery position...
 
galera-recovery.sh: Attempting to recover GTID positon...
 
2021-08-11 11:54:50 0 [Note] mysqld (server 10.6.4-MariaDB-1:10.6.4+maria~focal) starting as process 48 ...
 
galera-recovery.sh: Failed to start mysqld for wsrep recovery: '2021-08-11 11:54:50 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2021-08-11 11:54:50 0 [Note] InnoDB: Number of pools: 1
 
2021-08-11 11:54:50 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
 
2021-08-11 11:54:50 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
 
2021-08-11 11:54:50 0 [Note] InnoDB: Using Linux native AIO
 
2021-08-11 11:54:50 0 [Note] InnoDB: Initializing buffer pool, total size = 8858370048, chunk size = 134217728
 
2021-08-11 11:54:50 0 [Note] InnoDB: Completed initialization of buffer pool
 
2021-08-11 11:54:50 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1533806354857,1533806354857
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Page [page id: space=63, page number=6] log sequence number 1533966178233 is in the future! Current system log sequence number 1533923300737.
 
2021-08-11 11:54:51 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 https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Refusing to load './storage/active_directory_job.ibd' (id=14344, flags=0x15); dictionary contains id=14343, flags=0x15
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Could not find a valid tablespace file for storage/active_directory_job. Please refer to https://mariadb.com/kb/en/innodb-data-dictionary-troubleshooting/ for how to resolve the issue.
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Refusing to load './storage/snapshot_restore_files_job.ibd' (id=14381, flags=0x15); dictionary contains id=14380, flags=0x15
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Operating system error number 2 in a file operation.
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: The error means the system cannot find the path specified.
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Could not find a valid tablespace file for storage/snapshot_restore_files_job. Please refer to https://mariadb.com/kb/en/innodb-data-dictionary-troubleshooting/ for how to resolve the issue.
 
2021-08-11 11:54:51 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
 
2021-08-11 11:54:51 0 [Note] InnoDB: Trx id counter is 367821890
 
2021-08-11 11:54:51 0 [Note] InnoDB: Starting final batch to recover 23492 pages from redo log.
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Page [page id: space=44, page number=1] log sequence number 1533966146666 is in the future! Current system log sequence number 1533923300737.
 
2021-08-11 11:54:51 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 https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Page [page id: space=44, page number=0] log sequence number 1533965880965 is in the future! Current system log sequence number 1533923300737.
 
2021-08-11 11:54:51 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 https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Page [page id: space=44, page number=3] log sequence number 1533966175785 is in the future! Current system log sequence number 1533923300737.
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Page [page id: space=44, page number=31] log sequence number 1533965763157 is in the future! Current system log sequence number 1533923300737.
 
2021-08-11 11:54:51 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 https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
 
2021-08-11 11:54:51 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 https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Page [page id: space=44, page number=2] log sequence number 1533966173074 is in the future! Current system log sequence number 1533923300737.
 
2021-08-11 11:54:51 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 https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Page [page id: space=44, page number=32] log sequence number 1533939541945 is in the future! Current system log sequence number 1533923300737.
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Page [page id: space=44, page number=30] log sequence number 1533953268642 is in the future! Current system log sequence number 1533923300737.
 
2021-08-11 11:54:51 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 https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
 
2021-08-11 11:54:51 0 [ERROR] InnoDB: Page [page id: space=44, page number=50] log sequence number 1533965931411 is in the future! Current system log sequence number 1533923300737.
 
2021-08-11 11:54:51 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 https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.



 Comments   
Comment by Marko Mäkelä [ 2021-08-11 ]

The messages log sequence number … is in the future are already a sign of serious corruption. How exactly were the replicas set up? Was any kind of Galera snapshot transfer used?

Comment by Jaroslav [ 2021-08-17 ]

We upgraded at that time from 10.5 to 10.6 release that was all. It was using wsrep and everything as before. However we downgraded successfully with restoral and the issue is gone on 10.5. I can't provide more information into this then

Generated at Thu Feb 08 09:44:35 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.