[MDEV-19298] Assertion `space->id != 0xFFFFFFFEU || space == fil_system.temp_space' failed in Check::validate upon crash upgrade from 10.2.22 Created: 2019-04-21  Updated: 2020-07-31  Resolved: 2020-06-27

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Tests
Affects Version/s: 10.3, 10.4
Fix Version/s: 10.3.24, 10.4.14, 10.5.5

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Eugene Kosov (Inactive)
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Duplicate
is duplicated by MDEV-20213 binlog_encryption.binlog_incident fai... Closed
Relates
relates to MDEV-20159 Assertion `space->id != TRX_SYS_SPACE... Closed
relates to MDEV-20213 binlog_encryption.binlog_incident fai... Closed
relates to MDEV-20481 innodb.blob-crash crashes during reco... Closed

 Description   

10.3 cc492bfd

 
mysqld: /home/buildbot/10.3-src/storage/innobase/fil/fil0fil.cc:4626: static ulint Check::validate(const fil_space_t*): Assertion `space->id != 0xFFFFFFFEU || space == fil_system.temp_space' failed.
 
 
 
bin/mysqld(0x23f9b39 Check::validate(fil_space_t const*) + 868)[0x5607efe58b39]
 
bin/mysqld(0x23f50d7 fil_validate() + 490)[0x5607efe540d7]
 
bin/mysqld(0x23dba17 fil_validate_skip() + 53)[0x5607efe3aa17]
 
bin/mysqld(0x23f3fc5 fil_aio_wait(unsigned long) + 258)[0x5607efe52fc5]
 
bin/mysqld(0x2177385 io_handler_thread + 1633)[0x5607efbd6385]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7fce33c166ba]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fce330ab82d]

The failure happens upon 10.3 startup on this datadir with

--innodb-page-size=4K --innodb-compression-algorithm=none

but it's very poorly reproducible: it only happens once in hundreds of consequent attempts (even though there is no external concurrency there, just simple server startup on the same datadir); on some reason, so far it's only happened on an ASAN build; and it might also be limited to some particular systems – I was able to reproduce it on Xenial but not on Jessie, although given the irregularity, it could be a coincidence.

 Comments   
Comment by Marko Mäkelä [ 2019-06-12 ]

I just got this locally on 10.5 once, and analyzed the core dump. The space indeed is the temporary tablespace, and space==fil_system.temp_space does hold in the core dump.

For me, the assertion failed in a different thread:

10.5 177a571e01e8ea949601aa1124ea86c376fd0472

 
#8  0x000055e6d6ccb357 in Check::validate (space=0x55e6da591000)
 
    at /mariadb/10.5/storage/innobase/fil/fil0fil.cc:4562
 
#9  0x000055e6d6cc947c in fil_validate () at /mariadb/10.5/storage/innobase/fil/fil0fil.cc:4591
 
#10 0x000055e6d6cbb798 in fil_validate_skip () at /mariadb/10.5/storage/innobase/fil/fil0fil.cc:216
 
#11 0x000055e6d6cc8a5a in fil_io (type=..., sync=true, page_id=..., zip_size=65536, byte_offset=0, len=65536, buf=0x7f8da7730000, message=0x7f8da5c3fab0, ignore_missing_space=false) at /mariadb/10.5/storage/innobase/fil/fil0fil.cc:4321
 
#12 0x000055e6d6c6768d in buf_read_page_low (err=0x7f8d9cfe69c4, sync=true, type=0, mode=132, page_id=..., zip_size=0, unzip=false, ignore_missing_space=false) at /mariadb/10.5/storage/innobase/buf/buf0rea.cc:180
 
#13 0x000055e6d6c68014 in buf_read_page (page_id=..., zip_size=0) at /mariadb/10.5/storage/innobase/buf/buf0rea.cc:410
 
#14 0x000055e6d6c3a8b1 in buf_page_get_gen (page_id=..., zip_size=0, rw_latch=1, guess=0x0, mode=10, file=0x55e6d72cf328 "/mariadb/10.5/storage/innobase/btr/btr0cur.cc", line=8305, mtr=0x7f8d9cfe6e60, err=0x0) at /mariadb/10.5/storage/innobase/buf/buf0buf.cc:4380
 
#15 0x000055e6d6c10b03 in btr_copy_blob_prefix (buf=0x7f8d7806d488 '\245' <repeats 200 times>..., len=3072, space_id=79, page_no=235, offset=38) at /mariadb/10.5/storage/innobase/btr/btr0cur.cc:8304
 
#16 0x000055e6d6c114ef in btr_copy_externally_stored_field_prefix_low (buf=0x7f8d7806d488 '\245' <repeats 200 times>..., len=3072, zip_size=0, space_id=79, page_no=235, offset=38) at /mariadb/10.5/storage/innobase/btr/btr0cur.cc:8513
 
#17 0x000055e6d6c1165d in btr_copy_externally_stored_field_prefix (buf=0x7f8d7806d488 '\245' <repeats 200 times>..., len=3072, zip_size=0, data=0x7f8d7805950d "", local_len=0) at /mariadb/10.5/storage/innobase/btr/btr0cur.cc:8570
 
#18 0x000055e6d6d3c20d in row_ext_cache_fill (ext=0x7f8d7805e4b8, i=19, space=0x55e6da52cab0, dfield=0x7f8d7805dc90) at /mariadb/10.5/storage/innobase/row/row0ext.cc:78
 
#19 0x000055e6d6d3c390 in row_ext_create (n_ext=30, ext=0x7f8d7805d7b8, table=..., tuple=0x7f8d7805da68, heap=0x7f8d780435a0) at /mariadb/10.5/storage/innobase/row/row0ext.cc:128
 
#20 0x000055e6d6b3f5fb in row_build_low (type=2, index=0x55e6da595648, rec=0x7f8d7805936a "", offsets=0x7f8d7805d438, col_table=0x55e6da591cd8, defaults=0x0, add_v=0x0, col_map=0x0, ext=0x7f8d9cfe79b0, heap=0x7f8d780435a0) at /mariadb/10.5/storage/innobase/row/row0row.cc:602
 
#21 0x000055e6d6b3f68b in row_build (type=2, index=0x55e6da595648, rec=0x7f8d7805936a "", offsets=0x7f8d7805d438, col_table=0x0, defaults=0x0, col_map=0x0, ext=0x7f8d9cfe79b0, heap=0x7f8d780435a0) at /mariadb/10.5/storage/innobase/row/row0row.cc:661
 
#22 0x000055e6d6b6d080 in row_vers_old_has_index_entry (also_curr=false, rec=0x7f8da5fcba2b "", mtr=0x7f8d9cfe8200, index=0x55e6da597358, ientry=0x7f8d78042b78, roll_ptr=0, trx_id=0, vcol_info=0x0) at /mariadb/10.5/storage/innobase/row/row0vers.cc:1098
 
#23 0x000055e6d6d4351d in row_undo_mod_del_mark_or_remove_sec_low (node=0x7f8d78001678, thr=0x7f8d780014a8, index=0x55e6da597358, entry=0x7f8d78042b78, mode=2) at /mariadb/10.5/storage/innobase/row/row0umod.cc:603
 
#24 0x000055e6d6d43857 in row_undo_mod_del_mark_or_remove_sec (node=0x7f8d78001678, thr=0x7f8d780014a8, index=0x55e6da597358, entry=0x7f8d78042b78) at /mariadb/10.5/storage/innobase/row/row0umod.cc:671
 
#25 0x000055e6d6d44cc0 in row_undo_mod_upd_exist_sec (node=0x7f8d78001678, thr=0x7f8d780014a8) at /mariadb/10.5/storage/innobase/row/row0umod.cc:1151
 
#26 0x000055e6d6d45693 in row_undo_mod (node=0x7f8d78001678, thr=0x7f8d780014a8) at /mariadb/10.5/storage/innobase/row/row0umod.cc:1366
 
#27 0x000055e6d6b589a5 in row_undo (node=0x7f8d78001678, thr=0x7f8d780014a8) at /mariadb/10.5/storage/innobase/row/row0undo.cc:442
 
#28 0x000055e6d6b58bd5 in row_undo_step (thr=0x7f8d780014a8) at /mariadb/10.5/storage/innobase/row/row0undo.cc:499
 
#29 0x000055e6d6abe6e2 in que_thr_step (thr=0x7f8d780014a8) at /mariadb/10.5/storage/innobase/que/que0que.cc:1040
 
#30 0x000055e6d6abe932 in que_run_threads_low (thr=0x7f8d780014a8) at /mariadb/10.5/storage/innobase/que/que0que.cc:1104
 
#31 0x000055e6d6abeb22 in que_run_threads (thr=0x7f8d780014a8) at /mariadb/10.5/storage/innobase/que/que0que.cc:1144
 
#32 0x000055e6d6bb3151 in trx_rollback_active (trx=0x7f8da7c00140) at /mariadb/10.5/storage/innobase/trx/trx0roll.cc:669
 
#33 0x000055e6d6bb39c3 in trx_rollback_recovered (all=true) at /mariadb/10.5/storage/innobase/trx/trx0roll.cc:823
 
#34 0x000055e6d6bb3c36 in trx_rollback_all_recovered () at /mariadb/10.5/storage/innobase/trx/trx0roll.cc:861
 
#35 0x00007f8db3299fa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
 
#36 0x00007f8db23354cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

This thread is trying to roll back something in a user table test.t1 of the test innodb.innodb-64k-crash.

The fil_system.temp_space is being created in srv_open_tmp_tablespace(). It does make sense to defer the creation, because we want to avoid writing to the file system if the persistent files cannot be recovered. But, maybe the assignment in SysTablespace::open_or_create() should be properly protected by fil_system.mutex, or it should be pushed down to fil_space_create()?

On a related note, we should not release fil_system.mutex in the middle of creating fil_space_t, and we should accordingly remove all code that checks if space->chain is empty. We should simply not add an incomplete fil_space_t to fil_system.

Comment by Elena Stepanova [ 2019-06-17 ]

mariabackup.partial failed in buildbot with what is apparently the same problem:
http://buildbot.askmonty.org/buildbot/builders/win32-debug/builds/14528/steps/test/logs/stdio

bb-10.4-release 306e439c

 
Assertion failed: space->id != TRX_SYS_SPACE || space == fil_system.sys_space, file D:\win32-debug\build\src\storage\innobase\fil\fil0fil.cc, line 4557
 
190617 11:21:46 [ERROR] mysqld got exception 0x80000003 ;
 
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.4.6-MariaDB-debug-log
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=0
 
max_threads=65537
 
thread_count=0
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 3633 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...
 
mariabackup.exe!my_sigabrt_handler()[my_thr_init.c:485]
 
ucrtbase.DLL!raise()
 
ucrtbase.DLL!abort()
 
ucrtbase.DLL!_get_wpgmptr()
 
ucrtbase.DLL!_get_wpgmptr()
 
ucrtbase.DLL!_wassert()
 
mariabackup.exe!Check::validate()[fil0fil.cc:4556]
 
mariabackup.exe!fil_validate()[fil0fil.cc:4587]
 
mariabackup.exe!fil_validate_skip()[fil0fil.cc:216]
 
mariabackup.exe!fil_aio_wait()[fil0fil.cc:4342]
 
mariabackup.exe!io_handler_thread()[srv0start.cc:325]
 
KERNEL32.DLL!BaseThreadInitThunk()
 
ntdll.dll!RtlInitializeExceptionChain()
 
ntdll.dll!RtlInitializeExceptionChain()

Comment by Elena Stepanova [ 2019-07-30 ]

http://buildbot.askmonty.org/buildbot/builders/kvm-asan/builds/1753

innodb.blob-crash '4k,debug,innodb'      w4 [ fail ]
 
        Test ended at 2019-07-25 13:53:33

10.4 e9c1701e11e2441435223cc7c00c467f

 
mysqld: /home/buildbot/buildbot/build/mariadb-10.4.7/storage/innobase/fil/fil0fil.cc:4569: static ulint Check::validate(const fil_space_t*): Assertion `space->id != 0xFFFFFFFEU || space == fil_system.temp_space' failed.
 
