[MDEV-18454] Assertion `0' failed in ReadView::check_trx_id_sanity upon crash-upgrade from 10.2.6 Created: 2019-02-02  Updated: 2021-06-23  Resolved: 2021-06-21

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3, 10.4
Fix Version/s: 10.3.30, 10.4.20, 10.5.11, 10.6.3

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 1
Labels: None

Issue Links:
Relates
relates to MDEV-15158 On commit, do not write to the TRX_SY... Closed
relates to MDEV-15912 InnoDB: Failing assertion: purge_sys.... Closed

 Description   

10.3 14a58cea

 
2019-02-02 23:35:15 9 [Warning] InnoDB: A transaction id in a record of table `test`.`t003` is newer than the system-wide maximum.
 
mysqld: /data/src/10.3/storage/innobase/trx/trx0sys.cc:62: static void ReadView::check_trx_id_sanity(trx_id_t, const table_name_t&): Assertion `0' failed.
 
190202 23:35:15 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f83396d5ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
 
#8  0x000055f245849f66 in ReadView::check_trx_id_sanity (id=83180, name=...) at /data/src/10.3/storage/innobase/trx/trx0sys.cc:62
 
#9  0x000055f2456c913c in ReadView::changes_visible (this=0x7f8338037258, id=83180, name=...) at /data/src/10.3/storage/innobase/include/read0types.h:212
 
#10 0x000055f2456b42f8 in lock_clust_rec_cons_read_sees (rec=0x7f83169646a8 "\200", index=0x7f829002da08, offsets=0x7f8321ceae00, view=0x7f8338037258) at /data/src/10.3/storage/innobase/lock/lock0lock.cc:403
 
#11 0x000055f2457ce3ce in row_search_mvcc (buf=0x7f82900268d0 "", mode=PAGE_CUR_G, prebuilt=0x7f82900244c8, match_mode=0, direction=1) at /data/src/10.3/storage/innobase/row/row0sel.cc:5124
 
#12 0x000055f24578cc49 in row_search_for_mysql (buf=0x7f82900268d0 "", mode=PAGE_CUR_G, prebuilt=0x7f82900244c8, match_mode=0, direction=1) at /data/src/10.3/storage/innobase/include/row0sel.ic:137
 
#13 0x000055f24579871a in row_scan_index_for_mysql (prebuilt=0x7f82900244c8, index=0x7f829002da08, n_rows=0x7f8321cebc00) at /data/src/10.3/storage/innobase/row/row0mysql.cc:4835
 
#14 0x000055f2456458b5 in ha_innobase::check (this=0x7f8290021bc8, thd=0x7f8290000b00, check_opt=0x7f8290005928) at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:14542
 
#15 0x000055f24531dbdf in handler::ha_check (this=0x7f8290021bc8, thd=0x7f8290000b00, check_opt=0x7f8290005928) at /data/src/10.3/sql/handler.cc:4199
 
#16 0x000055f24518deff in mysql_admin_table(THD *, TABLE_LIST *, HA_CHECK_OPT *, const char *, thr_lock_type, bool, bool, uint, int (*)(THD *, TABLE_LIST *, HA_CHECK_OPT *), struct {...}, int (*)(THD *, TABLE_LIST *, HA_CHECK_OPT *)) (thd=0x7f8290000b00, tables=0x7f8290013a20, check_opt=0x7f8290005928, operator_name=0x55f245bc4914 "check", lock_type=TL_READ_NO_INSERT, org_open_for_modify=false, repair_table_use_frm=false, extra_open_options=32, prepare_func=0x0, operator_func=(int (handler::*)(handler * const, THD *, HA_CHECK_OPT *)) 0x55f24531da5c <handler::ha_check(THD*, st_ha_check_opt*)>, view_operator_func=0x55f245122e86 <view_check(THD*, TABLE_LIST*, st_ha_check_opt*)>) at /data/src/10.3/sql/sql_admin.cc:803
 
#17 0x000055f2451900ba in Sql_cmd_check_table::execute (this=0x7f8290014068, thd=0x7f8290000b00) at /data/src/10.3/sql/sql_admin.cc:1347
 
#18 0x000055f2450246aa in mysql_execute_command (thd=0x7f8290000b00) at /data/src/10.3/sql/sql_parse.cc:6285
 
#19 0x000055f24502977b in mysql_parse (thd=0x7f8290000b00, rawbuf=0x7f8290013948 "CHECK TABLE test.t003", length=21, parser_state=0x7f8321ced640, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:8092
 
#20 0x000055f24501692f in dispatch_command (command=COM_QUERY, thd=0x7f8290000b00, packet=0x7f829001ba31 "", packet_length=21, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1851
 
