[MDEV-20476] Assertion `!"wrong page type"' failed in row_log_table_low or ER_NOT_KEYFILE upon concurrent ALTER and UPDATE Created: 2019-09-03  Updated: 2023-04-14  Resolved: 2023-04-14

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.1, 10.2, 10.3
Fix Version/s: 10.5.5

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

Issue Links:
Duplicate
duplicates MDEV-8139 Fix scrubbing Closed

 Description   

Note: It currently fails every time for me, but the test case is still non-deterministic, run with --repeat=N if it doesn't fail right away.

Also run MTR with

--mysqld=--innodb_page_size=8K --mysqld=--loose-innodb_immediate_scrub_data_uncompressed=ON 


--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 ( 
    pk INTEGER,
 
    f1 VARCHAR(1024),
 
    f2 TEXT NULL,
 
    f3 YEAR DEFAULT 2020,
 
    f4 SMALLINT DEFAULT 0,
 
    f5 TIME DEFAULT '00:00:00',
 
    f6 BIT(30) DEFAULT b'0',
 
    f7 TIMESTAMP(6) DEFAULT '1971-01-01 00:00:00',
 
    f8 DATE DEFAULT '2020-01-01',
 
    f9 CHAR(170) DEFAULT '',
 
    f10 DECIMAL(16,0) DEFAULT 0,
 
    f11 DATETIME(5) DEFAULT '2000-01-01 00:00:00',
 
    PRIMARY KEY(pk)
 
) ENGINE=InnoDB;
 
 
 
INSERT INTO t1 (pk,f1,f2) VALUES
 
    (1,'a','haul'),
 
    (2,'f','speaker'),
 
    (3,'u','institutional'),
 
    (4,'t',NULL),
 
    (5,'p','powerful'),
 
    (6,'k','christian'),
 
    (7,'b',NULL),
 
    (8,REPEAT('a',199),REPEAT('b',30)),
 
    (9,'h',REPEAT('c',3420)),
 
    (10,'s','network'),
 
    (11,'r',REPEAT('d',31)),
 
    (12,'a',REPEAT('e',54)),
 
    (13,'','habit'),
 
    (14,'','mode'),
 
    (15,'l',REPEAT('f',33)),
 
    (16,'s','correspondent');
 
 
 
--send
 
    ALTER TABLE t1 DROP PRIMARY KEY, ADD UNIQUE(pk);
 
 
 
--connect (con1,localhost,root,,test)
 
PREPARE stmt FROM "UPDATE t1 SET f2 = 'foo'";
 
EXECUTE stmt;
 
 
 
# Cleanup
 
--disconnect con1
 
--connection default
 
--reap
 
DROP TABLE t1;


perl ./mtr bug.wrong_type --vardir=/dev/shm/mtr1   --mysqld=--innodb_page_size=8K     --mysqld=--loose-innodb_immediate_scrub_data_uncompressed=ON     --mysqld=--innodb --mysqld=--default-storage-engine=InnoDB      --ps-protocol  --repeat=10

10.3 396da1a7

 
mysqld: /data/src/10.3/storage/innobase/row/row0log.cc:971: void row_log_table_low(const rec_t*, dict_index_t*, const ulint*, bool, const dtuple_t*): Assertion `!"wrong page type"' failed.
 
190903 13:29:53 [ERROR] mysqld got signal 6 ;
 
 
 
#6  0x00007f151ae74e67 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x55c5b09bd4a1 "!\"wrong page type\"", file=file@entry=0x55c5b09bcce8 "/data/src/10.3/storage/innobase/row/row0log.cc", line=line@entry=971, function=function@entry=0x55c5b09bfb00 <row_log_table_low(unsigned char const*, dict_index_t*, unsigned long const*, bool, dtuple_t const*)::__PRETTY_FUNCTION__> "void row_log_table_low(const rec_t*, dict_index_t*, const ulint*, bool, const dtuple_t*)") at assert.c:92
 
#7  0x00007f151ae74f12 in __GI___assert_fail (assertion=0x55c5b09bd4a1 "!\"wrong page type\"", file=0x55c5b09bcce8 "/data/src/10.3/storage/innobase/row/row0log.cc", line=971, function=0x55c5b09bfb00 <row_log_table_low(unsigned char const*, dict_index_t*, unsigned long const*, bool, dtuple_t const*)::__PRETTY_FUNCTION__> "void row_log_table_low(const rec_t*, dict_index_t*, const ulint*, bool, const dtuple_t*)") at assert.c:101
 
