[MDEV-16982] Server crashes in mem_heap_dup upon DELETE from table with virtual columns Created: 2018-08-14  Updated: 2019-02-05  Resolved: 2019-02-05

Status: Closed
Project: MariaDB Server
Component/s: Data Manipulation - Delete, Storage Engine - InnoDB, Virtual Columns
Affects Version/s: 10.3, 10.4
Fix Version/s: 10.4.3, 10.2.22, 10.3.13

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Eugene Kosov (Inactive)
Resolution: Fixed Votes: 0
Labels: system_versioned_tables, virtual_columns


 Description   

--source include/have_innodb.inc
--source include/have_partition.inc
 
CREATE TABLE t1 ( 
   pk INTEGER AUTO_INCREMENT,
   f1 VARCHAR(3) NOT NULL DEFAULT '',
   f2 MEDIUMTEXT NOT NULL DEFAULT '',
   f3 VARCHAR(472) NULL,
   f4 DECIMAL(44,0) UNSIGNED NULL,
   v1 VARCHAR(3) AS (f1) VIRTUAL,
   v2 LONGBLOB AS (f2) VIRTUAL,
   PRIMARY KEY(pk)
) ENGINE=InnoDB WITH SYSTEM VERSIONING PARTITION BY system_time INTERVAL 5 MONTH ( PARTITION p1 HISTORY, PARTITION pn CURRENT );
 
INSERT INTO t1 (f1) VALUES ('foo');
DELETE FROM t1 ORDER BY pk LIMIT 1;
 
# Cleanup
DROP TABLE t1;

10.3 5e7496e2e

#3  <signal handler called>
#4  0x00007f65ed668d8c in __memmove_avx_unaligned_erms () from /lib/x86_64-linux-gnu/libc.so.6
#5  0x0000557a662d1456 in mem_heap_dup (heap=0x7f64ea5a5010, data=0xa5a5a5a5a5a5a5a5, len=2779096485) at /data/src/10.3/storage/innobase/include/mem0mem.h:306
#6  0x0000557a66407206 in dfield_dup (field=0x7f65901336b0, heap=0x7f64ea5a5010) at /data/src/10.3/storage/innobase/include/data0data.ic:287
#7  0x0000557a6640b0f4 in row_mysql_convert_row_to_innobase (row=0x7f6590133560, prebuilt=0x7f6590132938, mysql_rec=0x7f65900a5f88 "\247\001", blob_heap=0x7f65e2885728) at /data/src/10.3/storage/innobase/row/row0mysql.cc:639
#8  0x0000557a6640cfb0 in row_insert_for_mysql (mysql_rec=0x7f65900a5f88 "\247\001", prebuilt=0x7f6590132938, ins_mode=ROW_INS_NORMAL) at /data/src/10.3/storage/innobase/row/row0mysql.cc:1418
#9  0x0000557a662b6acc in ha_innobase::write_row (this=0x7f659000e088, record=0x7f65900a5f88 "\247\001") at /data/src/10.3/storage/innobase/handler/ha_innodb.cc:8170
#10 0x0000557a65fa1636 in handler::ha_write_row (this=0x7f659000e088, buf=0x7f65900a5f88 "\247\001") at /data/src/10.3/sql/handler.cc:6196
#11 0x0000557a666fe88c in ha_partition::update_row (this=0x7f659000d7d8, old_data=0x7f65900a61b0 "\247\001", new_data=0x7f65900a5f88 "\247\001") at /data/src/10.3/sql/ha_partition.cc:4418
#12 0x0000557a65fa193d in handler::ha_update_row (this=0x7f659000d7d8, old_data=0x7f65900a61b0 "\247\001", new_data=0x7f65900a5f88 "\247\001") at /data/src/10.3/sql/handler.cc:6228
#13 0x0000557a66139741 in TABLE::delete_row (this=0x7f659000cb90) at /data/src/10.3/sql/sql_delete.cc:260
#14 0x0000557a661368f1 in mysql_delete (thd=0x7f6590000b00, table_list=0x7f6590014e00, conds=0x0, order_list=0x7f6590005390, limit=1, options=0, result=0x0) at /data/src/10.3/sql/sql_delete.cc:749
#15 0x0000557a65ca7e5b in mysql_execute_command (thd=0x7f6590000b00) at /data/src/10.3/sql/sql_parse.cc:4924
#16 0x0000557a65cb1e9c in mysql_parse (thd=0x7f6590000b00, rawbuf=0x7f6590014d08 "DELETE FROM t1 ORDER BY pk LIMIT 1", length=34, parser_state=0x7f65e28875f0, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:8088
#17 0x0000557a65c9f156 in dispatch_command (command=COM_QUERY, thd=0x7f6590000b00, packet=0x7f6590126281 "DELETE FROM t1 ORDER BY pk LIMIT 1", packet_length=34, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1850
#18 0x0000557a65c9db7a in do_command (thd=0x7f6590000b00) at /data/src/10.3/sql/sql_parse.cc:1395
#19 0x0000557a65e04481 in do_handle_one_connection (connect=0x557a69990b00) at /data/src/10.3/sql/sql_connect.cc:1402
#20 0x0000557a65e04205 in handle_one_connection (arg=0x557a69990b00) at /data/src/10.3/sql/sql_connect.cc:1308
#21 0x0000557a66295a8f in pfs_spawn_thread (arg=0x557a69a32030) at /data/src/10.3/storage/perfschema/pfs.cc:1862
#22 0x00007f65ef242494 in start_thread (arg=0x7f65e2888700) at pthread_create.c:333
#23 0x00007f65ed62893f in clone () from /lib/x86_64-linux-gnu/libc.so.6



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

