Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-24780

[FATAL] InnoDB: Trying to read page number <...> with encryption and innodb-background-scrub-data-uncompressed

    XMLWordPrintable

Details

    Description

      Setting to Minor because scrubbing is involved, and only 10.4 seems to be affected.

      10.4 542d769e

      2021-02-03 20:22:32 0 [ERROR] [FATAL] InnoDB: Trying to read page number 0 in space 25, space name test/#sql-3ca387_d, which is outside the tablespace bounds. Byte offset 0, len 16384
      210203 20:22:32 [ERROR] mysqld got signal 6 ;
       
      #3  <signal handler called>
      #4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
      #5  0x00007f1a97120859 in __GI_abort () at abort.c:79
      #6  0x000055dc1129c58b in ib::fatal::~fatal (this=<optimized out>, __in_chrg=<optimized out>) at /data/src/10.4/storage/innobase/ut/ut0ut.cc:604
      #7  0x000055dc112b0327 in fil_report_invalid_page_access (block_offset=0, space_id=25, space_name=0x7f1a18011040 "test/#sql-3ca387_d", byte_offset=byte_offset@entry=0, len=len@entry=16384, is_read=<optimized out>) at /data/src/10.4/storage/innobase/include/ut0ut.h:354
      #8  0x000055dc112b18a1 in fil_io (type=..., sync=sync@entry=true, page_id=..., zip_size=zip_size@entry=0, byte_offset=byte_offset@entry=0, len=16384, buf=0x7f1a74a08000, message=0x7f1a74027210, ignore_missing_space=false) at /data/src/10.4/storage/innobase/include/buf0types.h:172
      #9  0x000055dc11921475 in buf_read_page_low (ignore_missing_space=false, unzip=false, zip_size=0, page_id=..., mode=132, type=0, sync=true, err=0x7f1a5effbbf4) at /data/src/10.4/storage/innobase/buf/buf0rea.cc:181
      #10 buf_read_page (page_id=..., zip_size=zip_size@entry=0) at /data/src/10.4/storage/innobase/buf/buf0rea.cc:388
      #11 0x000055dc1190379f in buf_page_get_low (page_id=..., zip_size=<optimized out>, rw_latch=<optimized out>, guess=<optimized out>, mode=<optimized out>, file=<optimized out>, line=<optimized out>, mtr=<optimized out>, err=<optimized out>) at /data/src/10.4/storage/innobase/buf/buf0buf.cc:4344
      #12 0x000055dc1196a2f9 in fil_crypt_flush_space (state=<optimized out>) at /data/src/10.4/storage/innobase/include/buf0types.h:148
      #13 0x000055dc1196a89e in fil_crypt_complete_rotate_space (state=<optimized out>) at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2353
      #14 0x000055dc119705fe in fil_crypt_thread () at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2456
      #15 0x00007f1a9762e609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #16 0x00007f1a9721d293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
       
      Thread 25 (Thread 0x7f1a807c1700 (LWP 3974059)):
      #0  futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x55dc13e7ff20) at ../sysdeps/nptl/futex-internal.h:183
      #1  __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x55dc13e7fed0, cond=0x55dc13e7fef8) at pthread_cond_wait.c:508
      #2  __pthread_cond_wait (cond=cond@entry=0x55dc13e7fef8, mutex=mutex@entry=0x55dc13e7fed0) at pthread_cond_wait.c:638
      #3  0x000055dc11811ee1 in os_event::wait (this=0x55dc13e7fec0) at /data/src/10.4/storage/innobase/include/sync0types.h:463
      #4  os_event::wait_low (this=0x55dc13e7fec0, reset_sig_count=3) at /data/src/10.4/storage/innobase/os/os0event.cc:325
      #5  0x000055dc11894259 in sync_array_wait_event (arr=0x55dc13d95eb0, cell=@0x7f1a807b8aa8: 0x55dc13d95fb0) at /data/src/10.4/storage/innobase/sync/sync0arr.cc:305
      #6  0x000055dc1195ab3d in TTASEventMutex<GenericPolicy>::enter (line=462, filename=0x55dc11e0a648 "/data/src/10.4/storage/innobase/fil/fil0fil.cc", max_delay=4, max_spins=60, this=0x55dc123a2300 <fil_system+32>) a
      t /usr/include/c++/9/bits/atomic_base.h:493
      #7  PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x55dc123a2300 <fil_system+32>, name=0x55dc11e0a648 "/data/src/10.4/storage/innobase/fil/fil0fil.cc", line=462, n_delay=4, n_spins=30) at /data/src/10.4
      /storage/innobase/include/ib0mutex.h:594
      #8  fil_space_t::add (this=0x7f1a18067a90, name=<optimized out>, handle=..., size=4, is_raw=<optimized out>, atomic_write=true, max_pages=18446744073709551614) at /data/src/10.4/storage/innobase/fil/fil0fil.cc:462
      #9  0x000055dc11963fc4 in fil_ibd_create (space_id=25, name=0x7f1a18151570 "test/#sql-3ca387_d", path=path@entry=0x7f1a18027710 "./test/#sql-3ca387_d.ibd", flags=<optimized out>, flags@entry=33, size=size@entry=4,
       mode=FIL_ENCRYPTION_DEFAULT, key_id=1, err=0x7f1a807b9144) at /data/src/10.4/storage/innobase/include/os0file.h:89
      #10 0x000055dc1192525f in dict_build_table_def_step (thr=<optimized out>, node=0x7f1a1804eb08) at /data/src/10.4/storage/innobase/dict/dict0crea.cc:423
      #11 0x000055dc11926624 in dict_create_table_step (thr=thr@entry=0x7f1a18067800) at /data/src/10.4/storage/innobase/dict/dict0crea.cc:1075
      #12 0x000055dc1182e108 in que_thr_step (thr=0x7f1a818a6198) at /data/src/10.4/storage/innobase/que/que0que.cc:1046
      #13 que_run_threads_low (thr=0x7f1a818a6198) at /data/src/10.4/storage/innobase/que/que0que.cc:1100
      #14 que_run_threads (thr=thr@entry=0x7f1a18067800) at /data/src/10.4/storage/innobase/que/que0que.cc:1140
      #15 0x000055dc1185b173 in row_create_table_for_mysql (table=table@entry=0x7f1a183de648, trx=0x7f1a818a6198, mode=FIL_ENCRYPTION_DEFAULT, key_id=1) at /data/src/10.4/storage/innobase/row/row0mysql.cc:2422
      #16 0x000055dc117a71cf in create_table_info_t::create_table_def (this=this@entry=0x7f1a807ba1d0) at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:11065
      #17 0x000055dc117a3534 in create_table_info_t::create_table (this=0x7f1a807ba1d0, create_fk=<optimized out>) at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:12303
      #18 0x000055dc117a7cc2 in ha_innobase::create (this=<optimized out>, name=<optimized out>, form=<optimized out>, create_info=<optimized out>, file_per_table=<optimized out>, trx=0x7f1a818a6198) at /data/src/10.4/s
      torage/innobase/handler/ha_innodb.cc:12855
      #19 0x000055dc115da094 in handler::ha_create (this=<optimized out>, name=<optimized out>, form=0x7f1a807ba760, info_arg=0x7f1a807be320) at /data/src/10.4/sql/handler.cc:4787
      #20 0x000055dc115daa1a in ha_create_table (thd=thd@entry=0x7f1a18000c48, path=path@entry=0x7f1a807bdf9d "./test/#sql-3ca387_d", db=0x7f1a180129e8 "test", table_name=0x7f1a180122b0 "table10_innodb_int", create_info
      =create_info@entry=0x7f1a807be320, frm=frm@entry=0x7f1a807bbcf0) at /data/src/10.4/sql/handler.cc:5251
      #21 0x000055dc1145364e in mysql_alter_table (thd=thd@entry=0x7f1a18000c48, new_db=new_db@entry=0x7f1a18005250, new_name=new_name@entry=0x7f1a18005658, create_info=create_info@entry=0x7f1a807be320, table_list=<opti
      mized out>, table_list@entry=0x7f1a18012328, alter_info=alter_info@entry=0x7f1a807be260, order_num=0, order=0x0, ignore=false) at /data/src/10.4/sql/sql_alter.h:292
      #22 0x000055dc114abe42 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x7f1a18000c48) at /data/src/10.4/sql/sql_alter.cc:520
      #23 0x000055dc113a89b0 in mysql_execute_command (thd=0x7f1a18000c48) at /data/src/10.4/sql/sql_parse.cc:6160
      #24 0x000055dc113b0263 in mysql_parse (thd=0x7f1a18000c48, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src/
      10.4/sql/sql_parse.cc:7958
      #25 0x000055dc113b281a in dispatch_command (command=COM_QUERY, thd=0x7f1a18000c48, packet=<optimized out>, packet_length=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src
      /10.4/sql/sql_class.h:1170
      #26 0x000055dc113b4a1a in do_command (thd=0x7f1a18000c48) at /data/src/10.4/sql/sql_parse.cc:1373
      #27 0x000055dc114a794e in do_handle_one_connection (connect=connect@entry=0x55dc14611a08) at /data/src/10.4/sql/sql_connect.cc:1412
      #28 0x000055dc114a7a6f in handle_one_connection (arg=0x55dc14611a08) at /data/src/10.4/sql/sql_connect.cc:1316
      #29 0x00007f1a9762e609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #30 0x00007f1a9721d293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
      

      A relatively easy way to reproduce it is running bootstrap in shm on a non-debug build of 10.4 (although it does not *only affect bootstrap, it happens upon normal operation as well):

      while [ 1 ] ; do rm -rf /dev/shm/data_scrub/*; \
      scripts/mysql_install_db --no-defaults \
      --innodb-encrypt-tables --innodb-encryption-threads=4 \
      --file-key-management-filename=`pwd`/mysql-test/std_data/keys.txt \
      --plugin-load-add=file_key_management \
      --innodb-encryption-rotate-key-age=0 \
      --innodb-background-scrub-data-uncompressed=1 \
      --datadir=/dev/shm/data_scrub; \
      if [ "$?" != "0" ] ; then break; fi; done
      

      This way it happens to be on average in 2-3 bootstrap attempts.

      Installing MariaDB/MySQL system tables in '/dev/shm/data_scrub' ...
      2021-02-03 20:00:52 0 [ERROR] [FATAL] InnoDB: Trying to read page number 0 in space 3, space name mysql/transaction_registry, which is outside the tablespace bounds. Byte offset 0, len 16384
      210203 20:00:52 [ERROR] mysqld got signal 6 ;
       
      Thread 17 (Thread 0x7fa877fff700 (LWP 3968928)):
      #0  0x00005583e5a4c713 in my_read (Filedes=Filedes@entry=21, Buffer=Buffer@entry=0x7fa877ffbe70 "Limit", ' ' <repeats 21 times>, "Soft Limit", ' ' <repeats 11 times>, "Hard Limit", ' ' <repeats 11 times>, "Units     \nMax cpu time", ' ' <repeats 14 times>, "unlimited", ' ' <repeats 12 times>, "unlimited", ' ' <repeats 12 times>, "seconds   \nMax file size", ' ' <repeats 13 times>, "unlimited       "..., Count=Count@entry=4096, MyFlags=MyFlags@entry=0) at /data/src/10.4/mysys/my_read.c:63
      #1  0x00005583e545cc3a in output_core_info () at /data/src/10.4/sql/signal_handler.cc:66
      #2  0x00005583e545d07e in handle_fatal_signal (sig=6) at /data/src/10.4/sql/signal_handler.cc:339
      #3  <signal handler called>
      #4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
      #5  0x00007fa8c8ea7859 in __GI_abort () at abort.c:79
      #6  0x00005583e512a58b in ib::fatal::~fatal (this=<optimized out>, __in_chrg=<optimized out>) at /data/src/10.4/storage/innobase/ut/ut0ut.cc:604
      #7  0x00005583e513e327 in fil_report_invalid_page_access (block_offset=0, space_id=3, space_name=0x5583e96f29c0 "mysql/transaction_registry", byte_offset=byte_offset@entry=0, len=len@entry=16384, is_read=<optimized out>) at /data/src/10.4/storage/innobase/include/ut0ut.h:354
      #8  0x00005583e513f8a1 in fil_io (type=..., sync=sync@entry=true, page_id=..., zip_size=zip_size@entry=0, byte_offset=byte_offset@entry=0, len=16384, buf=0x7fa8a4720000, message=0x7fa8a4017df0, ignore_missing_space=false) at /data/src/10.4/storage/innobase/include/buf0types.h:172
      #9  0x00005583e57af475 in buf_read_page_low (ignore_missing_space=false, unzip=false, zip_size=0, page_id=..., mode=132, type=0, sync=true, err=0x7fa877ffdbf4) at /data/src/10.4/storage/innobase/buf/buf0rea.cc:181
      #10 buf_read_page (page_id=..., zip_size=zip_size@entry=0) at /data/src/10.4/storage/innobase/buf/buf0rea.cc:388
      #11 0x00005583e579179f in buf_page_get_low (page_id=..., zip_size=<optimized out>, rw_latch=<optimized out>, guess=<optimized out>, mode=<optimized out>, file=<optimized out>, line=<optimized out>, mtr=<optimized out>, err=<optimized out>) at /data/src/10.4/storage/innobase/buf/buf0buf.cc:4344
      #12 0x00005583e57f82f9 in fil_crypt_flush_space (state=<optimized out>) at /data/src/10.4/storage/innobase/include/buf0types.h:148
      #13 0x00005583e57f889e in fil_crypt_complete_rotate_space (state=<optimized out>) at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2353
      #14 0x00005583e57fe5fe in fil_crypt_thread () at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2456
      #15 0x00007fa8c93b5609 in start_thread (arg=<optimized out>) at pthread_create.c:477
      #16 0x00007fa8c8fa4293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
       
      Thread 1 (Thread 0x7fa8c8e65d80 (LWP 3968901)):
      #0  futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x5583e8cf2f00) at ../sysdeps/nptl/futex-internal.h:183
      #1  __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x5583e8cf2eb0, cond=0x5583e8cf2ed8) at pthread_cond_wait.c:508
      #2  __pthread_cond_wait (cond=cond@entry=0x5583e8cf2ed8, mutex=mutex@entry=0x5583e8cf2eb0) at pthread_cond_wait.c:638
      #3  0x00005583e569fee1 in os_event::wait (this=0x5583e8cf2ea0) at /data/src/10.4/storage/innobase/include/sync0types.h:463
      #4  os_event::wait_low (this=0x5583e8cf2ea0, reset_sig_count=1) at /data/src/10.4/storage/innobase/os/os0event.cc:325
      #5  0x00005583e5722259 in sync_array_wait_event (arr=0x5583e8c08e90, cell=@0x7ffcb7b33818: 0x5583e8c08fd0) at /data/src/10.4/storage/innobase/sync/sync0arr.cc:305
      #6  0x00005583e57e8b3d in TTASEventMutex<GenericPolicy>::enter (line=462, filename=0x5583e5c98648 "/data/src/10.4/storage/innobase/fil/fil0fil.cc", max_delay=4, max_spins=60, this=0x5583e6230300 <fil_system+32>) at /usr/include/c++/9/bits/atomic_base.h:493
      #7  PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x5583e6230300 <fil_system+32>, name=0x5583e5c98648 "/data/src/10.4/storage/innobase/fil/fil0fil.cc", line=462, n_delay=4, n_spins=30) at /data/src/10.4/storage/innobase/include/ib0mutex.h:594
      #8  fil_space_t::add (this=0x5583e97022a0, name=<optimized out>, handle=..., size=4, is_raw=<optimized out>, atomic_write=true, max_pages=18446744073709551614) at /data/src/10.4/storage/innobase/fil/fil0fil.cc:462
      #9  0x00005583e57f1fc4 in fil_ibd_create (space_id=3, name=0x5583e96f3fa0 "mysql/transaction_registry", path=path@entry=0x5583e9704710 "./mysql/transaction_registry.ibd", flags=<optimized out>, flags@entry=33, size=size@entry=4, mode=FIL_ENCRYPTION_DEFAULT, key_id=1, err=0x7ffcb7b33eb4) at /data/src/10.4/storage/innobase/include/os0file.h:89
      #10 0x00005583e57b325f in dict_build_table_def_step (thr=<optimized out>, node=0x5583e97098e8) at /data/src/10.4/storage/innobase/dict/dict0crea.cc:423
      #11 0x00005583e57b4624 in dict_create_table_step (thr=thr@entry=0x5583e96f77d0) at /data/src/10.4/storage/innobase/dict/dict0crea.cc:1075
      #12 0x00005583e56bc108 in que_thr_step (thr=0x7fa8b33fe118) at /data/src/10.4/storage/innobase/que/que0que.cc:1046
      #13 que_run_threads_low (thr=0x7fa8b33fe118) at /data/src/10.4/storage/innobase/que/que0que.cc:1100
      #14 que_run_threads (thr=thr@entry=0x5583e96f77d0) at /data/src/10.4/storage/innobase/que/que0que.cc:1140
      #15 0x00005583e56e9173 in row_create_table_for_mysql (table=table@entry=0x5583e9702018, trx=0x7fa8b33fe118, mode=FIL_ENCRYPTION_DEFAULT, key_id=1) at /data/src/10.4/storage/innobase/row/row0mysql.cc:2422
      #16 0x00005583e56351cf in create_table_info_t::create_table_def (this=this@entry=0x7ffcb7b34f40) at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:11065
      #17 0x00005583e5631534 in create_table_info_t::create_table (this=0x7ffcb7b34f40, create_fk=<optimized out>) at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:12303
      #18 0x00005583e5635cc2 in ha_innobase::create (this=<optimized out>, name=<optimized out>, form=<optimized out>, create_info=<optimized out>, file_per_table=<optimized out>, trx=0x7fa8b33fe118) at /data/src/10.4/storage/innobase/handler/ha_innodb.cc:12855
      #19 0x00005583e5468094 in handler::ha_create (this=<optimized out>, name=<optimized out>, form=0x7ffcb7b354d0, info_arg=0x7ffcb7b37580) at /data/src/10.4/sql/handler.cc:4787
      #20 0x00005583e5468a1a in ha_create_table (thd=thd@entry=0x5583e8bef448, path=path@entry=0x7ffcb7b371b0 "./mysql/transaction_registry", db=0x5583e96fdce0 "mysql", table_name=0x5583e96fd5c8 "transaction_registry", create_info=create_info@entry=0x7ffcb7b37580, frm=frm@entry=0x7ffcb7b371a0) at /data/src/10.4/sql/handler.cc:5251
      #21 0x00005583e52dbdf9 in create_table_impl (thd=thd@entry=0x5583e8bef448, orig_db=..., orig_table_name=..., db=..., table_name=..., path=path@entry=0x7ffcb7b371b0 "./mysql/transaction_registry", options=..., create_info=0x7ffcb7b37580, alter_info=0x7ffcb7b374c0, create_table_mode=0, is_trans=0x7ffcb7b37437, key_info=0x7ffcb7b37198, key_count=0x7ffcb7b37194, frm=0x7ffcb7b371a0) at /data/src/10.4/sql/sql_table.cc:5126
      #22 0x00005583e52dc21f in mysql_create_table_no_lock (thd=thd@entry=0x5583e8bef448, db=db@entry=0x5583e96fd638, table_name=table_name@entry=0x5583e96fd648, create_info=create_info@entry=0x7ffcb7b37580, alter_info=0x7ffcb7b374c0, is_trans=is_trans@entry=0x7ffcb7b37437, create_table_mode=0, table_list=0x5583e96fd620) at /data/src/10.4/sql/sql_table.cc:5210
      #23 0x00005583e52dc450 in mysql_create_table (thd=thd@entry=0x5583e8bef448, create_table=create_table@entry=0x5583e96fd620, create_info=create_info@entry=0x7ffcb7b37580, alter_info=alter_info@entry=0x7ffcb7b374c0) at /data/src/10.4/sql/sql_table.cc:5302
      #24 0x00005583e52dd86b in Sql_cmd_create_table_like::execute (this=<optimized out>, thd=0x5583e8bef448) at /data/src/10.4/sql/sql_table.cc:11532
      #25 0x00005583e52369b0 in mysql_execute_command (thd=0x5583e8bef448) at /data/src/10.4/sql/sql_parse.cc:6160
      #26 0x00005583e5253a5e in Prepared_statement::execute (this=0x5583e96f6428, expanded_query=<optimized out>, open_cursor=false) at /data/src/10.4/sql/sql_prepare.cc:4969
      #27 0x00005583e5253c49 in Prepared_statement::execute_loop (packet=<optimized out>, packet_end=<optimized out>, open_cursor=<optimized out>, expanded_query=0x7ffcb7b391a0, this=0x5583e96f6428) at /data/src/10.4/sql/sql_prepare.cc:4438
      #28 Prepared_statement::execute_loop (this=0x5583e96f6428, expanded_query=0x7ffcb7b391a0, open_cursor=<optimized out>, packet=<optimized out>, packet_end=<optimized out>) at /data/src/10.4/sql/sql_prepare.cc:4393
      #29 0x00005583e5253f4b in mysql_sql_stmt_execute (thd=thd@entry=0x5583e8bef448) at /data/src/10.4/sql/sql_prepare.cc:3555
      #30 0x00005583e52391ee in mysql_execute_command (thd=0x5583e8bef448) at /data/src/10.4/sql/sql_parse.cc:3952
      #31 0x00005583e523e263 in mysql_parse (thd=0x5583e8bef448, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7ffcb7b3aa40, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.4/sql/sql_parse.cc:7958
      #32 0x00005583e523e751 in bootstrap (file=0x5583e6b4afa0 <instrumented_stdin>) at /data/src/10.4/sql/sql_class.h:1167
      #33 0x00005583e5177856 in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /data/src/10.4/sql/mysqld.cc:5835
      #34 0x00007fa8c8ea90b3 in __libc_start_main (main=0x5583e5152460 <main(int, char**)>, argc=18, argv=0x7ffcb7b3fce8, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffcb7b3fcd8) at ../csu/libc-start.c:308
      #35 0x00005583e516abae in _start () at /data/src/10.4/sql/mysqld.cc:4683
      

      All threads' stack trace is attached.

      Attachments

        Issue Links

          Activity

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.