#8  0x000055c5b01f73b9 in row_log_table_low (rec=0x7f15147d4169 "", index=0x7f14c40a5618, offsets=0x7f14c8030d10, insert=false, old_pk=0x7f14c80307c8) at /data/src/10.3/storage/innobase/row/row0log.cc:971
 
#9  0x000055c5b01f835a in row_log_table_update (rec=0x7f15147d4169 "", index=0x7f14c40a5618, offsets=0x7f14c8030d10, old_pk=0x7f14c80307c8) at /data/src/10.3/storage/innobase/row/row0log.cc:1110
 
#10 0x000055c5b02555f0 in row_upd_clust_rec (flags=0, node=0x7f14c802c560, index=0x7f14c40a5618, offsets=0x7f14c8030d10, offsets_heap=0x7f151416b9d0, thr=0x7f14c802ca78, mtr=0x7f151416bd40) at /data/src/10.3/storage/innobase/row/row0upd.cc:2929
 
#11 0x000055c5b02564a0 in row_upd_clust_step (node=0x7f14c802c560, thr=0x7f14c802ca78) at /data/src/10.3/storage/innobase/row/row0upd.cc:3197
 
#12 0x000055c5b02568ee in row_upd (node=0x7f14c802c560, thr=0x7f14c802ca78) at /data/src/10.3/storage/innobase/row/row0upd.cc:3295
 
#13 0x000055c5b0256edd in row_upd_step (thr=0x7f14c802ca78) at /data/src/10.3/storage/innobase/row/row0upd.cc:3439
 
#14 0x000055c5b01e4558 in row_update_for_mysql (prebuilt=0x7f14c802bb98) at /data/src/10.3/storage/innobase/row/row0mysql.cc:1888
 
#15 0x000055c5b004472c in ha_innobase::update_row (this=0x7f14c80286b8, old_row=0x7f14c8029a50 "@\200\002", new_row=0x7f14c8028e68 "@\200\002") at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:8850
 
#16 0x000055c5afe1e024 in handler::ha_update_row (this=0x7f14c80286b8, old_data=0x7f14c8029a50 "@\200\002", new_data=0x7f14c8028e68 "@\200\002") at /data/src/10.3/sql/handler.cc:6478
 
#17 0x000055c5afbf3cf5 in mysql_update (thd=0x7f14c8000b00, table_list=0x7f14c801a258, fields=..., values=..., conds=0x7f14c801ac88, order_num=0, order=0x0, limit=18446744073709551615, ignore=false, found_return=0x7f151416cbe0, updated_return=0x7f151416cca0) at /data/src/10.3/sql/sql_update.cc:955
 
#18 0x000055c5afaef863 in mysql_execute_command (thd=0x7f14c8000b00) at /data/src/10.3/sql/sql_parse.cc:4297
 
#19 0x000055c5afb1b2f6 in Prepared_statement::execute (this=0x7f14c8018580, expanded_query=0x7f151416d360, open_cursor=false) at /data/src/10.3/sql/sql_prepare.cc:4807
 
#20 0x000055c5afb19517 in Prepared_statement::execute_loop (this=0x7f14c8018580, expanded_query=0x7f151416d360, open_cursor=false, packet=0x7f14c8008c7a "", packet_end=0x7f14c8008c7a "") at /data/src/10.3/sql/sql_prepare.cc:4235
 
#21 0x000055c5afb16bbf in mysql_stmt_execute_common (thd=0x7f14c8000b00, stmt_id=1, packet=0x7f14c8008c7a "", packet_end=0x7f14c8008c7a "", cursor_flags=0, bulk_op=false, read_types=false) at /data/src/10.3/sql/sql_prepare.cc:3235
 
#22 0x000055c5afb16713 in mysqld_stmt_execute (thd=0x7f14c8000b00, packet_arg=0x7f14c8008c71 "\001", packet_length=9) at /data/src/10.3/sql/sql_prepare.cc:3133
 
#23 0x000055c5afae7f74 in dispatch_command (command=COM_STMT_EXECUTE, thd=0x7f14c8000b00, packet=0x7f14c8008c71 "\001", packet_length=9, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1798
 
#24 0x000055c5afae6c88 in do_command (thd=0x7f14c8000b00) at /data/src/10.3/sql/sql_parse.cc:1401
 
#25 0x000055c5afc5fc0c in do_handle_one_connection (connect=0x55c5b3d0bc50) at /data/src/10.3/sql/sql_connect.cc:1403
 
#26 0x000055c5afc5f96e in handle_one_connection (arg=0x55c5b3d0bc50) at /data/src/10.3/sql/sql_connect.cc:1308
 
#27 0x000055c5b064109c in pfs_spawn_thread (arg=0x55c5b3c54840) at /data/src/10.3/storage/perfschema/pfs.cc:1862
 
