Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.1(EOL), 10.2(EOL), 10.3(EOL), 10.4(EOL)
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
Issue Links
- links to
Activity
Hi elenst,
I couldn't reproduce (cannot find stack trace) using ASAN.
Based on doc and your example, I tried:
$ cmake . -LH|grep ASAN
|
WITH_ASAN:BOOL=ON
|
$ export ASAN_OPTIONS=abort_on_error=0:leak_check_at_exit=0
|
- Run the test (the same is obtained with {{ export ASAN_OPTIONS=abort_on_error=1:leak_check_at_exit=0}}
main.anel1 'innodb' [ pass ] 2684MTR's internal check of the test case 'main.anel1' failed.This means that the test case does not preserve the state that existedbefore the test case was executed. Most likely the test case did notdo a proper clean-up. It could also be caused by the previous test runby this thread, if the server wasn't restarted.This is the diff of the states of the servers before and after thetest case was executed:mysqltest: Logging to '/home/anel/mariadb/builds/10.2/mysql-test/var/tmp/check-mysqld_1.log'.mysqltest: Results saved in '/home/anel/mariadb/builds/10.2/mysql-test/var/tmp/check-mysqld_1.result'.mysqltest: Connecting to server localhost:16000 (socket /home/anel/mariadb/builds/10.2/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.--- /home/anel/mariadb/builds/10.2/mysql-test/var/tmp/check-mysqld_1.result 2020-11-16 15:33:28.859136651 +0100+++ /home/anel/mariadb/builds/10.2/mysql-test/var/tmp/check-mysqld_1.reject 2020-11-16 15:33:31.707168379 +0100@@ -687,6 +687,7 @@def performance_schema utf8 utf8_general_ci NULLdef test latin1 latin1_swedish_ci NULLtables_in_test+t1tables_in_mysqlmysql.columns_privmysql.column_statsmysqltest: Result length mismatchnot okAbove result is not the same as result in description?
- Inspect the error log (abort_on_error=0)
$ cat mysql-test/var/log/mysqld.1.errCURRENT_TEST: main.anel12020-11-16 15:33:28 140302458226752 [Note] /home/anel/mariadb/builds/10.2/sql/mysqld (mysqld 10.2.37-MariaDB-debug-log) starting as process 20851 .......Version: '10.2.37-MariaDB-debug-log' socket: '/home/anel/mariadb/builds/10.2/mysql-test/var/tmp/mysqld.1.sock' port: 16000 Source distribution2020-11-16 15:33:31 140486962697984 [Note] /home/anel/mariadb/builds/10.2/sql/mysqld (initiated by: root[root] @ localhost [127.0.0.1]): Normal shutdown2020-11-16 15:33:31 140487089346304 [Note] InnoDB: FTS optimize thread exiting.2020-11-16 15:33:31 140486962697984 [Note] Event Scheduler: Purging the queue. 0 events2020-11-16 15:33:31 140486962697984 [Note] InnoDB: Starting shutdown...2020-11-16 15:33:31 140487046579968 [Note] InnoDB: Dumping buffer pool(s) to /home/anel/mariadb/builds/10.2/mysql-test/var/mysqld.1/data/ib_buffer_pool2020-11-16 15:33:31 140487046579968 [Note] InnoDB: Instance 0, restricted to 128 pages due to innodb_buf_pool_dump_pct=252020-11-16 15:33:31 140487046579968 [Note] InnoDB: Buffer pool(s) dump completed at 201116 15:33:312020-11-16 15:33:33 140486962697984 [Note] InnoDB: Shutdown completed; log sequence number 16324652020-11-16 15:33:33 140486962697984 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"2020-11-16 15:33:33 140486962697984 [Note] Debug sync points hit: 10612020-11-16 15:33:33 140486962697984 [Note] Debug sync points executed: 02020-11-16 15:33:33 140486962697984 [Note] Debug sync points max active per thread: 02020-11-16 15:33:33 140486962697984 [Note] /home/anel/mariadb/builds/10.2/sql/mysqld: Shutdown complete
Or did I missing something?
Thanks
anel,
As you can see, the example in the description uses system versioning. It is not applicable to 10.2.
- Patch 42bad56aab25db4a0 allowed following output:
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019sys_vars.replicate_rewrite_db [ pass ] 22***Warnings generated in error logs during shutdown after running tests: sys_vars.replicate_rewrite_dbWarning: Memory not freed: 32==64078==ERROR: LeakSanitizer: detected memory leaksSUMMARY: AddressSanitizer: 32 byte(s) leaked in 1 allocation(s).Attempting backtrace. You can use the following information to find out--------------------------------------------------------------------------The servers were restarted 0 timesSpent 0.022 of 5 seconds executing testcasesWarnings in log: All 1 tests were successful.
- Example with the suggested patch PR 2251:
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019sys_vars.replicate_rewrite_db [ pass ] 26***Warnings generated in error logs during shutdown after running tests: sys_vars.replicate_rewrite_dbWarning: Memory not freed: 32==67812==ERROR: LeakSanitizer: detected memory leaksDirect leak of 32 byte(s) in 1 object(s) allocated from:#0 0x7f6f07a40808 in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cc:144#1 0x560e474cba0c in my_malloc /home/anel/mariadb/server/src/10.11-source/mysys/my_malloc.c:90#2 0x560e45508e0f in Rpl_filter::add_string_pair_list(char const*) /home/anel/mariadb/server/src/10.11-source/sql/rpl_filter.cc:546#3 0x560e45509283 in Rpl_filter::add_rewrite_db(char const*) /home/anel/mariadb/server/src/10.11-source/sql/rpl_filter.cc:604#4 0x560e455074b1 in Rpl_filter::parse_filter_rule(char const*, int (Rpl_filter::*)(char const*)) /home/anel/mariadb/server/src/10.11-source/sql/rpl_filter.cc:313#5 0x560e4550972b in Rpl_filter::set_rewrite_db(char const*) /home/anel/mariadb/server/src/10.11-source/sql/rpl_filter.cc:628#6 0x560e45cde299 in Sys_var_rpl_filter::set_filter_value(char const*, Master_info*) /home/anel/mariadb/server/src/10.11-source/sql/sys_vars.cc:5421#7 0x560e45cde179 in Sys_var_rpl_filter::global_update(THD*, set_var*) /home/anel/mariadb/server/src/10.11-source/sql/sys_vars.cc:5403#8 0x560e455139af in sys_var::update(THD*, set_var*) /home/anel/mariadb/server/src/10.11-source/sql/set_var.cc:207#9 0x560e45518445 in set_var::update(THD*) /home/anel/mariadb/server/src/10.11-source/sql/set_var.cc:863#10 0x560e4551781c in sql_set_variables(THD*, List<set_var_base>*, bool) /home/anel/mariadb/server/src/10.11-source/sql/set_var.cc:745#11 0x560e457ea27f in mysql_execute_command(THD*, bool) /home/anel/mariadb/server/src/10.11-source/sql/sql_parse.cc:5034#12 0x560e457fe656 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /home/anel/mariadb/server/src/10.11-source/sql/sql_parse.cc:8035#13 0x560e457d4730 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /home/anel/mariadb/server/src/10.11-source/sql/sql_parse.cc:1894#14 0x560e457d14b6 in do_command(THD*, bool) /home/anel/mariadb/server/src/10.11-source/sql/sql_parse.cc:1407#15 0x560e45c8b137 in do_handle_one_connection(CONNECT*, bool) /home/anel/mariadb/server/src/10.11-source/sql/sql_connect.cc:1418#16 0x560e45c8a9c3 in handle_one_connection /home/anel/mariadb/server/src/10.11-source/sql/sql_connect.cc:1312#17 0x560e468bb4b5 in pfs_spawn_thread /home/anel/mariadb/server/src/10.11-source/storage/perfschema/pfs.cc:2201#18 0x7f6f074b7608 in start_thread /build/glibc-SzIz7B/glibc-2.31/nptl/pthread_create.c:477SUMMARY: AddressSanitizer: 32 byte(s) leaked in 1 allocation(s).Attempting backtrace. You can use the following information to find out--------------------------------------------------------------------------The servers were restarted 0 timesSpent 0.026 of 5 seconds executing testcasesWarnings in log: All 1 tests were successful.Errors/warnings were found in logfiles during server shutdown after running thefollowing sequence(s) of tests:sys_vars.replicate_rewrite_dbmysql-test-run: *** ERROR: There where errors/warnings in server logs after running test cases.
I'll close the issue for versions where the bug was fixed. The PR is an improvement, that could be considered, but not a fix as such.
Is mysqltest checking the return value of the server process? If I remember correctly, LeakSanitizer (which is enabled as part of AddressSanitizer) should return 42 if leaks are detected. Perhaps all sanitizers would cause the process to exit with a nonzero status if any error was noticed?