[MDEV-17890] Server crash on DELETE with YEAR field with truncated expr Created: 2018-12-03  Updated: 2022-03-29  Resolved: 2021-07-16

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Virtual Columns
Affects Version/s: 10.2, 10.3, 10.4, 10.5, 10.6, 10.7
Fix Version/s: 10.2.40, 10.3.31, 10.4.21, 10.5.12, 10.6.4

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Nikita Malyavin
Resolution: Fixed Votes: 1
Labels: affects-tests, corruption, regression

Issue Links:
Duplicate
duplicates MDEV-20618 Assertion `btr_validate_index(index, ... Closed
Relates
relates to MDEV-18153 Assertion `0' or Assertion `btr_valid... Closed
relates to MDEV-19486 Server crashes in row_upd or row_upd_... Closed
relates to MDEV-26453 Assertion `0' failed in row_upd_sec_i... Closed
relates to MDEV-14134 gcol.innodb_virtual_debug sporadicall... Closed
relates to MDEV-15114 ASAN heap-use-after-free in mem_heap_... Closed
relates to MDEV-18156 Assertion `0' failed or `btr_validate... Closed
relates to MDEV-20152 Generated column's index not updated ... Open
relates to MDEV-27744 LPAD in vcol created in ORACLE mode m... Closed

 Description   

Actual description

Changing support_virtual_index to 1 in mysql-test/suite/gcol/t/gcol_ins_upd_innodb.test leads to a server crash.

The root cause test is following:

DROP TABLE IF EXISTS t;
CREATE TABLE t (
  a INT,
  b YEAR GENERATED ALWAYS AS ('a') VIRTUAL,
  c YEAR GENERATED ALWAYS AS ('aaaa') VIRTUAL,
  b1 YEAR GENERATED ALWAYS AS ('a') STORED,
  c1 YEAR GENERATED ALWAYS AS ('aaaa') STORED,
  UNIQUE(b),
  UNIQUE(b1)
) ENGINE=InnoDB;
INSERT IGNORE INTO t VALUES();
SELECT b from t;
SELECT b1 from t;
SELECT * from t;
DELETE FROM t;

Stack trace:

#0  0x00007ffff76f357f in raise () from /lib64/libc.so.6
#1  0x00007ffff76dd895 in abort () from /lib64/libc.so.6
#2  0x00007ffff76dd769 in __assert_fail_base.cold.0 () from /lib64/libc.so.6
#3  0x00007ffff76eba26 in __assert_fail () from /lib64/libc.so.6
#4  0x0000000000eff8b8 in row_upd_sec_index_entry (node=0x7fff680704d8, thr=0x7fff68074f88)
    at /home/bar/maria-git/server.10.4/storage/innobase/row/row0upd.cc:2429
#5  0x0000000000efff2a in row_upd_sec_step (node=0x7fff680704d8, thr=0x7fff68074f88)
    at /home/bar/maria-git/server.10.4/storage/innobase/row/row0upd.cc:2543
#6  0x0000000000f02642 in row_upd (node=0x7fff680704d8, thr=0x7fff68074f88)
    at /home/bar/maria-git/server.10.4/storage/innobase/row/row0upd.cc:3319
#7  0x0000000000f029a9 in row_upd_step (thr=0x7fff68074f88)
    at /home/bar/maria-git/server.10.4/storage/innobase/row/row0upd.cc:3434
#8  0x0000000000eb6458 in row_update_for_mysql (prebuilt=0x7fff6806f918)
    at /home/bar/maria-git/server.10.4/storage/innobase/row/row0mysql.cc:1889
#9  0x0000000000d60bd8 in ha_innobase::delete_row (this=0x7fff680659f8, 
    record=0x7fff6806e970 <incomplete sequence \313>)
    at /home/bar/maria-git/server.10.4/storage/innobase/handler/ha_innodb.cc:8970
#10 0x0000000000b4bfb2 in handler::ha_delete_row (this=0x7fff680659f8, 
    buf=0x7fff6806e970 <incomplete sequence \313>)
    at /home/bar/maria-git/server.10.4/sql/handler.cc:6790
#11 0x0000000000ce6581 in TABLE::delete_row (this=0x7fff68064b90)
    at /home/bar/maria-git/server.10.4/sql/sql_delete.cc:297
#12 0x0000000000ce3603 in mysql_delete (thd=0x7fff68000d60, table_list=0x7fff68014230, 
    conds=0x0, order_list=0x7fff68005710, limit=18446744073709551615, options=0, 
    result=0x0) at /home/bar/maria-git/server.10.4/sql/sql_delete.cc:834
#13 0x00000000008220ad in mysql_execute_command (thd=0x7fff68000d60)
    at /home/bar/maria-git/server.10.4/sql/sql_parse.cc:4727
#14 0x000000000082cd07 in mysql_parse (thd=0x7fff68000d60, 
    rawbuf=0x7fff68014168 "DELETE FROM t", length=13, parser_state=0x7ffff41d7000, 
    is_com_multi=false, is_next_command=false)
    at /home/bar/maria-git/server.10.4/sql/sql_parse.cc:7908

Original description

Note: MDEV-14134 is marked as a duplicate of MDEV-15114 and the latter is closed, so I'm filing a new one.

--source include/have_innodb.inc
 
CREATE TABLE t1 ( 
  pk BIGINT AUTO_INCREMENT,
  b BIT(15),
  v BIT(10) AS (b) VIRTUAL,
  PRIMARY KEY(pk),
  UNIQUE(v)
) ENGINE=InnoDB;
 
INSERT IGNORE INTO t1 (b) VALUES (b'101110001110100'),(b'011101');
SELECT pk, b FROM t1 INTO OUTFILE 'load.data';
LOAD DATA INFILE 'load.data' REPLACE INTO TABLE t1 (pk, b);
 
# Cleanup
DROP TABLE t1;
--let $datadir= `SELECT @@datadir`
--remove_file $datadir/test/load.data

10.2 f2c7972a debug