Maybe system versioning fails to compute the indexed virtual column values when performing an insert inside delete?

But, I do not see any index on the virtual columns. The unnecessary evaluation could be a separate bug (and should be fixed in 10.2 already). When testing system versioning, please ensure that there are some indexes on the virtual columns.

Comment by Eugene Kosov (Inactive) [ 2019-01-31 ]

Version is 10.3: 4e599c74bb673e6d752bdacffbe014cbfd033b0a

Build with: cmake -G Ninja -DCMAKE_BUILD_TYPE=Debug -DWITH_ASAN=1 ../mariadb

gcc (Ubuntu 8.2.0-7ubuntu1) 8.2.0

I'm able to see ASAN report similar to reported one.

#11 0x00005555572e1f0e in mem_heap_dup (heap=0x7fff39e73800, data=0xa5a5a5a5a5a5a5a5, len=2779096485) at mem0mem.h:304
(gdb) p/x len
$1 = 0xa5a5a5a5

It is uninitialized memory.

Problem field is:

$3 = {
  col_no = 13744632839234567870, 
  rec_field_no = 1, 
  rec_field_is_prefix = 13744632839234567870, 
  rec_prefix_field_no = 18446744073709551615, 
  clust_rec_field_no = 1, 
  icp_rec_field_no = 18446744073709551615, 
  mysql_col_offset = 532, 
  mysql_col_len = 12, 
  mysql_null_byte_offset = 0, 
  mysql_null_bit_mask = 8, 
  type = 5, 
  mysql_type = 252, 
  mysql_length_bytes = 0, 
  charset = 63, 
  mbminlen = 1, 
  mbmaxlen = 1, 
  is_unsigned = 0, 
  is_virtual = 1
}

Note the following:

  mysql_null_byte_offset = 0, 
  mysql_null_bit_mask = 8, 

(gdb) p mysql_rec[templ->mysql_null_byte_offset] & templ->mysql_null_bit_mask
$4 = 0
(gdb) p/x mysql_rec[templ->mysql_null_byte_offset]
$6 = 0xa7

It's uninitialized memory with one additional bit set:

(gdb) p/x 0xa5 | 2
$8 = 0xa7

Interesting byte is:

(gdb) p &mysql_rec[templ->mysql_null_byte_offset]
$10 = (const byte *) 0x61d000217108 "\247\001"

Comment by Eugene Kosov (Inactive) [ 2019-01-31 ]

Not I'm watching this byte of memory with ./mtr -mem innodb.kevg -gdb='awatch *(const byte *) 0x61d000217108;r'

I skipped some irrelevant stuff:

Continuing.
 
Thread 28 "mysqld" hit Hardware access (read/write) watchpoint 1: *(const byte *) 0x61d000217108
 
