[MDEV-16781] InnoDB: AddressSanitizer: use-after-poison during DDL Created: 2018-07-19  Updated: 2018-08-16  Resolved: 2018-08-16

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2.17, 10.3.9, 10.4.0
Fix Version/s: 10.2.18, 10.3.10

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Marko Mäkelä
Resolution: Duplicate Votes: 0
Labels: None
Environment:

Linux Ubuntu 17.10 but most probably unimportant

Attachments: File MDEV-16781.tgz    
Issue Links:
Relates
relates to MDEV-16063 [Draft] ASAN use-after-poison in row_... Closed
relates to MDEV-16136 Various ASAN failures when testing 10... Closed
relates to MDEV-16780 [draft] AddressSanitizer: use-after-p... Open

 Description    

Version: '10.4.0-MariaDB-debug-log' 
=================================================================
 
==19602==ERROR: AddressSanitizer: use-after-poison on address 0x7f154d0fd8a8 at pc 0x559823f00927 bp 0x7f15391e1b10 sp 0x7f15391e1b00
 
READ of size 4 at 0x7f154d0fd8a8 thread T20
 
==19602==AddressSanitizer: while reporting a bug found another one. Ignoring.
 
    #0 0x559823f00926 in ReadView::get_state() const /git/10.4/storage/innobase/include/read0types.h:152
 
    #1 0x559823fc462a in trx_sys_t::clone_oldest_view() /git/10.4/storage/innobase/read/read0read.cc:289
 
    #2 0x55982418f0b2 in trx_purge(unsigned long, bool) /git/10.4/storage/innobase/trx/trx0purge.cc:1549
 
    #3 0x55982413b43c in srv_do_purge /git/10.4/storage/innobase/srv/srv0srv.cc:2582
 
    #4 0x55982413bc16 in srv_purge_coordinator_thread /git/10.4/storage/innobase/srv/srv0srv.cc:2713
 
    #5 0x7f1559e776b9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76b9)
 
    #6 0x7f155930c41c in clone (/lib/x86_64-linux-gnu/libc.so.6+0x10741c)
 
 
 
0x7f154d0fd8a8 is located 8360 bytes inside of 4194304-byte region [0x7f154d0fb800,0x7f154d4fb800)
 
allocated by thread T0 here:
 
    #0 0x7f155b27b79a in __interceptor_calloc (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x9879a)
 
    #1 0x5598241db488 in Pool<trx_t, TrxFactory, TrxPoolLock>::Pool(unsigned long) /git/10.4/storage/innobase/include/ut0pool.h:65
 
    #2 0x5598241da300 in PoolManager<Pool<trx_t, TrxFactory, TrxPoolLock>, TrxPoolManagerLock>::add_pool(unsigned long) /git/10.4/storage/innobase/include/ut0pool.h:320
 
    #3 0x5598241d9c62 in PoolManager<Pool<trx_t, TrxFactory, TrxPoolLock>, TrxPoolManagerLock>::create() /git/10.4/storage/innobase/include/ut0pool.h:348
 
    #4 0x5598241d8fc4 in PoolManager<Pool<trx_t, TrxFactory, TrxPoolLock>, TrxPoolManagerLock>::PoolManager(unsigned long) /git/10.4/storage/innobase/include/ut0pool.h:232
 
    #5 0x5598241c8ad2 in trx_pool_init() /git/10.4/storage/innobase/trx/trx0trx.cc:375
 
    #6 0x559824136076 in srv_boot() /git/10.4/storage/innobase/srv/srv0srv.cc:1125
 
    #7 0x559824146864 in srv_start(bool) /git/10.4/storage/innobase/srv/srv0start.cc:1532
 
    #8 0x559823dc59c2 in innodb_init /git/10.4/storage/innobase/handler/ha_innodb.cc:4269
 
    #9 0x5598235ad09d in ha_initialize_handlerton(st_plugin_int*) /git/10.4/sql/handler.cc:522
 
    #10 0x559822f1b407 in plugin_initialize /git/10.4/sql/sql_plugin.cc:1432
 
    #11 0x559822f1cc74 in plugin_init(int*, char**, int) /git/10.4/sql/sql_plugin.cc:1714
 
    #12 0x559822c6419f in init_server_components /git/10.4/sql/mysqld.cc:5390
 
    #13 0x559822c660c8 in mysqld_main(int, char**) /git/10.4/sql/mysqld.cc:5997
 
    #14 0x559822c5080f in main /git/10.4/sql/main.cc:25
 
    #15 0x7f155922582f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)
 
 
 