2018-12-03 18:50:43 140185924466432 [ERROR] InnoDB: Record in index `v` of table `test`.`t1` was not found on update: TUPLE (info_bits=0, 2 fields): {NULL,[8]        (0x8000000000000001)} at: COMPACT RECORD(info_bits=0, 1 fields): {[8]infimum (0x696E66696D756D00)}
mysqld: /data/src/10.2/storage/innobase/row/row0upd.cc:2436: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `0' failed.
181203 18:50:43 [ERROR] mysqld got signal 6 ;
 
#7  0x00007f583467aee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
#8  0x0000562b2a093991 in row_upd_sec_index_entry (node=0x7f57c406cbc0, thr=0x7f57c408fd38) at /data/src/10.2/storage/innobase/row/row0upd.cc:2436
#9  0x0000562b2a094007 in row_upd_sec_step (node=0x7f57c406cbc0, thr=0x7f57c408fd38) at /data/src/10.2/storage/innobase/row/row0upd.cc:2549
#10 0x0000562b2a096288 in row_upd (node=0x7f57c406cbc0, thr=0x7f57c408fd38) at /data/src/10.2/storage/innobase/row/row0upd.cc:3308
#11 0x0000562b2a0965d9 in row_upd_step (thr=0x7f57c408fd38) at /data/src/10.2/storage/innobase/row/row0upd.cc:3425
#12 0x0000562b2a03cc7d in row_update_for_mysql (prebuilt=0x7f57c406c068) at /data/src/10.2/storage/innobase/row/row0mysql.cc:1830
#13 0x0000562b29f030c1 in ha_innobase::delete_row (this=0x7f57c4009d28, record=0x7f57c400b750 "\241\001") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9098
#14 0x0000562b29bf711a in handler::ha_delete_row (this=0x7f57c4009d28, buf=0x7f57c400b750 "\241\001") at /data/src/10.2/sql/handler.cc:6021
#15 0x0000562b2994c547 in write_record (thd=0x7f57c4000b00, table=0x7f57c4009120, info=0x7f582c2e4040) at /data/src/10.2/sql/sql_insert.cc:1893
#16 0x0000562b29d91a8c in read_sep_field (thd=0x7f57c4000b00, info=..., table_list=0x7f57c40125d0, fields_vars=..., set_fields=..., set_values=..., read_info=..., enclosed=..., skip_lines=0, ignore_check_option_errors=false) at /data/src/10.2/sql/sql_load.cc:1256
#17 0x0000562b29d8fc24 in mysql_load (thd=0x7f57c4000b00, ex=0x7f57c4012548, table_list=0x7f57c40125d0, fields_vars=..., set_fields=..., set_values=..., handle_duplicates=DUP_REPLACE, ignore=false, read_file_from_client=false) at /data/src/10.2/sql/sql_load.cc:649
#18 0x0000562b2997345c in mysql_execute_command (thd=0x7f57c4000b00) at /data/src/10.2/sql/sql_parse.cc:4834
#19 0x0000562b2997d1bd in mysql_parse (thd=0x7f57c4000b00, rawbuf=0x7f57c4012448 "LOAD DATA INFILE 'load.data' REPLACE INTO TABLE t1 (pk, b)", length=58, parser_state=0x7f582c2e5200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:8013
#20 0x0000562b2996aaf5 in dispatch_command (command=COM_QUERY, thd=0x7f57c4000b00, packet=0x7f57c4095ec1 "LOAD DATA INFILE 'load.data' REPLACE INTO TABLE t1 (pk, b)", packet_length=58, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1824
#21 0x0000562b29969458 in do_command (thd=0x7f57c4000b00) at /data/src/10.2/sql/sql_parse.cc:1378
#22 0x0000562b29abbbc9 in do_handle_one_connection (connect=0x562b2c34e0c0) at /data/src/10.2/sql/sql_connect.cc:1335
#23 0x0000562b29abb956 in handle_one_connection (arg=0x562b2c34e0c0) at /data/src/10.2/sql/sql_connect.cc:1241
#24 0x0000562b29ee15ee in pfs_spawn_thread (arg=0x562b2c299570) at /data/src/10.2/storage/perfschema/pfs.cc:1862
#25 0x00007f5836136494 in start_thread (arg=0x7f582c2e6700) at pthread_create.c:333
#26 0x00007f583473793f in clone () from /lib/x86_64-linux-gnu/libc.so.6

10.2 f2c7972a non-debug

2018-12-03 18:54:20 140039024932608 [ERROR] InnoDB: Record in index `v` of table `test`.`t1` was not found on update: TUPLE (info_bits=0, 2 fields): {NULL,[8]        (0x8000000000000001)} at: COMPACT RECORD(info_bits=0, 1 fields): {[8]infimum (0x696E66696D756D00)}
181203 18:54:20 [ERROR] mysqld got signal 11 ;
 
#2  <signal handler called>
#3  row_upd_build_difference_binary (index=0x7f5cfc0b9180, entry=entry@entry=0x7f5cfc0bd390, rec=<optimized out>, offsets=<optimized out>, offsets@entry=0x0, no_sys=no_sys@entry=true, trx=<optimized out>, heap=0x7f5cfc0b7b20, mysql_table=0x7f5cfc0bbc98) at /data/src/10.2/storage/innobase/row/row0upd.cc:1165
#4  0x000056283a9293d3 in row_ins_clust_index_entry_by_modify (mtr=0x7f5d6055b130, thr=<optimized out>, entry=0x7f5cfc0bd390, heap=0x7f5cfc0b7b20, offsets_heap=0x7f5d6055a5d0, offsets=0x7f5d6055a5d8, mode=2, flags=0, pcur=0x7f5d6055a630) at /data/src/10.2/storage/innobase/row/row0ins.cc:352
#5  row_ins_clust_index_entry_low (flags=<optimized out>, mode=2, index=0x7f5cfc0b9180, n_uniq=<optimized out>, entry=<optimized out>, n_ext=<optimized out>, thr=0x7f5cfc0b6868, dup_chk_only=false) at /data/src/10.2/storage/innobase/row/row0ins.cc:2650
#6  0x000056283a92a02b in row_ins_clust_index_entry (index=0x7f5cfc0b9180, entry=0x7f5cfc0bd390, thr=0x7f5cfc0b6868, n_ext=0, dup_chk_only=2, dup_chk_only@entry=false) at /data/src/10.2/storage/innobase/row/row0ins.cc:3170
#7  0x000056283a92a731 in row_ins_index_entry (thr=0x7f5cfc0b6868, entry=<optimized out>, index=0x7f5cfc0b9180) at /data/src/10.2/storage/innobase/row/row0ins.cc:3292
#8  row_ins_index_entry_step (thr=0x7f5cfc0b6868, node=<optimized out>) at /data/src/10.2/storage/innobase/row/row0ins.cc:3442
#9  row_ins (thr=<optimized out>, node=<optimized out>) at /data/src/10.2/storage/innobase/row/row0ins.cc:3585
#10 row_ins_step (thr=thr@entry=0x7f5cfc0b6868) at /data/src/10.2/storage/innobase/row/row0ins.cc:3811
#11 0x000056283a939468 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x7f5cfc0b9998 "\371\001", prebuilt=0x7f5cfc0b6070) at /data/src/10.2/storage/innobase/row/row0mysql.cc:1413
#12 0x000056283a889061 in ha_innobase::write_row (this=0x7f5cfc0bc830, record=0x7f5cfc0b9998 "\371\001") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:8224
#13 0x000056283a66957a in handler::ha_write_row (this=0x7f5cfc0bc830, buf=0x7f5cfc0b9998 "\371\001") at /data/src/10.2/sql/handler.cc:5961
#14 0x000056283a4af694 in write_record (thd=thd@entry=0x7f5cfc0009a8, table=table@entry=0x7f5cfc0bbc98, info=info@entry=0x7f5d6055c630) at /data/src/10.2/sql/sql_insert.cc:1655
#15 0x000056283a794ec4 in read_sep_field (ignore_check_option_errors=<optimized out>, skip_lines=<optimized out>, enclosed=..., read_info=..., set_values=..., set_fields=..., fields_vars=..., table_list=0x7f5cfc00f218, info=..., thd=0x7f5cfc0009a8) at /data/src/10.2/sql/sql_load.cc:1256
#16 mysql_load (thd=<optimized out>, ex=<optimized out>, table_list=0x7f5cfc00f218, fields_vars=..., set_fields=..., set_values=..., handle_duplicates=DUP_REPLACE, ignore=<optimized out>, read_file_from_client=false) at /data/src/10.2/sql/sql_load.cc:649
#17 0x000056283a4ce991 in mysql_execute_command (thd=0x7f5cfc0009a8) at /data/src/10.2/sql/sql_parse.cc:4834
#18 0x000056283a4d230a in mysql_parse (thd=0x7f5cfc0009a8, rawbuf=<optimized out>, length=<optimized out>, parser_state=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /data/src/10.2/sql/sql_parse.cc:8013
#19 0x000056283a4d5e84 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f5cfc0009a8, packet=packet@entry=0x7f5cfc006ce9 "LOAD DATA INFILE 'load.data' REPLACE INTO TABLE t1 (pk, b)", packet_length=packet_length@entry=58, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /data/src/10.2/sql/sql_parse.cc:1824
#20 0x000056283a4d68b9 in do_command (thd=0x7f5cfc0009a8) at /data/src/10.2/sql/sql_parse.cc:1378
#21 0x000056283a59f7c4 in do_handle_one_connection (connect=connect@entry=0x56283d977798) at /data/src/10.2/sql/sql_connect.cc:1335
#22 0x000056283a59f964 in handle_one_connection (arg=arg@entry=0x56283d977798) at /data/src/10.2/sql/sql_connect.cc:1241
#23 0x000056283a8638a4 in pfs_spawn_thread (arg=0x56283d93a078) at /data/src/10.2/storage/perfschema/pfs.cc:1862
#24 0x00007f5d71bc6494 in start_thread (arg=0x7f5d6055f700) at pthread_create.c:333
#25 0x00007f5d701c793f in clone () from /lib/x86_64-linux-gnu/libc.so.6



 Comments   
Comment by Marko Mäkelä [ 2019-01-30 ]

The entry format of the index v is (v,pk). Based on the input, v should never be NULL. But, we had this in the error log:

Record in index `v` of table `test`.`t1` was not found on update: TUPLE (info_bits=0, 2 fields): {NULL, (0x8000000000000001)}

As far as I understand, the SQL layer should be providing the values to the virtual columns on handler::ha_delete_row(). For some reason, it failed to fill in a value to the virtual column v, and passed it as NULL instead.

Comment by Alexander Barkov [ 2019-08-23 ]

I tried to change support_virtual_index to 1 in {{ mysql-test/suite/gcol/t/gcol_ins_upd_innodb.test}}, in here:

let $support_virtual_index= 0;
--source suite/gcol/inc/gcol_ins_upd.inc

but mtr gcol_ins_upd_innodb crashed.

The crash seems to be related to this bug report.

The crash is repeatable with the mysql command line client with this script:

DROP TABLE IF EXISTS t;
CREATE TABLE t (
  a INT,
  b YEAR GENERATED ALWAYS AS ('a') VIRTUAL,
  c YEAR GENERATED ALWAYS AS ('aaaa') VIRTUAL,
  b1 YEAR GENERATED ALWAYS AS ('a') STORED,
  c1 YEAR GENERATED ALWAYS AS ('aaaa') STORED,
  UNIQUE(b),
  UNIQUE(b1)
) ENGINE=InnoDB;
INSERT IGNORE INTO t VALUES();
SELECT b from t;
SELECT b1 from t;
SELECT * from t;
DELETE FROM t;

Here's the stack trace:

#0  0x00007ffff76f357f in raise () from /lib64/libc.so.6
#1  0x00007ffff76dd895 in abort () from /lib64/libc.so.6
#2  0x00007ffff76dd769 in __assert_fail_base.cold.0 () from /lib64/libc.so.6
#3  0x00007ffff76eba26 in __assert_fail () from /lib64/libc.so.6
#4  0x0000000000eff8b8 in row_upd_sec_index_entry (node=0x7fff680704d8, thr=0x7fff68074f88)
    at /home/bar/maria-git/server.10.4/storage/innobase/row/row0upd.cc:2429
#5  0x0000000000efff2a in row_upd_sec_step (node=0x7fff680704d8, thr=0x7fff68074f88)
    at /home/bar/maria-git/server.10.4/storage/innobase/row/row0upd.cc:2543
#6  0x0000000000f02642 in row_upd (node=0x7fff680704d8, thr=0x7fff68074f88)
    at /home/bar/maria-git/server.10.4/storage/innobase/row/row0upd.cc:3319
#7  0x0000000000f029a9 in row_upd_step (thr=0x7fff68074f88)
    at /home/bar/maria-git/server.10.4/storage/innobase/row/row0upd.cc:3434
#8  0x0000000000eb6458 in row_update_for_mysql (prebuilt=0x7fff6806f918)
    at /home/bar/maria-git/server.10.4/storage/innobase/row/row0mysql.cc:1889
#9  0x0000000000d60bd8 in ha_innobase::delete_row (this=0x7fff680659f8, 
    record=0x7fff6806e970 <incomplete sequence \313>)
    at /home/bar/maria-git/server.10.4/storage/innobase/handler/ha_innodb.cc:8970
#10 0x0000000000b4bfb2 in handler::ha_delete_row (this=0x7fff680659f8, 
    buf=0x7fff6806e970 <incomplete sequence \313>)
    at /home/bar/maria-git/server.10.4/sql/handler.cc:6790
#11 0x0000000000ce6581 in TABLE::delete_row (this=0x7fff68064b90)
    at /home/bar/maria-git/server.10.4/sql/sql_delete.cc:297
#12 0x0000000000ce3603 in mysql_delete (thd=0x7fff68000d60, table_list=0x7fff68014230, 
    conds=0x0, order_list=0x7fff68005710, limit=18446744073709551615, options=0, 
    result=0x0) at /home/bar/maria-git/server.10.4/sql/sql_delete.cc:834
#13 0x00000000008220ad in mysql_execute_command (thd=0x7fff68000d60)
    at /home/bar/maria-git/server.10.4/sql/sql_parse.cc:4727
#14 0x000000000082cd07 in mysql_parse (thd=0x7fff68000d60, 
    rawbuf=0x7fff68014168 "DELETE FROM t", length=13, parser_state=0x7ffff41d7000, 
    is_com_multi=false, is_next_command=false)
    at /home/bar/maria-git/server.10.4/sql/sql_parse.cc:7908

Comment by Elena Stepanova [ 2020-11-16 ]

Another test case, with UNIQUE BLOB and versioning (I'm not sure why timezone setting is important there, but on some reason it is):

--source include/have_innodb.inc
 
CREATE TABLE t1 (
  pk INT AUTO_INCREMENT PRIMARY KEY,
  b TEXT,
  i INT,
  UNIQUE(i),
  UNIQUE(b)
) ENGINE=InnoDB;
 
INSERT INTO t1 (b,i) VALUES ('foo',1);
SET STATEMENT time_zone= '-07:50' FOR ALTER TABLE t1 ADD SYSTEM VERSIONING;
REPLACE INTO t1 (b,i) VALUES ('foo',1);

10.5 1edd2243

2020-11-16  2:22:41 4 [ERROR] InnoDB: Record in index `b` of table `test`.`t1` was not found on update: TUPLE (info_bits=0, 3 fields): {[8] v -S=wX(0xB976E62D533D7758),[4]    (0x80000001),[7]     B?(0x7FFFFFFF0F423F)} at: COMPACT RECORD(
info_bits=0, 3 fields): {[8]4     : (0x34F3F6061BCE3AD8),[4]    (0x80000001),[7]     B?(0x7FFFFFFF0F423F)}
mariadbd: /data/src/10.5/storage/innobase/row/row0upd.cc:2109: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `0' failed.
201116  2:22:41 [ERROR] mysqld got signal 6 ;
 
