[MDEV-24620] ASAN heap-buffer-overflow in rec_init_offsets_comp_ordinary Created: 2021-01-18  Updated: 2021-04-14  Resolved: 2021-04-13

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3, 10.4
Fix Version/s: 10.3.29, 10.4.19, 10.5.10

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: rr-profile-analyzed

Issue Links:
Problem/Incident
is caused by MDEV-11369 Instant add column for InnoDB Closed

 Description   

10.3 f130adbf non-debug ASAN

 
==1376958==ERROR: AddressSanitizer: heap-buffer-overflow on address 0x60200002292f at pc 0x558682dfb7f2 bp 0x7f0b08d88bb0 sp 0x7f0b08d88ba0
 
READ of size 1 at 0x60200002292f thread T29
 
    #0 0x558682dfb7f1 in rec_init_offsets_comp_ordinary /data/src/10.3/storage/innobase/rem/rem0rec.cc:404
 
    #1 0x558682dfb7f1 in rec_init_offsets /data/src/10.3/storage/innobase/rem/rem0rec.cc:610
 
    #2 0x558682dfb7f1 in rec_get_offsets_func(unsigned char const*, dict_index_t const*, unsigned short*, bool, unsigned long, mem_block_info_t**) /data/src/10.3/storage/innobase/rem/rem0rec.cc:869
 
    #3 0x558682e008bf in rec_copy_prefix_to_dtuple(dtuple_t*, unsigned char const*, dict_index_t const*, bool, unsigned long, mem_block_info_t*) /data/src/10.3/storage/innobase/rem/rem0rec.cc:1761
 
    #4 0x5586831580d6 in dict_index_build_data_tuple(unsigned char const*, dict_index_t const*, bool, unsigned long, mem_block_info_t*) /data/src/10.3/storage/innobase/dict/dict0dict.cc:5106
 
    #5 0x558683090fed in btr_pcur_restore_position_func(unsigned long, btr_pcur_t*, char const*, unsigned int, mtr_t*) /data/src/10.3/storage/innobase/btr/btr0pcur.cc:360
 
    #6 0x558682ec00b5 in sel_restore_position_for_mysql /data/src/10.3/storage/innobase/row/row0sel.cc:3584
 
    #7 0x558682ed3048 in row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long) /data/src/10.3/storage/innobase/row/row0sel.cc:5724
 
    #8 0x558682c1a4dc in ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) /data/src/10.3/storage/innobase/handler/ha_innodb.cc:9268
 
    #9 0x558682bd1271 in ha_innobase::index_first(unsigned char*) /data/src/10.3/storage/innobase/handler/ha_innodb.cc:9642
 
    #10 0x558682613959 in handler::ha_index_first(unsigned char*) /data/src/10.3/sql/handler.cc:2995
 
    #11 0x558682a77c7d in rr_index_first /data/src/10.3/sql/records.cc:401
 
    #12 0x558682a77c7d in rr_index_first /data/src/10.3/sql/records.cc:391
 
    #13 0x5586821fc35a in READ_RECORD::read_record() /data/src/10.3/sql/records.h:70
 
    #14 0x5586821fc35a in mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*, unsigned int, st_order*, unsigned long long, bool, unsigned long long*, unsigned long long*) /data/src/10.3/sql/sql_update.cc:758
 
    #15 0x558681f73337 in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:4320
 
    #16 0x558681f87a3f in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.3/sql/sql_parse.cc:7840
 
    #17 0x558681f8e6c3 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.3/sql/sql_parse.cc:1852
 
    #18 0x558681f9551d in do_command(THD*) /data/src/10.3/sql/sql_parse.cc:1398
 
    #19 0x5586822d1d16 in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1403
 
    #20 0x5586822d259e in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1308
 
    #21 0x5586836568e8 in pfs_spawn_thread /data/src/10.3/storage/perfschema/pfs.cc:1869
 
    #22 0x7f0b1f8e7608 in start_thread /build/glibc-ZN95T4/glibc-2.31/nptl/pthread_create.c:477
 
    #23 0x7f0b1f4c1292 in __clone (/lib/x86_64-linux-gnu/libc.so.6+0x122292)
 
 
 