Thread T20 created by T0 here:
 
    #0 0x7f155b219253 in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x36253)
 
    #1 0x559823f6f251 in os_thread_create_func(void* (*)(void*), void*, unsigned long*) /git/10.4/storage/innobase/os/os0thread.cc:137
 
    #2 0x55982414a930 in srv_start(bool) /git/10.4/storage/innobase/srv/srv0start.cc:2449
 
    #3 0x559823dc59c2 in innodb_init /git/10.4/storage/innobase/handler/ha_innodb.cc:4269
 
    #4 0x5598235ad09d in ha_initialize_handlerton(st_plugin_int*) /git/10.4/sql/handler.cc:522
 
    #5 0x559822f1b407 in plugin_initialize /git/10.4/sql/sql_plugin.cc:1432
 
    #6 0x559822f1cc74 in plugin_init(int*, char**, int) /git/10.4/sql/sql_plugin.cc:1714
 
    #7 0x559822c6419f in init_server_components /git/10.4/sql/mysqld.cc:5390
 
    #8 0x559822c660c8 in mysqld_main(int, char**) /git/10.4/sql/mysqld.cc:5997
 
    #9 0x559822c5080f in main /git/10.4/sql/main.cc:25
 
    #10 0x7f155922582f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)
 
 
 
SUMMARY: AddressSanitizer: use-after-poison /git/10.4/storage/innobase/include/read0types.h:152 ReadView::get_state() const
 
Shadow bytes around the buggy address:
 
  0x0fe329a17ac0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0fe329a17ad0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0fe329a17ae0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0fe329a17af0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0fe329a17b00: 00 00 00 f7 00 00 00 00 00 00 00 00 00 00 00 00
 
=>0x0fe329a17b10: 00 00 f7 f7 f7[f7]f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0fe329a17b20: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0fe329a17b30: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0fe329a17b40: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0fe329a17b50: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0fe329a17b60: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
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
 
  Heap right redzone:      fb
 
  Freed heap region:       fd
 
  Stack left redzone:      f1
 
  Stack mid redzone:       f2
 
  Stack right redzone:     f3
 
  Stack partial redzone:   f4
 
  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
 
==19602==ABORTING



 Comments   
Comment by Alice Sherepa [ 2018-07-20 ] 

Version: '10.4.0-MariaDB-debug-log' 
=================================================================
 
==16192==ERROR: AddressSanitizer: use-after-poison on address 0x7fc6c6cd7278 at pc 0x55e2e0e7d091 bp 0x7fc6a2ca41a0 sp 0x7fc6a2ca4190
 
