[MDEV-26453] Assertion `0' failed in row_upd_sec_index_entry & corruption Created: 2021-08-20  Updated: 2022-10-11  Resolved: 2021-10-29

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.4, 10.5, 10.6, 10.7
Fix Version/s: 10.4.23, 10.5.14, 10.6.6, 10.7.2

Type: Bug Priority: Critical
Reporter: Roel Van de Paar Assignee: Nikita Malyavin
Resolution: Fixed Votes: 0
Labels: affects-tests, corruption, regression

Issue Links:
Relates
relates to MDEV-29761 Bulk insert fails to rollback during... Closed
relates to MDEV-17890 Server crash on DELETE with YEAR fiel... Closed
relates to MDEV-27744 LPAD in vcol created in ORACLE mode m... Closed
relates to MDEV-28190 sql_mode makes MDEV-371 virtual colum... Closed

 Description    

SET sql_mode= '';
 
CREATE TEMPORARY TABLE t (c INT AUTO_INCREMENT KEY,c2 INT,INDEX idx (c2)) ENGINE=InnoDB;
 
CREATE UNIQUE INDEX i1 USING HASH ON t (c ASC);
 
INSERT INTO t VALUES ('aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa','E0');
 
DELETE FROM t;

Leads to:

10.7.0 52505bf20de0ce77a5c0b0a74af021051987bb0d (Debug)

 
2021-08-28 10:55:06 0 [Note] /test/MD160821-mariadb-10.7.0-linux-x86_64-dbg/bin/mysqld: ready for connections.
 
Version: '10.7.0-MariaDB-debug'  socket: '/test/MD160821-mariadb-10.7.0-linux-x86_64-dbg/socket.sock'  port: 25303  MariaDB Server
 
2021-08-28 10:55:09 4 [ERROR] InnoDB: Record in index `i1` of table `data`.`#sql-temptable-3d10e-4-1` was not found on update: TUPLE (info_bits=0, 2 fields): {[8]        (0x00000104000002D0),[4]    (0x80000001)} at: COMPACT RECORD(info_bits=0, 2 fields): {[8]        (0x00000104000002C4),[4]    (0x80000001)}
 
mysqld: /test/10.7_dbg/storage/innobase/row/row0upd.cc:2051: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `0' failed.

10.7.0 52505bf20de0ce77a5c0b0a74af021051987bb0d (Debug)

 
mysqld: /test/10.7_dbg/storage/innobase/row/row0upd.cc:2051: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `0' failed.