#7  0x00007fb45ae63f36 in __GI___assert_fail (assertion=0x557089472121 "0", file=0x557089474690 "/data/src/10.5/storage/innobase/row/row0upd.cc", line=2109, function=0x5570894753f8 "dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*)") at assert.c:101
#8  0x0000557088d08b2b in row_upd_sec_index_entry (node=0x7fb424220c58, thr=0x7fb4240583f8) at /data/src/10.5/storage/innobase/row/row0upd.cc:2109
#9  0x0000557088d09511 in row_upd_sec_step (node=0x7fb424220c58, thr=0x7fb4240583f8) at /data/src/10.5/storage/innobase/row/row0upd.cc:2238
#10 0x0000557088d0c59f in row_upd (node=0x7fb424220c58, thr=0x7fb4240583f8) at /data/src/10.5/storage/innobase/row/row0upd.cc:3021
#11 0x0000557088d0c9ea in row_upd_step (thr=0x7fb4240583f8) at /data/src/10.5/storage/innobase/row/row0upd.cc:3136
#12 0x0000557088cae99d in row_update_for_mysql (prebuilt=0x7fb424220078) at /data/src/10.5/storage/innobase/row/row0mysql.cc:1847
#13 0x0000557088af8a85 in ha_innobase::update_row (this=0x7fb4242326e0, old_row=0x7fb424042a38 "\240\001", new_row=0x7fb424042a08 "\370\002") at /data/src/10.5/storage/innobase/handler/ha_innodb.cc:8375
#14 0x000055708868af97 in handler::ha_update_row (this=0x7fb4242326e0, old_data=0x7fb424042a38 "\240\001", new_data=0x7fb424042a08 "\370\002") at /data/src/10.5/sql/handler.cc:7196
#15 0x00005570882be4ed in write_record (thd=0x7fb424000db8, table=0x7fb424053408, info=0x7fb45420abe0, sink=0x0) at /data/src/10.5/sql/sql_insert.cc:2023
#16 0x00005570882bb6cf in mysql_insert (thd=0x7fb424000db8, table_list=0x7fb424014028, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_REPLACE, ignore=false, result=0x0) at /data/src/10.5/sql/sql_insert.cc:1099
#17 0x000055708830ea32 in mysql_execute_command (thd=0x7fb424000db8) at /data/src/10.5/sql/sql_parse.cc:4587
#18 0x000055708831a744 in mysql_parse (thd=0x7fb424000db8, rawbuf=0x7fb424013f30 "REPLACE INTO t1 (b,i) VALUES ('foo',1)", length=38, parser_state=0x7fb45420b510, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:8044
#19 0x00005570883066a9 in dispatch_command (command=COM_QUERY, thd=0x7fb424000db8, packet=0x7fb4240090a9 "REPLACE INTO t1 (b,i) VALUES ('foo',1)", packet_length=38, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1872
#20 0x0000557088304e9d in do_command (thd=0x7fb424000db8) at /data/src/10.5/sql/sql_parse.cc:1353
#21 0x00005570884b26c1 in do_handle_one_connection (connect=0x55708bf65718, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1410
#22 0x00005570884b2424 in handle_one_connection (arg=0x55708bf7f1a8) at /data/src/10.5/sql/sql_connect.cc:1312
#23 0x0000557088a10bc1 in pfs_spawn_thread (arg=0x55708bf65358) at /data/src/10.5/storage/perfschema/pfs.cc:2201
#24 0x00007fb45b37b609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#25 0x00007fb45af4f293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Reproducible with 10.4-10.5, the test case is not applicable to earlier versions.
Non-debug build does not crash, but produces the "record not found" error.

Comment by Elena Stepanova [ 2020-11-17 ]

Here is another assertion failure which I'm getting intermittently with the one from the description. I can't produce a test case because the one in the description usually happens first, but apparently sometimes it gets missed, and then the one below fires.

10.3 a00e21c0

RD(info_bits=0, 2 fields): {[4]    (0x80000000),[6]      (0x000000000200)}
2020-11-17  2:55:29 9 [ERROR] InnoDB: Clustered record for sec rec not found index `field3` of table `test`.`table_virtual`
InnoDB: sec index record PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 4; hex 80000000; asc     ;;
 1: len 6; hex 000000000200; asc       ;;
 
InnoDB: clust index record PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 696e66696d756d00; asc infimum ;;
 
TRANSACTION 247, ACTIVE 0 sec starting index read
mysql tables in use 2, locked 2
2 lock struct(s), heap size 1152, 1 row lock(s)
MySQL thread id 9, OS thread handle 47953711974144, query id 29 localhost root Checking permissions
UPDATE view1 SET field2 = 1, field2 = NULL, field2 = 215 WHERE field3 <=> 0 ORDER BY field1, field2, field3, field4
 
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
mysqld: /home/elenst/src/10.3/storage/innobase/row/row0sel.cc:3414: dberr_t Row_sel_get_clust_rec_for_mysql::operator()(row_prebuilt_t*, dict_index_t*, const rec_t*, que_thr_t*, const rec_t**, rec_offs**, mem_heap_t**, dtuple_t**, mtr_t*): Assertion `0' failed.
201117  2:55:29 [ERROR] mysqld got signal 6 ;
 
#6  0x00002b9d14c82156 in __assert_fail_base (fmt=0x2b9d14dddbe0 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x56109f9b3993 "0", file=file@entry=0x56109f9b3640 "/home/elenst/src/10.3/storage/innobase/row/row0se
l.cc", line=line@entry=3414, function=function@entry=0x56109f9b7880 <Row_sel_get_clust_rec_for_mysql::operator()(row_prebuilt_t*, dict_index_t*, unsigned char const*, que_thr_t*, unsigned char const**, unsigned short**, mem_block_info_t*
*, dtuple_t**, mtr_t*)::__PRETTY_FUNCTION__> "dberr_t Row_sel_get_clust_rec_for_mysql::operator()(row_prebuilt_t*, dict_index_t*, const rec_t*, que_thr_t*, const rec_t**, rec_offs**, mem_heap_t**, dtuple_t**, mtr_t*)") at assert.c:92
#7  0x00002b9d14c82202 in __GI___assert_fail (assertion=0x56109f9b3993 "0", file=0x56109f9b3640 "/home/elenst/src/10.3/storage/innobase/row/row0sel.cc", line=3414, function=0x56109f9b7880 <Row_sel_get_clust_rec_for_mysql::operator()(row_
prebuilt_t*, dict_index_t*, unsigned char const*, que_thr_t*, unsigned char const**, unsigned short**, mem_block_info_t**, dtuple_t**, mtr_t*)::__PRETTY_FUNCTION__> "dberr_t Row_sel_get_clust_rec_for_mysql::operator()(row_prebuilt_t*, di
ct_index_t*, const rec_t*, que_thr_t*, const rec_t**, rec_offs**, mem_heap_t**, dtuple_t**, mtr_t*)") at assert.c:101
#8  0x000056109f347195 in Row_sel_get_clust_rec_for_mysql::operator() (this=0x2b9d17f78860, prebuilt=0x2b9d6003c170, sec_index=0x2b9d600772b0, rec=0x2b9d1cc3807e "\200", thr=0x2b9d6003cc30, out_rec=0x2b9d17f78768, offsets=0x2b9d17f78788,
 offset_heap=0x2b9d17f78780, vrow=0x0, mtr=0x2b9d17f79060) at /home/elenst/src/10.3/storage/innobase/row/row0sel.cc:3414
#9  0x000056109f34c9a8 in row_search_mvcc (buf=0x2b9d60060b08 "\365", mode=PAGE_CUR_GE, prebuilt=0x2b9d6003c170, match_mode=1, direction=0) at /home/elenst/src/10.3/storage/innobase/row/row0sel.cc:5345
#10 0x000056109f1716af in ha_innobase::index_read (this=0x2b9d6006e558, buf=0x2b9d60060b08 "\365", key_ptr=0x2b9d60095ba8 "", key_len=5, find_flag=HA_READ_KEY_EXACT) at /home/elenst/src/10.3/storage/innobase/handler/ha_innodb.cc:9278
#11 0x000056109edca8c4 in handler::index_read_map (this=0x2b9d6006e558, buf=0x2b9d60060b08 "\365", key=0x2b9d60095ba8 "", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at /home/elenst/src/10.3/sql/handler.h:3479
#12 0x000056109edbbfb9 in handler::ha_index_read_map (this=0x2b9d6006e558, buf=0x2b9d60060b08 "\365", key=0x2b9d60095ba8 "", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at /home/elenst/src/10.3/sql/handler.cc:2904
#13 0x000056109edc475a in handler::read_range_first (this=0x2b9d6006e558, start_key=0x2b9d6006e648, end_key=0x2b9d6006e668, eq_range_arg=true, sorted=true) at /home/elenst/src/10.3/sql/handler.cc:5836
#14 0x000056109ec5a5d5 in handler::multi_range_read_next (this=0x2b9d6006e558, range_info=0x2b9d17f79850) at /home/elenst/src/10.3/sql/multi_range_read.cc:304
#15 0x000056109ec5a7b8 in Mrr_simple_index_reader::get_next (this=0x2b9d6006eaf0, range_info=0x2b9d17f79850) at /home/elenst/src/10.3/sql/multi_range_read.cc:336
#16 0x000056109ec5d58a in DsMrr_impl::dsmrr_next (this=0x2b9d6006e9b0, range_info=0x2b9d17f79850) at /home/elenst/src/10.3/sql/multi_range_read.cc:1406
#17 0x000056109f1857d6 in ha_innobase::multi_range_read_next (this=0x2b9d6006e558, range_info=0x2b9d17f79850) at /home/elenst/src/10.3/storage/innobase/handler/ha_innodb.cc:20602
#18 0x000056109ef3fb80 in QUICK_RANGE_SELECT::get_next (this=0x2b9d6007ce90) at /home/elenst/src/10.3/sql/opt_range.cc:11528
#19 0x000056109edaeaeb in find_all_keys (thd=0x2b9d60000af0, param=0x2b9d17f79b10, select=0x2b9d60090508, fs_info=0x2b9d6007a440, buffpek_pointers=0x2b9d17f79d10, tempfile=0x2b9d17f79ba0, pq=0x0, found_rows=0x2b9d6007a620) at /home/elens
t/src/10.3/sql/filesort.cc:780
#20 0x000056109edacf2b in filesort (thd=0x2b9d60000af0, table=0x2b9d6006d910, filesort=0x2b9d17f7a020, tracker=0x2b9d60090918, join=0x0, first_table_bit=0) at /home/elenst/src/10.3/sql/filesort.cc:274
#21 0x000056109eb956d2 in mysql_update (thd=0x2b9d60000af0, table_list=0x2b9d600359f0, fields=..., values=..., conds=0x2b9d6003adf0, order_num=4, order=0x2b9d600369e8, limit=18446744073709551615, ignore=false, found_return=0x2b9d17f7a5d0
, updated_return=0x2b9d17f7a690) at /home/elenst/src/10.3/sql/sql_update.cc:690
#22 0x000056109ea8fc1c in mysql_execute_command (thd=0x2b9d60000af0) at /home/elenst/src/10.3/sql/sql_parse.cc:4327
#23 0x000056109ea9bcf9 in mysql_parse (thd=0x2b9d60000af0, rawbuf=0x2b9d60035858 "UPDATE view1 SET field2 = 1, field2 = NULL, field2 = 215 WHERE field3 <=> 0 ORDER BY field1, field2, field3, field4", length=115, parser_state=0x2b9d17f7b4
f0, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.3/sql/sql_parse.cc:7839
#24 0x000056109ea88573 in dispatch_command (command=COM_QUERY, thd=0x2b9d60000af0, packet=0x2b9d6002d721 "UPDATE view1 SET field2 = 1, field2 = NULL, field2 = 215 WHERE field3 <=> 0 ORDER BY field1, field2, field3, field4", packet_length
=115, is_com_multi=false, is_next_command=false) at /home/elenst/src/10.3/sql/sql_parse.cc:1853
#25 0x000056109ea86dd8 in do_command (thd=0x2b9d60000af0) at /home/elenst/src/10.3/sql/sql_parse.cc:1399
#26 0x000056109ec0369c in do_handle_one_connection (connect=0x5610a368a490) at /home/elenst/src/10.3/sql/sql_connect.cc:1403
#27 0x000056109ec033de in handle_one_connection (arg=0x5610a368a490) at /home/elenst/src/10.3/sql/sql_connect.cc:1308
#28 0x00002b9d12ecbe65 in start_thread (arg=0x2b9d17f7c700) at pthread_create.c:307
#29 0x00002b9d14d5188d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Comment by Elena Stepanova [ 2021-02-01 ]

The test case from the description doesn't seem to cause the crash anymore, but the one from Bar's comment still does, also in its MTR variation:

--source include/have_innodb.inc
 
DROP TABLE IF EXISTS t;
CREATE TABLE t (
  a INT,
  b YEAR GENERATED ALWAYS AS ('a') VIRTUAL,
  c YEAR GENERATED ALWAYS AS ('aaaa') VIRTUAL,
  b1 YEAR GENERATED ALWAYS AS ('a') STORED,
  c1 YEAR GENERATED ALWAYS AS ('aaaa') STORED,
  UNIQUE(b),
  UNIQUE(b1)
) ENGINE=InnoDB;
INSERT IGNORE INTO t VALUES();
SELECT b from t;
SELECT b1 from t;
SELECT * from t;
DELETE FROM t;

10.2 b87c342d

2021-02-01 15:42:05 140343493056256 [ERROR] InnoDB: Record in index `b` of table `test`.`t` was not found on update: TUPLE (info_bits=0, 2 fields): {[1]d(0x64),[6]      (0x000000000200)} at: COMPACT RECORD(info_bits=0, 2 fields): {[1] (0x00),[6]      (0x000000000200)}
mysqld: /data/src/10.2/storage/innobase/row/row0upd.cc:2432: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `0' failed.
210201 15:42:05 [ERROR] mysqld got signal 6 ;
 