190725 13:53:29 [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.4.7-MariaDB-debug-log
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=0
 
max_threads=153
 
thread_count=0
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63616 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 0x5fc00
 
/usr/lib/x86_64-linux-gnu/libasan.so.2(+0x4a077)[0x7f4da1935077]
 
/home/buildbot/buildbot/build/mariadb-10.4.7/sql/mysqld(my_print_stacktrace+0xce)[0x221f2e1]
 
/home/buildbot/buildbot/build/mariadb-10.4.7/sql/mysqld(handle_fatal_signal+0x87a)[0x10fde7c]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f4da03b3390]
 
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7f4d9f569428]
 
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f4d9f56b02a]
 
/lib/x86_64-linux-gnu/libc.so.6(+0x2dbd7)[0x7f4d9f561bd7]
 
/lib/x86_64-linux-gnu/libc.so.6(+0x2dc82)[0x7f4d9f561c82]
 
/home/buildbot/buildbot/build/mariadb-10.4.7/sql/mysqld[0x1ee3878]
 
/home/buildbot/buildbot/build/mariadb-10.4.7/sql/mysqld[0x1edf851]
 
/home/buildbot/buildbot/build/mariadb-10.4.7/sql/mysqld[0x1ec7221]
 
page/page0zip.cc:1479(page_zip_compress(page_zip_des_t*, unsigned char const*, dict_index_t*, unsigned long, mtr_t*))[0x1edd18e]
 