#21 0x000055f245015353 in do_command (thd=0x7f8290000b00) at /data/src/10.3/sql/sql_parse.cc:1396
 
#22 0x000055f24517d47a in do_handle_one_connection (connect=0x55f248cabdc0) at /data/src/10.3/sql/sql_connect.cc:1402
 
#23 0x000055f24517d1fe in handle_one_connection (arg=0x55f248cabdc0) at /data/src/10.3/sql/sql_connect.cc:1308
 
#24 0x00007f833b3ac494 in start_thread (arg=0x7f8321cee700) at pthread_create.c:333
 
#25 0x00007f833979293f in clone () from /lib/x86_64-linux-gnu/libc.so.6

The failure happened upon crash upgrade from 10.2.6 running concurrent DML workflow. The datadir stored after the intentional 10.2.6 crash before any attempt to start the server can be found here:
ftp://perro.askmonty.org/public/jira/mdev18454-data.tar.gz

To reproduce, unpack the datadir, start 10.3 or 10.4 debug server with

--file-key-management --file-key-management-filename=/data/bld/keys.txt --plugin-load-add=file_key_management.so --innodb-encrypt-tables --innodb-encrypt-log --innodb-encryption-threads=4 --aria-encrypt-tables=1 --encrypt-tmp-disk-tables=1 --encrypt-binlog --innodb-page-size=8K --innodb-compression-algorithm=none --loose-innodb-file-format=Barracuda --loose-innodb-file-per-table=1 --loose-max-statement-time=20 --loose-lock-wait-timeout=20 --loose-innodb-lock-wait-timeout=10 --loose-innodb_log_compressed_pages=on

(modify the path to the key file as needed), and run

CHECK TABLE test.t003;

If you use the interactive client to run the statement, start it with no-auto-rehash (-A)

Reproducible on 10.3 and 10.4.
Non-debug builds don't crash, but produce a bunch of errors:

2019-02-02 23:30:36 10 [Warning] InnoDB: A transaction id in a record of table `test`.`t003` is newer than the system-wide maximum.
 
2019-02-02 23:30:36 10 [Warning] InnoDB: A transaction id in a record of table `test`.`t003` is newer than the system-wide maximum.
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: PAGE_MAX_TRX_ID out of bounds: 83182, 83180
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: Apparent corruption in space 15 page 48 index `col_timestamp_key`
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: In page 48 of index `col_timestamp_key` of table `test`.`t003`
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: PAGE_MAX_TRX_ID out of bounds: 83182, 83180
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: Apparent corruption in space 15 page 37 index `col_int_not_null_key`
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: In page 37 of index `col_int_not_null_key` of table `test`.`t003`
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: PAGE_MAX_TRX_ID out of bounds: 83182, 83180
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: Apparent corruption in space 15 page 42 index `col_int_key`
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: In page 42 of index `col_int_key` of table `test`.`t003`
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: PAGE_MAX_TRX_ID out of bounds: 83182, 83180
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: Apparent corruption in space 15 page 46 index `col_timestamp_not_null_key`
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: In page 46 of index `col_timestamp_not_null_key` of table `test`.`t003`
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: PAGE_MAX_TRX_ID out of bounds: 83182, 83180
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: Apparent corruption in space 15 page 35 index `col_varchar_8_key`
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: In page 35 of index `col_varchar_8_key` of table `test`.`t003`
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: PAGE_MAX_TRX_ID out of bounds: 83182, 83180
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: Apparent corruption in space 15 page 34 index `col_varchar_8_not_null_key`
 
2019-02-02 23:30:36 10 [ERROR] InnoDB: In page 34 of index `col_varchar_8_not_null_key` of table `test`.`t003`

Doesn't seem to be reproducible on 10.2.

 Comments   
Comment by Alice Sherepa [ 2019-03-06 ]