#28 0x00007f151c9e94a4 in start_thread (arg=0x7f151416e700) at pthread_create.c:456
 
#29 0x00007f151af31d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Non-debug build doesn't crash, it produces ER_NOT_KEYFILE instead:

mysqltest: At line 47: query 'reap' failed: 1034: Index for table 't1' is corrupt; try to repair it

Note: For a while I was attributing this failure to MDEV-18322, but it appears to be different, both in stack trace and in server options. Also, I'm not yet sure why a prepared statement is important here, but it is. It wasn't the case in MDEV-18322.
Reproducible on 10.1-10.3. Not reproducible with the provided test case on 10.4.

 Comments   
Comment by Elena Stepanova [ 2019-09-15 ]

Here is one without prepared statements:

--mem --mysqld=--loose-innodb_immediate_scrub_data_uncompressed=ON


--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 ( 
    col_varchar VARCHAR(2817) INVISIBLE,
 
    col_blob TEXT,
 
    col_time TIME,
 
    col_bit BIT(3),
 
    col_timestamp TIMESTAMP,
 
    col_date DATE,
 
    col_char CHAR(170),
 
    pk INTEGER AUTO_INCREMENT,
 
    PRIMARY KEY(pk)
 
) ENGINE=InnoDB;
 
 
 
INSERT INTO t1 (col_varchar,col_blob,col_time,col_bit,col_timestamp,col_date,col_char) VALUES
 
    ('w',NULL,'22:27:26',b'0','1980-01-01 00:00:00','2028-10-02','w'),
 
    (REPEAT('w',1522),REPEAT('k',34921),'22:05:18',b'1','2015-07-20 02:17:02','1973-12-04','f'),
 
    ('av',REPEAT('j',20676),'00:00:00',b'1','1990-01-01 00:00:00','2002-06-06','voa'),
 
    (NULL,REPEAT('i',18886),'12:20:12',b'0','2003-04-19 18:19:42','2021-02-22','f'),
 
    ('o',REPEAT('h',993),'17:54:12',b'1','2025-07-10 10:38:04',NULL,'ad'),
 
    ('du',REPEAT('g',56766),NULL,b'0','1988-04-14 05:29:19','1990-01-25','u'),
 
    ('',REPEAT('f',17839),'00:00:00',b'0','2024-01-11 00:36:44',NULL,''),
 
    ('egsys',REPEAT('e',6849),NULL,b'0','1975-02-18 13:27:01','1998-11-04','g'),
 
    ('cpksvm',REPEAT('d',2406),'17:19:23',b'1','2033-05-12 03:23:31','1979-09-06','pksvm'),
 
    ('cf',NULL,'15:46:41',b'0','1975-05-25 20:41:30','1979-01-16','f'),
 
    ('xfkvhy',NULL,NULL,b'0','1988-09-25 00:06:00','1900-01-01','fk'),
 
    ('k',REPEAT('c',20701),'15:39:09',b'0','2006-10-17 00:00:00','2001-09-08','v'),
 
    ('hy',REPEAT('b',48223),'00:54:23',b'1','1986-10-16 19:09:32',NULL,'yd'),
 
    ('dzkwmn',REPEAT('a',1000),NULL,b'0','2032-08-21 11:18:44','1900-01-01','a'),
 
    ('zkw',NULL,'00:00:00',b'1','1985-01-13 00:00:00',NULL,'z');
 
 
 
--connect (con1,localhost,root,,test)
 
--send
 
    OPTIMIZE TABLE t1;
 
 
 
--connection default
 
SELECT * FROM t1 INTO OUTFILE 'load_t1';
 
LOAD DATA INFILE 'load_t1' REPLACE INTO TABLE t1;
 
 
 
# Cleanup
 
--connection con1
 
--reap
 
--disconnect con1
 
--connection default
 
DROP TABLE t1;
 
--let $datadir= `SELECT @@datadir`
 
--remove_file $datadir/test/load_t1

