Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-21014

MTR does not detect [A,M,T,L,UB]SAN errors which happen upon server shutdown

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open (View Workflow)
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 10.1, 10.2, 10.3, 10.4
    • Fix Version/s: 10.1, 10.2, 10.3, 10.4
    • Component/s: Tests
    • Labels:
      None

      Description

      Example (applicable as of 10.4 c24ec3ce, it might stop being an example after the underlying server bug is fixed):

      --source include/have_innodb.inc
       
      CREATE TABLE t1 ( 
       col_timestamp TIMESTAMP,
       col_varchar VARBINARY(1000),
       col_bit BIT(15),
       col_datetime DATETIME,
       col_blob BLOB,
       col_year YEAR,
       col_int TINYINT,
       col_dec DECIMAL(5,2),
       col_char CHAR(125),
       col_time TIME,
       col_date DATE,
       pk INT,
       PRIMARY KEY(pk)
       ) ENGINE=InnoDB ;
       
      INSERT INTO t1 VALUES
       ('2017-10-15 10:40:31','foo',NULL,'1981-06-28 00:00:00','bar',1977,3,0.1,'foobar','07:54:20','2029-06-13',1) ;
       
      --connect (con1,localhost,root,,)
      --send
          ALTER TABLE t1 ADD COLUMN s BIGINT UNSIGNED AS ROW START, ADD COLUMN e BIGINT UNSIGNED AS ROW END, ADD PERIOD FOR SYSTEM_TIME(s,e), WITH SYSTEM VERSIONING;
       
      --connection default
      --source include/restart_mysqld.inc
      

      Test output

      ...
      ALTER TABLE t1 ADD COLUMN s BIGINT UNSIGNED AS ROW START, ADD COLUMN e BIGINT UNSIGNED AS ROW END, ADD PERIOD FOR SYSTEM_TIME(s,e), WITH SYSTEM VERSIONING;
      connection default;
      # restart
      bug2.4772 'innodb'                       [ pass ]   2708
       
      MTR's internal check of the test case 'bug2.4772' failed.
      This means that the test case does not preserve the state that existed
      before the test case was executed.  Most likely the test case did not
      do a proper clean-up. It could also be caused by the previous test run
      by this thread, if the server wasn't restarted.
      This is the diff of the states of the servers before and after the
      test case was executed:
      mysqltest: Logging to '/data/bld/10.4-asan-nightly/mysql-test/var/tmp/check-mysqld_1.log'.
      mysqltest: Results saved in '/data/bld/10.4-asan-nightly/mysql-test/var/tmp/check-mysqld_1.result'.
      mysqltest: Connecting to server localhost:16020 (socket /data/bld/10.4-asan-nightly/mysql-test/var/tmp/mysqld.1.sock) as 'root', connection 'default', attempt 0 ...
      mysqltest: ... Connected.
      mysqltest: Start processing test commands from './include/check-testcase.test' ...
      mysqltest: ... Done processing test commands.
      --- /data/bld/10.4-asan-nightly/mysql-test/var/tmp/check-mysqld_1.result	2019-11-08 17:47:53.855973236 +0200
      +++ /data/bld/10.4-asan-nightly/mysql-test/var/tmp/check-mysqld_1.reject	2019-11-08 17:47:56.931935331 +0200
      @@ -727,6 +727,7 @@
       def	performance_schema	utf8	utf8_general_ci	NULL
       def	test	latin1	latin1_swedish_ci	NULL
       tables_in_test
      +t1
       tables_in_mysql
       mysql.columns_priv
       mysql.column_stats
      @@ -1101,3 +1102,4 @@
       partition	1.0	DISABLED	STORAGE ENGINE	100410.0	NULL	NULL	Mikael Ronstrom, MySQL AB	Partition Storage Engine Helper	GPL	OFF	Stable	1.0
       VARIABLE_NAME	VARIABLE_VALUE
       DEBUG_SYNC	ON - current signal: ''
      +#sql-36ac_a.frm
       
      mysqltest: Result length mismatch
       
      not ok
      

      Error log

      CURRENT_TEST: bug2.4772
      2019-11-08 17:47:53 0 [Note] /data/bld/10.4-asan-nightly/bin/mysqld (mysqld 10.4.10-MariaDB-debug-log) starting as process 13996 ...
      2019-11-08 17:47:53 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4190)
      ...
      Version: '10.4.10-MariaDB-debug-log'  socket: '/data/bld/10.4-asan-nightly/mysql-test/var/tmp/mysqld.1.sock'  port: 16020  Source distribution
      2019-11-08 17:47:54 0 [Note] /data/bld/10.4-asan-nightly/bin/mysqld (initiated by: root[root] @ localhost []): Normal shutdown
      2019-11-08 17:47:54 0 [Note] Event Scheduler: Purging the queue. 0 events
      2019-11-08 17:47:54 0 [Note] InnoDB: FTS optimize thread exiting.
      =================================================================
      ==13996==ERROR: AddressSanitizer: heap-use-after-free on address 0x619000049b80 at pc 0x563190e29597 bp 0x7f17656e3790 sp 0x7f17656e3788
      WRITE of size 8 at 0x619000049b80 thread T28
          #0 0x563190e29596 in trx_update_mod_tables_timestamp /data/src/10.4/storage/innobase/trx/trx0trx.cc:1288
          #1 0x563190e2aab1 in trx_commit_in_memory /data/src/10.4/storage/innobase/trx/trx0trx.cc:1415
          #2 0x563190e2d04a in trx_commit_low(trx_t*, mtr_t*) /data/src/10.4/storage/innobase/trx/trx0trx.cc:1618
          #3 0x563190e2d173 in trx_commit(trx_t*) /data/src/10.4/storage/innobase/trx/trx0trx.cc:1642
          #4 0x563190e2dbda in trx_commit_for_mysql(trx_t*) /data/src/10.4/storage/innobase/trx/trx0trx.cc:1788
          #5 0x563190ab0579 in rollback_inplace_alter_table(Alter_inplace_info*, TABLE const*, row_prebuilt_t*) (/data/bld/10.4-asan-nightly/bin/mysqld+0x1fa5579)
          #6 0x563190a8dd3b in ha_innobase::commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) /data/src/10.4/storage/innobase/handler/handler0alter.cc:10713
          #7 0x5631904c44b2 in handler::ha_commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) /data/src/10.4/sql/handler.cc:4567
          #8 0x56318ff6c413 in mysql_inplace_alter_table /data/src/10.4/sql/sql_table.cc:7871
          #9 0x56318ff7a01f 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) /data/src/10.4/sql/sql_table.cc:10094
          #10 0x5631900d0f49 in Sql_cmd_alter_table::execute(THD*) /data/src/10.4/sql/sql_alter.cc:508
          #11 0x56318fd561b4 in mysql_execute_command(THD*) /data/src/10.4/sql/sql_parse.cc:6099
          #12 0x56318fd60bad in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.4/sql/sql_parse.cc:7898
          #13 0x56318fd39e6a in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.4/sql/sql_parse.cc:1842
          #14 0x56318fd36d5e in do_command(THD*) /data/src/10.4/sql/sql_parse.cc:1360
          #15 0x5631900bbc02 in do_handle_one_connection(CONNECT*) /data/src/10.4/sql/sql_connect.cc:1412
          #16 0x5631900bb5b6 in handle_one_connection /data/src/10.4/sql/sql_connect.cc:1316
          #17 0x56319151addd in pfs_spawn_thread /data/src/10.4/storage/perfschema/pfs.cc:1862
          #18 0x7f177d1574a3 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x74a3)
          #19 0x7f177b69ed0e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe8d0e)
       
      0x619000049b80 is located 1024 bytes inside of 1048-byte region [0x619000049780,0x619000049b98)
      freed by thread T28 here:
          #0 0x7f177d42ea10 in free (/usr/lib/x86_64-linux-gnu/libasan.so.3+0xc1a10)
          #1 0x563190b8ffa1 in mem_heap_block_free(mem_block_info_t*, mem_block_info_t*) /data/src/10.4/storage/innobase/mem/mem0mem.cc:426
          #2 0x563190fde8b7 in mem_heap_free /data/src/10.4/storage/innobase/include/mem0mem.ic:437
          #3 0x563190fe0f35 in dict_mem_table_free(dict_table_t*) /data/src/10.4/storage/innobase/dict/dict0mem.cc:234
          #4 0x563190fa4b72 in dict_sys_t::remove(dict_table_t*, bool, bool) /data/src/10.4/storage/innobase/dict/dict0dict.cc:1733
          #5 0x563190cd2cd7 in row_drop_table_from_cache /data/src/10.4/storage/innobase/row/row0mysql.cc:3275
          #6 0x563190cd4cc2 in row_drop_table_for_mysql(char const*, trx_t*, enum_sql_command, bool, bool) /data/src/10.4/storage/innobase/row/row0mysql.cc:3751
          #7 0x563190cb0d10 in row_merge_drop_table(trx_t*, dict_table_t*) /data/src/10.4/storage/innobase/row/row0merge.cc:4499
          #8 0x563190f9d49d in dict_table_close_and_drop(trx_t*, dict_table_t*) /data/src/10.4/storage/innobase/dict/dict0dict.cc:396
          #9 0x563190aaf7d6 in rollback_inplace_alter_table(Alter_inplace_info*, TABLE const*, row_prebuilt_t*) (/data/bld/10.4-asan-nightly/bin/mysqld+0x1fa47d6)
          #10 0x563190a8dd3b in ha_innobase::commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) /data/src/10.4/storage/innobase/handler/handler0alter.cc:10713
          #11 0x5631904c44b2 in handler::ha_commit_inplace_alter_table(TABLE*, Alter_inplace_info*, bool) /data/src/10.4/sql/handler.cc:4567
          #12 0x56318ff6c413 in mysql_inplace_alter_table /data/src/10.4/sql/sql_table.cc:7871
          #13 0x56318ff7a01f 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) /data/src/10.4/sql/sql_table.cc:10094
          #14 0x5631900d0f49 in Sql_cmd_alter_table::execute(THD*) /data/src/10.4/sql/sql_alter.cc:508
          #15 0x56318fd561b4 in mysql_execute_command(THD*) /data/src/10.4/sql/sql_parse.cc:6099
          #16 0x56318fd60bad in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.4/sql/sql_parse.cc:7898
          #17 0x56318fd39e6a in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.4/sql/sql_parse.cc:1842
          #18 0x56318fd36d5e in do_command(THD*) /data/src/10.4/sql/sql_parse.cc:1360
          #19 0x5631900bbc02 in do_handle_one_connection(CONNECT*) /data/src/10.4/sql/sql_connect.cc:1412
          #20 0x5631900bb5b6 in handle_one_connection /data/src/10.4/sql/sql_connect.cc:1316
          #21 0x56319151addd in pfs_spawn_thread /data/src/10.4/storage/perfschema/pfs.cc:1862
          #22 0x7f177d1574a3 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x74a3)
       
      previously allocated by thread T28 here:
          #0 0x7f177d42ed28 in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.3+0xc1d28)
          #1 0x563190b8f4f1 in mem_heap_create_block_func(mem_block_info_t*, unsigned long, char const*, unsigned int, unsigned long) /data/src/10.4/storage/innobase/mem/mem0mem.cc:280
          #2 0x563190b8fc56 in mem_heap_add_block(mem_block_info_t*, unsigned long) /data/src/10.4/storage/innobase/mem/mem0mem.cc:386
          #3 0x563190fde532 in mem_heap_alloc /data/src/10.4/storage/innobase/include/mem0mem.ic:203
          #4 0x563190fde337 in mem_heap_zalloc /data/src/10.4/storage/innobase/include/mem0mem.ic:170
          #5 0x563190fe0376 in dict_mem_table_create(char const*, fil_space_t*, unsigned long, unsigned long, unsigned long, unsigned long) /data/src/10.4/storage/innobase/dict/dict0mem.cc:146
          #6 0x563190a70196 in prepare_inplace_alter_table_dict /data/src/10.4/storage/innobase/handler/handler0alter.cc:6332
          #7 0x563190a80e5f in ha_innobase::prepare_inplace_alter_table(TABLE*, Alter_inplace_info*) /data/src/10.4/storage/innobase/handler/handler0alter.cc:8150
          #8 0x5631904c41b5 in handler::ha_prepare_inplace_alter_table(TABLE*, Alter_inplace_info*) /data/src/10.4/sql/handler.cc:4547
          #9 0x56318ff6b78c in mysql_inplace_alter_table /data/src/10.4/sql/sql_table.cc:7694
          #10 0x56318ff7a01f 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) /data/src/10.4/sql/sql_table.cc:10094
          #11 0x5631900d0f49 in Sql_cmd_alter_table::execute(THD*) /data/src/10.4/sql/sql_alter.cc:508
          #12 0x56318fd561b4 in mysql_execute_command(THD*) /data/src/10.4/sql/sql_parse.cc:6099
          #13 0x56318fd60bad in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.4/sql/sql_parse.cc:7898
          #14 0x56318fd39e6a in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.4/sql/sql_parse.cc:1842
          #15 0x56318fd36d5e in do_command(THD*) /data/src/10.4/sql/sql_parse.cc:1360
          #16 0x5631900bbc02 in do_handle_one_connection(CONNECT*) /data/src/10.4/sql/sql_connect.cc:1412
          #17 0x5631900bb5b6 in handle_one_connection /data/src/10.4/sql/sql_connect.cc:1316
          #18 0x56319151addd in pfs_spawn_thread /data/src/10.4/storage/perfschema/pfs.cc:1862
          #19 0x7f177d1574a3 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x74a3)
       
      Thread T28 created by T0 here:
          #0 0x7f177d39df59 in __interceptor_pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.3+0x30f59)
          #1 0x56319151b1ca in spawn_thread_v1 /data/src/10.4/storage/perfschema/pfs.cc:1912
          #2 0x56318fa91bd8 in inline_mysql_thread_create /data/src/10.4/include/mysql/psi/mysql_thread.h:1268
          #3 0x56318faa617c in create_thread_to_handle_connection(CONNECT*) /data/src/10.4/sql/mysqld.cc:6234
          #4 0x56318faa685f in create_new_thread(CONNECT*) /data/src/10.4/sql/mysqld.cc:6304
          #5 0x56318faa6bea in handle_accepted_socket(st_mysql_socket, st_mysql_socket) /data/src/10.4/sql/mysqld.cc:6402
          #6 0x56318faa783c in handle_connections_sockets() /data/src/10.4/sql/mysqld.cc:6560
          #7 0x56318faa59fd in mysqld_main(int, char**) /data/src/10.4/sql/mysqld.cc:5892
          #8 0x56318fa8fabf in main /data/src/10.4/sql/main.cc:25
          #9 0x7f177b5d62e0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202e0)
       
      SUMMARY: AddressSanitizer: heap-use-after-free /data/src/10.4/storage/innobase/trx/trx0trx.cc:1288 in trx_update_mod_tables_timestamp
      Shadow bytes around the buggy address:
        0x0c3280001320: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
        0x0c3280001330: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
        0x0c3280001340: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
        0x0c3280001350: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
        0x0c3280001360: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
      =>0x0c3280001370:[fd]fd fd fa fa fa fa fa fa fa fa fa fa fa fa fa
        0x0c3280001380: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
        0x0c3280001390: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
        0x0c32800013a0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
        0x0c32800013b0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
        0x0c32800013c0: 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
        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
        Left alloca redzone:     ca
        Right alloca redzone:    cb
      ==13996==ABORTING
      2019-11-08 17:47:55 0 [Note] /data/bld/10.4-asan-nightly/bin/mysqld (mysqld 10.4.10-MariaDB-debug-log) starting as process 14039 ...
      2019-11-08 17:47:55 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4190)
      2019-11-08 17:47:55 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
      2019-11-08 17:47:55 0 [Warning] setrlimit could not change the size of core files to 'infinity';  We may not be able to generate a core file on signals
      2019-11-08 17:47:55 0 [Note] Plugin 'partition' is disabled.
      2019-11-08 17:47:55 0 [Note] Plugin 'SEQUENCE' is disabled.
      2019-11-08 17:47:55 0 [Note] InnoDB: Using Linux native AIO
      2019-11-08 17:47:55 0 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
      2019-11-08 17:47:55 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
      2019-11-08 17:47:55 0 [Note] InnoDB: Uses event mutexes
      2019-11-08 17:47:55 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
      2019-11-08 17:47:55 0 [Note] InnoDB: Number of pools: 1
      2019-11-08 17:47:55 0 [Note] InnoDB: Using SSE2 crc32 instructions
      2019-11-08 17:47:55 0 [Note] mysqld: O_TMPFILE is not supported on /data/bld/10.4-asan-nightly/mysql-test/var/tmp/mysqld.1 (disabling future attempts)
      2019-11-08 17:47:55 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
      2019-11-08 17:47:55 0 [Note] InnoDB: Completed initialization of buffer pool
      2019-11-08 17:47:55 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
      2019-11-08 17:47:55 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=152140
      2019-11-08 17:47:55 0 [Note] InnoDB: Starting final batch to recover 14 pages from redo log.
      2019-11-08 17:47:56 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
      2019-11-08 17:47:56 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
      2019-11-08 17:47:56 0 [Note] InnoDB: Creating shared tablespace for temporary tables
      2019-11-08 17:47:56 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
      2019-11-08 17:47:56 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
      2019-11-08 17:47:56 0 [Note] InnoDB: 10.4.10 started; log sequence number 163295; transaction id 47
      2019-11-08 17:47:56 0 [Note] InnoDB: Loading buffer pool(s) from /data/bld/10.4-asan-nightly/mysql-test/var/mysqld.1/data/ib_buffer_pool
      2019-11-08 17:47:56 0 [Note] InnoDB: Buffer pool(s) load completed at 191108 17:47:56
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_CMP' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'FEEDBACK' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'user_variables' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
      2019-11-08 17:47:56 0 [Note] Plugin 'unix_socket' is disabled.
      2019-11-08 17:47:56 0 [Warning] /data/bld/10.4-asan-nightly/bin/mysqld: unknown option '--loose-pam-debug'
      2019-11-08 17:47:56 0 [Warning] /data/bld/10.4-asan-nightly/bin/mysqld: unknown option '--loose-aria'
      2019-11-08 17:47:56 0 [Note] Server socket created on IP: '127.0.0.1'.
      2019-11-08 17:47:56 0 [Note] Reading of all Master_info entries succeeded
      2019-11-08 17:47:56 0 [Note] Added new Master_info '' to hash table
      2019-11-08 17:47:56 0 [Note] /data/bld/10.4-asan-nightly/bin/mysqld: ready for connections.
      Version: '10.4.10-MariaDB-debug-log'  socket: '/data/bld/10.4-asan-nightly/mysql-test/var/tmp/mysqld.1.sock'  port: 16020  Source distribution
      2019-11-08 17:47:56 0 [Note] /data/bld/10.4-asan-nightly/bin/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown
      2019-11-08 17:47:56 0 [Note] Event Scheduler: Purging the queue. 0 events
      2019-11-08 17:47:56 0 [Note] InnoDB: FTS optimize thread exiting.
      2019-11-08 17:47:57 0 [Note] InnoDB: Starting shutdown...
      2019-11-08 17:47:57 0 [Note] InnoDB: Dumping buffer pool(s) to /data/bld/10.4-asan-nightly/mysql-test/var/mysqld.1/data/ib_buffer_pool
      2019-11-08 17:47:57 0 [Note] InnoDB: Instance 0, restricted to 123 pages due to innodb_buf_pool_dump_pct=25
      2019-11-08 17:47:57 0 [Note] InnoDB: Buffer pool(s) dump completed at 191108 17:47:57
      2019-11-08 17:47:58 0 [Note] InnoDB: Shutdown completed; log sequence number 163474; transaction id 47
      2019-11-08 17:47:58 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
      2019-11-08 17:47:58 0 [Note] Debug sync points hit:                   1317
      2019-11-08 17:47:58 0 [Note] Debug sync points executed:              0
      2019-11-08 17:47:58 0 [Note] Debug sync points max active per thread: 0
      2019-11-08 17:47:58 0 [Note] /data/bld/10.4-asan-nightly/bin/mysqld: Shutdown complete
      

      Providing explicit ASAN_OPTIONS="abort_on_error=1" helps a bit, but only to the extent that it causes SIGABRT, upon which the line Attempting backtrace is printed, and that is actually noticed by MTR:

      Test output with ASAN_OPTIONS=abort_on_error=1"

      ...
      ALTER TABLE t1 ADD COLUMN s BIGINT UNSIGNED AS ROW START, ADD COLUMN e BIGINT UNSIGNED AS ROW END, ADD PERIOD FOR SYSTEM_TIME(s,e), WITH SYSTEM VERSIONING;
      connection default;
      # restart
      bug2.4772 'innodb'                       [ fail ]  Found warnings/errors in server log file!
              Test ended at 2019-11-08 17:51:49
      line
      Attempting backtrace. You can use the following information to find out
      ^ Found warnings in /data/bld/10.4-asan-nightly/mysql-test/var/log/mysqld.1.err
      ok
      

      Still, it says nothing about actual ASAN errors.

      The simplest fix would be to add a line to MTR warning patterns:

      diff --git a/data/src/10.4/mysql-test/mysql-test-run.pl b/mysql-test-run.pl
      index 6d4549d..a1b11c3 100755
      --- a/data/src/10.4/mysql-test/mysql-test-run.pl
      +++ b/mysql-test-run.pl
      @@ -4651,6 +4651,7 @@ sub extract_warning_lines ($$) {
            qr/missing DBUG_RETURN/,
            qr/Attempting backtrace/,
            qr/Assertion .* failed/,
      +     qr/ERROR: AddressSanitizer/,
           );
         # These are taken from the include/mtr_warnings.sql global suppression
         # list. They occur delayed, so they can be parsed during shutdown rather
      

      Then the output would look like this:

      Test output without explicit ASAN_OPTIONS

      ...
      ALTER TABLE t1 ADD COLUMN s BIGINT UNSIGNED AS ROW START, ADD COLUMN e BIGINT UNSIGNED AS ROW END, ADD PERIOD FOR SYSTEM_TIME(s,e), WITH SYSTEM VERSIONING;
      connection default;
      # restart
      bug2.4772 'innodb'                       [ fail ]  Found warnings/errors in server log file!
              Test ended at 2019-11-08 17:57:45
      line
      ==15059==ERROR: AddressSanitizer: heap-use-after-free on address 0x619000049b80 at pc 0x56250ff56597 bp 0x7f135cf49790 sp 0x7f135cf49788
      ^ Found warnings in /data/bld/10.4-asan-nightly/mysql-test/var/log/mysqld.1.err
      ok
      

      or

      Test output with ASAN_OPTIONS="abort_on_error=1"

      ...
      ALTER TABLE t1 ADD COLUMN s BIGINT UNSIGNED AS ROW START, ADD COLUMN e BIGINT UNSIGNED AS ROW END, ADD PERIOD FOR SYSTEM_TIME(s,e), WITH SYSTEM VERSIONING;
      connection default;
      # restart
      bug2.4772 'innodb'                       [ fail ]  Found warnings/errors in server log file!
              Test ended at 2019-11-08 17:56:44
      line
      ==14876==ERROR: AddressSanitizer: heap-use-after-free on address 0x61900006ee80 at pc 0x55875d2ae597 bp 0x7f728dad6790 sp 0x7f728dad6788
      Attempting backtrace. You can use the following information to find out
      ^ Found warnings in /data/bld/10.4-asan-nightly/mysql-test/var/log/mysqld.1.err
      ok
      

      But possibly you want to print more in the test output than just that, so I'm passing it over.

        Attachments

          Activity

            People

            Assignee:
            kevg Eugene Kosov
            Reporter:
            elenst Elena Stepanova
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Dates

              Created:
              Updated: