[MDEV-22736] Assertion failure in file rem0rec.cc line 814 Created: 2020-05-28  Updated: 2023-04-14  Resolved: 2023-04-14

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3.14
Fix Version/s: 10.6.9, 10.8.4, 10.9.2, 10.10.1

Type: Bug Priority: Major
Reporter: Yosh Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None
Environment:

CentOS 7.8

Issue Links:
Duplicate
duplicates MDEV-21098 Crash in rec_get_offsets_func() due t... Closed
Relates
relates to MDEV-23432 MariaDB (mysql) crash with 80000003 i... Closed

 Description   

Since yesterday mariadb suddenly failed to start on our entire mariadb cluster.
We are using master-slave replication with GTID's and master-master replication between 2 datacenters.

This the error log of one of the slaves after I was able to start the master server with innodb_force_recovery = 6 set. 

2020-05-28  5:58:27 0 [Note] InnoDB: Using Linux native AIO
 
2020-05-28  5:58:27 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2020-05-28  5:58:27 0 [Note] InnoDB: Uses event mutexes
 
2020-05-28  5:58:27 0 [Note] InnoDB: Compressed tables use zlib 1.2.7
 
2020-05-28  5:58:27 0 [Note] InnoDB: Number of pools: 1
 
2020-05-28  5:58:27 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
2020-05-28  5:58:27 0 [Note] InnoDB: Initializing buffer pool, total size = 8G, instances = 4, chunk size = 128M
 
2020-05-28  5:58:28 0 [Note] InnoDB: Completed initialization of buffer pool
 
2020-05-28  5:58:28 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2020-05-28  5:58:28 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1395344903391
 
2020-05-28  5:58:34 0 [Note] InnoDB: Starting final batch to recover 81885 pages from redo log.
 
2020-05-28  5:58:37 0 [Note] InnoDB: Last binlog file './mariadb-bin.003482', position 1688
 
2020-05-28  5:58:38 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2020-05-28  5:58:38 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2020-05-28  5:58:38 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2020-05-28  5:58:38 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2020-05-28  5:58:38 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2020-05-28  5:58:38 0 [Note] InnoDB: 10.3.14 started; log sequence number 1395538094571; transaction id 766830539
 
2020-05-28  5:58:38 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
 
2020-05-28  5:58:38 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2020-05-28  5:58:38 0 [Note] Recovering after a crash using mariadb-bin
 
2020-05-28  5:58:38 0 [Note] Starting crash recovery...
 
2020-05-28  5:58:38 0 [Note] Crash recovery finished.
 
2020-05-28 05:58:38 0x7f09f2dcd700  InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.3.14/storage/innobase/rem/rem0rec.cc line 814
 
InnoDB: We intentionally generate a memory trap.
 
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
 
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: https://mariadb.com/kb/en/library/innodb-recovery-modes/
 
InnoDB: about forcing recovery.
 
200528  5:58:38 [ERROR] 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.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.3.14-MariaDB-log
 
key_buffer_size=16777216
 
read_buffer_size=131072
 
max_used_connections=0
 
max_threads=1002
 
thread_count=6
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2219062 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7f09b40009a8
 
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 = 0x7f09f2dccbf0 thread_stack 0x40000
 
2020-05-28  5:58:38 0 [Note] Server socket created on IP: '0.0.0.0'.
 
2020-05-28  5:58:38 0 [Note] Reading of all Master_info entries succeded
 
2020-05-28  5:58:38 0 [Note] Added new Master_info '' to hash table
 
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x5610ac707dfe]
 
/usr/sbin/mysqld(handle_fatal_signal+0x357)[0x5610ac1a7cc7]
 
2020-05-28  5:58:38 10 [Note] Slave I/O thread: Start asynchronous replication to master 'slave@master:3306' in log 'mariadb-bin.001462' at position 424
 
2020-05-28  5:58:38 11 [Note] Slave SQL thread initialized, starting replication in log 'mariadb-bin.001462' at position 424, relay log './mariadb-relay-bin.000001' position: 4; GTID position '1-3117982927-205587455,2-2811022535-23281327,100-1-140363414'
 
2020-05-28  5:58:38 0 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '10.3.14-MariaDB-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MariaDB Server
 