READ of size 8 at 0x7fc6c6cd7278 thread T33
 
    #0 0x55e2e0e7d090 in std::vector<ib_lock_t*, ut_allocator<ib_lock_t*, true> >::end() const /usr/include/c++/5/bits/stl_vector.h:575
 
    #1 0x55e2e0e7ac75 in std::vector<ib_lock_t*, ut_allocator<ib_lock_t*, true> >::empty() const /usr/include/c++/5/bits/stl_vector.h:744
 
    #2 0x55e2e0e519be in lock_table_has /git/10.4/storage/innobase/include/lock0priv.ic:391
 
    #3 0x55e2e0e6dd77 in lock_rec_insert_check_and_lock(unsigned long, unsigned char const*, buf_block_t*, dict_index_t*, que_thr_t*, mtr_t*, bool*) /git/10.4/storage/innobase/lock/lock0lock.cc:5341
 
    #4 0x55e2e11bd649 in btr_cur_ins_lock_and_undo /git/10.4/storage/innobase/btr/btr0cur.cc:2999
 
    #5 0x55e2e11be3e2 in btr_cur_optimistic_insert(unsigned long, btr_cur_t*, unsigned long**, mem_block_info_t**, dtuple_t*, unsigned char**, big_rec_t**, unsigned long, que_thr_t*, mtr_t*) /git/10.4/storage/innobase/btr/btr0cur.cc:3226
 
    #6 0x55e2e0f9a3ec in row_ins_clust_index_entry_low(unsigned long, unsigned long, dict_index_t*, unsigned long, dtuple_t*, unsigned long, que_thr_t*, bool) /git/10.4/storage/innobase/row/row0ins.cc:2760
 
    #7 0x55e2e0f9c606 in row_ins_clust_index_entry(dict_index_t*, dtuple_t*, que_thr_t*, unsigned long, bool) /git/10.4/storage/innobase/row/row0ins.cc:3264
 
    #8 0x55e2e0f9ceed in row_ins_index_entry /git/10.4/storage/innobase/row/row0ins.cc:3389
 
    #9 0x55e2e0f9d9ee in row_ins_index_entry_step /git/10.4/storage/innobase/row/row0ins.cc:3539
 
    #10 0x55e2e0f9e34a in row_ins /git/10.4/storage/innobase/row/row0ins.cc:3681
 
    #11 0x55e2e0f9f917 in row_ins_step(que_thr_t*) /git/10.4/storage/innobase/row/row0ins.cc:3935
 
    #12 0x55e2e0f38e2a in que_thr_step /git/10.4/storage/innobase/que/que0que.cc:1025
 
    #13 0x55e2e0f393ce in que_run_threads_low /git/10.4/storage/innobase/que/que0que.cc:1108
 
    #14 0x55e2e0f39715 in que_run_threads(que_thr_t*) /git/10.4/storage/innobase/que/que0que.cc:1148
 
    #15 0x55e2e0dc4c8b in create_index_dict /git/10.4/storage/innobase/handler/handler0alter.cc:4802
 
    #16 0x55e2e0dcdb21 in prepare_inplace_alter_table_dict /git/10.4/storage/innobase/handler/handler0alter.cc:5611
 
    #17 0x55e2e0dd705b in ha_innobase::prepare_inplace_alter_table(TABLE*, Alter_inplace_info*) /git/10.4/storage/innobase/handler/handler0alter.cc:6976
 
    #18 0x55e2e053d1e4 in handler::ha_prepare_inplace_alter_table(TABLE*, Alter_inplace_info*) /git/10.4/sql/handler.cc:4397
 
    #19 0x55e2e0067069 in mysql_inplace_alter_table /git/10.4/sql/sql_table.cc:7533
 
    #20 0x55e2e007402b in mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) /git/10.4/sql/sql_table.cc:9710
 
    #21 0x55e2e01af99d in Sql_cmd_alter_table::execute(THD*) /git/10.4/sql/sql_alter.cc:495
 
    #22 0x55e2dfe6da74 in mysql_execute_command(THD*) /git/10.4/sql/sql_parse.cc:6283
 
    #23 0x55e2dfe78128 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /git/10.4/sql/sql_parse.cc:8063
 
    #24 0x55e2dfe5324e in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /git/10.4/sql/sql_parse.cc:1847
 
    #25 0x55e2dfe503e6 in do_command(THD*) /git/10.4/sql/sql_parse.cc:1392
 
    #26 0x55e2e01a1201 in do_handle_one_connection(CONNECT*) /git/10.4/sql/sql_connect.cc:1402
 
    #27 0x55e2e01a0bde in handle_one_connection /git/10.4/sql/sql_connect.cc:1308
 
    #28 0x7fc6d3a1c6b9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76b9)
 
    #29 0x7fc6d2eb141c in clone (/lib/x86_64-linux-gnu/libc.so.6+0x10741c)
 
 
 
0x7fc6c6cd7278 is located 6776 bytes inside of 4194304-byte region [0x7fc6c6cd5800,0x7fc6c70d5800)
 
allocated by thread T0 here:
 
    #0 0x7fc6d4e2079a in __interceptor_calloc (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x9879a)
 
    #1 0x55e2e1152488 in Pool<trx_t, TrxFactory, TrxPoolLock>::Pool(unsigned long) /git/10.4/storage/innobase/include/ut0pool.h:65
 
    #2 0x55e2e1151300 in PoolManager<Pool<trx_t, TrxFactory, TrxPoolLock>, TrxPoolManagerLock>::add_pool(unsigned long) /git/10.4/storage/innobase/include/ut0pool.h:320
 
    #3 0x55e2e1150c62 in PoolManager<Pool<trx_t, TrxFactory, TrxPoolLock>, TrxPoolManagerLock>::create() /git/10.4/storage/innobase/include/ut0pool.h:348
 
    #4 0x55e2e114ffc4 in PoolManager<Pool<trx_t, TrxFactory, TrxPoolLock>, TrxPoolManagerLock>::PoolManager(unsigned long) /git/10.4/storage/innobase/include/ut0pool.h:232
 
    #5 0x55e2e113fad2 in trx_pool_init() /git/10.4/storage/innobase/trx/trx0trx.cc:375
 
    #6 0x55e2e10ad076 in srv_boot() /git/10.4/storage/innobase/srv/srv0srv.cc:1125
 
    #7 0x55e2e10bd864 in srv_start(bool) /git/10.4/storage/innobase/srv/srv0start.cc:1532
 
    #8 0x55e2e0d3c9c2 in innodb_init /git/10.4/storage/innobase/handler/ha_innodb.cc:4269
 
    #9 0x55e2e052409d in ha_initialize_handlerton(st_plugin_int*) /git/10.4/sql/handler.cc:522
 
    #10 0x55e2dfe92407 in plugin_initialize /git/10.4/sql/sql_plugin.cc:1432
 
    #11 0x55e2dfe93c74 in plugin_init(int*, char**, int) /git/10.4/sql/sql_plugin.cc:1714
 
    #12 0x55e2dfbdb19f in init_server_components /git/10.4/sql/mysqld.cc:5390
 
    #13 0x55e2dfbdd0c8 in mysqld_main(int, char**) /git/10.4/sql/mysqld.cc:5997
 
    #14 0x55e2dfbc780f in main /git/10.4/sql/main.cc:25
 
    #15 0x7fc6d2dca82f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)
 
 
 