10.3 f1309fac

 
mysqld: /data/src/10.3/storage/innobase/row/row0log.cc:971: void row_log_table_low(const rec_t*, dict_index_t*, const ulint*, bool, const dtuple_t*): Assertion `!"wrong page type"' failed.
 
190916  2:42:10 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007fb376e05f12 in __GI___assert_fail (assertion=0x5568984fc7d1 "!\"wrong page type\"", file=0x5568984fc018 "/data/src/10.3/storage/innobase/row/row0log.cc", line=971, function=0x5568984fee20 <row_log_table_low(unsigned char const*, dict_index_t*, unsigned long const*, bool, dtuple_t const*)::__PRETTY_FUNCTION__> "void row_log_table_low(const rec_t*, dict_index_t*, const ulint*, bool, const dtuple_t*)") at assert.c:101
 
#8  0x0000556897d35f17 in row_log_table_low (rec=0x7fb3709c807e "", index=0x7fb32406c1d8, offsets=0x7fb32405a788, insert=false, old_pk=0x0) at /data/src/10.3/storage/innobase/row/row0log.cc:971
 
#9  0x0000556897d36eb8 in row_log_table_update (rec=0x7fb3709c807e "", index=0x7fb32406c1d8, offsets=0x7fb32405a788, old_pk=0x0) at /data/src/10.3/storage/innobase/row/row0log.cc:1110
 
#10 0x0000556897d93e6c in row_upd_clust_rec (flags=0, node=0x7fb324058770, index=0x7fb32406c1d8, offsets=0x7fb32405a788, offsets_heap=0x7fb3701a1930, thr=0x7fb324058b98, mtr=0x7fb3701a1ca0) at /data/src/10.3/storage/innobase/row/row0upd.cc:2929
 
#11 0x0000556897d94d1c in row_upd_clust_step (node=0x7fb324058770, thr=0x7fb324058b98) at /data/src/10.3/storage/innobase/row/row0upd.cc:3197
 
#12 0x0000556897d9516a in row_upd (node=0x7fb324058770, thr=0x7fb324058b98) at /data/src/10.3/storage/innobase/row/row0upd.cc:3295
 
#13 0x0000556897d95759 in row_upd_step (thr=0x7fb324058b98) at /data/src/10.3/storage/innobase/row/row0upd.cc:3439
 
#14 0x0000556897d231ac in row_update_for_mysql (prebuilt=0x7fb324036408) at /data/src/10.3/storage/innobase/row/row0mysql.cc:1888
 
#15 0x0000556897b83b88 in ha_innobase::update_row (this=0x7fb32406e458, old_row=0x7fb324173090 "\202\001", new_row=0x7fb3241724c8 "\303") at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:8850
 
#16 0x000055689795c492 in handler::ha_update_row (this=0x7fb32406e458, old_data=0x7fb324173090 "\202\001", new_data=0x7fb3241724c8 "\303") at /data/src/10.3/sql/handler.cc:6478
 
#17 0x00005568975ec999 in write_record (thd=0x7fb324000b00, table=0x7fb32406d3b0, info=0x7fb3701a2760) at /data/src/10.3/sql/sql_insert.cc:1950
 
#18 0x000055689761c730 in read_sep_field (thd=0x7fb324000b00, info=..., table_list=0x7fb324012980, fields_vars=..., set_fields=..., set_values=..., read_info=..., enclosed=..., skip_lines=0, ignore_check_option_errors=false) at /data/src/10.3/sql/sql_load.cc:1179
 
#19 0x000055689761abb6 in mysql_load (thd=0x7fb324000b00, ex=0x7fb3240128f8, table_list=0x7fb324012980, fields_vars=..., set_fields=..., set_values=..., handle_duplicates=DUP_REPLACE, ignore=false, read_file_from_client=false) at /data/src/10.3/sql/sql_load.cc:685
 
#20 0x000055689762fadd in mysql_execute_command (thd=0x7fb324000b00) at /data/src/10.3/sql/sql_parse.cc:4866
 
#21 0x00005568976399fd in mysql_parse (thd=0x7fb324000b00, rawbuf=0x7fb324012818 "LOAD DATA INFILE 'load_t1' REPLACE INTO TABLE t1", length=48, parser_state=0x7fb3701a35e0, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7830
 
#22 0x00005568976262fb in dispatch_command (command=COM_QUERY, thd=0x7fb324000b00, packet=0x7fb32415fe11 "LOAD DATA INFILE 'load_t1' REPLACE INTO TABLE t1", packet_length=48, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1856
 
#23 0x0000556897624c22 in do_command (thd=0x7fb324000b00) at /data/src/10.3/sql/sql_parse.cc:1401
 
#24 0x000055689779dd40 in do_handle_one_connection (connect=0x556899daa150) at /data/src/10.3/sql/sql_connect.cc:1403
 
#25 0x000055689779daa2 in handle_one_connection (arg=0x556899daa150) at /data/src/10.3/sql/sql_connect.cc:1308
 
#26 0x00005568981800a0 in pfs_spawn_thread (arg=0x556899ced6f0) at /data/src/10.3/storage/perfschema/pfs.cc:1862
 
#27 0x00007fb37897a4a4 in start_thread (arg=0x7fb3701a4700) at pthread_create.c:456
 
#28 0x00007fb376ec2d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

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