2020-05-28  5:58:38 10 [Note] Slave I/O thread: connected to master 'slave@master:3306',replication starts at GTID position '1-3117982927-205587455,2-2811022535-23281327,100-1-140363414'
 
sigaction.c:0(__restore_rt)[0x7f0c68771630]
 
:0(__GI_raise)[0x7f0c66a42387]
 
:0(__GI_abort)[0x7f0c66a43a78]
 
/usr/sbin/mysqld(+0x4c4b3a)[0x5610abee9b3a]
 
/usr/sbin/mysqld(+0x9b83c3)[0x5610ac3dd3c3]
 
/usr/sbin/mysqld(+0x99576c)[0x5610ac3ba76c]
 
/usr/sbin/mysqld(+0xa91413)[0x5610ac4b6413]
 
/usr/sbin/mysqld(+0x9f92cb)[0x5610ac41e2cb]
 
/usr/sbin/mysqld(+0x9fa8e7)[0x5610ac41f8e7]
 
/usr/sbin/mysqld(+0x9f4d52)[0x5610ac419d52]
 
/usr/sbin/mysqld(+0x9f76d3)[0x5610ac41c6d3]
 
/usr/sbin/mysqld(+0x9f859b)[0x5610ac41d59b]
 
/usr/sbin/mysqld(+0x9b3d7a)[0x5610ac3d8d7a]
 
/usr/sbin/mysqld(+0xa3eb88)[0x5610ac463b88]
 
/usr/sbin/mysqld(+0xa22de2)[0x5610ac447de2]
 
pthread_create.c:0(start_thread)[0x7f0c68769ea5]
 
/lib64/libc.so.6(clone+0x6d)[0x7f0c66b0a8dd]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x0): 
Connection ID (thread ID): 1
 
Status: NOT_KILLED
 
 
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on
 
 
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
information that should help you find out what is causing the crash.

We have rebuild the entire cluster from one slave that was still working, but a few hours later the same thing happened again.

Each server has 16GB of memory, so the notice about the required memory keyspace isn't the issue.

 Comments   
Comment by Ján Kľuka [ 2020-07-20 ]

We have, what appears to be, encountered a similar problem with a single node installation of mariadb 10.3.22 on a Debian 10 server.

After what appeared to be a clean shutdown, mariadb refused to start. The shutdown and first failed start looked like this in the log:

2020-07-17 10:32:56 0 [Note] InnoDB: Starting shutdown...
 
2020-07-17 10:32:56 0 [Note] InnoDB: Dumping buffer pool(s) to /var/lib/mysql/ib_buffer_pool
 
2020-07-17 10:32:56 0 [Note] InnoDB: Instance 0, restricted to 2047 pages due to innodb_buf_pool_dump_pct=25
 
2020-07-17 10:32:56 0 [Note] InnoDB: Buffer pool(s) dump completed at 200717 10:32:56
 
2020-07-17 10:32:59 0 [Note] InnoDB: Shutdown completed; log sequence number 41371175619; transaction id 218033773
 
2020-07-17 10:32:59 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2020-07-17 10:32:59 0 [Note] /usr/sbin/mysqld: Shutdown complete
 
 
 
2020-07-17 11:37:23 0 [Note] Using unique option prefix 'myisam-recover' is error-prone and can break in the future. Please use the full name 'myisam-recover-options' instead.
 
2020-07-17 11:37:25 0 [Note] InnoDB: Using Linux native AIO
 
2020-07-17 11:37:25 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2020-07-17 11:37:25 0 [Note] InnoDB: Uses event mutexes
 
2020-07-17 11:37:25 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2020-07-17 11:37:25 0 [Note] InnoDB: Number of pools: 1
 
2020-07-17 11:37:25 0 [Note] InnoDB: Using generic crc32 instructions
 
2020-07-17 11:37:25 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
 
2020-07-17 11:37:26 0 [Note] InnoDB: Completed initialization of buffer pool
 
2020-07-17 11:37:26 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2020-07-17 11:37:31 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2020-07-17 11:37:31 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2020-07-17 11:37:31 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2020-07-17 11:37:31 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2020-07-17 11:37:31 0 [Note] InnoDB: Waiting for purge to start
 