0x60200002292f is located 1 bytes to the left of 11-byte region [0x602000022930,0x60200002293b)
 
allocated by thread T29 here:
 
    #0 0x7f0b1fe4ebc8 in malloc (/lib/x86_64-linux-gnu/libasan.so.5+0x10dbc8)
 
    #1 0x558682e012a3 in rec_copy_prefix_to_buf(unsigned char const*, dict_index_t const*, unsigned long, unsigned char**, unsigned long*) /data/src/10.3/storage/innobase/rem/rem0rec.cc:1966
 
    #2 0x55868308f452 in btr_pcur_store_position(btr_pcur_t*, mtr_t*) /data/src/10.3/storage/innobase/btr/btr0pcur.cc:173
 
    #3 0x558682ed4273 in row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long) /data/src/10.3/storage/innobase/row/row0sel.cc:5685
 
    #4 0x558682c1a4dc in ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) /data/src/10.3/storage/innobase/handler/ha_innodb.cc:9268
 
    #5 0x558682bd1271 in ha_innobase::index_first(unsigned char*) /data/src/10.3/storage/innobase/handler/ha_innodb.cc:9642
 
    #6 0x558682613959 in handler::ha_index_first(unsigned char*) /data/src/10.3/sql/handler.cc:2995
 
    #7 0x558682a77c7d in rr_index_first /data/src/10.3/sql/records.cc:401
 
    #8 0x558682a77c7d in rr_index_first /data/src/10.3/sql/records.cc:391
 
    #9 0x5586821fc35a in READ_RECORD::read_record() /data/src/10.3/sql/records.h:70
 
    #10 0x5586821fc35a in mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*, unsigned int, st_order*, unsigned long long, bool, unsigned long long*, unsigned long long*) /data/src/10.3/sql/sql_update.cc:758
 
    #11 0x558681f73337 in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:4320
 
    #12 0x558681f87a3f in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.3/sql/sql_parse.cc:7840
 
    #13 0x558681f8e6c3 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.3/sql/sql_parse.cc:1852
 
    #14 0x558681f9551d in do_command(THD*) /data/src/10.3/sql/sql_parse.cc:1398
 
    #15 0x5586822d1d16 in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1403
 
    #16 0x5586822d259e in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1308
 
    #17 0x5586836568e8 in pfs_spawn_thread /data/src/10.3/storage/perfschema/pfs.cc:1869
 
    #18 0x7f0b1f8e7608 in start_thread /build/glibc-ZN95T4/glibc-2.31/nptl/pthread_create.c:477
 
 
 
Thread T29 created by T0 here:
 
    #0 0x7f0b1fd7b805 in pthread_create (/lib/x86_64-linux-gnu/libasan.so.5+0x3a805)
 
    #1 0x55868365e43e in spawn_thread_v1 /data/src/10.3/storage/perfschema/pfs.cc:1919
 
    #2 0x558681d03a9e in inline_mysql_thread_create /data/src/10.3/include/mysql/psi/mysql_thread.h:1275
 
    #3 0x558681d03a9e in create_thread_to_handle_connection(CONNECT*) /data/src/10.3/sql/mysqld.cc:6658
 
    #4 0x558681d14415 in create_new_thread /data/src/10.3/sql/mysqld.cc:6728
 
    #5 0x558681d14415 in handle_connections_sockets() /data/src/10.3/sql/mysqld.cc:6986
 
    #6 0x558681d163a5 in mysqld_main(int, char**) /data/src/10.3/sql/mysqld.cc:6280
 
    #7 0x7f0b1f3c60b2 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x270b2)
 
 
 
SUMMARY: AddressSanitizer: heap-buffer-overflow /data/src/10.3/storage/innobase/rem/rem0rec.cc:404 in rec_init_offsets_comp_ordinary
 