Thread T33 created by T0 here:
 
    #0 0x7fc6d4dbe253 in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x36253)
 
    #1 0x55e2e16261be in spawn_thread_noop /git/10.4/mysys/psi_noop.c:187
 
    #2 0x55e2dfbc90e4 in inline_mysql_thread_create /git/10.4/include/mysql/psi/mysql_thread.h:1268
 
    #3 0x55e2dfbde53d in create_thread_to_handle_connection(CONNECT*) /git/10.4/sql/mysqld.cc:6572
 
    #4 0x55e2dfbdec3d in create_new_thread /git/10.4/sql/mysqld.cc:6642
 
    #5 0x55e2dfbdfc7a in handle_connections_sockets() /git/10.4/sql/mysqld.cc:6917
 
    #6 0x55e2dfbdd9fd in mysqld_main(int, char**) /git/10.4/sql/mysqld.cc:6194
 
    #7 0x55e2dfbc780f in main /git/10.4/sql/main.cc:25
 
    #8 0x7fc6d2dca82f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)
 
 
 
SUMMARY: AddressSanitizer: use-after-poison /usr/include/c++/5/bits/stl_vector.h:575 std::vector<ib_lock_t*, ut_allocator<ib_lock_t*, true> >::end() const
 
Shadow bytes around the buggy address:
 
  0x0ff958d92df0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0ff958d92e00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0ff958d92e10: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 f7
 
  0x0ff958d92e20: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 f7 f7
 
  0x0ff958d92e30: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
=>0x0ff958d92e40: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7[f7]
 
  0x0ff958d92e50: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0ff958d92e60: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0ff958d92e70: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0ff958d92e80: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0ff958d92e90: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
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
 
  Heap right redzone:      fb
 
  Freed heap region:       fd
 
  Stack left redzone:      f1
 
  Stack mid redzone:       f2
 
  Stack right redzone:     f3
 
  Stack partial redzone:   f4
 
  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
 
==16192==ABORTING


Version: '10.4.0-MariaDB-debug-log'  socket: '/aliska/7/mysql.sock'  port: 19300  Source distribution
 
=================================================================
 
==17885==ERROR: AddressSanitizer: use-after-poison on address 0x7fed178b9648 at pc 0x5558db22cc53 bp 0x7fecf2ef0cd0 sp 0x7fecf2ef0cc0
 