#7  0x00007fa448e40f36 in __GI___assert_fail (assertion=0x55ac6642953f "0", file=0x55ac6642bf78 "/data/src/10.2/storage/innobase/row/row0upd.cc", line=2432, function=0x55ac6642cc10 "dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*)") at assert.c:101
#8  0x000055ac65e2d4fd in row_upd_sec_index_entry (node=0x7fa3f4088f28, thr=0x7fa3f408a4a0) at /data/src/10.2/storage/innobase/row/row0upd.cc:2432
#9  0x000055ac65e2de39 in row_upd_sec_step (node=0x7fa3f4088f28, thr=0x7fa3f408a4a0) at /data/src/10.2/storage/innobase/row/row0upd.cc:2582
#10 0x000055ac65e300de in row_upd (node=0x7fa3f4088f28, thr=0x7fa3f408a4a0) at /data/src/10.2/storage/innobase/row/row0upd.cc:3344
#11 0x000055ac65e30433 in row_upd_step (thr=0x7fa3f408a4a0) at /data/src/10.2/storage/innobase/row/row0upd.cc:3461
#12 0x000055ac65dd9293 in row_update_for_mysql (prebuilt=0x7fa3f4088380) at /data/src/10.2/storage/innobase/row/row0mysql.cc:1825
#13 0x000055ac65c99d73 in ha_innobase::delete_row (this=0x7fa3f409c668, record=0x7fa3f4099d50 "\313") at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:9061
#14 0x000055ac65a9a2fa in handler::ha_delete_row (this=0x7fa3f409c668, buf=0x7fa3f4099d50 "\313") at /data/src/10.2/sql/handler.cc:6178
#15 0x000055ac65c1ed8d in mysql_delete (thd=0x7fa3f4000d90, table_list=0x7fa3f40127b8, conds=0x0, order_list=0x7fa3f4005328, limit=18446744073709551615, options=0, result=0x0) at /data/src/10.2/sql/sql_delete.cc:583
#16 0x000055ac6580a57d in mysql_execute_command (thd=0x7fa3f4000d90) at /data/src/10.2/sql/sql_parse.cc:4397
#17 0x000055ac65815065 in mysql_parse (thd=0x7fa3f4000d90, rawbuf=0x7fa3f40126f8 "DELETE FROM t", length=13, parser_state=0x7fa4440cc5f0, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7763
#18 0x000055ac6580333e in dispatch_command (command=COM_QUERY, thd=0x7fa3f4000d90, packet=0x7fa3f4008b51 "DELETE FROM t", packet_length=13, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1827
#19 0x000055ac65801e39 in do_command (thd=0x7fa3f4000d90) at /data/src/10.2/sql/sql_parse.cc:1381
#20 0x000055ac6595c75e in do_handle_one_connection (connect=0x55ac67c05f90) at /data/src/10.2/sql/sql_connect.cc:1336
#21 0x000055ac6595c4c3 in handle_one_connection (arg=0x55ac67c05f90) at /data/src/10.2/sql/sql_connect.cc:1241
#22 0x000055ac66184a52 in pfs_spawn_thread (arg=0x55ac67be9380) at /data/src/10.2/storage/perfschema/pfs.cc:1869
#23 0x00007fa449350609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#24 0x00007fa448f2c293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

There are countless variations of the test case, all involving indexed virtual columns and resulting in the corruption error and assertion failure.


Also, the infamous assertion !cursor->index->is_committed() failure has been seen under the similar circumstances (although all attempts to reproduce it end up with the errors and/or assertions as above):

10.2 b87c342d

2021-01-31 21:31:27 0x7f202c6ab700  InnoDB: Assertion failure in file /home/vsts/src/storage/innobase/row/row0ins.cc line 253
InnoDB: Failing assertion: !cursor->index->is_committed()
 