Old value = 143 '\217'
New value = 165 '\245'
__memset_avx2_unaligned_erms () at memset-vec-unaligned-erms.S:193
193     in memset-vec-unaligned-erms.S
(gdb) bt
#0  __memset_avx2_unaligned_erms () at memset-vec-unaligned-erms.S:193
#1  ?? () from /usr/lib/x86_64-linux-gnu/libasan.so.5
#2  alloc_root (mem_root=0x61f0000567b8, length=1656) at my_alloc.c:277
#3  open_table_from_share (thd=0x62a0000ba270, share=0x61b000086d08, alias=0x62b0000003c8, db_stat=33, prgflag=8, ha_open_flags=16, outparam=0x61f000055cf0, is_create_table=false, partitions_to_open=0x0) at table.cc:3219
#4  open_table (thd=0x62a0000ba270, table_list=0x62b000000380, ot_ctx=0x7fffdfad9110) at sql_base.cc:1971
#5  open_and_process_table (thd=0x62a0000ba270, lex=0x62a0000be058, tables=0x62b000000380, counter=0x7fffdfad9210, flags=0, prelocking_strategy=0x7fffdfad9390, has_prelocking_list=false, ot_ctx=0x7fffdfad9110) at sql_base.cc:3596
#6  open_tables (thd=0x62a0000ba270, options=..., start=0x7fffdfad9250, counter=0x7fffdfad9210, flags=0, prelocking_strategy=0x7fffdfad9390) at sql_base.cc:4119
#7  open_and_lock_tables (thd=0x62a0000ba270, options=..., tables=0x62b000000380, derived=true, flags=0, prelocking_strategy=0x7fffdfad9390) at sql_base.cc:4996
#8  open_and_lock_tables (thd=0x62a0000ba270, tables=0x62b000000380, derived=true, flags=0) at sql_base.h:500
#9  mysql_insert (thd=0x62a0000ba270, table_list=0x62b000000380, fields=List<Item> with 1 elements, values_list=..., update_fields=List<Item> with 0 elements, update_values=List<Item> with 0 elements, duplic=DUP_ERROR, ignore=false) at sql_insert.cc:760
#10 mysql_execute_command (thd=0x62a0000ba270) at sql_parse.cc:4725
#11 mysql_parse (thd=0x62a0000ba270, rawbuf=0x62b000000288 "INSERT INTO t1 (f1) VALUES ('foo')", length=34, parser_state=0x7fffdfadbc00, is_com_multi=false, is_next_command=false) at sql_parse.cc:8092
#12 dispatch_command (command=COM_QUERY, thd=0x62a0000ba270, packet=0x629000131271 "INSERT INTO t1 (f1) VALUES ('foo')", packet_length=34, is_com_multi=false, is_next_command=false) at sql_parse.cc:1850
#13 do_command (thd=0x62a0000ba270) at sql_parse.cc:1395
#14 do_handle_one_connection (connect=0x61100004a570) at sql_connect.cc:1402
#15 handle_one_connection (arg=0x61100004a570) at sql_connect.cc:1308
#16 pfs_spawn_thread (arg=0x6160000318f0) at pfs.cc:1862
#17 start_thread (arg=<optimized out>) at pthread_create.c:486
#18 clone () at clone.S:95
 
(gdb) c
Continuing.
 
Thread 28 "mysqld" hit Hardware access (read/write) watchpoint 1: *(const byte *) 0x61d000217108
 