WRITE of size 4 at 0x7fed178b9648 thread T34
 
    #0 0x5558db22cc52 in trx_t::release_reference() /git/10.4/storage/innobase/include/trx0trx.h:1129
 
    #1 0x5558db22371b in lock_rec_convert_impl_to_expl_for_trx /git/10.4/storage/innobase/lock/lock0lock.cc:5481
 
    #2 0x5558db223f78 in lock_rec_convert_impl_to_expl /git/10.4/storage/innobase/lock/lock0lock.cc:5598
 
    #3 0x5558db2254b1 in lock_clust_rec_read_check_and_lock(unsigned long, buf_block_t const*, unsigned char const*, dict_index_t*, unsigned long const*, lock_mode, unsigned long, que_thr_t*) /git/10.4/storage/innobase/lock/lock0lock.cc:5856
 
    #4 0x5558db34a6eb in row_ins_set_shared_rec_lock /git/10.4/storage/innobase/row/row0ins.cc:1506
 
    #5 0x5558db34d80b in row_ins_duplicate_error_in_clust /git/10.4/storage/innobase/row/row0ins.cc:2371
 
    #6 0x5558db34f1f0 in row_ins_clust_index_entry_low(unsigned long, unsigned long, dict_index_t*, unsigned long, dtuple_t*, unsigned long, que_thr_t*, bool) /git/10.4/storage/innobase/row/row0ins.cc:2716
 
    #7 0x5558db351606 in row_ins_clust_index_entry(dict_index_t*, dtuple_t*, que_thr_t*, unsigned long, bool) /git/10.4/storage/innobase/row/row0ins.cc:3264
 
    #8 0x5558db351eed in row_ins_index_entry /git/10.4/storage/innobase/row/row0ins.cc:3389
 
    #9 0x5558db3529ee in row_ins_index_entry_step /git/10.4/storage/innobase/row/row0ins.cc:3539
 
    #10 0x5558db35334a in row_ins /git/10.4/storage/innobase/row/row0ins.cc:3681
 
    #11 0x5558db354917 in row_ins_step(que_thr_t*) /git/10.4/storage/innobase/row/row0ins.cc:3935
 
    #12 0x5558db2ede2a in que_thr_step /git/10.4/storage/innobase/que/que0que.cc:1025
 
    #13 0x5558db2ee3ce in que_run_threads_low /git/10.4/storage/innobase/que/que0que.cc:1108
 
    #14 0x5558db2ee715 in que_run_threads(que_thr_t*) /git/10.4/storage/innobase/que/que0que.cc:1148
 
    #15 0x5558db2eecc9 in que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*) /git/10.4/storage/innobase/que/que0que.cc:1225
 
    #16 0x5558db6ad394 in dict_stats_exec_sql /git/10.4/storage/innobase/dict/dict0stats.cc:311
 
    #17 0x5558db6b5fd2 in dict_stats_save /git/10.4/storage/innobase/dict/dict0stats.cc:2492
 
    #18 0x5558db6b8a45 in dict_stats_update_for_index(dict_index_t*) /git/10.4/storage/innobase/dict/dict0stats.cc:3121
 
    #19 0x5558db195b6a in alter_stats_norebuild /git/10.4/storage/innobase/handler/handler0alter.cc:9238
 
    #20 0x5558db19b4c9 in ha_innobase::commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) /git/10.4/storage/innobase/handler/handler0alter.cc:10036
 
    #21 0x5558da8f24b5 in handler::ha_commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) /git/10.4/sql/handler.cc:4417
 
    #22 0x5558da41c7c0 in mysql_inplace_alter_table /git/10.4/sql/sql_table.cc:7616
 
    #23 0x5558da42902b in mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) /git/10.4/sql/sql_table.cc:9710
 
    #24 0x5558da56499d in Sql_cmd_alter_table::execute(THD*) /git/10.4/sql/sql_alter.cc:495
 
    #25 0x5558da222a74 in mysql_execute_command(THD*) /git/10.4/sql/sql_parse.cc:6283
 
    #26 0x5558da22d128 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /git/10.4/sql/sql_parse.cc:8063
 
    #27 0x5558da20824e in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /git/10.4/sql/sql_parse.cc:1847
 
    #28 0x5558da2053e6 in do_command(THD*) /git/10.4/sql/sql_parse.cc:1392
 
    #29 0x5558da556201 in do_handle_one_connection(CONNECT*) /git/10.4/sql/sql_connect.cc:1402
 
    #30 0x5558da555bde in handle_one_connection /git/10.4/sql/sql_connect.cc:1308
 
    #31 0x7fed245e96b9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76b9)
 
    #32 0x7fed23a7e41c in clone (/lib/x86_64-linux-gnu/libc.so.6+0x10741c)
 
 
 
0x7fed178b9648 is located 3656 bytes inside of 4194304-byte region [0x7fed178b8800,0x7fed17cb8800)
 
allocated by thread T0 here:
 
    #0 0x7fed259ed79a in __interceptor_calloc (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x9879a)
 
    #1 0x5558db507488 in Pool<trx_t, TrxFactory, TrxPoolLock>::Pool(unsigned long) /git/10.4/storage/innobase/include/ut0pool.h:65
 
    #2 0x5558db506300 in PoolManager<Pool<trx_t, TrxFactory, TrxPoolLock>, TrxPoolManagerLock>::add_pool(unsigned long) /git/10.4/storage/innobase/include/ut0pool.h:320
 
    #3 0x5558db505c62 in PoolManager<Pool<trx_t, TrxFactory, TrxPoolLock>, TrxPoolManagerLock>::create() /git/10.4/storage/innobase/include/ut0pool.h:348
 
    #4 0x5558db504fc4 in PoolManager<Pool<trx_t, TrxFactory, TrxPoolLock>, TrxPoolManagerLock>::PoolManager(unsigned long) /git/10.4/storage/innobase/include/ut0pool.h:232
 
    #5 0x5558db4f4ad2 in trx_pool_init() /git/10.4/storage/innobase/trx/trx0trx.cc:375
 
    #6 0x5558db462076 in srv_boot() /git/10.4/storage/innobase/srv/srv0srv.cc:1125
 
    #7 0x5558db472864 in srv_start(bool) /git/10.4/storage/innobase/srv/srv0start.cc:1532
 
    #8 0x5558db0f19c2 in innodb_init /git/10.4/storage/innobase/handler/ha_innodb.cc:4269
 
    #9 0x5558da8d909d in ha_initialize_handlerton(st_plugin_int*) /git/10.4/sql/handler.cc:522
 
    #10 0x5558da247407 in plugin_initialize /git/10.4/sql/sql_plugin.cc:1432
 
    #11 0x5558da248c74 in plugin_init(int*, char**, int) /git/10.4/sql/sql_plugin.cc:1714
 
    #12 0x5558d9f9019f in init_server_components /git/10.4/sql/mysqld.cc:5390
 
    #13 0x5558d9f920c8 in mysqld_main(int, char**) /git/10.4/sql/mysqld.cc:5997
 
    #14 0x5558d9f7c80f in main /git/10.4/sql/main.cc:25
 
    #15 0x7fed2399782f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)
 
 
 