#5  0x00007f207230603a in __GI_abort () at abort.c:89
#6  0x000000000194bd01 in ut_dbg_assertion_failed (expr=0x27d7c40 "!cursor->index->is_committed()", file=0x27d79e0 "/home/vsts/src/storage/innobase/row/row0ins.cc", line=253) at /home/vsts/src/storage/innobase/ut/ut0dbg.cc:60
#7  0x0000000001703d02 in row_ins_sec_index_entry_by_modify (flags=0, mode=2, cursor=0x7f202c6a4cf0, offsets=0x7f202c6a4bb0, offsets_heap=0x6190011a8a80, heap=0x6190003bdd80, entry=0x619001ec4508, thr=0x6200001acc78, mtr=0x7f202c6a5030) at /home/vsts/src/storage/innobase/row/row0ins.cc:253
#8  0x0000000001712a06 in row_ins_sec_index_entry_low (flags=0, mode=2, index=0x618001c92508, offsets_heap=0x6190011a8a80, heap=0x6190003bdd80, entry=0x619001ec4508, trx_id=0, thr=0x6200001acc78) at /home/vsts/src/storage/innobase/row/row0ins.cc:3028
#9  0x0000000001713e96 in row_ins_sec_index_entry (index=0x618001c92508, entry=0x619001ec4508, thr=0x6200001acc78) at /home/vsts/src/storage/innobase/row/row0ins.cc:3215
#10 0x00000000018319f9 in row_upd_sec_index_entry (node=0x6200001ac928, thr=0x6200001acc78) at /home/vsts/src/storage/innobase/row/row0upd.cc:2555
#11 0x0000000001831f44 in row_upd_sec_step (node=0x6200001ac928, thr=0x6200001acc78) at /home/vsts/src/storage/innobase/row/row0upd.cc:2582
#12 0x0000000001836d58 in row_upd (node=0x6200001ac928, thr=0x6200001acc78) at /home/vsts/src/storage/innobase/row/row0upd.cc:3344
#13 0x0000000001837868 in row_upd_step (thr=0x6200001acc78) at /home/vsts/src/storage/innobase/row/row0upd.cc:3461
#14 0x0000000001760985 in row_update_for_mysql (prebuilt=0x6200001ac108) at /home/vsts/src/storage/innobase/row/row0mysql.cc:1825
#15 0x0000000001460b79 in ha_innobase::update_row (this=0x61d002ab0d10, old_row=0x61900073ba38 <incomplete sequence \371>, new_row=0x61900073ba20 "\377") at /home/vsts/src/storage/innobase/handler/ha_innodb.cc:8945
#16 0x0000000000f275fb in handler::ha_update_row (this=0x61d002ab0d10, old_data=0x61900073ba38 <incomplete sequence \371>, new_data=0x61900073ba20 "\377") at /home/vsts/src/sql/handler.cc:6150
#17 0x0000000000b33b06 in mysql_update (thd=0x62a00013e270, table_list=0x62b001636c90, fields=..., values=..., conds=0x0, order_num=1, order=0x629002c5b3a8, limit=8, handle_duplicates=DUP_ERROR, ignore=false, found_return=0x7f202c6a8480, updated_return=0x7f202c6a84c0) at /home/vsts/src/sql/sql_update.cc:819
#18 0x00000000008978f2 in mysql_execute_command (thd=0x62a00013e270) at /home/vsts/src/sql/sql_parse.cc:4033
#19 0x0000000000905ed3 in Prepared_statement::execute (this=0x619002a76af0, expanded_query=0x7f202c6a9710, open_cursor=false) at /home/vsts/src/sql/sql_prepare.cc:5037
#20 0x000000000090155d in Prepared_statement::execute_loop (this=0x619002a76af0, expanded_query=0x7f202c6a9710, open_cursor=false, packet=0x629002e4027a "", packet_end=0x629002e4027a "") at /home/vsts/src/sql/sql_prepare.cc:4466
#21 0x00000000008fb3e7 in mysql_stmt_execute_common (thd=0x62a00013e270, stmt_id=7158, packet=0x629002e4027a "", packet_end=0x629002e4027a "", cursor_flags=0, bulk_op=false, read_types=false) at /home/vsts/src/sql/sql_prepare.cc:3468
#22 0x00000000008fa6be in mysqld_stmt_execute (thd=0x62a00013e270, packet_arg=0x629002e40271 "\366\033", packet_length=9) at /home/vsts/src/sql/sql_prepare.cc:3258
#23 0x0000000000889243 in dispatch_command (command=COM_STMT_EXECUTE, thd=0x62a00013e270, packet=0x629002e40271 "\366\033", packet_length=9, is_com_multi=false, is_next_command=false) at /home/vsts/src/sql/sql_parse.cc:1770
#24 0x0000000000886173 in do_command (thd=0x62a00013e270) at /home/vsts/src/sql/sql_parse.cc:1381
#25 0x0000000000c351a1 in do_handle_one_connection (connect=0x611001673c70) at /home/vsts/src/sql/sql_connect.cc:1336
#26 0x0000000000c34a5e in handle_one_connection (arg=0x611001673c70) at /home/vsts/src/sql/sql_connect.cc:1241
#27 0x00000000020cdb0e in pfs_spawn_thread (arg=0x61600008c4f0) at /home/vsts/src/storage/perfschema/pfs.cc:1869
#28 0x00007f2072fa46ba in start_thread (arg=0x7f202c6ab700) at pthread_create.c:333
#29 0x00007f20723d64dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
 
Query (0x62b0016358e8): UPDATE /* QNO 6988 CON_ID 16 */ tmp SET fld = JSON_MERGE( '{"coffee": 0,"crowded": "false","traditionally": "gcjalvglhtprlogosdbmbyetiddlfcwfadamungmlzvibzvpfblxqbrdjrs","precisely": 0,"whenever": "false","tight": "null","popular": "cja","ours": 0,"survive": 0,"economy": "true","supermarket": "false","conclude": "jalvglhtprl","scandal": 0,"down": "alvglhtprlogosdbmbyetiddl","minor": "null","dream": "null","clearly": {"grocery": "false","resist": "false","vulnerable": "null"},"obtain": 0,"wolf": "false","sex": "null","jet": "lvg","fellow": 0,"thread": "false"}', JSON_ARRAY_APPEND( JSON_DETAILED( JSON_KEYS( JSON_MERGE( JSON_ARRAY_INSERT( '{"meanwhile": "null","extended": "true","record": "false","gasoline": 0,"bench": 0,"reasonable": 0,"huh": "null","characterize": "null","among": "null","strike": "null","breast": "false","cluster": "vglhtprlogosdbmbyetiddlfcwfadamungmlzvibzvpfblxqbrdjrs","generate": "null","excited": "g","summer": "null","harassment": "u","spine": 0,"green": 0,"idea": "false","solar": "lhtprlogosdbmbyetiddl","remember": "htprlogosdbmbyeti","gentle": "null","supportive": "null","ethics": "true","van": "tprlogosdbmbyetiddlfcwfadam","constitute": "p","feminist": 0,"literature": "null","some": 0,"reliable": "false","muslim": 0,"priority": "true","cancel": "false","beam": "","survivor": "true","need": "null","content": "rlogosdbmbyetiddlfcwfadamungmlzvibzvpfblxqbrdjrshubpmcqrzq","breeze": 0,"biography": "false","consist": "logosdbmbye"}', '$.grave', '"null"', '$[5]', '["true","false","o","go","false","osdbmbyetiddlfcwfa","sdbmbyetidd",[0,"null","false","dbmbyetiddl","bmby","null","false","mbyet"],0,0,0,"null"]' ), '[0,"true","null",0,"true","byetiddlfcwfadamungmlzvibz","null","false","ye","true","false","null",0,"false",0,"e","tiddlfcwfadamungmlzv","null","null",0,"iddlfcwfadamun","true","ddlfcwfadamungmlzv","dlfcwfadamungmlzvibzvpfblxq","true",0,"false","lfcwfadamungmlzvibzvpfblxqbrdjrshu","false","null","true",0,"fcwfadamungmlzvibzv","cwfadamungmlzvibzvpfblxqbrdjrsh",0,"null",["null","wfad",0,0,"true","true","false",0,"false","true","null","false",0,0,"true","true"],"null","true",0,"null",{"retreat": "true","canvas": "true","bottom": "fadamungmlzvib","complexity": "null"},0,"null",0,"true",0,"true",0,0,"false","false","false",["false","false"],"false","null"]' ), '$.priest' ) ), '$[3]', '0', '$[3]', '"adamungmlzvibzvpfblxqbrdjr"' ) ) ORDER BY fld LIMIT 8
Status: NOT_KILLED

The tmp table with which the failure above occurred at the moment of update was

CREATE TABLE `tmp` (
  `x` bit(1) DEFAULT NULL,
  `fld` blob DEFAULT NULL,
  `vfld` text COLLATE cp1251_general_nopad_ci GENERATED ALWAYS AS (`fld`) VIRTUAL,
  KEY `fld` (`fld`(3072)),
  KEY `vfld` (`vfld`(3072))
) ENGINE=InnoDB DEFAULT CHARSET=cp1251 COLLATE=cp1251_general_nopad_ci;

Comment by Roel Van de Paar [ 2021-04-26 ]

SET sql_mode='';
CREATE TABLE t1 (a INT AUTO_INCREMENT KEY) ENGINE=InnoDB;
ALTER TABLE t1 ADD UNIQUE u USING HASH(a);
INSERT INTO t1 VALUES (0);
DELETE FROM t1;

Leads to:

10.6.0 a3e3225cd3b816d47621e749e21a71b6a864a96a (Debug)

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

10.6.0 a3e3225cd3b816d47621e749e21a71b6a864a96a (Debug)

Core was generated by `/test/MD150421-mariadb-10.6.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 0x1543ed616700 (LWP 3354333))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x0000154404491859 in __GI_abort () at abort.c:79
#2  0x0000154404491729 in __assert_fail_base (fmt=0x154404627588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55ecc7f151a8 "0", file=0x55ecc80043a0 "/test/10.6_dbg/storage/innobase/row/row0upd.cc", line=2110, function=<optimized out>) at assert.c:92
#3  0x00001544044a2f36 in __GI___assert_fail (assertion=assertion@entry=0x55ecc7f151a8 "0", file=file@entry=0x55ecc80043a0 "/test/10.6_dbg/storage/innobase/row/row0upd.cc", line=line@entry=2110, function=function@entry=0x55ecc8005750 "dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*)") at assert.c:101
#4  0x000055ecc7979000 in row_upd_sec_index_entry (node=node@entry=0x1543b404cf68, thr=thr@entry=0x1543b4094af8) at /test/10.6_dbg/storage/innobase/row/row0upd.cc:2110
#5  0x000055ecc7979fa7 in row_upd_sec_step (thr=0x1543b4094af8, node=0x1543b404cf68) at /test/10.6_dbg/storage/innobase/row/row0upd.cc:2263
#6  row_upd (thr=0x1543b4094af8, node=0x1543b404cf68) at /test/10.6_dbg/storage/innobase/row/row0upd.cc:2994
#7  row_upd_step (thr=thr@entry=0x1543b4094af8) at /test/10.6_dbg/storage/innobase/row/row0upd.cc:3109
#8  0x000055ecc791a736 in row_update_for_mysql (prebuilt=0x1543b404c518) at /test/10.6_dbg/storage/innobase/row/row0mysql.cc:1815
#9  0x000055ecc779e705 in ha_innobase::delete_row (this=0x1543b404b850, record=0x1543b404b3e8 "\377\001") at /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc:8308
#10 0x000055ecc73ab98c in handler::ha_delete_row (this=0x1543b404b850, buf=0x1543b404b3e8 "\377\001") at /test/10.6_dbg/sql/handler.cc:7274
#11 0x000055ecc75923d9 in TABLE::delete_row (this=0x1543b4048f68) at /test/10.6_dbg/sql/sql_delete.cc:280
#12 0x000055ecc7590596 in mysql_delete (thd=thd@entry=0x1543b4000db8, table_list=0x1543b4013c70, conds=<optimized out>, order_list=order_list@entry=0x1543b4005a30, limit=18446744073709551615, options=<optimized out>, result=0x0) at /test/10.6_dbg/sql/sql_delete.cc:815
#13 0x000055ecc70d7d20 in mysql_execute_command (thd=thd@entry=0x1543b4000db8) at /test/10.6_dbg/sql/sql_limit.h:67
#14 0x000055ecc70c1a06 in mysql_parse (thd=thd@entry=0x1543b4000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1543ed615410) at /test/10.6_dbg/sql/sql_parse.cc:8017
#15 0x000055ecc70d07df in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x1543b4000db8, packet=packet@entry=0x1543b400b369 "DELETE FROM t1", packet_length=packet_length@entry=14, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_class.h:1331
#16 0x000055ecc70d3bd5 in do_command (thd=0x1543b4000db8, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_parse.cc:1406
#17 0x000055ecc722d77c in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55ecc9c4b568, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1410
#18 0x000055ecc722dd81 in handle_one_connection (arg=arg@entry=0x55ecc9c4b568) at /test/10.6_dbg/sql/sql_connect.cc:1312
#19 0x000055ecc76dba03 in pfs_spawn_thread (arg=0x55ecc9b4ed18) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
#20 0x000015440499f609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#21 0x000015440458e293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.4.19 (dbg), 10.5.10 (dbg), 10.6.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.38 (dbg), 10.2.38 (opt), 10.3.29 (dbg), 10.3.29 (opt), 10.4.19 (opt), 10.5.10 (opt), 10.6.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.33 (dbg), 5.7.33 (opt), 8.0.23 (dbg), 8.0.23 (opt)

Comment by Roel Van de Paar [ 2021-04-26 ]

Added regression tag as there is an established regression as of 10.4 (ref last testcase above). 10.3 Output:

10.3.29 7d5ec9f1aeec1ea8d00a0aa5bfec521948cfb8be (Debug)

10.3.29-dbg>SET sql_mode='';
Query OK, 0 rows affected (0.000 sec)
 
10.3.29-dbg>CREATE TABLE t1 (a INT AUTO_INCREMENT KEY) ENGINE=InnoDB;
Query OK, 0 rows affected (0.020 sec)
 
10.3.29-dbg>ALTER TABLE t1 ADD UNIQUE u USING HASH(a);
Query OK, 0 rows affected (0.020 sec)
Records: 0  Duplicates: 0  Warnings: 0
 
10.3.29-dbg>INSERT INTO t1 VALUES (0);
Query OK, 1 row affected (0.004 sec)
 
10.3.29-dbg>DELETE FROM t1;
Query OK, 1 row affected (0.004 sec)
 
10.3.29-dbg>

Also, optimized output does not seem to produce the 'record not found' error (mentioned above) anymore;

10.6.0 a3e3225cd3b816d47621e749e21a71b6a864a96a (Optimized)

10.6.0-opt>SET sql_mode='';
Query OK, 0 rows affected (0.000 sec)
 
10.6.0-opt>CREATE TABLE t1 (a INT AUTO_INCREMENT KEY) ENGINE=InnoDB;
Query OK, 0 rows affected (0.014 sec)
 
10.6.0-opt>ALTER TABLE t1 ADD UNIQUE u USING HASH(a);
Query OK, 0 rows affected (0.038 sec)              
Records: 0  Duplicates: 0  Warnings: 0
 
10.6.0-opt>INSERT INTO t1 VALUES (0);
Query OK, 1 row affected (0.004 sec)
 
10.6.0-opt>DELETE FROM t1;
Query OK, 1 row affected (0.002 sec)
 
10.6.0-opt>

Comment by Roel Van de Paar [ 2021-05-31 ]

CREATE TABLE t (c INT UNSIGNED AUTO_INCREMENT KEY) ENGINE=InnoDB;
CREATE UNIQUE INDEX i1 USING HASH ON t (c ASC);
INSERT INTO t VALUES();
DELETE FROM t;

Leads to:

10.6 34340fb501f97d7289c165dd6599a3942087bc41 (Debug)

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

10.6 34340fb501f97d7289c165dd6599a3942087bc41 (Debug)

2021-05-31 21:24:40 4 [ERROR] InnoDB: Record in index `i1` of table `test`.`t` was not found on update: TUPLE (info_bits=0, 2 fields): {[8]        (0x00000104000002D0),[4]    (0x00000001)} at: COMPACT RECORD(info_bits=0, 2 fields): {[8]        (0x00000104000002C4),[4]    (0x00000001)}
mysqld: /test/10.6_dbg/storage/innobase/row/row0upd.cc:2110: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `0' failed.

10.6 34340fb501f97d7289c165dd6599a3942087bc41 (Debug)

Core was generated by `/test/MD180521-mariadb-10.6.1-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 0x1531c00fb700 (LWP 2539891))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00001531d7d90859 in __GI_abort () at abort.c:79
#2  0x00001531d7d90729 in __assert_fail_base (fmt=0x1531d7f26588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x559a8c71bca8 "0", file=0x559a8c80b338 "/test/10.6_dbg/storage/innobase/row/row0upd.cc", line=2110, function=<optimized out>) at assert.c:92
#3  0x00001531d7da1f36 in __GI___assert_fail (assertion=assertion@entry=0x559a8c71bca8 "0", file=file@entry=0x559a8c80b338 "/test/10.6_dbg/storage/innobase/row/row0upd.cc", line=line@entry=2110, function=function@entry=0x559a8c80c6e8 "dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*)") at assert.c:101
#4  0x0000559a8c17a712 in row_upd_sec_index_entry (node=node@entry=0x153184049498, thr=thr@entry=0x153184090e88) at /test/10.6_dbg/storage/innobase/row/row0upd.cc:2110
#5  0x0000559a8c17b6b9 in row_upd_sec_step (thr=0x153184090e88, node=0x153184049498) at /test/10.6_dbg/storage/innobase/row/row0upd.cc:2263
#6  row_upd (thr=0x153184090e88, node=0x153184049498) at /test/10.6_dbg/storage/innobase/row/row0upd.cc:2994
#7  row_upd_step (thr=thr@entry=0x153184090e88) at /test/10.6_dbg/storage/innobase/row/row0upd.cc:3109
#8  0x0000559a8c11c6de in row_update_for_mysql (prebuilt=0x153184048a48) at /test/10.6_dbg/storage/innobase/row/row0mysql.cc:1815
#9  0x0000559a8bf9de9d in ha_innobase::delete_row (this=0x153184047d80, record=0x153184045b58 "\377\001") at /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc:8301
#10 0x0000559a8bbaa55e in handler::ha_delete_row (this=0x153184047d80, buf=0x153184045b58 "\377\001") at /test/10.6_dbg/sql/handler.cc:7280
#11 0x0000559a8bd9068b in TABLE::delete_row (this=0x153184046f18) at /test/10.6_dbg/sql/sql_delete.cc:280
#12 0x0000559a8bd8e876 in mysql_delete (thd=thd@entry=0x153184000db8, table_list=0x1531840140a0, conds=<optimized out>, order_list=order_list@entry=0x153184005bd8, limit=18446744073709551615, options=<optimized out>, result=0x0) at /test/10.6_dbg/sql/sql_delete.cc:815
#13 0x0000559a8b8d02fa in mysql_execute_command (thd=thd@entry=0x153184000db8) at /test/10.6_dbg/sql/sql_limit.h:83
#14 0x0000559a8b8b9f8d in mysql_parse (thd=thd@entry=0x153184000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1531c00fa410) at /test/10.6_dbg/sql/sql_parse.cc:8019
#15 0x0000559a8b8c8dbf in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x153184000db8, packet=packet@entry=0x15318400b799 "DELETE FROM t", packet_length=packet_length@entry=13, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_class.h:1333
#16 0x0000559a8b8cc1b2 in do_command (thd=0x153184000db8, blocking=blocking@entry=true) at /test/10.6_dbg/sql/sql_parse.cc:1406
#17 0x0000559a8ba26e78 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x559a8e852aa8, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1410
#18 0x0000559a8ba2747d in handle_one_connection (arg=arg@entry=0x559a8e852aa8) at /test/10.6_dbg/sql/sql_connect.cc:1312
#19 0x0000559a8bed9d98 in pfs_spawn_thread (arg=0x559a8e73c3b8) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
#20 0x00001531d829e609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#21 0x00001531d7e8d293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.4.19 (dbg), 10.5.10 (dbg), 10.6.1 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.38 (dbg), 10.2.38 (opt), 10.3.29 (dbg), 10.3.29 (opt), 10.4.19 (opt), 10.5.10 (opt), 10.6.0 (opt), 10.6.1 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.34 (dbg), 5.7.34 (opt), 8.0.24 (dbg), 8.0.24 (opt)

Comment by Roel Van de Paar [ 2021-05-31 ]

Another testcase with somewhat different output, and this one affects 10.4 only.

SET sql_mode='';
CREATE TEMPORARY TABLE t (c INT AUTO_INCREMENT KEY, c2 VARCHAR(1025) BINARY CHARACTER SET 'utf8' COLLATE 'utf8_bin', c3 VARCHAR(1024), c4 VARCHAR(1) CHARACTER SET 'latin1' COLLATE 'latin1_bin') ROW_FORMAT=REDUNDANT ENGINE=InnoDB;
ALTER TABLE t ADD UNIQUE (c4,c3,c2,c);
INSERT INTO t VALUES ('','','fzu{HUd=F6I#A=zRZ6h+}f]]Q$bgIS/iwS&9AtjUYU7Q*LOPlQ[GQq=WDP79) 1=1 ( (G=1aOP0@',1.e+20);
UPDATE t SET c=0;

Leads to:

10.4.19 9e6310e323a3abd411f852ff57fe41c9f149ff3a (Debug)

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

10.4.19 9e6310e323a3abd411f852ff57fe41c9f149ff3a (Debug)

2021-05-31 22:51:29 9 [ERROR] InnoDB: Record in index `c4` of table `data`.`#sqlae1d9_9_1` was not found on update: TUPLE (info_bits=0, 2 fields): {[8]a    a  (0x619ABFB80B61D0A2),[4]    (0x80000001)} at: RECORD(info_bits=0, 1 fields): {[8]infimum (0x696E66696D756D00)}
mysqld: /test/10.4_dbg/storage/innobase/row/row0upd.cc:2417: dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*): Assertion `0' failed.

10.4.19 9e6310e323a3abd411f852ff57fe41c9f149ff3a (Debug)

Core was generated by `/test/MD270421-mariadb-10.4.19-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 0x15499c116700 (LWP 686837))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x000015499d8fe859 in __GI_abort () at abort.c:79
#2  0x000015499d8fe729 in __assert_fail_base (fmt=0x15499da94588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x560ee675c84d "0", file=0x560ee67dd678 "/test/10.4_dbg/storage/innobase/row/row0upd.cc", line=2417, function=<optimized out>) at assert.c:92
#3  0x000015499d90ff36 in __GI___assert_fail (assertion=assertion@entry=0x560ee675c84d "0", file=file@entry=0x560ee67dd678 "/test/10.4_dbg/storage/innobase/row/row0upd.cc", line=line@entry=2417, function=function@entry=0x560ee67debe8 "dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*)") at assert.c:101
#4  0x0000560ee6069a3c in row_upd_sec_index_entry (node=node@entry=0x15493c022c70, thr=thr@entry=0x15493c023008) at /test/10.4_dbg/storage/innobase/row/row0upd.cc:2417
#5  0x0000560ee606aa18 in row_upd_sec_step (thr=0x15493c023008, node=0x15493c022c70) at /test/10.4_dbg/storage/innobase/row/row0upd.cc:2564
#6  row_upd (thr=0x15493c023008, node=0x15493c022c70) at /test/10.4_dbg/storage/innobase/row/row0upd.cc:3319
#7  row_upd_step (thr=thr@entry=0x15493c023008) at /test/10.4_dbg/storage/innobase/row/row0upd.cc:3434
#8  0x0000560ee6008cd0 in row_update_for_mysql (prebuilt=0x15493c033bd0) at /test/10.4_dbg/storage/innobase/row/row0mysql.cc:1845
#9  0x0000560ee5e6ba35 in ha_innobase::update_row (this=0x15493c02ddb8, old_row=0x15493c0322f0 "\360\001", new_row=0x15493c0312d8 <incomplete sequence \360>) at /test/10.4_dbg/storage/innobase/handler/ha_innodb.cc:8903
#10 0x0000560ee5c0f013 in handler::ha_update_row (this=0x15493c02ddb8, old_data=0x15493c0322f0 "\360\001", new_data=0x15493c0312d8 <incomplete sequence \360>) at /test/10.4_dbg/sql/handler.cc:6802
#11 0x0000560ee5a167ee in mysql_update (thd=thd@entry=0x15493c000d90, table_list=<optimized out>, fields=@0x15493c005608: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x15493c013b78, last = 0x15493c013b78, elements = 1}, <No data fields>}, values=@0x15493c005bb0: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x15493c013b88, last = 0x15493c013b88, elements = 1}, <No data fields>}, conds=<optimized out>, order_num=<optimized out>, order=<optimized out>, limit=18446744073709551615, ignore=false, found_return=0x15499c113c10, updated_return=0x15499c113cd0) at /test/10.4_dbg/sql/sql_update.cc:1074
#12 0x0000560ee5927e3f in mysql_execute_command (thd=thd@entry=0x15493c000d90) at /test/10.4_dbg/sql/sql_parse.cc:4439
#13 0x0000560ee593027a in mysql_parse (thd=thd@entry=0x15493c000d90, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x15499c115490, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_parse.cc:7995
#14 0x0000560ee5932bf1 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x15493c000d90, packet=packet@entry=0x15493c01a351 "UPDATE t SET c=0", packet_length=packet_length@entry=16, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_dbg/sql/sql_class.h:1183
#15 0x0000560ee593646d in do_command (thd=0x15493c000d90) at /test/10.4_dbg/sql/sql_parse.cc:1373
#16 0x0000560ee5a704e8 in do_handle_one_connection (connect=connect@entry=0x560ee9e203d0) at /test/10.4_dbg/sql/sql_connect.cc:1412
#17 0x0000560ee5a70607 in handle_one_connection (arg=0x560ee9e203d0) at /test/10.4_dbg/sql/sql_connect.cc:1316
#18 0x000015499de0c609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#19 0x000015499d9fb293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.4.19 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.2.38 (dbg), 10.2.38 (opt), 10.3.29 (dbg), 10.3.29 (opt), 10.4.19 (opt), 10.5.10 (dbg), 10.5.10 (opt), 10.6.1 (dbg), 10.6.1 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.34 (dbg), 5.7.34 (opt), 8.0.24 (dbg), 8.0.24 (opt)

