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

Assertion `0' failed in ReadView::check_trx_id_sanity upon crash-upgrade from 10.2.6

Details

    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.

      Attachments

        Issue Links

          Activity

            alice Alice Sherepa added a comment -

            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]
            

            alice Alice Sherepa added a comment - 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]

            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.

            marko Marko Mäkelä added a comment - 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 .

            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.)

            marko Marko Mäkelä added a comment - 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.)

            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
            

            marko Marko Mäkelä added a comment - 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

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              1 Vote for this issue
              Watchers:
              4 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.