Thread T34 created by T0 here:
 
    #0 0x7fed2598b253 in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x36253)
 
    #1 0x5558db9db1be in spawn_thread_noop /git/10.4/mysys/psi_noop.c:187
 
    #2 0x5558d9f7e0e4 in inline_mysql_thread_create /git/10.4/include/mysql/psi/mysql_thread.h:1268
 
    #3 0x5558d9f9353d in create_thread_to_handle_connection(CONNECT*) /git/10.4/sql/mysqld.cc:6572
 
    #4 0x5558d9f93c3d in create_new_thread /git/10.4/sql/mysqld.cc:6642
 
    #5 0x5558d9f94c7a in handle_connections_sockets() /git/10.4/sql/mysqld.cc:6917
 
    #6 0x5558d9f929fd in mysqld_main(int, char**) /git/10.4/sql/mysqld.cc:6194
 
    #7 0x5558d9f7c80f in main /git/10.4/sql/main.cc:25
 
    #8 0x7fed2399782f in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x2082f)
 
 
 
SUMMARY: AddressSanitizer: use-after-poison /git/10.4/storage/innobase/include/trx0trx.h:1129 trx_t::release_reference()
 
Shadow bytes around the buggy address:
 
  0x0ffe22f0f270: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0ffe22f0f280: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0ffe22f0f290: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0ffe22f0f2a0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
  0x0ffe22f0f2b0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
 
=>0x0ffe22f0f2c0: 00 00 00 00 00 00 00 00 00[f7]00 00 00 00 00 00
 
  0x0ffe22f0f2d0: 00 00 00 00 00 00 00 00 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0ffe22f0f2e0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0ffe22f0f2f0: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0ffe22f0f300: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
  0x0ffe22f0f310: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
 
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
 
  Heap right redzone:      fb
 
  Freed heap region:       fd
 
  Stack left redzone:      f1
 
  Stack mid redzone:       f2
 
  Stack right redzone:     f3
 
  Stack partial redzone:   f4
 
  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
 
==17885==ABORTING

Comment by Alice Sherepa [ 2018-07-20 ]

repeatable with join_cache_level>2, 10.4 fee463238793dcc196273654b, built as (cmake . -DCMAKE_BUILD_TYPE=Debug -DWITH_ASAN=YES)

perl runall-new.pl --no-mask --seed=time --threads=8 --duration=600 --queries=100M --reporter=Backtrace,ErrorLog --engine=InnoDB --mysqld=--join_cache_level=3 --grammar=conf/optimizer/range_access.yy --gendata=conf/optimizer/outer_join.zz  --basedir=/git/10.4 --vardir=~/1


Version: '10.4.0-MariaDB-debug-log' 
=================================================================
 
==25508==ERROR: AddressSanitizer: use-after-poison on address 0x7f41cccfc4f8 at pc 0x55f8b55808fb bp 0x7f41aaa95200 sp 0x7f41aaa951f0
 
WRITE of size 8 at 0x7f41cccfc4f8 thread T32
 
==25508==AddressSanitizer: while reporting a bug found another one. Ignoring.
 
    #0 0x55f8b55808fa in que_eval_sql(pars_info_t*, char const*, unsigned long, trx_t*) /git/10.4/storage/innobase/que/que0que.cc:1219
 
    #1 0x55f8b594a286 in dict_stats_fetch_from_ps /git/10.4/storage/innobase/dict/dict0stats.cc:3074
 
    #2 0x55f8b594b204 in dict_stats_update(dict_table_t*, dict_stats_upd_option_t) /git/10.4/storage/innobase/dict/dict0stats.cc:3288
 
    #3 0x55f8b5376faf in dict_stats_init /git/10.4/storage/innobase/include/dict0stats.ic:166
 
    #4 0x55f8b538b275 in ha_innobase::open(char const*, int, unsigned int) /git/10.4/storage/innobase/handler/ha_innodb.cc:6245
 
    #5 0x55f8b4b74ef0 in handler::ha_open(TABLE*, char const*, int, unsigned int, st_mem_root*, List<String>*) /git/10.4/sql/handler.cc:2684
 
    #6 0x55f8b47357c4 in open_table_from_share(THD*, TABLE_SHARE*, st_mysql_const_lex_string const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, List<String>*) /git/10.4/sql/table.cc:3499
 
    #7 0x55f8b434c5af in open_table(THD*, TABLE_LIST*, Open_table_context*) /git/10.4/sql/sql_base.cc:1947
 
    #8 0x55f8b46ac550 in mysql_inplace_alter_table /git/10.4/sql/sql_table.cc:7654
 
    #9 0x55f8b46b8bab in mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool) /git/10.4/sql/sql_table.cc:9710
 
    #10 0x55f8b47f451d in Sql_cmd_alter_table::execute(THD*) /git/10.4/sql/sql_alter.cc:495
 
    #11 0x55f8b44b25f4 in mysql_execute_command(THD*) /git/10.4/sql/sql_parse.cc:6283
 
    #12 0x55f8b44bcca8 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /git/10.4/sql/sql_parse.cc:8063
 
    #13 0x55f8b4497dce in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /git/10.4/sql/sql_parse.cc:1847
 
    #14 0x55f8b4494f66 in do_command(THD*) /git/10.4/sql/sql_parse.cc:1392
 
    #15 0x55f8b47e5d81 in do_handle_one_connection(CONNECT*) /git/10.4/sql/sql_connect.cc:1402
 
    #16 0x55f8b47e575e in handle_one_connection /git/10.4/sql/sql_connect.cc:1308
 
    #17 0x7f41d9a786b9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76b9)
 
    #18 0x7f41d8f0d41c in clone (/lib/x86_64-linux-gnu/libc.so.6+0x10741c)

with 1 thread :

=================================================================
 
==17317==ERROR: LeakSanitizer: detected memory leaks
 
 
 
Direct leak of 4672 byte(s) in 8 object(s) allocated from:
 
    #0 0x7f02e512f602 in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x98602)
 
    #1 0x556518edfbe4 in coc_malloc /git/10.4/mysys_ssl/openssl.c:45
 
    #2 0x7f02e429bedd in CRYPTO_zalloc (/usr/lib/x86_64-linux-gnu/libcrypto.so.1.1+0x156edd)
 
 
 
SUMMARY: AddressSanitizer: 4672 byte(s) leaked in 8 allocation(s).

Comment by Marko Mäkelä [ 2018-07-26 ]

I would like to get the failure repeated on a DDL operation.
As mleich noted in MDEV-16136,

SET GLOBAL innodb_stats_persistent=off;

helps avoid most of these failures. I would first fix the failure on DDL operation, because I believe that it should be more deterministic than the failures that occur when persistent statistics are updated (at random intervals).

Comment by Matthias Leich [ 2018-08-06 ] 

I am working on some simplified RQG grammar.
 
The version direct after automatic simplification is
 
query:
 
    { $idx_table = '' ; @idx_fields = () ; "" } ALTER TABLE { my $idx_table_candidate = $prng->arrayElement($executors->[0]->baseTables()) ; $idx_table = $idx_table_candidate ; $idx_table } ADD INDEX `test_idx` USING BTREE (_field_int, { push @idx_fields, $last_field; '' } _field_int { push @idx_fields, $last_field; '' }) ; DROP INDEX `test_idx` ON { $idx_table };

Comment by Matthias Leich [ 2018-08-07 ]

My simplified RQG grammar:
thread1_init:
CREATE TABLE t1 (col1 int, col2 int) ENGINE=innodb ; CREATE TABLE t2 LIKE t1 ;
thread1:
ALTER TABLE t1 ADD INDEX test_idx (col1, col2) ; DROP INDEX test_idx ON t1 ;
thread2_init:
SELECT SLEEP(1);
thread2:
ALTER TABLE t2 ADD INDEX test_idx (col1, col2) ; DROP INDEX test_idx ON t2 ;

The RQG test setup is with
 
  --mysqld=--innodb_lock_schedule_algorithm=fcfs --mysqld=--innodb_stats_persistent=off --threads=2