Old value = 165 '\245'
New value = 255 '\377'
__memmove_sse2_unaligned_erms () at memmove-vec-unaligned-erms.S:469
469     memmove-vec-unaligned-erms.S: No such file or directory.
(gdb) bt
#0  __memmove_sse2_unaligned_erms () at memmove-vec-unaligned-erms.S:469
#1  ?? () from /usr/lib/x86_64-linux-gnu/libasan.so.5
#2  TABLE::init (this=0x61f000055cf0, thd=0x62a0000ba270, tl=0x62b000000380) at table.cc:4654
#3  open_table (thd=0x62a0000ba270, table_list=0x62b000000380, ot_ctx=0x7fffdfad9110) at sql_base.cc:2044
#4  open_and_process_table (thd=0x62a0000ba270, lex=0x62a0000be058, tables=0x62b000000380, counter=0x7fffdfad9210, flags=0, prelocking_strategy=0x7fffdfad9390, has_prelocking_list=false, ot_ctx=0x7fffdfad9110) at sql_base.cc:3596
#5  open_tables (thd=0x62a0000ba270, options=..., start=0x7fffdfad9250, counter=0x7fffdfad9210, flags=0, prelocking_strategy=0x7fffdfad9390) at sql_base.cc:4119
#6  open_and_lock_tables (thd=0x62a0000ba270, options=..., tables=0x62b000000380, derived=true, flags=0, prelocking_strategy=0x7fffdfad9390) at sql_base.cc:4996
#7  open_and_lock_tables (thd=0x62a0000ba270, tables=0x62b000000380, derived=true, flags=0) at sql_base.h:500
#8  mysql_insert (thd=0x62a0000ba270, table_list=0x62b000000380, fields=List<Item> with 1 elements, values_list=..., update_fields=List<Item> with 0 elements, update_values=List<Item> with 0 elements, duplic=DUP_ERROR, ignore=false) at sql_insert.cc:760
#9  mysql_execute_command (thd=0x62a0000ba270) at sql_parse.cc:4725
#10 mysql_parse (thd=0x62a0000ba270, rawbuf=0x62b000000288 "INSERT INTO t1 (f1) VALUES ('foo')", length=34, parser_state=0x7fffdfadbc00, is_com_multi=false, is_next_command=false) at sql_parse.cc:8092
#11 dispatch_command (command=COM_QUERY, thd=0x62a0000ba270, packet=0x629000131271 "INSERT INTO t1 (f1) VALUES ('foo')", packet_length=34, is_com_multi=false, is_next_command=false) at sql_parse.cc:1850
#12 do_command (thd=0x62a0000ba270) at sql_parse.cc:1395
#13 do_handle_one_connection (connect=0x61100004a570) at sql_connect.cc:1402
#14 handle_one_connection (arg=0x61100004a570) at sql_connect.cc:1308
#15 pfs_spawn_thread (arg=0x6160000318f0) at pfs.cc:1862
#16 start_thread (arg=<optimized out>) at pthread_create.c:486
#17 clone () at clone.S:95

It is restore_record(table,s->default_values);

Skipped some more...

Value = 255 '\377'
__memmove_sse2_unaligned_erms () at memmove-vec-unaligned-erms.S:469
469     memmove-vec-unaligned-erms.S: No such file or directory.
(gdb) bt
#0  __memmove_sse2_unaligned_erms () at memmove-vec-unaligned-erms.S:469
#1  ?? () from /usr/lib/x86_64-linux-gnu/libasan.so.5
#2  TABLE::init (this=0x61f000055cf0, thd=0x62a0000ba270, tl=0x62b000000380) at table.cc:4654
#3  open_table (thd=0x62a0000ba270, table_list=0x62b000000380, ot_ctx=0x7fffdfad89c0) at sql_base.cc:2044
#4  open_and_process_table (thd=0x62a0000ba270, lex=0x62a0000be058, tables=0x62b000000380, counter=0x7fffdfad8ac0, flags=0, prelocking_strategy=0x7fffdfad8c40, has_prelocking_list=false, ot_ctx=0x7fffdfad89c0) at sql_base.cc:3596
#5  open_tables (thd=0x62a0000ba270, options=..., start=0x7fffdfad8b00, counter=0x7fffdfad8ac0, flags=0, prelocking_strategy=0x7fffdfad8c40) at sql_base.cc:4119
#6  open_and_lock_tables (thd=0x62a0000ba270, options=..., tables=0x62b000000380, derived=true, flags=0, prelocking_strategy=0x7fffdfad8c40) at sql_base.cc:4996
#7  open_and_lock_tables (thd=0x62a0000ba270, tables=0x62b000000380, derived=true, flags=0) at sql_base.h:500
#8  mysql_delete (thd=0x62a0000ba270, table_list=0x62b000000380, conds=0x0, order_list=0x62a0000beb08, limit=1, options=0, result=0x0) at sql_delete.cc:308
#9  mysql_execute_command (thd=0x62a0000ba270) at sql_parse.cc:4922
#10 mysql_parse (thd=0x62a0000ba270, rawbuf=0x62b000000288 "DELETE FROM t1 ORDER BY pk LIMIT 1", length=34, parser_state=0x7fffdfadbc00, is_com_multi=false, is_next_command=false) at sql_parse.cc:8092
#11 dispatch_command (command=COM_QUERY, thd=0x62a0000ba270, packet=0x629000131271 "DELETE FROM t1 ORDER BY pk LIMIT 1", packet_length=34, is_com_multi=false, is_next_command=false) at sql_parse.cc:1850
#12 do_command (thd=0x62a0000ba270) at sql_parse.cc:1395
#13 do_handle_one_connection (connect=0x61100004a570) at sql_connect.cc:1402
#14 handle_one_connection (arg=0x61100004a570) at sql_connect.cc:1308
#15 pfs_spawn_thread (arg=0x6160000318f0) at pfs.cc:1862
#16 start_thread (arg=<optimized out>) at pthread_create.c:486
#17 clone () at clone.S:95