Shadow bytes around the buggy address:
 
  0x0c047fffc4d0: fa fa fd fa fa fa fd fa fa fa fd fa fa fa fd fd
 
  0x0c047fffc4e0: fa fa fd fa fa fa fd fa fa fa fd fd fa fa fd fa
 
  0x0c047fffc4f0: fa fa fd fa fa fa fd fa fa fa fd fd fa fa 00 00
 
  0x0c047fffc500: fa fa fd fa fa fa fd fd fa fa fd fa fa fa fd fa
 
  0x0c047fffc510: fa fa fd fd fa fa fd fa fa fa fd fa fa fa 00 00
 
=>0x0c047fffc520: fa fa 00 00 fa[fa]00 03 fa fa fa fa fa fa fa fa
 
  0x0c047fffc530: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c047fffc540: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c047fffc550: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c047fffc560: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c047fffc570: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
Shadow byte legend (one shadow byte represents 8 application bytes):
 
  Addressable:           00
 
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
 
  Freed heap region:       fd
 
  Stack left redzone:      f1
 
  Stack mid redzone:       f2
 
  Stack right redzone:     f3
 
  Stack after return:      f5
 
  Stack use after scope:   f8
 
  Global redzone:          f9
 
  Global init order:       f6
 
  Poisoned by user:        f7
 
  Container overflow:      fc
 
  Array cookie:            ac
 
  Intra object redzone:    bb
 
  ASan internal:           fe
 
  Left alloca redzone:     ca
 
  Right alloca redzone:    cb
 
  Shadow gap:              cc
 
==1376958==ABORTING

Reproducible on 10.3-10.4 at least.
Reproducible both on debug and non-debug ASAN, but easier on a non-debug ASAN, and the test itself is much faster there.
Couldn't reproduce on 10.5, but it's not conclusive, as the test is highly non-deterministic. Run with high value of --repeat (hundreds at least).
Didn't get any crashes on non-ASAN builds.

rr profile is available.

--source include/have_innodb.inc
 
 
 
CREATE TABLE t1 (a VARBINARY(542) NOT NULL DEFAULT '', id INT, PRIMARY KEY (a,id)) ENGINE=InnoDB;
 
INSERT INTO t1 VALUES (1,1);
 
--send
 
  ALTER TABLE t1 ADD n INT;
 
 
 
--connect (con1,localhost,root,,test)
 
--send
 
  DELETE FROM t1 ORDER BY a LIMIT 5;
 
 
 
--connect (con2,localhost,root,,test)
 
--send
 
  DELETE FROM t1 ORDER BY id LIMIT 3;
 
 
 
--connection default
 
--reap
 
UPDATE t1 SET n = 1 ORDER BY a LIMIT 1;
 
 
 
# Cleanup
 
 
 
--connection con2
 
--reap
 
--disconnect con2
 
--connection con1
 
--reap
 
--disconnect con1
 
--connection default
 
DROP TABLE t1;



 Comments   
Comment by Marko Mäkelä [ 2021-04-09 ]

I started checking the rr replay, and the pointer is rather ‘wild’. The ASAN shadow byte was initialized as a red zone for something completely unrelated:

10.3 f130adbf35b5b8ef7ed091549ed764982801480c

 
#6  0x00007f8af01d9b0b in malloc () from /usr/lib/x86_64-linux-gnu/libasan.so.4
 
#7  0x00007f8aee54da2a in __GI___strdup (s=s@entry=0x7f8aee665487 "/etc/localtime") at strdup.c:42
 
#8  0x00007f8aee584281 in tzset_internal (always=1) at tzset.c:403
 
#9  __tzset () at tzset.c:552
 
#10 0x0000556a2a6ec3f2 in init_common_variables () at /home/mariadb/MDEV-24620/10.3/sql/mysqld.cc:4261
 
#11 0x0000556a2a6f2b4c in mysqld_main (argc=147, argv=0x61b000000f58)

The problem is that we are accessing something that was not allocated in the btr_pcur_t::old_rec at all:

