[MDEV-21137] Assertion `mode == 16 || mode == 12 || !fix_block->page.file_page_was_freed' failed in buf_page_get_gen Created: 2019-11-23  Updated: 2020-04-04  Resolved: 2020-04-04

Status: Closed
Project: MariaDB Server
Component/s: Full-text Search, Storage Engine - InnoDB
Affects Version/s: 10.3, 10.4
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Aleksey Midenkov
Resolution: Duplicate Votes: 0
Labels: foreign-keys

Issue Links:
Duplicate
duplicates MDEV-21138 Assertion `col->ord_part' or `f.col->... Closed

 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



 Comments   
Comment by Marko Mäkelä [ 2019-11-25 ]

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.

Comment by Elena Stepanova [ 2020-02-01 ]

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

Comment by Marko Mäkelä [ 2020-03-12 ]

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.

Comment by Aleksey Midenkov [ 2020-04-02 ]

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?

Generated at Thu Feb 08 09:04:52 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.