And some even more:

Continuing.
 
Thread 28 "mysqld" hit Hardware access (read/write) watchpoint 1: *(const byte *) 0x61d000217108
 
Old value = 255 '\377'
New value = 167 '\247'
__memmove_sse2_unaligned_erms () at memmove-vec-unaligned-erms.S:469
469     memmove-vec-unaligned-erms.S: No such file or directory.
(gdb) bt
#0  __memmove_sse2_unaligned_erms () at memmove-vec-unaligned-erms.S:469
#1  ?? () from /usr/lib/x86_64-linux-gnu/libasan.so.5
#2  ha_partition::return_top_record (this=0x61d000215308, buf=0x61d000217108 "\247\001") at ha_partition.cc:7672
#3  ha_partition::handle_ordered_index_scan (this=0x61d000215308, buf=0x61d000217108 "\247\001", reverse_order=false) at ha_partition.cc:7644
#4  ha_partition::common_first_last (this=0x61d000215308, buf=0x61d000217108 "\247\001") at ha_partition.cc:5735
#5  ha_partition::index_first (this=0x61d000215308, buf=0x61d000217108 "\247\001") at ha_partition.cc:5679
#6  handler::ha_index_first (this=0x61d000215308, buf=0x61d000217108 "\247\001") at handler.cc:2914
#7  rr_index_first (info=0x7fffdfad9200) at records.cc:397
#8  READ_RECORD::read_record (this=0x7fffdfad9200) at records.h:73
#9  mysql_delete (thd=0x62a0000ba270, table_list=0x62b000000380, conds=0x0, order_list=0x62a0000beb08, limit=1, options=0, result=0x0) at sql_delete.cc:731
#10 mysql_execute_command (thd=0x62a0000ba270) at sql_parse.cc:4922
#11 mysql_parse (thd=0x62a0000ba270, rawbuf=0x62b000000288 "DELETE FROM t1 ORDER BY pk LIMIT 1", length=34, parser_state=0x7fffdfadbc00, is_com_multi=false, is_next_command=false) at sql_parse.cc:8092
#12 dispatch_command (command=COM_QUERY, thd=0x62a0000ba270, packet=0x629000131271 "DELETE FROM t1 ORDER BY pk LIMIT 1", packet_length=34, is_com_multi=false, is_next_command=false) at sql_parse.cc:1850
#13 do_command (thd=0x62a0000ba270) at sql_parse.cc:1395
#14 do_handle_one_connection (connect=0x61100004a570) at sql_connect.cc:1402
#15 handle_one_connection (arg=0x61100004a570) at sql_connect.cc:1308
#16 pfs_spawn_thread (arg=0x6160000318f0) at pfs.cc:1862
#17 start_thread (arg=<optimized out>) at pthread_create.c:486
#18 clone () at clone.S:95

And here we see it's a memcpy() from another buffer:

   |7671      part_id= uint2korr(key_buffer);                                                                                                                                                 |
  >|7672      memcpy(buf, rec_buffer, m_rec_length);                                                                                                                                          |
   |7673      m_last_part= part_id;                                                                                                                                                           |

Our interesting address is the first byte of buf:

(gdb) p (const byte *) 0x61d000217108 - buf
$4 = 0

The first byte of other buffer is:

(gdb) p rec_buffer
$5 = (uchar *) 0x61a000087f14 "\247\001"

It has it's final unititialized + 1 bit value:

(gdb) p/x rec_buffer[0]
$6 = 0xa7

Let's see where it came from.

Comment by Eugene Kosov (Inactive) [ 2019-01-31 ]

./mtr -mem innodb.kevg -gdb='awatch *(const byte *) 0x61a000087f14;r'