#0  0x0000556a2ba05f5b in rec_init_offsets_comp_ordinary (rec=0x6020000073d6 "1\200", 
    index=0x618000033908, offsets=0x7f8ad3be07a0, n_core=5, def_val=0x0, format=REC_LEAF_ORDINARY)
 
    at /home/mariadb/MDEV-24620/10.3/storage/innobase/rem/rem0rec.cc:404
 
#1  0x0000556a2ba080de in rec_init_offsets (rec=0x6020000073d6 "1\200", index=0x618000033908, 
    leaf=true, offsets=0x7f8ad3be07a0)
 
    at /home/mariadb/MDEV-24620/10.3/storage/innobase/rem/rem0rec.cc:610
 
#2  0x0000556a2ba09e31 in rec_get_offsets_func (rec=0x6020000073d6 "1\200", index=0x618000033908, 
    offsets=0x7f8ad3be07a0, leaf=true, n_fields=2, 
    file=0x556a2cd97860 "/home/mariadb/MDEV-24620/10.3/storage/innobase/rem/rem0rec.cc", line=1762, 
    heap=0x7f8ad3be06f0) at /home/mariadb/MDEV-24620/10.3/storage/innobase/rem/rem0rec.cc:869
 
#3  0x0000556a2ba11098 in rec_copy_prefix_to_dtuple (tuple=0x6130000fb488, rec=0x6020000073d6 "1\200", 
    index=0x618000033908, is_leaf=true, n_fields=2, heap=0x6130000fb400)
 
    at /home/mariadb/MDEV-24620/10.3/storage/innobase/rem/rem0rec.cc:1761
 
#4  0x0000556a2beb39ec in dict_index_build_data_tuple (rec=0x6020000073d6 "1\200", 
    index=0x618000033908, leaf=true, n_fields=2, heap=0x6130000fb400)
 
    at /home/mariadb/MDEV-24620/10.3/storage/innobase/dict/dict0dict.cc:5106
 
#5  0x0000556a2bd8289e in btr_pcur_restore_position_func (latch_mode=1, cursor=0x6200000132e0, 
    file=0x556a2ce0b0e0 "/home/mariadb/MDEV-24620/10.3/storage/innobase/row/row0sel.cc", line=3584, 
    mtr=0x7f8ad3be2640) at /home/mariadb/MDEV-24620/10.3/storage/innobase/btr/btr0pcur.cc:360

At the time of the out-of-bounds access is detected, we dereferenced lens = 0x6020000073cf, which is right before btr_pcur_t::old_rec_buf. The memory was last modified here, as expected:

#2  0x0000556a2ba1364d in rec_copy_prefix_to_buf (rec=0x7f8ae490407e "1\200", index=0x618000033908, 
    n_fields=2, buf=0x6200000133c8, buf_size=0x6200000133d0)
 
    at /home/mariadb/MDEV-24620/10.3/storage/innobase/rem/rem0rec.cc:1993
 
#3  0x0000556a2beb3887 in dict_index_copy_rec_order_prefix (index=0x618000033908, 
    rec=0x7f8ae490407e "1\200", n_fields=0x620000013390, buf=0x6200000133c8, buf_size=0x6200000133d0)
 
    at /home/mariadb/MDEV-24620/10.3/storage/innobase/dict/dict0dict.cc:5084
 
#4  0x0000556a2bd8173f in btr_pcur_store_position (cursor=0x6200000132e0, mtr=0x7f8ad3be2640)
 
    at /home/mariadb/MDEV-24620/10.3/storage/innobase/btr/btr0pcur.cc:173
 
#5  0x0000556a2bb6c9d6 in row_search_mvcc (buf=0x61a000079310 "\377", mode=PAGE_CUR_G, 
    prebuilt=0x620000013108, match_mode=0, direction=0)
 
    at /home/mariadb/MDEV-24620/10.3/storage/innobase/row/row0sel.cc:5685