10.7.0 52505bf20de0ce77a5c0b0a74af021051987bb0d (Debug)

 
Core was generated by `/test/MD160821-mariadb-10.7.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
[Current thread is 1 (Thread 0x14f400e3d700 (LWP 1962842))]
 
(gdb) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x000014f4039fb859 in __GI_abort () at abort.c:79
 
#2  0x000014f4039fb729 in __assert_fail_base (fmt=0x14f403b91588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5567400ceb6b "0", file=0x5567401a5310 "/test/10.7_dbg/storage/innobase/row/row0upd.cc", line=2051, function=<optimized out>) at assert.c:92
 
#3  0x000014f403a0cf36 in __GI___assert_fail (assertion=assertion@entry=0x5567400ceb6b "0", file=file@entry=0x5567401a5310 "/test/10.7_dbg/storage/innobase/row/row0upd.cc", line=line@entry=2051, function=function@entry=0x5567401a66e8 "dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*)") at assert.c:101
 
#4  0x000055673fb0a1c1 in row_upd_sec_index_entry (node=node@entry=0x14f3bc02af58, thr=thr@entry=0x14f3bc022b18) at /test/10.7_dbg/storage/innobase/row/row0upd.cc:2051
 
#5  0x000055673fb0afcf in row_upd_sec_step (thr=0x14f3bc022b18, node=0x14f3bc02af58) at /test/10.7_dbg/storage/innobase/row/row0upd.cc:2200
 
#6  row_upd (thr=0x14f3bc022b18, node=0x14f3bc02af58) at /test/10.7_dbg/storage/innobase/row/row0upd.cc:2936
 
#7  row_upd_step (thr=thr@entry=0x14f3bc022b18) at /test/10.7_dbg/storage/innobase/row/row0upd.cc:3051
 
#8  0x000055673faafbb3 in row_update_for_mysql (prebuilt=0x14f3bc02a4b8) at /test/10.7_dbg/storage/innobase/row/row0mysql.cc:1740
 
#9  0x000055673f938b50 in ha_innobase::delete_row (this=0x14f3bc0297d0, record=0x14f3bc026c28 "\375\001") at /test/10.7_dbg/storage/innobase/handler/ha_innodb.cc:8660
 
#10 0x000055673f59e53a in handler::ha_delete_row (this=0x14f3bc0297d0, buf=0x14f3bc026c28 "\375\001") at /test/10.7_dbg/sql/handler.cc:7646
 
#11 0x000055673f2347a1 in TABLE::delete_row (this=0x14f3bc026798) at /test/10.7_dbg/sql/sql_delete.cc:281
 
#12 0x000055673f2327d3 in mysql_delete (thd=thd@entry=0x14f3bc000db8, table_list=0x14f3bc013d40, conds=<optimized out>, order_list=order_list@entry=0x14f3bc005c00, limit=18446744073709551615, options=<optimized out>, result=<optimized out>) at /test/10.7_dbg/sql/sql_delete.cc:825
 
#13 0x000055673f294a26 in mysql_execute_command (thd=thd@entry=0x14f3bc000db8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/10.7_dbg/sql/sql_limit.h:83
 
#14 0x000055673f27eac3 in mysql_parse (thd=thd@entry=0x14f3bc000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14f400e3c400) at /test/10.7_dbg/sql/sql_parse.cc:8030
 
#15 0x000055673f28d6c8 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14f3bc000db8, packet=packet@entry=0x14f3bc00b739 "DELETE FROM t", packet_length=packet_length@entry=13, blocking=blocking@entry=true) at /test/10.7_dbg/sql/sql_class.h:1357
 
#16 0x000055673f290ae9 in do_command (thd=0x14f3bc000db8, blocking=blocking@entry=true) at /test/10.7_dbg/sql/sql_parse.cc:1404
 
#17 0x000055673f406dd6 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x556741e96f38, put_in_cache=put_in_cache@entry=true) at /test/10.7_dbg/sql/sql_connect.cc:1418
 
#18 0x000055673f4073db in handle_one_connection (arg=arg@entry=0x556741e96f38) at /test/10.7_dbg/sql/sql_connect.cc:1312
 
#19 0x000055673f86fce4 in pfs_spawn_thread (arg=0x556741dbffe8) at /test/10.7_dbg/storage/perfschema/pfs.cc:2201
 
#20 0x000014f403f0a609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#21 0x000014f403af8293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.4.22 (dbg), 10.5.13 (dbg), 10.6.5 (dbg), 10.7.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.41 (dbg), 10.2.41 (opt), 10.3.32 (dbg), 10.3.32 (opt), 10.4.22 (opt), 10.5.13 (opt), 10.6.5 (opt), 10.7.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.35 (dbg), 5.7.35 (opt), 8.0.26 (dbg), 8.0.26 (opt)

 Comments   
Comment by Roel Van de Paar [ 2021-08-20 ]

See MDEV-17890 for additional testcases that still crash.

Comment by Roel Van de Paar [ 2021-08-28 ]

Improved testcase. Looks like a common testcase/high prio.

SET sql_mode='';
 
CREATE TABLE t (c INT AUTO_INCREMENT KEY) ENGINE=InnoDB;
 
CREATE UNIQUE INDEX i USING HASH ON t (c);
 
INSERT INTO t VALUES (0);
 
DELETE FROM t;

Leads to:

10.7.0 52505bf20de0ce77a5c0b0a74af021051987bb0d (Debug)

 
2021-08-28 10:42:43 0 [Note] /test/MD160821-mariadb-10.7.0-linux-x86_64-dbg/bin/mysqld: ready for connections.
 
Version: '10.7.0-MariaDB-debug'  socket: '/test/MD160821-mariadb-10.7.0-linux-x86_64-dbg/socket.sock'  port: 25303  MariaDB Server
 
2021-08-28 10:42:53 4 [ERROR] InnoDB: Record in index `i` of table `test`.`t` was not found on update: TUPLE (info_bits=0, 2 fields): {[8]        (0x00000104000002D0),[4]    (0x80000001)} at: COMPACT RECORD(info_bits=0, 2 fields): {[8]        (0x00000104000002C4),[4]    (0x80000001)}
 
mysqld: /test/10.7_dbg/storage/innobase/row/row0upd.cc:2051: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `0' failed.