Old value = 190 '\276'
New value = 165 '\245'
__memset_avx2_unaligned_erms () at memset-vec-unaligned-erms.S:207
207     in memset-vec-unaligned-erms.S
(gdb) bt
#0  __memset_avx2_unaligned_erms () at memset-vec-unaligned-erms.S:207
#1  ?? () from /usr/lib/x86_64-linux-gnu/libasan.so.5
#2  sf_malloc (size=1112, my_flags=16) at safemalloc.c:168
#3  my_malloc (size=1112, my_flags=16) at my_malloc.c:101
#4  ha_partition::init_record_priority_queue (this=0x61d000215308) at ha_partition.cc:5259
#5  ha_partition::index_init (this=0x61d000215308, inx=0, sorted=true) at ha_partition.cc:5364
#6  handler::ha_index_init (this=0x61d000215308, idx=0, sorted=true) at handler.h:3060
#7  init_read_record_idx (info=0x7fffdfad9200, thd=0x62a0000ba270, table=0x61f000055cf0, print_error=true, idx=0, reverse=false) at records.cc:86
#8  mysql_delete (thd=0x62a0000ba270, table_list=0x62b000000380, conds=0x0, order_list=0x62a0000beb08, limit=1, options=0, result=0x0) at sql_delete.cc:665
#9  mysql_execute_command (thd=0x62a0000ba270) at sql_parse.cc:4922
#10 mysql_parse (thd=0x62a0000ba270, rawbuf=0x62b000000288 "DELETE FROM t1 ORDER BY pk LIMIT 1", length=34, parser_state=0x7fffdfadbc00, is_com_multi=false, is_next_command=false) at sql_parse.cc:8092
#11 dispatch_command (command=COM_QUERY, thd=0x62a0000ba270, packet=0x629000131271 "DELETE FROM t1 ORDER BY pk LIMIT 1", packet_length=34, is_com_multi=false, is_next_command=false) at sql_parse.cc:1850
#12 do_command (thd=0x62a0000ba270) at sql_parse.cc:1395
#13 do_handle_one_connection (connect=0x61100004a570) at sql_connect.cc:1402
#14 handle_one_connection (arg=0x61100004a570) at sql_connect.cc:1308
#15 pfs_spawn_thread (arg=0x6160000318f0) at pfs.cc:1862
#16 start_thread (arg=<optimized out>) at pthread_create.c:486
#17 clone () at clone.S:95
 
(gdb) c
Continuing.
 
Thread 28 "mysqld" hit Hardware access (read/write) watchpoint 1: *(const byte *) 0x61a000087f14
 
Value = 165 '\245'
row_sel_store_mysql_field (mysql_rec=0x61a000087f14 "\245\001", prebuilt=0x6210000aa188, rec=0x7fffec2ec080 "\200", index=0x617000041788, offsets=0x7fffdfad76a0, field_no=6, templ=0x61a000087830) at row0sel.cc:3013
3013                                    |= (byte) templ->mysql_null_bit_mask;
(gdb) bt
#0  row_sel_store_mysql_field (mysql_rec=0x61a000087f14 "\245\001", prebuilt=0x6210000aa188, rec=0x7fffec2ec080 "\200", index=0x617000041788, offsets=0x7fffdfad76a0, field_no=6, templ=0x61a000087830) at row0sel.cc:3013
#1  row_sel_store_mysql_rec (mysql_rec=0x61a000087f14 "\245\001", prebuilt=0x6210000aa188, rec=0x7fffec2ec080 "\200", vrow=0x0, rec_clust=false, index=0x617000041788, offsets=0x7fffdfad76a0) at row0sel.cc:3177
#2  row_search_mvcc (buf=0x61a000087f14 "\245\001", mode=PAGE_CUR_G, prebuilt=0x6210000aa188, match_mode=0, direction=0) at row0sel.cc:5457
#3  ha_innobase::index_read (this=0x61d000216708, buf=0x61a000087f14 "\245\001", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at ha_innodb.cc:9277
#4  ha_innobase::index_first (this=0x61d000216708, buf=0x61a000087f14 "\245\001") at ha_innodb.cc:9652
#5  handler::ha_index_first (this=0x61d000216708, buf=0x61a000087f14 "\245\001") at handler.cc:2914
#6  ha_partition::handle_ordered_index_scan (this=0x61d000215308, buf=0x61d000217108 "\377", reverse_order=false) at ha_partition.cc:7510
#7  ha_partition::common_first_last (this=0x61d000215308, buf=0x61d000217108 "\377") at ha_partition.cc:5735
#8  ha_partition::index_first (this=0x61d000215308, buf=0x61d000217108 "\377") at ha_partition.cc:5679
#9  handler::ha_index_first (this=0x61d000215308, buf=0x61d000217108 "\377") at handler.cc:2914
#10 rr_index_first (info=0x7fffdfad9200) at records.cc:397
#11 READ_RECORD::read_record (this=0x7fffdfad9200) at records.h:73
#12 mysql_delete (thd=0x62a0000ba270, table_list=0x62b000000380, conds=0x0, order_list=0x62a0000beb08, limit=1, options=0, result=0x0) at sql_delete.cc:731
#13 mysql_execute_command (thd=0x62a0000ba270) at sql_parse.cc:4922
#14 mysql_parse (thd=0x62a0000ba270, rawbuf=0x62b000000288 "DELETE FROM t1 ORDER BY pk LIMIT 1", length=34, parser_state=0x7fffdfadbc00, is_com_multi=false, is_next_command=false) at sql_parse.cc:8092
#15 dispatch_command (command=COM_QUERY, thd=0x62a0000ba270, packet=0x629000131271 "DELETE FROM t1 ORDER BY pk LIMIT 1", packet_length=34, is_com_multi=false, is_next_command=false) at sql_parse.cc:1850
#16 do_command (thd=0x62a0000ba270) at sql_parse.cc:1395
#17 do_handle_one_connection (connect=0x61100004a570) at sql_connect.cc:1402
#18 handle_one_connection (arg=0x61100004a570) at sql_connect.cc:1308
#19 pfs_spawn_thread (arg=0x6160000318f0) at pfs.cc:1862
#20 start_thread (arg=<optimized out>) at pthread_create.c:486
#21 clone () at clone.S:95