page/page0cur.cc:2131(page_copy_rec_list_end_to_created_page(unsigned char*, unsigned char*, dict_index_t*, mtr_t*))[0x1e283a4]
 
lock/lock0lock.cc:1743(lock_rec_enqueue_waiting(ib_lock_t*, unsigned long, buf_block_t const*, unsigned long, dict_index_t*, que_thr_t*, lock_prdt*))[0x1e2948f]
 
lock/lock0lock.cc:1839(lock_rec_add_to_queue(unsigned long, buf_block_t const*, unsigned long, dict_index_t*, trx_t*, bool))[0x1dd5be0]
 
handler/i_s.cc:2938(i_s_fts_deleted_fill(THD*, TABLE_LIST*, Item*))[0x1d86ba2]
 
handler/handler0alter.cc:7985(ha_innobase::prepare_inplace_alter_table(TABLE*, Alter_inplace_info*))[0x1d8752b]
 
handler/handler0alter.cc:6492(prepare_inplace_alter_table_dict(Alter_inplace_info*, TABLE const*, TABLE const*, char const*, unsigned long, unsigned long, unsigned long, bool, bool))[0x1d79d29]
 
row/row0log.cc:705(row_log_table_delete(unsigned char const*, dict_index_t*, unsigned long const*, unsigned char const*))[0x1fcd9c3]
 