10.7.0 52505bf20de0ce77a5c0b0a74af021051987bb0d (Debug)

 
mysqld: /test/10.7_dbg/storage/innobase/row/row0upd.cc:2051: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `0' failed.

10.7.0 52505bf20de0ce77a5c0b0a74af021051987bb0d (Debug)

 
Core was generated by `/test/MD160821-mariadb-10.7.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
[Current thread is 1 (Thread 0x1477c41ad700 (LWP 63015))]
 
(gdb) bt
 
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
 
#1  0x00001477d8c59859 in __GI_abort () at abort.c:79
 
#2  0x00001477d8c59729 in __assert_fail_base (fmt=0x1477d8def588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5574afff7b6b "0", file=0x5574b00ce310 "/test/10.7_dbg/storage/innobase/row/row0upd.cc", line=2051, function=<optimized out>) at assert.c:92
 
#3  0x00001477d8c6af36 in __GI___assert_fail (assertion=assertion@entry=0x5574afff7b6b "0", file=file@entry=0x5574b00ce310 "/test/10.7_dbg/storage/innobase/row/row0upd.cc", line=line@entry=2051, function=function@entry=0x5574b00cf6e8 "dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*)") at assert.c:101
 
#4  0x00005574afa331c1 in row_upd_sec_index_entry (node=node@entry=0x14779403b3a8, thr=thr@entry=0x14779407ff68) at /test/10.7_dbg/storage/innobase/row/row0upd.cc:2051
 
#5  0x00005574afa33fcf in row_upd_sec_step (thr=0x14779407ff68, node=0x14779403b3a8) at /test/10.7_dbg/storage/innobase/row/row0upd.cc:2200
 
#6  row_upd (thr=0x14779407ff68, node=0x14779403b3a8) at /test/10.7_dbg/storage/innobase/row/row0upd.cc:2936
 
#7  row_upd_step (thr=thr@entry=0x14779407ff68) at /test/10.7_dbg/storage/innobase/row/row0upd.cc:3051
 
#8  0x00005574af9d8bb3 in row_update_for_mysql (prebuilt=0x14779403a958) at /test/10.7_dbg/storage/innobase/row/row0mysql.cc:1740
 
#9  0x00005574af861b50 in ha_innobase::delete_row (this=0x147794039c70, record=0x1477940397e8 "\377\001") at /test/10.7_dbg/storage/innobase/handler/ha_innodb.cc:8660
 
#10 0x00005574af4c753a in handler::ha_delete_row (this=0x147794039c70, buf=0x1477940397e8 "\377\001") at /test/10.7_dbg/sql/handler.cc:7646
 
#11 0x00005574af15d7a1 in TABLE::delete_row (this=0x147794039358) at /test/10.7_dbg/sql/sql_delete.cc:281
 
#12 0x00005574af15b7d3 in mysql_delete (thd=thd@entry=0x147794000db8, table_list=0x147794013d40, conds=<optimized out>, order_list=order_list@entry=0x147794005c00, limit=18446744073709551615, options=<optimized out>, result=<optimized out>) at /test/10.7_dbg/sql/sql_delete.cc:825
 