Here it gets its final value:

Old value = 165 '\245'
New value = 167 '\247'
row_sel_store_mysql_field (mysql_rec=0x61a000087f14 "\247\001", prebuilt=0x6210000aa188, rec=0x7fffec2ec080 "\200", index=0x617000041788, offsets=0x7fffdfad76a0, field_no=7, templ=0x61a0000878c0) at row0sel.cc:3014
3014                            memcpy(mysql_rec + templ->mysql_col_offset,
(gdb) bt
#0  row_sel_store_mysql_field (mysql_rec=0x61a000087f14 "\247\001", prebuilt=0x6210000aa188, rec=0x7fffec2ec080 "\200", index=0x617000041788, offsets=0x7fffdfad76a0, field_no=7, templ=0x61a0000878c0) at row0sel.cc:3014
#1  row_sel_store_mysql_rec (mysql_rec=0x61a000087f14 "\247\001", prebuilt=0x6210000aa188, rec=0x7fffec2ec080 "\200", vrow=0x0, rec_clust=false, index=0x617000041788, offsets=0x7fffdfad76a0) at row0sel.cc:3177
#2  row_search_mvcc (buf=0x61a000087f14 "\247\001", mode=PAGE_CUR_G, prebuilt=0x6210000aa188, match_mode=0, direction=0) at row0sel.cc:5457
#3  ha_innobase::index_read (this=0x61d000216708, buf=0x61a000087f14 "\247\001", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at ha_innodb.cc:9277
#4  ha_innobase::index_first (this=0x61d000216708, buf=0x61a000087f14 "\247\001") at ha_innodb.cc:9652
#5  handler::ha_index_first (this=0x61d000216708, buf=0x61a000087f14 "\247\001") at handler.cc:2914
#6  ha_partition::handle_ordered_index_scan (this=0x61d000215308, buf=0x61d000217108 "\377", reverse_order=false) at ha_partition.cc:7510
#7  ha_partition::common_first_last (this=0x61d000215308, buf=0x61d000217108 "\377") at ha_partition.cc:5735
#8  ha_partition::index_first (this=0x61d000215308, buf=0x61d000217108 "\377") at ha_partition.cc:5679
#9  handler::ha_index_first (this=0x61d000215308, buf=0x61d000217108 "\377") at handler.cc:2914
#10 rr_index_first (info=0x7fffdfad9200) at records.cc:397
#11 READ_RECORD::read_record (this=0x7fffdfad9200) at records.h:73
#12 mysql_delete (thd=0x62a0000ba270, table_list=0x62b000000380, conds=0x0, order_list=0x62a0000beb08, limit=1, options=0, result=0x0) at sql_delete.cc:731
#13 mysql_execute_command (thd=0x62a0000ba270) at sql_parse.cc:4922
#14 mysql_parse (thd=0x62a0000ba270, rawbuf=0x62b000000288 "DELETE FROM t1 ORDER BY pk LIMIT 1", length=34, parser_state=0x7fffdfadbc00, is_com_multi=false, is_next_command=false) at sql_parse.cc:8092
#15 dispatch_command (command=COM_QUERY, thd=0x62a0000ba270, packet=0x629000131271 "DELETE FROM t1 ORDER BY pk LIMIT 1", packet_length=34, is_com_multi=false, is_next_command=false) at sql_parse.cc:1850
#16 do_command (thd=0x62a0000ba270) at sql_parse.cc:1395
#17 do_handle_one_connection (connect=0x61100004a570) at sql_connect.cc:1402
#18 handle_one_connection (arg=0x61100004a570) at sql_connect.cc:1308
#19 pfs_spawn_thread (arg=0x6160000318f0) at pfs.cc:1862
#20 start_thread (arg=<optimized out>) at pthread_create.c:486
#21 clone () at clone.S:95

row_sel_store_mysql_rec() sets some bits to uninitialized byte and that's initial bug, IMO. It skips virtual fields as those was not requested.

   |3102                            /* Skip virtual columns if it is not a covered                                                                                                            |
   |3103                            search or virtual key read is not requested. */                                                                                                           |
   |3104                            if (!dict_index_has_virtual(prebuilt->index)                                                                                                              |
   |3105                                || (!prebuilt->read_just_key                                                                                                                          |
   |3106                                    && !prebuilt->m_read_virtual_key)                                                                                                                 |
   |3107                                || !rec_clust) {                                                                                                                                      |
   |3108                                    continue;                                                                                                                                         |
   |3109                            }                                                                                                                                                         |

Then this buffer is copied to table->record[0], then it's inserted into InnoDB, then InnoDB reads NULL bites which it itself didn't initialized and crash occures.

Comment by Marko Mäkelä [ 2019-01-31 ]

Finally, I am repeating a crash with the following instrumentation:

diff --git a/mysys/my_malloc.c b/mysys/my_malloc.c
index 6a3ec8da093..1f0f3256d37 100644
--- a/mysys/my_malloc.c
+++ b/mysys/my_malloc.c
@@ -123,6 +123,7 @@ void *my_malloc(size_t size, myf my_flags)
                       my_free(point);
                       point= NULL;
                     });