Comment by Roel Van de Paar [ 2021-06-12 ]

The second last testcase above, whilst not crashing, does still introduce corruption in optimized builds inc 10.6.2 as of today:

CREATE TABLE t (c INT UNSIGNED AUTO_INCREMENT KEY) ENGINE=InnoDB;
CREATE UNIQUE INDEX i1 USING HASH ON t (c ASC);
INSERT INTO t VALUES();
DELETE FROM t;

10.6.2 6c39eaeb126328e7813b146ecf652d51e4508981 (Optimized)

2021-06-12 16:20:38 0 [Note] /test/MD120621-mariadb-10.6.2-linux-x86_64-opt/bin/mysqld: ready for connections.
Version: '10.6.2-MariaDB'  socket: '/test/MD120621-mariadb-10.6.2-linux-x86_64-opt/socket.sock'  port: 38846  MariaDB Server
2021-06-12 16:20:38 0 [Note] InnoDB: Buffer pool(s) load completed at 210612 16:20:38
2021-06-12 16:20:57 4 [ERROR] InnoDB: Record in index `i1` of table `test`.`t` was not found on update: TUPLE (info_bits=0, 2 fields): {[8]        (0x00000104000002D0),[4]    (0x00000001)} at: COMPACT RECORD(info_bits=0, 2 fields): {[8]        (0x00000104000002C4),[4]    (0x00000001)}
2021-06-12 16:20:59 0 [Note] /test/MD120621-mariadb-10.6.2-linux-x86_64-opt/bin/mysqld (initiated by: root[root] @ localhost []): Normal shutdown

Comment by Nikita Malyavin [ 2021-06-20 ]

This goes deeper in the year truncation cripples. Even for MyISAM the behavior is undefined:

CREATE TABLE t (
a INT,
b YEAR GENERATED ALWAYS AS ('a') VIRTUAL,
c YEAR GENERATED ALWAYS AS ('aaaa') VIRTUAL,
b1 YEAR GENERATED ALWAYS AS ('a') STORED,
c1 YEAR GENERATED ALWAYS AS ('aaaa') STORED,
UNIQUE(b),
UNIQUE(b1)
) ENGINE=MYISAM;
INSERT IGNORE INTO t VALUES();
Warnings:
Warning	1366	Incorrect integer value: 'a' for column `test`.`t`.`b` at row 1
Warning	1366	Incorrect integer value: 'a' for column `test`.`t`.`b1` at row 1
Warning	1366	Incorrect integer value: 'aaaa' for column `test`.`t`.`c1` at row 1
SELECT b from t;
b
2000
SELECT b1 from t;
b1
0000
SELECT b from t;
b
2000
SELECT b, b1 from t;
b	b1
2000	0000
SELECT * from t;
a	b	c	b1	c1
NULL	2000	0000	0000	0000
DELETE FROM t;
DROP TABLE t;

INSERT IGNORE calculates the value as 0000, but SELECT calculates it as 2000.

The difference is dictated by THD::count_cuted_fields parameter value, which is set to CHECK_FIELD_WARN for INSERT IGNORE, and to CHECK_FIELD_IGNORE (default) in most other statements.

Innodb requires the virtual index record be always accessible when calculated, while Aria/MyISAM are careless. My side guess is MyISAM may even store junk secondary index records in such cases.

With this simple patch
(note that TABLE::update_virtual_field is only called by InnoDB, and by MyISAM's repair)

--- a/sql/table.cc
+++ b/sql/table.cc
@@ -7798,8 +7798,11 @@ int TABLE::update_virtual_field(Field *vf)
   in_use->push_internal_handler(&count_errors);
   in_use->set_n_backup_active_arena(expr_arena, &backup_arena);
   bitmap_clear_all(&tmp_set);
+  enum_check_fields check_fields= in_use->count_cuted_fields;
+  in_use->count_cuted_fields= CHECK_FIELD_WARN;
   vf->vcol_info->expr->walk(&Item::update_vcol_processor, 0, &tmp_set);
   vf->vcol_info->expr->save_in_field(vf, 0);
+  in_use->count_cuted_fields= check_fields;
   in_use->restore_active_arena(expr_arena, &backup_arena);
   in_use->pop_internal_handler();
   DBUG_RETURN(count_errors.errors);

The crash gets fixed, but the results may vary even depending on the optimizer path (depending on whether the column value was calculated in the runtime side (sql_select.cc, etc) or inside the engine). Therefore, even two identical SELECT calls may return different results for a single record.

With the patch above:

CREATE TABLE t (
a INT,
b YEAR GENERATED ALWAYS AS ('a') VIRTUAL,
c YEAR GENERATED ALWAYS AS ('aaaa') VIRTUAL,
b1 YEAR GENERATED ALWAYS AS ('a') STORED,
c1 YEAR GENERATED ALWAYS AS ('aaaa') STORED,
UNIQUE(b),
UNIQUE(b1)
) ENGINE=InnoDB;
INSERT IGNORE INTO t VALUES();
Warnings:
Warning	1366	Incorrect integer value: 'a' for column `test`.`t`.`b` at row 1
Warning	1366	Incorrect integer value: 'a' for column `test`.`t`.`b1` at row 1
Warning	1366	Incorrect integer value: 'aaaa' for column `test`.`t`.`c1` at row 1
SELECT b from t;
b
0000
SELECT b1 from t;
b1
0000
SELECT b from t;
b
0000
SELECT b, b1 from t;
b	b1
2000	0000
SELECT * from t;
a	b	c	b1	c1
NULL	2000	0000	0000	0000
DELETE FROM t;
Warnings:
Warning	1366	Incorrect integer value: 'a' for column `test`.`t`.`b` at row 1

Due to our legacy treatments, we would prefer to preserve current behavior, however changing Field_year behavior a bit:

diff --git a/sql/field.cc b/sql/field.cc
--- a/sql/field.cc	(revision cd1a195b22d2dac248228b6b7ecbd0a54997ecf7)
+++ b/sql/field.cc	(date 1624212410457)
@@ -6384,7 +6384,7 @@
     set_warning(ER_WARN_DATA_OUT_OF_RANGE, 1);
     return 1;
   }