row/row0log.cc:867(row_log_table_low_redundant(unsigned char const*, dict_index_t*, bool, dtuple_t const*, dict_index_t const*))[0x1fcf087]
 
row/row0log.cc:1654(row_log_table_apply_convert_mrec(unsigned char const*, dict_index_t*, unsigned long const*, row_log_t*, mem_block_info_t*, dberr_t*))[0x1fd49dc]
 
maria/ma_rprev.c:78(maria_rprev)[0x1c3271c]
 
maria/ma_rprev.c:102(maria_rprev)[0x1c32bb2]
 
maria/ma_loghandler.c:3686(translog_init_with_table)[0x1b09e1e]
 
maria/ma_loghandler.c:3758(translog_init_with_table)[0x1b0a246]
 
maria/ma_loghandler.c:3819(translog_init_with_table)[0x1b0a59f]
 
include/dict0priv.ic:87(dict_table_check_if_in_cache_low(char const*))[0x1cdeb54]
 
handler/ha_innodb.cc:1404(innobase_flush_logs(handlerton*, bool))[0x1cdfcd0]
 
handler/ha_innodb.cc:1657(thd_trx_is_auto_commit(THD*))[0x1ce032f]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f4da03a96ba]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f4d9f63a82d]
 
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 /dev/shm/var/4/mysqld.1/data
 
Resource Limits:
 
Limit                     Soft Limit           Hard Limit           Units     
Max cpu time              unlimited            unlimited            seconds   
Max file size             unlimited            unlimited            bytes     
Max data size             unlimited            unlimited            bytes     
Max stack size            8388608              unlimited            bytes     
Max core file size        0                    0                    bytes     
Max resident set          unlimited            unlimited            bytes     
Max processes             23715                23715                processes 
Max open files            1024                 1024                 files     
Max locked memory         65536                65536                bytes     
Max address space         unlimited            unlimited            bytes     
Max file locks            unlimited            unlimited            locks     
Max pending signals       23715                23715                signals   
Max msgqueue size         819200               819200               bytes     
Max nice priority         0                    0                    
Max realtime priority     0                    0                    
Max realtime timeout      unlimited            unlimited            us

Comment by Eugene Kosov (Inactive) [ 2020-06-27 ]

This issue is pretty much the same as https://jira.mariadb.org/browse/MDEV-20213 and the same analysis applies.

Generated at Thu Feb 08 08:50:34 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.