#13 0x00005574af1bda26 in mysql_execute_command (thd=thd@entry=0x147794000db8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/10.7_dbg/sql/sql_limit.h:83
 
#14 0x00005574af1a7ac3 in mysql_parse (thd=thd@entry=0x147794000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1477c41ac400) at /test/10.7_dbg/sql/sql_parse.cc:8030
 
#15 0x00005574af1b66c8 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x147794000db8, packet=packet@entry=0x14779400b739 "DELETE FROM t", packet_length=packet_length@entry=13, blocking=blocking@entry=true) at /test/10.7_dbg/sql/sql_class.h:1357
 
#16 0x00005574af1b9ae9 in do_command (thd=0x147794000db8, blocking=blocking@entry=true) at /test/10.7_dbg/sql/sql_parse.cc:1404
 
#17 0x00005574af32fdd6 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x5574b19b6f68, put_in_cache=put_in_cache@entry=true) at /test/10.7_dbg/sql/sql_connect.cc:1418
 
#18 0x00005574af3303db in handle_one_connection (arg=arg@entry=0x5574b19b6f68) at /test/10.7_dbg/sql/sql_connect.cc:1312
 
#19 0x00005574af798ce4 in pfs_spawn_thread (arg=0x5574b189cf58) at /test/10.7_dbg/storage/perfschema/pfs.cc:2201
 
#20 0x00001477d9168609 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
#21 0x00001477d8d56293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.4.22 (dbg), 10.5.13 (dbg), 10.6.5 (dbg), 10.7.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.41 (dbg), 10.2.41 (opt), 10.3.30 (dbg), 10.3.32 (dbg), 10.3.32 (opt), 10.4.22 (opt), 10.5.13 (opt), 10.6.5 (opt), 10.7.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.35 (dbg), 5.7.35 (opt), 8.0.26 (dbg), 8.0.26 (opt)

Comment by Nikita Malyavin [ 2021-10-27 ]

Thanks Roel! Your condensed test saved me some time.

I have added SELECT to see whats actually going on.

CREATE TABLE t (c INT AUTO_INCREMENT KEY) ENGINE=InnoDB;
 
CREATE UNIQUE INDEX i USING HASH ON t (c);
 
INSERT INTO t VALUES (0);
 
SELECT * FROM t;
 
c
 
1
 
DELETE FROM t;

The value inserted is 1, because it was auto-incremented.

However, the hash was calculated for value 0.

Thread 2 hit Breakpoint 11, Item_func_hash::val_int (this=0x7f664c180768) at /home/nik/mariadb/sql/item_func.cc:1774
 
1774	    if(args[i]->null_value)
 
(gdb) p str->c_ptr()
 
$1 = 0x7f664c087388 "0"
 
(gdb) bt
 
#0  Item_func_hash::val_int (this=0x7f664c180768) at /home/nik/mariadb/sql/item_func.cc:1774
 
#1   Item::save_int_in_field (this=0x7f664c180768, field=0x7f664c0d2318, no_conversions=false) at /home/nik/mariadb/sql/item.cc:6619
 
#2  Type_handler_int_result::Item_save_in_field (this=0x55859a1ee848 <type_handler_long>, item=0x7f664c180768, field=0x7f664c0d2318, no_conversions=false) at /home/nik/mariadb/sql/sql_type.cc:3838
 
#3  Item::save_in_field (this=0x7f664c180768, field=0x7f664c0d2318, no_conversions=false) at /home/nik/mariadb/sql/item.cc:6629
 
#4  TABLE::update_virtual_fields (this=0x7f664c090248, h=0x7f664c091040, update_mode=VCOL_UPDATE_FOR_WRITE) at /home/nik/mariadb/sql/table.cc:8407
 
#5  fill_record (thd=0x7f664c001618, table=0x7f664c090248, ptr=0x7f664c0d2240, values=..., ignore_errors=false, use_value=false) at /home/nik/mariadb/sql/sql_base.cc:8877
 