-  if (get_thd()->count_cuted_fields && 
+  if (get_thd()->count_cuted_fields == CHECK_FIELD_ERROR_FOR_NULL && 
       (error= check_int(cs, from, len, end, error)))
   {
     if (error == 1)  /* empty or incorrect string */

produces charming results:

CREATE TABLE t (
a INT,
b YEAR GENERATED ALWAYS AS ('a') VIRTUAL,
c YEAR GENERATED ALWAYS AS ('aaaa') VIRTUAL,
b1 YEAR GENERATED ALWAYS AS ('a') STORED,
c1 YEAR GENERATED ALWAYS AS ('aaaa') STORED,
UNIQUE(b),
UNIQUE(b1)
) ENGINE=InnoDB;
INSERT IGNORE INTO t VALUES();
SELECT b from t;
b
2000
SELECT b1 from t;
b1
2000
SELECT b from t;
b
2000
SELECT b, b1 from t;
b	b1
2000	2000
SELECT * from t;
a	b	c	b1	c1
NULL	2000	0000	2000	0000
DELETE FROM t;
DROP TABLE t;

If the test runs will produce no significant changes, I would propose the second solution, which will change the behaviour slightly for 10.2+.

serg, sanja what's your opinion?

Comment by Nikita Malyavin [ 2021-06-20 ]

main.type_year and main.type_date have meaningfully failed:

--- /home/nik/mariadb/mysql-test/r/type_date.result	2021-06-15 22:28:31.819710775 +0300
+++ /home/nik/mariadb/mysql-test/r/type_date.reject	2021-06-20 21:43:28.526054857 +0300
@@ -107,11 +107,9 @@
 DROP TABLE t1, t2, t3;
 CREATE TABLE t1 (y YEAR);
 INSERT IGNORE INTO t1 VALUES ('abc');
-Warnings:
-Warning	1366	Incorrect integer value: 'abc' for column `test`.`t1`.`y` at row 1
 SELECT * FROM t1;
 y
-0000
+2000
 DROP TABLE t1;
 create table t1(start_date date, end_date date);
 insert into t1 values ('2000-01-01','2000-01-02');

--- /home/nik/mariadb/mysql-test/r/type_year.result	2021-06-15 22:28:31.826377462 +0300
+++ /home/nik/mariadb/mysql-test/r/type_year.reject	2021-06-20 21:41:33.795394375 +0300
@@ -43,8 +43,6 @@
 #
 create table t1(a year);
 insert into t1 values (2000.5), ('2000.5'), ('2001a'), ('2.001E3');
-Warnings:
-Warning	1265	Data truncated for column 'a' at row 3
 select * from t1;
 a
 2001

Of course, gcol.gcol_ins_upd_myisam had failed too, but that's relatively insignificant, and reflects type_date results

Comment by Nikita Malyavin [ 2021-06-20 ]

Warnings should not be removed. Thereby, a little bit more careful patch does well:

diff --git a/sql/field.cc b/sql/field.cc
--- a/sql/field.cc	(revision cd1a195b22d2dac248228b6b7ecbd0a54997ecf7)
+++ b/sql/field.cc	(date 1624216210532)
@@ -6384,10 +6384,11 @@
     set_warning(ER_WARN_DATA_OUT_OF_RANGE, 1);
     return 1;
   }
-  if (get_thd()->count_cuted_fields && 
+  if (get_thd()->count_cuted_fields != CHECK_FIELD_IGNORE && 
       (error= check_int(cs, from, len, end, error)))
   {
-    if (error == 1)  /* empty or incorrect string */
+    if (unlikely(error == 1) &&      /* empty or incorrect string */
+        get_thd()->count_cuted_fields == CHECK_FIELD_ERROR_FOR_NULL)
     {
       *ptr= 0;
       return 1;

Only main.type_date differs then:

--- /home/nik/mariadb/mysql-test/r/type_date.result	2021-06-15 22:28:31.819710775 +0300
+++ /home/nik/mariadb/mysql-test/r/type_date.reject	2021-06-20 22:11:55.703674542 +0300
@@ -111,7 +111,7 @@
 Warning	1366	Incorrect integer value: 'abc' for column `test`.`t1`.`y` at row 1
 SELECT * FROM t1;
 y
-0000
+2000
 DROP TABLE t1;
 create table t1(start_date date, end_date date);
 insert into t1 values ('2000-01-01','2000-01-02');

And type_year passes.

Comment by Nikita Malyavin [ 2021-06-21 ]

Turns out that setting a value to 0000 was a previous decision: see Bug #6067 and commit [ 6162c4a6eb|https://github.com/MariaDB/server/commit/6162c4a6eb22b413a477bb6b9b0f08ec9b98a193]

So I think we should stay consistent with that decision. This also means that current SELECT output for myisam is incorrect in gcol.gcol_ins_upd_myisam

The patch is ready for a review: https://github.com/MariaDB/server/commit/8185a2889f21e4782eeb8a09d386d4a4e661cc08

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

Various testcases in this bug still fail including the following testcase from Elena.

CREATE TABLE t1 (pk INT AUTO_INCREMENT PRIMARY KEY, b TEXT, i INT, UNIQUE(i), UNIQUE(b)) ENGINE=InnoDB;
INSERT INTO t1 (b,i) VALUES ('foo',1);
SET STATEMENT time_zone= '-07:50' FOR ALTER TABLE t1 ADD SYSTEM VERSIONING;
REPLACE INTO t1 (b,i) VALUES ('foo',1);

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 0x149ffc91b700 (LWP 473547))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x0000149fff4d9859 in __GI_abort () at abort.c:79
#2  0x0000149fff4d9729 in __assert_fail_base (fmt=0x149fff66f588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x562312ed5b6b "0", file=0x562312fac310 "/test/10.7_dbg/storage/innobase/row/row0upd.cc", line=2051, function=<optimized out>) at assert.c:92
#3  0x0000149fff4eaf36 in __GI___assert_fail (assertion=assertion@entry=0x562312ed5b6b "0", file=file@entry=0x562312fac310 "/test/10.7_dbg/storage/innobase/row/row0upd.cc", line=line@entry=2051, function=function@entry=0x562312fad6e8 "dberr_t row_upd_sec_index_entry(upd_node_t*, que_thr_t*)") at assert.c:101
#4  0x00005623129111c1 in row_upd_sec_index_entry (node=node@entry=0x149fb8084370, thr=thr@entry=0x149fb808ddd8) at /test/10.7_dbg/storage/innobase/row/row0upd.cc:2051
#5  0x0000562312911fcf in row_upd_sec_step (thr=0x149fb808ddd8, node=0x149fb8084370) at /test/10.7_dbg/storage/innobase/row/row0upd.cc:2200
#6  row_upd (thr=0x149fb808ddd8, node=0x149fb8084370) at /test/10.7_dbg/storage/innobase/row/row0upd.cc:2936
#7  row_upd_step (thr=thr@entry=0x149fb808ddd8) at /test/10.7_dbg/storage/innobase/row/row0upd.cc:3051
#8  0x00005623128b6bb3 in row_update_for_mysql (prebuilt=0x149fb80837c8) at /test/10.7_dbg/storage/innobase/row/row0mysql.cc:1740
#9  0x0000562312740567 in ha_innobase::update_row (this=0x149fb80826e0, old_row=0x149fb8023dc8 "\240\001", new_row=0x149fb8023d98 "\370\002") at /test/10.7_dbg/storage/innobase/handler/ha_innodb.cc:8549
#10 0x00005623123a4fa1 in handler::ha_update_row (this=0x149fb80826e0, old_data=0x149fb8023dc8 "\240\001", new_data=0x149fb8023d98 "\370\002") at /test/10.7_dbg/sql/handler.cc:7567
#11 0x00005623120494c2 in write_record (thd=thd@entry=0x149fb8000db8, table=table@entry=0x149fb8024528, info=info@entry=0x149ffc919cc0, sink=sink@entry=0x0) at /test/10.7_dbg/sql/sql_insert.cc:2052
#12 0x0000562312054de4 in mysql_insert (thd=thd@entry=0x149fb8000db8, table_list=0x149fb8013d70, fields=@0x149fb8005fc8: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x149fb8014578, last = 0x149fb80146a8, elements = 2}, <No data fields>}, values_list=@0x149fb8006010: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x149fb8014c68, last = 0x149fb8014c68, elements = 1}, <No data fields>}, update_fields=@0x149fb8005ff8: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x562313663b80 <end_of_list>, last = 0x149fb8005ff8, elements = 0}, <No data fields>}, update_values=@0x149fb8005fe0: {<base_list> = {<Sql_alloc> = {<No data fields>}, first = 0x562313663b80 <end_of_list>, last = 0x149fb8005fe0, elements = 0}, <No data fields>}, duplic=DUP_REPLACE, ignore=false, result=0x0) at /test/10.7_dbg/sql/sql_insert.cc:1123
#13 0x000056231209aeaf in mysql_execute_command (thd=thd@entry=0x149fb8000db8, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/10.7_dbg/sql/sql_parse.cc:4565
#14 0x0000562312085ac3 in mysql_parse (thd=thd@entry=0x149fb8000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x149ffc91a400) at /test/10.7_dbg/sql/sql_parse.cc:8030
#15 0x00005623120946c8 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x149fb8000db8, packet=packet@entry=0x149fb800b739 "REPLACE INTO t1 (b,i) VALUES ('foo',1)", packet_length=packet_length@entry=38, blocking=blocking@entry=true) at /test/10.7_dbg/sql/sql_class.h:1357
#16 0x0000562312097ae9 in do_command (thd=0x149fb8000db8, blocking=blocking@entry=true) at /test/10.7_dbg/sql/sql_parse.cc:1404
#17 0x000056231220ddd6 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x56231482b368, put_in_cache=put_in_cache@entry=true) at /test/10.7_dbg/sql/sql_connect.cc:1418
#18 0x000056231220e3db in handle_one_connection (arg=arg@entry=0x56231482b368) at /test/10.7_dbg/sql/sql_connect.cc:1312
#19 0x0000562312676ce4 in pfs_spawn_thread (arg=0x562314753bc8) at /test/10.7_dbg/storage/perfschema/pfs.cc:2201
#20 0x0000149fff9e8609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#21 0x0000149fff5d6293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

10.7.0 52505bf20de0ce77a5c0b0a74af021051987bb0d (Debug)

2021-08-21  6:50:30 4 [ERROR] InnoDB: Record in index `b` of table `test`.`t1` was not found on update: TUPLE (info_bits=0, 3 fields): {[8]    UW  (0x8EE2E0E255578A98),[4]    (0x80000001),[7]     B?(0x7FFFFFFF0F423F)} at: COMPACT RECORD(info_bits=0, 3 fields): {[8]4     : (0x34F3F6061BCE3AD8),[4]    (0x80000001),[7]     B?(0x7FFFFFFF0F423F)}
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.

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