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

Assertion `mode == 16 || mode == 12 || !fix_block->page.file_page_was_freed' failed in buf_page_get_gen

Details

    Description

      Note: The assertion is the same as in MDEV-14711, but the stack trace is completely different, so I don't have enough evidence to assume it's the same problem.

      Note: The test case uses versioning, so it's not applicable to 10.2. Possibly the underlying problem exists in 10.2 as well.

      --source include/have_innodb.inc
       
      CREATE TABLE t1 (f1 INT, f2 TEXT, f3 INT, FULLTEXT ftidx(f2), KEY idx (f1), FOREIGN KEY (f3) REFERENCES t1 (f1) ON DELETE SET NULL) WITH SYSTEM VERSIONING ENGINE=InnoDB;
      SET system_versioning_alter_history= KEEP;
      ALTER TABLE t1 DROP KEY ftidx;
      INSERT INTO t1 VALUES (1,REPEAT('a',8193),1), (1,REPEAT('b',8193),1);
      --error ER_FOREIGN_DUPLICATE_KEY_WITH_CHILD_INFO
      DELETE FROM t1;
      ALTER TABLE t1 ADD FULLTEXT ftidx(f2);
       
      # Cleanup
      DROP TABLE t1;
      

      10.4 f9528821

      mysqld: /data/src/10.4/storage/innobase/buf/buf0buf.cc:4861: buf_block_t* buf_page_get_gen(page_id_t, ulint, ulint, buf_block_t*, ulint, const char*, unsigned int, mtr_t*, dberr_t*): Assertion `mode == 16 || mode == 12 || !fix_block->page.file_page_was_freed' failed.
      191123 22:02:27 [ERROR] mysqld got signal 6 ;
       
      #6  0x00007f1a8d952e67 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x5557f644ccc8 "mode == 16 || mode == 12 || !fix_block->page.file_page_was_freed", file=file@entry=0x5557f644acb0 "/data/src/10.4/storage/innobase/buf/buf0buf.cc", line=line@entry=4861, function=function@entry=0x5557f6450340 <buf_page_get_gen(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*)::__PRETTY_FUNCTION__> "buf_block_t* buf_page_get_gen(page_id_t, ulint, ulint, buf_block_t*, ulint, const char*, unsigned int, mtr_t*, dberr_t*)") at assert.c:92
      #7  0x00007f1a8d952f12 in __GI___assert_fail (assertion=0x5557f644ccc8 "mode == 16 || mode == 12 || !fix_block->page.file_page_was_freed", file=0x5557f644acb0 "/data/src/10.4/storage/innobase/buf/buf0buf.cc", line=4861, function=0x5557f6450340 <buf_page_get_gen(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned int, mtr_t*, dberr_t*)::__PRETTY_FUNCTION__> "buf_block_t* buf_page_get_gen(page_id_t, ulint, ulint, buf_block_t*, ulint, const char*, unsigned int, mtr_t*, dberr_t*)") at assert.c:101
      #8  0x00005557f5d23413 in buf_page_get_gen (page_id=..., zip_size=0, rw_latch=1, guess=0x0, mode=10, file=0x5557f6435b50 "/data/src/10.4/storage/innobase/btr/btr0cur.cc", line=8350, mtr=0x7f1a62ffc570, err=0x0) at /data/src/10.4/storage/innobase/buf/buf0buf.cc:4861
      #9  0x00005557f5ced739 in btr_copy_blob_prefix (buf=0x7f1a2c000bd8 "", len=8193, space_id=5, page_no=8, offset=38) at /data/src/10.4/storage/innobase/btr/btr0cur.cc:8350
      #10 0x00005557f5cee229 in btr_copy_externally_stored_field_prefix_low (buf=0x7f1a2c000bd8 "", len=8193, zip_size=0, space_id=5, page_no=8, offset=38) at /data/src/10.4/storage/innobase/btr/btr0cur.cc:8559
      #11 0x00005557f5cee4be in btr_copy_externally_stored_field (len=0x7f1a62ffcc18, data=0x7f1a38152cf0 "", zip_size=0, local_len=0, heap=0x7f1a2c0008c0) at /data/src/10.4/storage/innobase/btr/btr0cur.cc:8665
      #12 0x00005557f5b70e61 in fts_parallel_tokenization (arg=0x7f1a38150130) at /data/src/10.4/storage/innobase/row/row0ftsort.cc:837
      #13 0x00007f1a8f4c84a4 in start_thread (arg=0x7f1a62ffd700) at pthread_create.c:456
      #14 0x00007f1a8da0fd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
      

      Reproducible on 10.3-10.5.
      No crash on a non-debug build, instead it fails with

      DROP TABLE t1;
      bug.buf1 'innodb'                        [ fail ]  Found warnings/errors in server log file!
              Test ended at 2019-11-23 22:05:09
      line
      2019-11-23 22:05:09 9 [ERROR] InnoDB: Duplicate FTS_DOC_ID value on table `test`.`t1`
      ^ Found warnings in /data/bld/10.4-rel-nightly/mysql-test/var/log/mysqld.1.err
      ok
      

      Attachments

        Issue Links

          Activity

            For me, the freed BLOB page is page 8 in test/t1.ibd (tablespace ID 5). It was freed during a ROLLBACK of the INSERT part of a versioned DELETE statement:

            10.4 f9ceb0a67ffb20631c936a7e8e8776c000d677ac

            #0  fseg_free_page_func (seg_header=0x7ffff089404a "", space=0x7fffa0020e70, 
                offset=8, ahi=false, log=true, mtr=0x7ffff00c1880)
                at /mariadb/10.4/storage/innobase/fsp/fsp0fsp.cc:2864
            #1  0x000055555679ce37 in btr_page_free (index=0x7fffa00232f8, 
                block=0x7ffff0398e20, mtr=0x7ffff00c1880, blob=true)
                at /mariadb/10.4/storage/innobase/btr/btr0btr.cc:761
            #2  0x00005555567ef07d in btr_free_externally_stored_field (
                index=0x7fffa00232f8, field_ref=0x7ffff0894131 "", rec=0x7ffff089411a "", 
                offsets=0x7fffa00962d8, page_zip=0x0, i=4, rollback=true, 
                local_mtr=0x7ffff00c2560)
                at /mariadb/10.4/storage/innobase/btr/btr0cur.cc:8219
            #3  0x00005555567e844c in btr_rec_free_externally_stored_fields (
                index=0x7fffa00232f8, rec=0x7ffff089411a "", offsets=0x7fffa00962d8, 
                page_zip=0x0, rollback=true, mtr=0x7ffff00c2560)
                at /mariadb/10.4/storage/innobase/btr/btr0cur.cc:8270
            #4  0x00005555567e70f9 in btr_cur_pessimistic_delete (err=0x7ffff00c254c, 
                has_reserved_extents=0, cursor=0x7fffa00a0e18, flags=0, rollback=true, 
                mtr=0x7ffff00c2560) at /mariadb/10.4/storage/innobase/btr/btr0cur.cc:5941
            #5  0x00005555569a107e in row_undo_ins_remove_clust_rec (node=0x7fffa00a0da8)
                at /mariadb/10.4/storage/innobase/row/row0uins.cc:187
            #6  0x000055555699ec1d in row_undo_ins (node=0x7fffa00a0da8, 
                thr=0x7fffa0022928) at /mariadb/10.4/storage/innobase/row/row0uins.cc:587
            #7  0x00005555566e69fb in row_undo (node=0x7fffa00a0da8, thr=0x7fffa0022928)
                at /mariadb/10.4/storage/innobase/row/row0undo.cc:438
            #8  0x00005555566e6570 in row_undo_step (thr=0x7fffa0022928)
                at /mariadb/10.4/storage/innobase/row/row0undo.cc:499
            #9  0x00005555566001d6 in que_thr_step (thr=0x7fffa0022928)
                at /mariadb/10.4/storage/innobase/que/que0que.cc:1035
            #10 0x00005555565ff1d8 in que_run_threads_low (thr=0x7fffa0022928)
                at /mariadb/10.4/storage/innobase/que/que0que.cc:1099
            #11 0x00005555565feef8 in que_run_threads (thr=0x7fffa0022928)
                at /mariadb/10.4/storage/innobase/que/que0que.cc:1139
            #12 0x000055555676b20f in trx_rollback_to_savepoint_low (trx=0x7ffff0b64140, 
                savept=0x7ffff00c3b28)
                at /mariadb/10.4/storage/innobase/trx/trx0roll.cc:136
            #13 0x000055555676ab3f in trx_rollback_to_savepoint (trx=0x7ffff0b64140, 
                savept=0x7ffff00c3b28)
                at /mariadb/10.4/storage/innobase/trx/trx0roll.cc:189
            #14 0x00005555566778f2 in row_mysql_handle_errors (new_err=0x7ffff00c3b24, 
                trx=0x7ffff0b64140, thr=0x7fffa009a4d8, savept=0x7ffff00c3b28)
                at /mariadb/10.4/storage/innobase/row/row0mysql.cc:735
            #15 0x000055555667cb05 in row_update_for_mysql (prebuilt=0x7fffa0033258)
                at /mariadb/10.4/storage/innobase/row/row0mysql.cc:1908
            #16 0x0000555556478266 in ha_innobase::update_row (this=0x7fffa003c9a0, 
                old_row=0x7fffa001d120 "\370\001", new_row=0x7fffa001d0f8 "\370\001")
                at /mariadb/10.4/storage/innobase/handler/ha_innodb.cc:8841
            #17 0x00005555561cf5df in handler::ha_update_row (this=0x7fffa003c9a0, 
                old_data=0x7fffa001d120 "\370\001", new_data=0x7fffa001d0f8 "\370\001")
                at /mariadb/10.4/sql/handler.cc:6719
            #18 0x00005555563eafca in TABLE::delete_row (this=0x7fffa0050308)
                at /mariadb/10.4/sql/sql_delete.cc:293
            #19 0x00005555563e6cb3 in mysql_delete (thd=0x7fffa0000ce8, 
                table_list=0x7fffa00146f8, conds=0x7fffa0015be8, 
                order_list=0x7fffa0005698, limit=18446744073709551615, options=0, 
                result=0x0) at /mariadb/10.4/sql/sql_delete.cc:804
            #20 0x0000555555dd7677 in mysql_execute_command (thd=0x7fffa0000ce8)
                at /mariadb/10.4/sql/sql_parse.cc:4728
            #21 0x0000555555dc971a in mysql_parse (thd=0x7fffa0000ce8, 
                rawbuf=0x7fffa0014630 "DELETE FROM t1", length=14, 
                parser_state=0x7ffff00c9928, is_com_multi=false, is_next_command=false)
                at /mariadb/10.4/sql/sql_parse.cc:7901
            

            If I change the last ALTER TABLE to CHECK TABLE t1; then it will report the following:

            CREATE TABLE t1 (f1 INT, f2 TEXT, f3 INT, FULLTEXT ftidx(f2), KEY idx (f1), FOREIGN KEY (f3) REFERENCES t1 (f1) ON DELETE SET NULL) WITH SYSTEM VERSIONING ENGINE=InnoDB;
            SET system_versioning_alter_history= KEEP;
            ALTER TABLE t1 DROP KEY ftidx;
            INSERT INTO t1 VALUES (1,REPEAT('a',8193),1), (1,REPEAT('b',8193),1);
            DELETE FROM t1;
            ERROR 23000: Foreign key constraint for table 't1', record '1' would lead to a duplicate entry in table 't1', key 'FTS_DOC_ID_INDEX'
            CHECK TABLE t1;
            Table	Op	Msg_type	Msg_text
            test.t1	check	Warning	InnoDB: Index 'idx' contains 1 entries, should be 2.
            test.t1	check	error	Corrupt
            DROP TABLE t1;
            innodb.MDEV-21137 'innodb'                      [ fail ]  Found warnings/errors in server log file!
                    Test ended at 2019-11-25 16:24:29
            line
            2019-11-25 16:24:29 9 [ERROR] InnoDB: Duplicate FTS_DOC_ID value on table `test`.`t1`
            2019-11-25 16:24:29 9 [ERROR] InnoDB: Flagged corruption of `idx` in table `test`.`t1` in CHECK TABLE; Wrong count
            

            I think that something is wrong with the implementation of system-versioned tables.

            marko Marko Mäkelä added a comment - For me, the freed BLOB page is page 8 in test/t1.ibd (tablespace ID 5). It was freed during a ROLLBACK of the INSERT part of a versioned DELETE statement: 10.4 f9ceb0a67ffb20631c936a7e8e8776c000d677ac #0 fseg_free_page_func (seg_header=0x7ffff089404a "", space=0x7fffa0020e70, offset=8, ahi=false, log=true, mtr=0x7ffff00c1880) at /mariadb/10.4/storage/innobase/fsp/fsp0fsp.cc:2864 #1 0x000055555679ce37 in btr_page_free (index=0x7fffa00232f8, block=0x7ffff0398e20, mtr=0x7ffff00c1880, blob=true) at /mariadb/10.4/storage/innobase/btr/btr0btr.cc:761 #2 0x00005555567ef07d in btr_free_externally_stored_field ( index=0x7fffa00232f8, field_ref=0x7ffff0894131 "", rec=0x7ffff089411a "", offsets=0x7fffa00962d8, page_zip=0x0, i=4, rollback=true, local_mtr=0x7ffff00c2560) at /mariadb/10.4/storage/innobase/btr/btr0cur.cc:8219 #3 0x00005555567e844c in btr_rec_free_externally_stored_fields ( index=0x7fffa00232f8, rec=0x7ffff089411a "", offsets=0x7fffa00962d8, page_zip=0x0, rollback=true, mtr=0x7ffff00c2560) at /mariadb/10.4/storage/innobase/btr/btr0cur.cc:8270 #4 0x00005555567e70f9 in btr_cur_pessimistic_delete (err=0x7ffff00c254c, has_reserved_extents=0, cursor=0x7fffa00a0e18, flags=0, rollback=true, mtr=0x7ffff00c2560) at /mariadb/10.4/storage/innobase/btr/btr0cur.cc:5941 #5 0x00005555569a107e in row_undo_ins_remove_clust_rec (node=0x7fffa00a0da8) at /mariadb/10.4/storage/innobase/row/row0uins.cc:187 #6 0x000055555699ec1d in row_undo_ins (node=0x7fffa00a0da8, thr=0x7fffa0022928) at /mariadb/10.4/storage/innobase/row/row0uins.cc:587 #7 0x00005555566e69fb in row_undo (node=0x7fffa00a0da8, thr=0x7fffa0022928) at /mariadb/10.4/storage/innobase/row/row0undo.cc:438 #8 0x00005555566e6570 in row_undo_step (thr=0x7fffa0022928) at /mariadb/10.4/storage/innobase/row/row0undo.cc:499 #9 0x00005555566001d6 in que_thr_step (thr=0x7fffa0022928) at /mariadb/10.4/storage/innobase/que/que0que.cc:1035 #10 0x00005555565ff1d8 in que_run_threads_low (thr=0x7fffa0022928) at /mariadb/10.4/storage/innobase/que/que0que.cc:1099 #11 0x00005555565feef8 in que_run_threads (thr=0x7fffa0022928) at /mariadb/10.4/storage/innobase/que/que0que.cc:1139 #12 0x000055555676b20f in trx_rollback_to_savepoint_low (trx=0x7ffff0b64140, savept=0x7ffff00c3b28) at /mariadb/10.4/storage/innobase/trx/trx0roll.cc:136 #13 0x000055555676ab3f in trx_rollback_to_savepoint (trx=0x7ffff0b64140, savept=0x7ffff00c3b28) at /mariadb/10.4/storage/innobase/trx/trx0roll.cc:189 #14 0x00005555566778f2 in row_mysql_handle_errors (new_err=0x7ffff00c3b24, trx=0x7ffff0b64140, thr=0x7fffa009a4d8, savept=0x7ffff00c3b28) at /mariadb/10.4/storage/innobase/row/row0mysql.cc:735 #15 0x000055555667cb05 in row_update_for_mysql (prebuilt=0x7fffa0033258) at /mariadb/10.4/storage/innobase/row/row0mysql.cc:1908 #16 0x0000555556478266 in ha_innobase::update_row (this=0x7fffa003c9a0, old_row=0x7fffa001d120 "\370\001", new_row=0x7fffa001d0f8 "\370\001") at /mariadb/10.4/storage/innobase/handler/ha_innodb.cc:8841 #17 0x00005555561cf5df in handler::ha_update_row (this=0x7fffa003c9a0, old_data=0x7fffa001d120 "\370\001", new_data=0x7fffa001d0f8 "\370\001") at /mariadb/10.4/sql/handler.cc:6719 #18 0x00005555563eafca in TABLE::delete_row (this=0x7fffa0050308) at /mariadb/10.4/sql/sql_delete.cc:293 #19 0x00005555563e6cb3 in mysql_delete (thd=0x7fffa0000ce8, table_list=0x7fffa00146f8, conds=0x7fffa0015be8, order_list=0x7fffa0005698, limit=18446744073709551615, options=0, result=0x0) at /mariadb/10.4/sql/sql_delete.cc:804 #20 0x0000555555dd7677 in mysql_execute_command (thd=0x7fffa0000ce8) at /mariadb/10.4/sql/sql_parse.cc:4728 #21 0x0000555555dc971a in mysql_parse (thd=0x7fffa0000ce8, rawbuf=0x7fffa0014630 "DELETE FROM t1", length=14, parser_state=0x7ffff00c9928, is_com_multi=false, is_next_command=false) at /mariadb/10.4/sql/sql_parse.cc:7901 If I change the last ALTER TABLE to CHECK TABLE t1; then it will report the following: CREATE TABLE t1 (f1 INT, f2 TEXT, f3 INT, FULLTEXT ftidx(f2), KEY idx (f1), FOREIGN KEY (f3) REFERENCES t1 (f1) ON DELETE SET NULL) WITH SYSTEM VERSIONING ENGINE=InnoDB; SET system_versioning_alter_history= KEEP; ALTER TABLE t1 DROP KEY ftidx; INSERT INTO t1 VALUES (1,REPEAT('a',8193),1), (1,REPEAT('b',8193),1); DELETE FROM t1; ERROR 23000: Foreign key constraint for table 't1', record '1' would lead to a duplicate entry in table 't1', key 'FTS_DOC_ID_INDEX' CHECK TABLE t1; Table Op Msg_type Msg_text test.t1 check Warning InnoDB: Index 'idx' contains 1 entries, should be 2. test.t1 check error Corrupt DROP TABLE t1; innodb.MDEV-21137 'innodb' [ fail ] Found warnings/errors in server log file! Test ended at 2019-11-25 16:24:29 line 2019-11-25 16:24:29 9 [ERROR] InnoDB: Duplicate FTS_DOC_ID value on table `test`.`t1` 2019-11-25 16:24:29 9 [ERROR] InnoDB: Flagged corruption of `idx` in table `test`.`t1` in CHECK TABLE; Wrong count I think that something is wrong with the implementation of system-versioned tables.

            If "InnoDB: Flagged corruption" is indeed another representation of the same problem, here is a test case which doesn't involve fulltext-search at all (system versioning still seems to be needed):

            --source include/have_innodb.inc
             
            CREATE TABLE t1 (f1 INT, f2 INT, KEY(f2), FOREIGN KEY (f1) REFERENCES t1 (f2)) ENGINE=InnoDB WITH SYSTEM VERSIONING;
            INSERT INTO t1 (f1,f2) VALUES (0,0),(0,0);
            --error ER_ROW_IS_REFERENCED_2
            DELETE FROM t1 LIMIT 1;
            CHECK TABLE t1;
             
            # Cleanup
            DROP TABLE t1;
            

            10.4 d87b725e

            DELETE FROM t1 LIMIT 1;
            ERROR 23000: Cannot delete or update a parent row: a foreign key constraint fails (`test`.`t1`, CONSTRAINT `t1_ibfk_1` FOREIGN KEY (`f1`) REFERENCES `t1` (`f2`))
            CHECK TABLE t1;
            Table	Op	Msg_type	Msg_text
            test.t1	check	Warning	InnoDB: Index 'f2' contains 1 entries, should be 2.
            test.t1	check	error	Corrupt
            DROP TABLE t1;
            bug.flagged1 'innodb'                    [ fail ]  Found warnings/errors in server log file!
                    Test ended at 2020-02-01 14:46:46
            line
            2020-02-01 14:46:46 9 [ERROR] InnoDB: Flagged corruption of `f2` in table `test`.`t1` in CHECK TABLE; Wrong count
            ^ Found warnings in /dev/shm/var3/log/mysqld.1.err
            

            elenst Elena Stepanova added a comment - If "InnoDB: Flagged corruption" is indeed another representation of the same problem, here is a test case which doesn't involve fulltext-search at all (system versioning still seems to be needed): --source include/have_innodb.inc   CREATE TABLE t1 (f1 INT , f2 INT , KEY (f2), FOREIGN KEY (f1) REFERENCES t1 (f2)) ENGINE=InnoDB WITH SYSTEM VERSIONING; INSERT INTO t1 (f1,f2) VALUES (0,0),(0,0); --error ER_ROW_IS_REFERENCED_2 DELETE FROM t1 LIMIT 1; CHECK TABLE t1;   # Cleanup DROP TABLE t1; 10.4 d87b725e DELETE FROM t1 LIMIT 1; ERROR 23000: Cannot delete or update a parent row: a foreign key constraint fails (`test`.`t1`, CONSTRAINT `t1_ibfk_1` FOREIGN KEY (`f1`) REFERENCES `t1` (`f2`)) CHECK TABLE t1; Table Op Msg_type Msg_text test.t1 check Warning InnoDB: Index 'f2' contains 1 entries, should be 2. test.t1 check error Corrupt DROP TABLE t1; bug.flagged1 'innodb' [ fail ] Found warnings/errors in server log file! Test ended at 2020-02-01 14:46:46 line 2020-02-01 14:46:46 9 [ERROR] InnoDB: Flagged corruption of `f2` in table `test`.`t1` in CHECK TABLE; Wrong count ^ Found warnings in /dev/shm/var3/log/mysqld.1.err

            Note: MDEV-15528 in 10.5.2 replaced !fix_block->page.file_page_was_freed with fix_block->page.status != buf_page_t::FREED in the assertion expression.

            marko Marko Mäkelä added a comment - Note: MDEV-15528 in 10.5.2 replaced !fix_block->page.file_page_was_freed with fix_block->page.status != buf_page_t::FREED in the assertion expression.

            Apart from it doesn't generate ER_FOREIGN_DUPLICATE_KEY_WITH_CHILD_INFO otherwise it duplicates MDEV-21138. I suppose ER_FOREIGN_DUPLICATE_KEY_WITH_CHILD_INFO is not expected for non-versioned table?

            midenok Aleksey Midenkov added a comment - Apart from it doesn't generate ER_FOREIGN_DUPLICATE_KEY_WITH_CHILD_INFO otherwise it duplicates MDEV-21138 . I suppose ER_FOREIGN_DUPLICATE_KEY_WITH_CHILD_INFO is not expected for non-versioned table?

            People

              midenok Aleksey Midenkov
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 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.