#6  fill_record_n_invoke_before_triggers (thd=0x7f664c001618, table=0x7f664c090248, ptr=0x7f664c0d2228, values=..., ignore_errors=false, event=TRG_EVENT_INSERT) at /home/nik/mariadb/sql/sql_base.cc:8919
 
#7  mysql_insert (thd=0x7f664c001618, table_list=0x7f664c013ba8, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/nik/mariadb/sql/sql_insert.cc:1020
 
#8  mysql_execute_command (thd=0x7f664c001618) at /home/nik/mariadb/sql/sql_parse.cc:4598
 
#9  mysql_parse (thd=0x7f664c001618, rawbuf=0x7f664c013ad0 "INSERT INTO t VALUES (0)", length=24, parser_state=0x7f6668067578, is_com_multi=false, is_next_command=false) at /home/nik/mariadb/sql/sql_parse.cc:7995

Then auto-increment happens, on the very last stage:

Thread 2 hit Breakpoint 12, Field_long::store (this=0x7f664c0d2240, nr=1, unsigned_val=true) at /home/nik/mariadb/sql/field.cc:4298
 
4298	  int4store(ptr,res);
 
(gdb) p nr
 
$2 = 1
 
(gdb) bt
 
#0  Field_long::store (this=0x7f664c0d2240, nr=1, unsigned_val=true) at /home/nik/mariadb/sql/field.cc:4298
 
#1  handler::update_auto_increment (this=0x7f664c091040) at /home/nik/mariadb/sql/handler.cc:3480
 
#2  ha_innobase::write_row (this=0x7f664c091040, record=0x7f664c0d2208 "\377") at /home/nik/mariadb/storage/innobase/handler/ha_innodb.cc:8074
 
#3  handler::ha_write_row (this=0x7f664c091040, buf=0x7f664c0d2208 "\377") at /home/nik/mariadb/sql/handler.cc:6771
 
#4  write_record (thd=0x7f664c001618, table=0x7f664c090248, info=0x7f6668064890) at /home/nik/mariadb/sql/sql_insert.cc:2072
 
#5  mysql_insert (thd=0x7f664c001618, table_list=0x7f664c013ba8, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/nik/mariadb/sql/sql_insert.cc:1078
 
#6  mysql_execute_command (thd=0x7f664c001618) at /home/nik/mariadb/sql/sql_parse.cc:4598
 
#7  mysql_parse (thd=0x7f664c001618, rawbuf=0x7f664c013ad0 "INSERT INTO t VALUES (0)", length=24, parser_state=0x7f6668067578, is_com_multi=false, is_next_command=false) at /home/nik/mariadb/sql/sql_parse.cc:7995

As we may see, autoincrement is handled inside ha_innobase::write_row, this late!

Note also, that other values are not affected, because only 0 is forbidden to begin from.
in create_table_info_t::create_table_update_dict:

		ib_uint64_t	autoinc = m_create_info->auto_increment_value;
 
 
 
		if (autoinc == 0) {
 
			autoinc = 1;
 
		}

marko, HASH key should be forbidden, for AUTO_INCREMENT fields.
Compare with the obvious example:

CREATE TABLE t (c INT AUTO_INCREMENT KEY, c2 int as (c), key(c2)) ENGINE=InnoDB;

results in ER_GENERATED_COLUMN_FUNCTION_IS_NOT_ALLOWED: 

Function or expression 'AUTO_INCREMENT' cannot be used in the GENERATED ALWAYS AS clause of `c`

If it wouldn't be forbidden, it would have resulted with the same failure.

This is the same case: we are silently creating a virtual column on an AUTO_INCREMENT field, which should be impossible.

Comment by Nikita Malyavin [ 2021-10-28 ]

Please review https://github.com/MariaDB/server/commit/ff0d66b99009c3e3025e001923804b9de32ca5ec

Comment by Alexander Barkov [ 2021-10-28 ]

Ok to push.

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