Replay on binaries complied from source with ASAN:

  • 10.2.17 commit 4ddcb4eb46c62cf459936554d43351db740ba14d
  • 10.3.9 commit cb1945dd0dd244b0fb901c1b950b4ef856c1b725
  • 10.4.0 commit 01e4426a6352740973ff275eac60ddacc90da119
Comment by Matthias Leich [ 2018-08-07 ]

The file MDEV-16781.tgz is an archive with some MTR based test
and shell scripts for replaying the problem.

How to replay:
export MTR_BINDIR=<where the binaries are> like <MariaDB tree>/bld_asan
cd <MariaDB tree>/mysql-test
tar xvzf <path to>/MDEV-16781.tgz
export ASAN_OPTIONS=abort_on_errorr=1,disable_coredump=0
./MULTIRUN.sh t/MDEV-16781.test cpu

When done with testing please don't forget to run
unset MTR_BINDIR.

Comment by Marko Mäkelä [ 2018-08-13 ]

So far, I have been unable to repeat the lock_table_has() problem (or any other problem) with the attached test case. lock_table_has() seems to be redundantly calling std::vector::empty() (which in turn will call end()) and then traversing the vector in reverse direction, even though the forward direction should work equally well. Perhaps the reverse-direction iteration was employed for perceived performance reasons. The function always worked that way in InnoDB. As far as I can tell, lock_table() is mostly being called for the first row access in each SQL statement. The iteration direction should not matter for correctness. So, we could remove the empty() call, and simply keep an iteration loop in the forward direction.

While examining the code, I noticed that trx->lock.rec_pool and trx->lock.table_pool are using a fixed-size std::vector of pointers to pre-allocated storage. It would be simpler to allocate these caches as part of trx_t:

diff --git a/storage/innobase/include/trx0trx.h b/storage/innobase/include/trx0trx.h
 
index 6ed69e6c5c4..e4fab6361da 100644
 
--- a/storage/innobase/include/trx0trx.h
 
+++ b/storage/innobase/include/trx0trx.h
 
@@ -704,13 +704,19 @@ struct trx_lock_t {
 
 					only be modified by the thread that is
 
 					serving the running transaction. */
 
 
-	lock_pool_t	rec_pool;	/*!< Pre-allocated record locks */
 
+	/** Pre-allocated record locks */
 
+	struct {
 
+		ib_lock_t lock; byte pad[256];
 
+	} rec_pool[8];
 
 
-	lock_pool_t	table_pool;	/*!< Pre-allocated table locks */
 
+	/** Pre-allocated table locks */
 
+	ib_lock_t	table_pool[8];
 
 
-	ulint		rec_cached;	/*!< Next free rec lock in pool */
 
+	/** Next available rec_pool[] entry */
 
+	unsigned	rec_cached;
 
 
-	ulint		table_cached;	/*!< Next free table lock in pool */
 
+	/** Next available table_pool[] entry */
 
+	unsigned	table_cached;
 
 
 	mem_heap_t*	lock_heap;	/*!< memory heap for trx_locks;
 
 					protected by lock_sys->mutex */

Comment by Marko Mäkelä [ 2018-08-13 ]

mleich, I pushed some cleanup to bb-10.2-marko. I wonder if the problem repeats differently with that. Maybe the added assertion ut_ad(trx->lock.table_locks.empty()) in trx_create_low() would cause similar failures.

Comment by Marko Mäkelä [ 2018-08-13 ]

I was thinking if there could be a race condition scenario:

  1. lock_trx_release_locks() sees !trx_is_referenced() and returns.
  2. A thread acquires a transaction reference in trx_reference().
  3. The trx is released to the pool with n_ref > 0 and poisoned.

At the surface, this race is not possible, because trx->state and trx->n_ref are protected by trx_mutex_enter(trx), and because trx->state = TRX_STATE_COMMITTED_IN_MEMORY would prevent trx->n_ref from being incremented.

In any case, we are missing debug assertions !trx->n_ref. assert_trx_is_free() must be changed to cover that.

But, would it be possible to have a more complex race condition:

  1. A thread successfully looked up an active transaction.
  2. While the transaction is being committed, lock_trx_release_locks() sees !trx_is_referenced() and returns.
  3. The thread that got the trx looked up is executing in trx_reference().
  4. After commit, the trx is released to the pool with n_ref > 0 and poisoned.
  5. The trx is allocated from the pool for some other transaction.
  6. Now, the trx_reference() succeeds in incrementing the n_ref for the reused object, referring to a different transaction!
Comment by Marko Mäkelä [ 2018-08-16 ]

I believe that this is a duplicate of MDEV-16136, caused by a race condition between the MDEV-15030 Pool memory poisoning and unpoisoning.

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