At frame 5, we had the offsets of the record indicating that there be 6 record header bytes, corresponding to what was copied to btr_pcur_t::old_rec_buf. We do have index->is_instant() at that point; the column n had been instantly added.
The contents of the record at that point is (note: no instantly added column is present):
(a,id,DB_TRX_ID,DB_ROLL_PTR)=('1',1,0x29,(update))

The problem is that between the time of storing and restoring the cursor, the table ‘lost instantness’, and hence we are expecting to find more header bytes than the 6:

#0  0x0000556a2b818b79 in dict_index_t::remove_instant (this=0x618000033908)
 
    at /home/mariadb/MDEV-24620/10.3/storage/innobase/include/dict0mem.h:1133
 
#1  0x0000556a2bd67147 in btr_cur_optimistic_delete_func (cursor=0x61a000001fb0, flags=0, 
    mtr=0x7f8ada3780f0) at /home/mariadb/MDEV-24620/10.3/storage/innobase/btr/btr0cur.cc:5530
 
#2  0x0000556a2bb1f2e1 in row_purge_remove_clust_if_poss_low (node=0x61a000001f08, mode=2)
 
    at /home/mariadb/MDEV-24620/10.3/storage/innobase/row/row0purge.cc:144

Maybe the simplest fix would be to maintain a copy of dict_index_t::n_core_fields in btr_pcur_t and use that value in btr_pcur_restore_pos().

Here is a repeatable test case for 10.3:

diff --git a/mysql-test/suite/innodb/t/instant_alter_debug.test b/mysql-test/suite/innodb/t/instant_alter_debug.test
 
index 0431177a130..3f3e20442a2 100644
 
--- a/mysql-test/suite/innodb/t/instant_alter_debug.test
 
+++ b/mysql-test/suite/innodb/t/instant_alter_debug.test
 
@@ -364,6 +364,43 @@ DROP TABLE t1;
 
 
 SET GLOBAL innodb_limit_optimistic_insert_debug = @saved_limit;
 
 
+--echo #
 
+--echo # MDEV-24620 ASAN heap-buffer-overflow in btr_pcur_restore_position()
 
+--echo #
 
+
 
+CREATE TABLE t1 (a VARCHAR(1) PRIMARY KEY) ENGINE=InnoDB;
 
+INSERT INTO t1 VALUES (1);
 
+connect (stop_purge,localhost,root,,);
 
+START TRANSACTION WITH CONSISTENT SNAPSHOT;
 
+
 
+connection default;
 
+ALTER TABLE t1 ADD c INT;
 
+BEGIN;
 
+DELETE FROM t1;
 
+
 
+connect (dml,localhost,root,,test);
 
+SET DEBUG_SYNC='row_mysql_handle_errors SIGNAL s1 WAIT_FOR s2';
 
+send UPDATE t1 SET c=1;
 
+
 
+connection default;
 
+SET DEBUG_SYNC='now WAIT_FOR s1';
 
+COMMIT;
 
+
 
+connection stop_purge;
 
+COMMIT;
 
+disconnect stop_purge;
 
+
 
+connection default;
 
+--source include/wait_all_purged.inc
 
+SET DEBUG_SYNC='now SIGNAL s2';
 
+
 
+connection dml;
 
+reap;
 
+disconnect dml;
 
+
 
+connection default;
 
+DROP TABLE t1;
 
+
 
 --echo # End of 10.3 tests
 
 
 SET GLOBAL innodb_purge_rseg_truncate_frequency = @save_frequency;
 
diff --git a/storage/innobase/row/row0mysql.cc b/storage/innobase/row/row0mysql.cc
 
index d79cf29e53c..f16fe16dc89 100644
 
--- a/storage/innobase/row/row0mysql.cc
 
+++ b/storage/innobase/row/row0mysql.cc
 
@@ -689,6 +689,7 @@ row_mysql_handle_errors(
 
 	dberr_t	err;
 
 
 	DBUG_ENTER("row_mysql_handle_errors");
 
+	DEBUG_SYNC_C("row_mysql_handle_errors");
 
 
 handle_new_error:
 
 	err = trx->error_state;

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