+    TRASH_ALLOC(point, size);
     if (my_flags & MY_ZEROFILL)
       bzero(point, size);
   }

I do not know why, but cmake -DWITH_SAFEMALLOC=ON did not seem to help me. I do see that safe_malloc() does something similar at the end.

Without the fix, I would see a crash:

==25092==ERROR: AddressSanitizer: unknown-crash on address 0xa5a5a5a5a5a5a5a5 at pc 0x7fcf2457748f bp 0x7fcf0b5be000 sp 0x7fcf0b5bd7b0
READ of size 2779096485 at 0xa5a5a5a5a5a5a5a5 thread T27
    #0 0x7fcf2457748e  (/usr/lib/x86_64-linux-gnu/libasan.so.3+0x5d48e)
    #1 0x55a3ca03cc38 in mem_heap_dup(mem_block_info_t*, void const*, unsigned long) /mariadb/10.3/storage/innobase/include/mem0mem.h:304
    #2 0x55a3ca2bd455 in dfield_dup /mariadb/10.3/storage/innobase/include/data0data.ic:287
    #3 0x55a3ca2c7e58 in row_mysql_convert_row_to_innobase /mariadb/10.3/storage/innobase/row/row0mysql.cc:638
    #4 0x55a3ca2cc8de in row_insert_for_mysql(unsigned char const*, row_prebuilt_t*, ins_mode_t) /mariadb/10.3/storage/innobase/row/row0mysql.cc:1417
    #5 0x55a3ca000027 in ha_innobase::write_row(unsigned char*) /mariadb/10.3/storage/innobase/handler/ha_innodb.cc:8061

And the fix cures this.

I will try to figure out how to repeat this on 10.2, and I will also try Valgrind once more, now that the correct instrumentation is in place.

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