2020-07-17 11:37:31 0 [Note] InnoDB: 10.3.22 started; log sequence number 41371175619; transaction id 218033775
 
2020-07-17 11:37:31 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
 
2020-07-17 11:37:31 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2020-07-17 11:37:32 0xdc002b40  InnoDB: Assertion failure in file /build/mariadb-10.3-PCCNAU/mariadb-10.3-10.3.22/storage/innobase/rem/rem0rec.cc line 815
 
InnoDB: We intentionally generate a memory trap.
 
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
 
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: https://mariadb.com/kb/en/library/innodb-recovery-modes/
 
InnoDB: about forcing recovery.
 
200717 11:37:32 [ERROR] 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.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.3.22-MariaDB-0+deb10u1-log
 
key_buffer_size=16777216
 
read_buffer_size=131072
 
max_used_connections=0
 
max_threads=202
 
thread_count=6
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 458822 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0
 
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 = 0x0 thread_stack 0x30000
 
/usr/sbin/mysqld(my_print_stacktrace+0x28)[0x570fa1d8]
 
/usr/sbin/mysqld(handle_fatal_signal+0x557)[0x56be0507]
 
addr2line: 'linux-gate.so.1': No such file
 
linux-gate.so.1(__kernel_sigreturn+0x0)[0xf7f52080]
 
linux-gate.so.1(__kernel_vsyscall+0x9)[0xf7f52069]
 
/lib/i386-linux-gnu/libc.so.6(gsignal+0xc2)[0xf792b382]
 
/lib/i386-linux-gnu/libc.so.6(abort+0xf0)[0xf79152b6]
 
2020-07-17 11:37:36 0 [Note] Server socket created on IP: '0.0.0.0'.
 
/usr/sbin/mysqld(+0x2a24c2)[0x568f14c2]
 
/usr/sbin/mysqld(+0x2868a8)[0x568d58a8]
 
/usr/sbin/mysqld(+0x787364)[0x56dd6364]
 
/usr/sbin/mysqld(+0x74c317)[0x56d9b317]
 
/usr/sbin/mysqld(+0x7529b2)[0x56da19b2]
 
/usr/sbin/mysqld(+0x874d5b)[0x56ec3d5b]
 
/usr/sbin/mysqld(+0x8c763b)[0x56f1663b]
 
/usr/sbin/mysqld(+0x800d59)[0x56e4fd59]
 
/lib/i386-linux-gnu/libpthread.so.0(+0x6fd2)[0xf7f11fd2]
 
i386/clone.S:110(clone)[0xf79f66d6]
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
information that should help you find out what is causing the crash.
 
Writing a core file...
 
Working directory at /var/lib/mysql
 
Resource Limits:
 
Fatal signal 11 while backtracing

However, the server was able to recover with innodb_force_recovery set to 4.

Comment by Ján Kľuka [ 2020-07-20 ]

After the successful recovery with innodb_force_recovery set to 4, I tried shutting mariadb down again, setting innodb_force_recovery back to the default 0 – and it failed to start again.

Comment by Ján Kľuka [ 2020-07-20 ]

Actually, the server crashed soon after recovery was completed with 2020-07-20 12:33:44 0 [ERROR] InnoDB: N heap is wrong 1205, 607, which is followed by a dump of the corrupted page and the following information:

2020-07-20 12:33:44 0 [Note] InnoDB: Uncompressed page, stored checksum in field1 282246985, calculated checksums for field1: crc32 282246985, innodb 3123919523,  page type 17855 == INDEX.none 3735928559, stored checksum in field2 282246985, calculated checksums for field2: crc32 282246985, innodb 1626369560, none 3735928559,  page LSN 9 2716470081, low 4 bytes of LSN at page end 2716470081, page number (if stored to page already) 14564, space id (if created with >= MySQL-4.1.1 and stored already) 0
 
2020-07-20 12:33:44 0 [Note] InnoDB: Page may be an index page where index id is 366349
 
2020-07-20 12:33:44 0 [ERROR] [FATAL] InnoDB: Apparent corruption of an index page [page id: space=0, page number=14564] to be written to data file. We intentionally crash the server to prevent corrupt data from ending up in data files.

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