[MDEV-16982] Server crashes in mem_heap_dup upon DELETE from table with virtual columns - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.3(EOL), 10.4(EOL)
Fix Version/s: 10.4.3, 10.2.22, 10.3.13
Component/s: Data Manipulation - Delete, Storage Engine - InnoDB, Virtual Columns
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

Attachments

Activity

Ascending order - Click to sort in descending order

Marko Mäkelä added a comment - 2019-01-18 06:00

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.

Marko Mäkelä added a comment - 2019-01-18 06:00 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.

Eugene Kosov (Inactive) added a comment - 2019-01-31 14:26

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"

Eugene Kosov (Inactive) added a comment - 2019-01-31 14:26 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"

Eugene Kosov (Inactive) added a comment - 2019-01-31 14:40

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.

Eugene Kosov (Inactive) added a comment - 2019-01-31 14:40 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.

Eugene Kosov (Inactive) added a comment - 2019-01-31 14:48 - edited

./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.

Eugene Kosov (Inactive) added a comment - 2019-01-31 14:48 - edited ./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.

Marko Mäkelä added a comment - 2019-01-31 18:30

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.

Marko Mäkelä added a comment - 2019-01-31 18:30 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.

People

Assignee:: Eugene Kosov (Inactive)

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2018-08-14 23:54

Updated:: 2019-02-05 10:28

Resolved:: 2019-02-05 10:28

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server