10.4 1bcb66c597b79ed61a

 
mysqld: /git/10.4/storage/innobase/trx/trx0sys.cc:62: static void ReadView::check_trx_id_sanity(trx_id_t, const table_name_t&): Assertion `0' failed.
 
 
 
/lib/x86_64-linux-gnu/libc.so.6(+0x2dc82)[0x7f5836a8cc82]
 
trx/trx0sys.cc:62(ReadView::check_trx_id_sanity(unsigned long, table_name_t const&))[0x55643d9bee8d]
 
include/read0types.h:222(ReadView::changes_visible(unsigned long, table_name_t const&) const)[0x55643d71ea18]
 
lock/lock0lock.cc:404(lock_clust_rec_cons_read_sees(unsigned char const*, dict_index_t*, unsigned long const*, ReadView*))[0x55643d6f8f32]
 
row/row0sel.cc:1899(row_sel(sel_node_t*, que_thr_t*))[0x55643d8edb81]
 
row/row0sel.cc:2343(row_sel_step(que_thr_t*))[0x55643d8ef678]
 
que/que0que.cc:1018(que_thr_step(que_thr_t*))[0x55643d7ddda7]
 
que/que0que.cc:1104(que_run_threads_low(que_thr_t*))[0x55643d7de40e]
 
que/que0que.cc:1146(que_run_threads(que_thr_t*))[0x55643d7de755]
 
fts/fts0sql.cc:240(fts_eval_sql(trx_t*, que_fork_t*))[0x55643dc51f26]
 
fts/fts0fts.cc:7134(fts_drop_orphaned_tables())[0x55643dc22ae6]
 
log/log0recv.cc:3605(recv_recovery_rollback_active())[0x55643d75525e]
 
srv/srv0start.cc:2159(srv_start(bool))[0x55643d94bfc2]
 
handler/ha_innodb.cc:4269(innodb_init(void*))[0x55643d5c734e]
 
sql/handler.cc:531(ha_initialize_handlerton(st_plugin_int*))[0x55643cd8645c]
 
sql/sql_plugin.cc:1437(plugin_initialize(st_mem_root*, st_plugin_int*, int*, char**, bool))[0x55643c65626a]
 
sql/sql_plugin.cc:1719(plugin_init(int*, char**, int))[0x55643c657ad7]
 
sql/mysqld.cc:5089(init_server_components())[0x55643c385047]
 
sql/mysqld.cc:5618(mysqld_main(int, char**))[0x55643c386f4a]
 
sql/main.cc:26(main)[0x55643c371ba0]
 
csu/libc-start.c:325(__libc_start_main)[0x7f5836a7f830]
 
/git/10.4/sql/mysqld(_start+0x29)[0x55643c371a79]

Comment by Marko Mäkelä [ 2019-03-26 ]

MDEV-15158 in MariaDB 10.3.5 writes the transaction metadata only to undo log pages, not to the TRX_SYS page. But it should recover the data from the TRX_SYS page as well.

Possibly the data set has something in common with MDEV-15912.

Comment by Marko Mäkelä [ 2021-06-21 ]

This was fixed by fixing MDEV-15912. Startup will now be refused as follows:

2021-06-21 18:19:23 0 [ERROR] InnoDB: upgrade from older version than MariaDB 10.3 requires clean shutdown
 
2021-06-21 18:19:23 0 [Note] InnoDB: Retry with innodb_force_recovery=5
 
2021-06-21 18:19:23 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[2000] with error Data structure corruption

If I add innodb_force_recovery=5 to the startup options, the server will start up and CHECK TABLE t003 will report OK status. (It will be using READ UNCOMMITTED isolation level in this case.)

Comment by Marko Mäkelä [ 2021-06-23 ]

MDEV-15912 introduced a too strict check that was corrected in MDEV-25981. The dataset will actually crash-upgrade just fine now:

10.4 09b03ff31b8fd71aee265c22479613a28879f3b9

 
2021-06-23  9:19:02 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=17249777
 
2021-06-23  9:19:03 0 [Note] InnoDB: Trying to recover page [page id: space=0, page number=731] from the doublewrite buffer.
 
…
 
2021-06-23  9:19:03 0 [Note] InnoDB: Trying to recover page [page id: space=0, page number=745] from the doublewrite buffer.
 
2021-06-23  9:19:03 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
 
2021-06-23  9:19:03 0 [Note] InnoDB: Trx id counter is 83185
 
2021-06-23  9:19:03 0 [Note] InnoDB: Starting final batch to recover 1459 pages from redo log.
 
2021-06-23  9:19:04 0 [Note] InnoDB: Upgrading redo log: 2*5242880 bytes; LSN=18571208
 
…
 
2021-06-23  9:19:05 0 [Note] Server socket created on IP: '::'.
 
2021-06-23  9:19:05 0 [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','IGNORE_BAD_TABLE_OPTIONS','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH','EMPTY_STRING_IS_NULL','SIMULTANEOUS_ASSIGNMENT'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','IGNORE_BAD_TABLE_OPTIONS','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALU
 
2021-06-23  9:19:05 0 [ERROR] mysqld: Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
 
2021-06-23  9:19:05 0 [Note] Reading of all Master_info entries succeeded
 
2021-06-23  9:19:05 0 [Note] Added new Master_info '' to hash table
 
2021-06-23  9:19:05 0 [Note] 10.4/sql/mysqld: ready for connections.
 
Version: '10.4.21-MariaDB-debug'  socket: '/tmp/mysql.sock'  port: 3306  Source distribution

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