Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.2.7, 10.3.1
-
None
-
10.2.12
Description
|
10.2 0c4d11e8199f4c7a with the injection below |
mysqld: /data/src/10.2-bug/storage/innobase/rem/rem0rec.cc:2183: trx_id_t rec_get_trx_id(const rec_t*, const dict_index_t*): Assertion `(fil_page_get_type(page) == 17855 || fil_page_get_type(page) == 17854)' failed.
|
171116 17:54:16 [ERROR] mysqld got signal 6 ;
|
|
|
#7 0x00007f046b4c1ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6
|
#8 0x0000563d6fa15548 in rec_get_trx_id (rec=0x7f0414010c7e "\200", index=0x7f041012fc88) at /data/src/10.2-bug/storage/innobase/rem/rem0rec.cc:2183
|
#9 0x0000563d6fa846bd in row_sel_sec_rec_is_for_clust_rec (sec_rec=0x7f046510407d "\200", sec_index=0x7f0410039ca8, clust_rec=0x7f0414010c7e "\200", clust_index=0x7f041012fc88, thr=0x7f041401e9a0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:188
|
#10 0x0000563d6fa8b1bf in row_sel_get_clust_rec_for_mysql (prebuilt=0x7f041401e288, sec_index=0x7f0410039ca8, rec=0x7f046510407d "\200", thr=0x7f041401e9a0, out_rec=0x7f04640e1aa8, offsets=0x7f04640e1ac8, offset_heap=0x7f04640e1ac0, vrow=0x0, mtr=0x7f04640e25c0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:3522
|
#11 0x0000563d6fa8f023 in row_search_mvcc (buf=0x7f041401de28 "\377", mode=PAGE_CUR_G, prebuilt=0x7f041401e288, match_mode=0, direction=0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:5242
|
#12 0x0000563d6f91c233 in ha_innobase::index_read (this=0x7f041401c6d8, buf=0x7f041401de28 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /data/src/10.2-bug/storage/innobase/handler/ha_innodb.cc:9823
|
#13 0x0000563d6f91d5d6 in ha_innobase::index_first (this=0x7f041401c6d8, buf=0x7f041401de28 "\377") at /data/src/10.2-bug/storage/innobase/handler/ha_innodb.cc:10261
|
#14 0x0000563d6f60a63b in handler::ha_index_first (this=0x7f041401c6d8, buf=0x7f041401de28 "\377") at /data/src/10.2-bug/sql/handler.cc:2717
|
#15 0x0000563d6f77460f in rr_index_first (info=0x7f0414013c30) at /data/src/10.2-bug/sql/records.cc:401
|
#16 0x0000563d6f4058e2 in join_init_read_record (tab=0x7f0414013b68) at /data/src/10.2-bug/sql/sql_select.cc:19560
|
#17 0x0000563d6f5217fe in JOIN_TAB_SCAN::open (this=0x7f0414014988) at /data/src/10.2-bug/sql/sql_join_cache.cc:3339
|
#18 0x0000563d6f51fd0c in JOIN_CACHE::join_matching_records (this=0x7f0414014858, skip_last=false) at /data/src/10.2-bug/sql/sql_join_cache.cc:2250
|
#19 0x0000563d6f51f890 in JOIN_CACHE::join_records (this=0x7f0414014858, skip_last=false) at /data/src/10.2-bug/sql/sql_join_cache.cc:2087
|
#20 0x0000563d6f40330a in sub_select_cache (join=0x7f0414012150, join_tab=0x7f0414013b68, end_of_records=true) at /data/src/10.2-bug/sql/sql_select.cc:18417
|
#21 0x0000563d6f40351c in sub_select (join=0x7f0414012150, join_tab=0x7f04140137b8, end_of_records=true) at /data/src/10.2-bug/sql/sql_select.cc:18589
|
#22 0x0000563d6f402d32 in do_select (join=0x7f0414012150, procedure=0x0) at /data/src/10.2-bug/sql/sql_select.cc:18184
|
#23 0x0000563d6f3dd3e3 in JOIN::exec_inner (this=0x7f0414012150) at /data/src/10.2-bug/sql/sql_select.cc:3514
|
#24 0x0000563d6f3dc892 in JOIN::exec (this=0x7f0414012150) at /data/src/10.2-bug/sql/sql_select.cc:3309
|
#25 0x0000563d6f3dda5b in mysql_select (thd=0x7f0414000b00, tables=0x7f04140113d0, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7f0414012130, unit=0x7f04140046a0, select_lex=0x7f0414004dd8) at /data/src/10.2-bug/sql/sql_select.cc:3709
|
#26 0x0000563d6f3d22bc in handle_select (thd=0x7f0414000b00, lex=0x7f04140045d8, result=0x7f0414012130, setup_tables_done_option=0) at /data/src/10.2-bug/sql/sql_select.cc:373
|
#27 0x0000563d6f39e0fc in execute_sqlcom_select (thd=0x7f0414000b00, all_tables=0x7f04140113d0) at /data/src/10.2-bug/sql/sql_parse.cc:6428
|
#28 0x0000563d6f394159 in mysql_execute_command (thd=0x7f0414000b00) at /data/src/10.2-bug/sql/sql_parse.cc:3462
|
#29 0x0000563d6f3a1abe in mysql_parse (thd=0x7f0414000b00, rawbuf=0x7f0414011088 "SELECT a1.f1, a1.f2 FROM t1 AS a1, t1 AS a2", length=43, parser_state=0x7f04640e4200, is_com_multi=false, is_next_command=false) at /data/src/10.2-bug/sql/sql_parse.cc:7869
|
#30 0x0000563d6f38fa4a in dispatch_command (command=COM_QUERY, thd=0x7f0414000b00, packet=0x7f04140088a1 "", packet_length=43, is_com_multi=false, is_next_command=false) at /data/src/10.2-bug/sql/sql_parse.cc:1805
|
#31 0x0000563d6f38e3a8 in do_command (thd=0x7f0414000b00) at /data/src/10.2-bug/sql/sql_parse.cc:1360
|
#32 0x0000563d6f4db98d in do_handle_one_connection (connect=0x563d73106c40) at /data/src/10.2-bug/sql/sql_connect.cc:1354
|
#33 0x0000563d6f4db71a in handle_one_connection (arg=0x563d73106c40) at /data/src/10.2-bug/sql/sql_connect.cc:1260
|
#34 0x0000563d6f8f8e1a in pfs_spawn_thread (arg=0x563d731a8ad0) at /data/src/10.2-bug/storage/perfschema/pfs.cc:1863
|
#35 0x00007f046d198494 in start_thread (arg=0x7f04640e5700) at pthread_create.c:333
|
#36 0x00007f046b57e93f in clone () from /lib/x86_64-linux-gnu/libc.so.6
|
The problem happens in concurrent tests on a normal server (without the sleep below), but very rarely. With the delay, for me it's reproducible reliably enough, although probably not 100%. I suppose it might require different sleep times on other machines.
diff --git a/storage/innobase/rem/rem0rec.cc b/storage/innobase/rem/rem0rec.cc
|
index 37bf6e6..08cf8b8 100644
|
--- a/storage/innobase/rem/rem0rec.cc
|
+++ b/storage/innobase/rem/rem0rec.cc
|
@@ -2179,6 +2179,7 @@ rec_get_trx_id(
|
ulint* offsets = offsets_;
|
|
ut_ad(trx_id_col <= MAX_REF_PARTS);
|
+ my_sleep(200000);
|
ut_ad(fil_page_index_page_check(page));
|
ut_ad(mach_read_from_8(page + PAGE_HEADER + PAGE_INDEX_ID)
|
== index->id);
|
Run with --mysqld=--innodb_locks_unsafe_for_binlog and, if it's not reproducible right away, with --repeat=N.
--source include/have_innodb.inc
|
|
|
CREATE TABLE t1 (f1 INT NOT NULL AUTO_INCREMENT PRIMARY KEY, f2 INT) ENGINE=InnoDB; |
INSERT IGNORE INTO t1 VALUES (5,9),(NULL,3),(NULL,0),(4,105),(197,66),(0,0); |
ALTER TABLE t1 ADD KEY (f1); |
|
|
--connect (con1,localhost,root,,test)
|
|
|
--connection default
|
--send
|
INSERT IGNORE INTO t1 SELECT f1, f2 FROM t1 ORDER BY f1, f2 LIMIT 4; |
|
|
--connection con1
|
DELETE FROM t1 ORDER BY f1, f2 LIMIT 1; |
SELECT a1.f1, a1.f2 FROM t1 AS a1, t1 AS a2; |
--disconnect con1
|
|
|
--connection default
|
--reap
|
|
|
# Cleanup
|
DROP TABLE t1; |
Reproducible on 10.2 and 10.3. I've never encountered it on 10.1 so far.
|
10.2 0c4d11e8199f4 ASAN |
=================================================================
|
==23938==ERROR: AddressSanitizer: heap-buffer-overflow on address 0x613000124018 at pc 0x55b828cf4a44 bp 0x7f860123dd40 sp 0x7f860123dd38
|
READ of size 1 at 0x613000124018 thread T28
|
#0 0x55b828cf4a43 in mach_read_from_2 /data/src/10.2-asan/storage/innobase/include/mach0data.ic:84
|
#1 0x55b828d5c961 in fil_page_get_type(unsigned char const*) /data/src/10.2-asan/storage/innobase/include/fil0fil.h:1322
|
#2 0x55b828f014d7 in rec_get_trx_id(unsigned char const*, dict_index_t const*) /data/src/10.2-asan/storage/innobase/rem/rem0rec.cc:2183
|
#3 0x55b828fd352d in row_sel_sec_rec_is_for_clust_rec /data/src/10.2-asan/storage/innobase/row/row0sel.cc:188
|
#4 0x55b828fe0492 in row_sel_get_clust_rec_for_mysql /data/src/10.2-asan/storage/innobase/row/row0sel.cc:3522
|
#5 0x55b828fe72b2 in row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long) /data/src/10.2-asan/storage/innobase/row/row0sel.cc:5242
|
#6 0x55b828d22b63 in ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) /data/src/10.2-asan/storage/innobase/handler/ha_innodb.cc:9823
|
#7 0x55b828d26136 in ha_innobase::index_first(unsigned char*) /data/src/10.2-asan/storage/innobase/handler/ha_innodb.cc:10261
|
#8 0x55b82858807f in handler::ha_index_first(unsigned char*) /data/src/10.2-asan/sql/handler.cc:2717
|
#9 0x55b8288fe18c in rr_index_first /data/src/10.2-asan/sql/records.cc:401
|
#10 0x55b8280b7b5a in join_init_read_record(st_join_table*) /data/src/10.2-asan/sql/sql_select.cc:19560
|
#11 0x55b8283586a5 in JOIN_TAB_SCAN::open() /data/src/10.2-asan/sql/sql_join_cache.cc:3339
|
#12 0x55b82835389c in JOIN_CACHE::join_matching_records(bool) /data/src/10.2-asan/sql/sql_join_cache.cc:2250
|
#13 0x55b828352922 in JOIN_CACHE::join_records(bool) /data/src/10.2-asan/sql/sql_join_cache.cc:2087
|
#14 0x55b8280b041c in sub_select_cache(JOIN*, st_join_table*, bool) /data/src/10.2-asan/sql/sql_select.cc:18417
|
#15 0x55b8280b092a in sub_select(JOIN*, st_join_table*, bool) /data/src/10.2-asan/sql/sql_select.cc:18589
|
#16 0x55b8280af449 in do_select /data/src/10.2-asan/sql/sql_select.cc:18184
|
#17 0x55b82804f912 in JOIN::exec_inner() /data/src/10.2-asan/sql/sql_select.cc:3514
|
#18 0x55b82804d5a9 in JOIN::exec() /data/src/10.2-asan/sql/sql_select.cc:3309
|
#19 0x55b82805098f in mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) /data/src/10.2-asan/sql/sql_select.cc:3709
|
#20 0x55b828030a3c in handle_select(THD*, LEX*, select_result*, unsigned long) /data/src/10.2-asan/sql/sql_select.cc:373
|
#21 0x55b827fb42dc in execute_sqlcom_select /data/src/10.2-asan/sql/sql_parse.cc:6428
|
#22 0x55b827fa1167 in mysql_execute_command(THD*) /data/src/10.2-asan/sql/sql_parse.cc:3462
|
#23 0x55b827fbc7d1 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2-asan/sql/sql_parse.cc:7869
|
#24 0x55b827f97cee in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2-asan/sql/sql_parse.cc:1805
|
#25 0x55b827f94d8d in do_command(THD*) /data/src/10.2-asan/sql/sql_parse.cc:1360
|
#26 0x55b8282cc7a7 in do_handle_one_connection(CONNECT*) /data/src/10.2-asan/sql/sql_connect.cc:1354
|
#27 0x55b8282cc1bc in handle_one_connection /data/src/10.2-asan/sql/sql_connect.cc:1260
|
#28 0x55b828cd21f9 in pfs_spawn_thread /data/src/10.2-asan/storage/perfschema/pfs.cc:1863
|
#29 0x7f861d702493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493)
|
#30 0x7f861bae893e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e)
|
|
|
AddressSanitizer can not describe address in more detail (wild memory access suspected).
|
SUMMARY: AddressSanitizer: heap-buffer-overflow /data/src/10.2-asan/storage/innobase/include/mach0data.ic:84 mach_read_from_2
|
Shadow bytes around the buggy address:
|
0x0c268001c7b0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
|
0x0c268001c7c0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
|
0x0c268001c7d0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
|
0x0c268001c7e0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
|
0x0c268001c7f0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
|
=>0x0c268001c800: fa fa fa[fa]fa fa fa fa fa fa fa fa fa fa fa fa
|
0x0c268001c810: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
|
0x0c268001c820: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
|
0x0c268001c830: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
|
0x0c268001c840: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
|
0x0c268001c850: 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
|
Contiguous container OOB:fc
|
ASan internal: fe
|
Thread T28 created by T0 here:
|
#0 0x7f861d93bbba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba)
|
#1 0x55b828cd27c1 in spawn_thread_v1 /data/src/10.2-asan/storage/perfschema/pfs.cc:1913
|
#2 0x55b827d9773f in inline_mysql_thread_create /data/src/10.2-asan/include/mysql/psi/mysql_thread.h:1239
|
#3 0x55b827dac56b in create_thread_to_handle_connection(CONNECT*) /data/src/10.2-asan/sql/mysqld.cc:6445
|
#4 0x55b827dacc70 in create_new_thread /data/src/10.2-asan/sql/mysqld.cc:6515
|
#5 0x55b827dadc81 in handle_connections_sockets() /data/src/10.2-asan/sql/mysqld.cc:6790
|
#6 0x55b827dabab8 in mysqld_main(int, char**) /data/src/10.2-asan/sql/mysqld.cc:6064
|
#7 0x55b827d95c6f in main /data/src/10.2-asan/sql/main.cc:25
|
#8 0x7f861ba202b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0)
|
|
|
==23938==ABORTING
|
Attachments
Activity
| Field | Original Value | New Value |
|---|---|---|
| Attachment | threads1 [ 43945 ] |
| Attachment | core.gz [ 43946 ] |
| Attachment | data.tar.gz [ 43947 ] |
| Attachment | master.err [ 43948 ] | |
| Attachment | master.log [ 43949 ] |
| Attachment | threads_full [ 43950 ] |
| Fix Version/s | 10.2 [ 14601 ] |
| Fix Version/s | 10.2 [ 14601 ] | |
| Description |
{noformat:title=10.2 86f9b7714791f45f386e9aaa6f469ada626cd69d}
mysqld: /data/src/10.2/storage/innobase/rem/rem0rec.cc:2268: trx_id_t rec_get_trx_id(const rec_t*, const dict_index_t*): Assertion `(fil_page_get_type(page) == 17855 || fil_page_get_type(page) == 17854)' failed. 170809 23:41:24 [ERROR] mysqld got signal 6 ; #7 0x00007f8960491ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x000056089997bed6 in rec_get_trx_id (rec=0x7f88e4058e80 "\200", index=0x7f88ec0466c8) at /data/src/10.2/storage/innobase/rem/rem0rec.cc:2268 #9 0x00005608999ecc31 in row_sel_sec_rec_is_for_clust_rec (sec_rec=0x7f89454c407d "", sec_index=0x7f88ec02fd98, clust_rec=0x7f88e4058e80 "\200", clust_index=0x7f88ec0466c8, thr=0x7f88e402ca60) at /data/src/10.2/storage/innobase/row/row0sel.cc:188 #10 0x00005608999f3819 in row_sel_get_clust_rec_for_mysql (prebuilt=0x7f88e402c2a8, sec_index=0x7f88ec02fd98, rec=0x7f89454c407d "", thr=0x7f88e402ca60, out_rec=0x7f895c30c748, offsets=0x7f895c30c768, offset_heap=0x7f895c30c760, vrow=0x0, mtr=0x7f895c30d260) at /data/src/10.2/storage/innobase/row/row0sel.cc:3551 #11 0x00005608999f75f9 in row_search_mvcc (buf=0x7f88e4038780 "\210\a", mode=PAGE_CUR_G, prebuilt=0x7f88e402c2a8, match_mode=0, direction=0) at /data/src/10.2/storage/innobase/row/row0sel.cc:5263 #12 0x00005608999b9fad in row_search_for_mysql (buf=0x7f88e4038780 "\210\a", mode=PAGE_CUR_G, prebuilt=0x7f88e402c2a8, match_mode=0, direction=0) at /data/src/10.2/storage/innobase/include/row0sel.ic:137 #13 0x00005608999c5745 in row_scan_index_for_mysql (prebuilt=0x7f88e402c2a8, index=0x7f88ec02fd98, n_rows=0x7f895c30dd70) at /data/src/10.2/storage/innobase/row/row0mysql.cc:5027 #14 0x000056089988d754 in ha_innobase::check (this=0x7f88e40351a8, thd=0x7f88e4000b00, check_opt=0x7f88e40054d0) at /data/src/10.2/storage/innobase/handler/ha_innodb.cc:15363 #15 0x00005608995749e1 in handler::ha_check (this=0x7f88e40351a8, thd=0x7f88e4000b00, check_opt=0x7f88e40054d0) at /data/src/10.2/sql/handler.cc:3941 #16 0x00005608994567e8 in mysql_admin_table(THD *, TABLE_LIST *, HA_CHECK_OPT *, const char *, thr_lock_type, bool, bool, uint, int (*)(THD *, TABLE_LIST *, HA_CHECK_OPT *), struct {...}, int (*)(THD *, TABLE_LIST *, HA_CHECK_OPT *)) (thd=0x7f88e4000b00, tables=0x7f88e4011190, check_opt=0x7f88e40054d0, operator_name=0x560899d9a4dc "check", lock_type=TL_READ_NO_INSERT, open_for_modify=false, repair_table_use_frm=false, extra_open_options=32, prepare_func=0x0, operator_func=(int (handler::*)(handler * const, THD *, HA_CHECK_OPT *)) 0x5608995748bc <handler::ha_check(THD*, st_ha_check_opt*)>, view_operator_func=0x5608993f35ab <view_check(THD*, TABLE_LIST*, st_ha_check_opt*)>) at /data/src/10.2/sql/sql_admin.cc:798 #17 0x0000560899458954 in Sql_cmd_check_table::execute (this=0x7f88e40117a8, thd=0x7f88e4000b00) at /data/src/10.2/sql/sql_admin.cc:1338 #18 0x0000560899307382 in mysql_execute_command (thd=0x7f88e4000b00) at /data/src/10.2/sql/sql_parse.cc:6213 #19 0x000056089930bc30 in mysql_parse (thd=0x7f88e4000b00, rawbuf=0x7f88e4011068 "CHECK TABLE t1 /* QNO 142 CON_ID 20 */", length=38, parser_state=0x7f895c30f250, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:7880 #20 0x00005608992f9cc6 in dispatch_command (command=COM_QUERY, thd=0x7f88e4000b00, packet=0x7f88e40086d1 "", packet_length=39, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1817 #21 0x00005608992f8607 in do_command (thd=0x7f88e4000b00) at /data/src/10.2/sql/sql_parse.cc:1362 #22 0x00005608994443d5 in do_handle_one_connection (connect=0x56089c2b9e90) at /data/src/10.2/sql/sql_connect.cc:1354 #23 0x0000560899444162 in handle_one_connection (arg=0x56089c2b9e90) at /data/src/10.2/sql/sql_connect.cc:1260 #24 0x00007f89623d6494 in start_thread (arg=0x7f895c310700) at pthread_create.c:333 #25 0x00007f896054e93f in clone () from /lib/x86_64-linux-gnu/libc.so.6 Trying to get some variables. Some pointers may be invalid and cause the dump to abort. Query (0x7f88e4011068): CHECK TABLE t1 /* QNO 142 CON_ID 20 */ Connection ID (thread ID): 20 Status: NOT_KILLED {noformat} {noformat:title=rqg experimental 6a2805af973691baafe04546f939a50f4a607b90} perl ./runall.pl --no-mask --seed=1502269167 --threads=5 --duration=2400 --queries=100M --reporters=QueryTimeout,Backtrace,ErrorLog,Deadlock,Shutdown --redefine=conf/mariadb/redefine_random_keys.yy --redefine=conf/mariadb/redefine_set_session_vars.yy --validators=TransformerNoComparator --transformers=ConvertSubqueriesToViews,DisableOptimizations,EnableOptimizations,ExecuteAsCTE,ExecuteAsInsertSelect,ExecuteAsPreparedOnce,ExecuteAsSelectItem,ExecuteAsUnion,ExecuteAsUpdateDelete,ExecuteAsView,NullIf,OrderBy,StraightJoin,ExecuteAsExecuteImmediate --grammar=conf/runtime/alter_online.yy --gendata=conf/runtime/alter_online.zz --mtr-build-thread=150 --basedir1=/data/bld/10.2 --vardir1=/data/logs/analyze1 {noformat} |
{noformat:title=10.2 0c4d11e8199f4c7a with the injection below}
mysqld: /data/src/10.2-bug/storage/innobase/rem/rem0rec.cc:2183: trx_id_t rec_get_trx_id(const rec_t*, const dict_index_t*): Assertion `(fil_page_get_type(page) == 17855 || fil_page_get_type(page) == 17854)' failed. 171116 17:54:16 [ERROR] mysqld got signal 6 ; #7 0x00007f046b4c1ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x0000563d6fa15548 in rec_get_trx_id (rec=0x7f0414010c7e "\200", index=0x7f041012fc88) at /data/src/10.2-bug/storage/innobase/rem/rem0rec.cc:2183 #9 0x0000563d6fa846bd in row_sel_sec_rec_is_for_clust_rec (sec_rec=0x7f046510407d "\200", sec_index=0x7f0410039ca8, clust_rec=0x7f0414010c7e "\200", clust_index=0x7f041012fc88, thr=0x7f041401e9a0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:188 #10 0x0000563d6fa8b1bf in row_sel_get_clust_rec_for_mysql (prebuilt=0x7f041401e288, sec_index=0x7f0410039ca8, rec=0x7f046510407d "\200", thr=0x7f041401e9a0, out_rec=0x7f04640e1aa8, offsets=0x7f04640e1ac8, offset_heap=0x7f04640e1ac0, vrow=0x0, mtr=0x7f04640e25c0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:3522 #11 0x0000563d6fa8f023 in row_search_mvcc (buf=0x7f041401de28 "\377", mode=PAGE_CUR_G, prebuilt=0x7f041401e288, match_mode=0, direction=0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:5242 #12 0x0000563d6f91c233 in ha_innobase::index_read (this=0x7f041401c6d8, buf=0x7f041401de28 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /data/src/10.2-bug/storage/innobase/handler/ha_innodb.cc:9823 #13 0x0000563d6f91d5d6 in ha_innobase::index_first (this=0x7f041401c6d8, buf=0x7f041401de28 "\377") at /data/src/10.2-bug/storage/innobase/handler/ha_innodb.cc:10261 #14 0x0000563d6f60a63b in handler::ha_index_first (this=0x7f041401c6d8, buf=0x7f041401de28 "\377") at /data/src/10.2-bug/sql/handler.cc:2717 #15 0x0000563d6f77460f in rr_index_first (info=0x7f0414013c30) at /data/src/10.2-bug/sql/records.cc:401 #16 0x0000563d6f4058e2 in join_init_read_record (tab=0x7f0414013b68) at /data/src/10.2-bug/sql/sql_select.cc:19560 #17 0x0000563d6f5217fe in JOIN_TAB_SCAN::open (this=0x7f0414014988) at /data/src/10.2-bug/sql/sql_join_cache.cc:3339 #18 0x0000563d6f51fd0c in JOIN_CACHE::join_matching_records (this=0x7f0414014858, skip_last=false) at /data/src/10.2-bug/sql/sql_join_cache.cc:2250 #19 0x0000563d6f51f890 in JOIN_CACHE::join_records (this=0x7f0414014858, skip_last=false) at /data/src/10.2-bug/sql/sql_join_cache.cc:2087 #20 0x0000563d6f40330a in sub_select_cache (join=0x7f0414012150, join_tab=0x7f0414013b68, end_of_records=true) at /data/src/10.2-bug/sql/sql_select.cc:18417 #21 0x0000563d6f40351c in sub_select (join=0x7f0414012150, join_tab=0x7f04140137b8, end_of_records=true) at /data/src/10.2-bug/sql/sql_select.cc:18589 #22 0x0000563d6f402d32 in do_select (join=0x7f0414012150, procedure=0x0) at /data/src/10.2-bug/sql/sql_select.cc:18184 #23 0x0000563d6f3dd3e3 in JOIN::exec_inner (this=0x7f0414012150) at /data/src/10.2-bug/sql/sql_select.cc:3514 #24 0x0000563d6f3dc892 in JOIN::exec (this=0x7f0414012150) at /data/src/10.2-bug/sql/sql_select.cc:3309 #25 0x0000563d6f3dda5b in mysql_select (thd=0x7f0414000b00, tables=0x7f04140113d0, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7f0414012130, unit=0x7f04140046a0, select_lex=0x7f0414004dd8) at /data/src/10.2-bug/sql/sql_select.cc:3709 #26 0x0000563d6f3d22bc in handle_select (thd=0x7f0414000b00, lex=0x7f04140045d8, result=0x7f0414012130, setup_tables_done_option=0) at /data/src/10.2-bug/sql/sql_select.cc:373 #27 0x0000563d6f39e0fc in execute_sqlcom_select (thd=0x7f0414000b00, all_tables=0x7f04140113d0) at /data/src/10.2-bug/sql/sql_parse.cc:6428 #28 0x0000563d6f394159 in mysql_execute_command (thd=0x7f0414000b00) at /data/src/10.2-bug/sql/sql_parse.cc:3462 #29 0x0000563d6f3a1abe in mysql_parse (thd=0x7f0414000b00, rawbuf=0x7f0414011088 "SELECT a1.f1, a1.f2 FROM t1 AS a1, t1 AS a2", length=43, parser_state=0x7f04640e4200, is_com_multi=false, is_next_command=false) at /data/src/10.2-bug/sql/sql_parse.cc:7869 #30 0x0000563d6f38fa4a in dispatch_command (command=COM_QUERY, thd=0x7f0414000b00, packet=0x7f04140088a1 "", packet_length=43, is_com_multi=false, is_next_command=false) at /data/src/10.2-bug/sql/sql_parse.cc:1805 #31 0x0000563d6f38e3a8 in do_command (thd=0x7f0414000b00) at /data/src/10.2-bug/sql/sql_parse.cc:1360 #32 0x0000563d6f4db98d in do_handle_one_connection (connect=0x563d73106c40) at /data/src/10.2-bug/sql/sql_connect.cc:1354 #33 0x0000563d6f4db71a in handle_one_connection (arg=0x563d73106c40) at /data/src/10.2-bug/sql/sql_connect.cc:1260 #34 0x0000563d6f8f8e1a in pfs_spawn_thread (arg=0x563d731a8ad0) at /data/src/10.2-bug/storage/perfschema/pfs.cc:1863 #35 0x00007f046d198494 in start_thread (arg=0x7f04640e5700) at pthread_create.c:333 #36 0x00007f046b57e93f in clone () from /lib/x86_64-linux-gnu/libc.so.6 {noformat} The problem happens in concurrent tests on a normal server (without the sleep below), but very rarely. With the delay, for me it's reproducible reliably enough, although probably not 100%. I suppose it might require different sleep times on other machines. {noformat} diff --git a/storage/innobase/rem/rem0rec.cc b/storage/innobase/rem/rem0rec.cc index 37bf6e6..08cf8b8 100644 --- a/storage/innobase/rem/rem0rec.cc +++ b/storage/innobase/rem/rem0rec.cc @@ -2179,6 +2179,7 @@ rec_get_trx_id( ulint* offsets = offsets_; ut_ad(trx_id_col <= MAX_REF_PARTS); + my_sleep(200000); ut_ad(fil_page_index_page_check(page)); ut_ad(mach_read_from_8(page + PAGE_HEADER + PAGE_INDEX_ID) == index->id); {noformat} Run with {{\-\-mysqld=\-\-innodb_locks_unsafe_for_binlog}} and, if it's not reproducible right away, with {{--repeat=N}}. {code:sql} --source include/have_innodb.inc CREATE TABLE t1 (f1 INT NOT NULL AUTO_INCREMENT PRIMARY KEY, f2 INT) ENGINE=InnoDB; INSERT IGNORE INTO t1 VALUES (5,9),(NULL,3),(NULL,0),(4,105),(197,66),(0,0); ALTER TABLE t1 ADD KEY (f1); --connect (con1,localhost,root,,test) --connection default --send INSERT IGNORE INTO t1 SELECT f1, f2 FROM t1 ORDER BY f1, f2 LIMIT 4; --connection con1 DELETE FROM t1 ORDER BY f1, f2 LIMIT 1; SELECT a1.f1, a1.f2 FROM t1 AS a1, t1 AS a2; --disconnect con1 --connection default --reap # Cleanup DROP TABLE t1; {code} Reproducible on 10.2 and 10.3. I've never encountered it on 10.1 so far. |
| Summary | [Draft] Assertion `(fil_page_get_type(page) == 17855 || fil_page_get_type(page) == 17854)' failed in trx_id_t rec_get_trx_id(const rec_t*, const dict_index_t*) | Assertion `(fil_page_get_type(page) == 17855 || fil_page_get_type(page) == 17854)' failed in rec_get_trx_id |
| Description |
{noformat:title=10.2 0c4d11e8199f4c7a with the injection below}
mysqld: /data/src/10.2-bug/storage/innobase/rem/rem0rec.cc:2183: trx_id_t rec_get_trx_id(const rec_t*, const dict_index_t*): Assertion `(fil_page_get_type(page) == 17855 || fil_page_get_type(page) == 17854)' failed. 171116 17:54:16 [ERROR] mysqld got signal 6 ; #7 0x00007f046b4c1ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x0000563d6fa15548 in rec_get_trx_id (rec=0x7f0414010c7e "\200", index=0x7f041012fc88) at /data/src/10.2-bug/storage/innobase/rem/rem0rec.cc:2183 #9 0x0000563d6fa846bd in row_sel_sec_rec_is_for_clust_rec (sec_rec=0x7f046510407d "\200", sec_index=0x7f0410039ca8, clust_rec=0x7f0414010c7e "\200", clust_index=0x7f041012fc88, thr=0x7f041401e9a0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:188 #10 0x0000563d6fa8b1bf in row_sel_get_clust_rec_for_mysql (prebuilt=0x7f041401e288, sec_index=0x7f0410039ca8, rec=0x7f046510407d "\200", thr=0x7f041401e9a0, out_rec=0x7f04640e1aa8, offsets=0x7f04640e1ac8, offset_heap=0x7f04640e1ac0, vrow=0x0, mtr=0x7f04640e25c0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:3522 #11 0x0000563d6fa8f023 in row_search_mvcc (buf=0x7f041401de28 "\377", mode=PAGE_CUR_G, prebuilt=0x7f041401e288, match_mode=0, direction=0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:5242 #12 0x0000563d6f91c233 in ha_innobase::index_read (this=0x7f041401c6d8, buf=0x7f041401de28 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /data/src/10.2-bug/storage/innobase/handler/ha_innodb.cc:9823 #13 0x0000563d6f91d5d6 in ha_innobase::index_first (this=0x7f041401c6d8, buf=0x7f041401de28 "\377") at /data/src/10.2-bug/storage/innobase/handler/ha_innodb.cc:10261 #14 0x0000563d6f60a63b in handler::ha_index_first (this=0x7f041401c6d8, buf=0x7f041401de28 "\377") at /data/src/10.2-bug/sql/handler.cc:2717 #15 0x0000563d6f77460f in rr_index_first (info=0x7f0414013c30) at /data/src/10.2-bug/sql/records.cc:401 #16 0x0000563d6f4058e2 in join_init_read_record (tab=0x7f0414013b68) at /data/src/10.2-bug/sql/sql_select.cc:19560 #17 0x0000563d6f5217fe in JOIN_TAB_SCAN::open (this=0x7f0414014988) at /data/src/10.2-bug/sql/sql_join_cache.cc:3339 #18 0x0000563d6f51fd0c in JOIN_CACHE::join_matching_records (this=0x7f0414014858, skip_last=false) at /data/src/10.2-bug/sql/sql_join_cache.cc:2250 #19 0x0000563d6f51f890 in JOIN_CACHE::join_records (this=0x7f0414014858, skip_last=false) at /data/src/10.2-bug/sql/sql_join_cache.cc:2087 #20 0x0000563d6f40330a in sub_select_cache (join=0x7f0414012150, join_tab=0x7f0414013b68, end_of_records=true) at /data/src/10.2-bug/sql/sql_select.cc:18417 #21 0x0000563d6f40351c in sub_select (join=0x7f0414012150, join_tab=0x7f04140137b8, end_of_records=true) at /data/src/10.2-bug/sql/sql_select.cc:18589 #22 0x0000563d6f402d32 in do_select (join=0x7f0414012150, procedure=0x0) at /data/src/10.2-bug/sql/sql_select.cc:18184 #23 0x0000563d6f3dd3e3 in JOIN::exec_inner (this=0x7f0414012150) at /data/src/10.2-bug/sql/sql_select.cc:3514 #24 0x0000563d6f3dc892 in JOIN::exec (this=0x7f0414012150) at /data/src/10.2-bug/sql/sql_select.cc:3309 #25 0x0000563d6f3dda5b in mysql_select (thd=0x7f0414000b00, tables=0x7f04140113d0, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7f0414012130, unit=0x7f04140046a0, select_lex=0x7f0414004dd8) at /data/src/10.2-bug/sql/sql_select.cc:3709 #26 0x0000563d6f3d22bc in handle_select (thd=0x7f0414000b00, lex=0x7f04140045d8, result=0x7f0414012130, setup_tables_done_option=0) at /data/src/10.2-bug/sql/sql_select.cc:373 #27 0x0000563d6f39e0fc in execute_sqlcom_select (thd=0x7f0414000b00, all_tables=0x7f04140113d0) at /data/src/10.2-bug/sql/sql_parse.cc:6428 #28 0x0000563d6f394159 in mysql_execute_command (thd=0x7f0414000b00) at /data/src/10.2-bug/sql/sql_parse.cc:3462 #29 0x0000563d6f3a1abe in mysql_parse (thd=0x7f0414000b00, rawbuf=0x7f0414011088 "SELECT a1.f1, a1.f2 FROM t1 AS a1, t1 AS a2", length=43, parser_state=0x7f04640e4200, is_com_multi=false, is_next_command=false) at /data/src/10.2-bug/sql/sql_parse.cc:7869 #30 0x0000563d6f38fa4a in dispatch_command (command=COM_QUERY, thd=0x7f0414000b00, packet=0x7f04140088a1 "", packet_length=43, is_com_multi=false, is_next_command=false) at /data/src/10.2-bug/sql/sql_parse.cc:1805 #31 0x0000563d6f38e3a8 in do_command (thd=0x7f0414000b00) at /data/src/10.2-bug/sql/sql_parse.cc:1360 #32 0x0000563d6f4db98d in do_handle_one_connection (connect=0x563d73106c40) at /data/src/10.2-bug/sql/sql_connect.cc:1354 #33 0x0000563d6f4db71a in handle_one_connection (arg=0x563d73106c40) at /data/src/10.2-bug/sql/sql_connect.cc:1260 #34 0x0000563d6f8f8e1a in pfs_spawn_thread (arg=0x563d731a8ad0) at /data/src/10.2-bug/storage/perfschema/pfs.cc:1863 #35 0x00007f046d198494 in start_thread (arg=0x7f04640e5700) at pthread_create.c:333 #36 0x00007f046b57e93f in clone () from /lib/x86_64-linux-gnu/libc.so.6 {noformat} The problem happens in concurrent tests on a normal server (without the sleep below), but very rarely. With the delay, for me it's reproducible reliably enough, although probably not 100%. I suppose it might require different sleep times on other machines. {noformat} diff --git a/storage/innobase/rem/rem0rec.cc b/storage/innobase/rem/rem0rec.cc index 37bf6e6..08cf8b8 100644 --- a/storage/innobase/rem/rem0rec.cc +++ b/storage/innobase/rem/rem0rec.cc @@ -2179,6 +2179,7 @@ rec_get_trx_id( ulint* offsets = offsets_; ut_ad(trx_id_col <= MAX_REF_PARTS); + my_sleep(200000); ut_ad(fil_page_index_page_check(page)); ut_ad(mach_read_from_8(page + PAGE_HEADER + PAGE_INDEX_ID) == index->id); {noformat} Run with {{\-\-mysqld=\-\-innodb_locks_unsafe_for_binlog}} and, if it's not reproducible right away, with {{--repeat=N}}. {code:sql} --source include/have_innodb.inc CREATE TABLE t1 (f1 INT NOT NULL AUTO_INCREMENT PRIMARY KEY, f2 INT) ENGINE=InnoDB; INSERT IGNORE INTO t1 VALUES (5,9),(NULL,3),(NULL,0),(4,105),(197,66),(0,0); ALTER TABLE t1 ADD KEY (f1); --connect (con1,localhost,root,,test) --connection default --send INSERT IGNORE INTO t1 SELECT f1, f2 FROM t1 ORDER BY f1, f2 LIMIT 4; --connection con1 DELETE FROM t1 ORDER BY f1, f2 LIMIT 1; SELECT a1.f1, a1.f2 FROM t1 AS a1, t1 AS a2; --disconnect con1 --connection default --reap # Cleanup DROP TABLE t1; {code} Reproducible on 10.2 and 10.3. I've never encountered it on 10.1 so far. |
{noformat:title=10.2 0c4d11e8199f4c7a with the injection below}
mysqld: /data/src/10.2-bug/storage/innobase/rem/rem0rec.cc:2183: trx_id_t rec_get_trx_id(const rec_t*, const dict_index_t*): Assertion `(fil_page_get_type(page) == 17855 || fil_page_get_type(page) == 17854)' failed. 171116 17:54:16 [ERROR] mysqld got signal 6 ; #7 0x00007f046b4c1ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x0000563d6fa15548 in rec_get_trx_id (rec=0x7f0414010c7e "\200", index=0x7f041012fc88) at /data/src/10.2-bug/storage/innobase/rem/rem0rec.cc:2183 #9 0x0000563d6fa846bd in row_sel_sec_rec_is_for_clust_rec (sec_rec=0x7f046510407d "\200", sec_index=0x7f0410039ca8, clust_rec=0x7f0414010c7e "\200", clust_index=0x7f041012fc88, thr=0x7f041401e9a0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:188 #10 0x0000563d6fa8b1bf in row_sel_get_clust_rec_for_mysql (prebuilt=0x7f041401e288, sec_index=0x7f0410039ca8, rec=0x7f046510407d "\200", thr=0x7f041401e9a0, out_rec=0x7f04640e1aa8, offsets=0x7f04640e1ac8, offset_heap=0x7f04640e1ac0, vrow=0x0, mtr=0x7f04640e25c0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:3522 #11 0x0000563d6fa8f023 in row_search_mvcc (buf=0x7f041401de28 "\377", mode=PAGE_CUR_G, prebuilt=0x7f041401e288, match_mode=0, direction=0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:5242 #12 0x0000563d6f91c233 in ha_innobase::index_read (this=0x7f041401c6d8, buf=0x7f041401de28 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /data/src/10.2-bug/storage/innobase/handler/ha_innodb.cc:9823 #13 0x0000563d6f91d5d6 in ha_innobase::index_first (this=0x7f041401c6d8, buf=0x7f041401de28 "\377") at /data/src/10.2-bug/storage/innobase/handler/ha_innodb.cc:10261 #14 0x0000563d6f60a63b in handler::ha_index_first (this=0x7f041401c6d8, buf=0x7f041401de28 "\377") at /data/src/10.2-bug/sql/handler.cc:2717 #15 0x0000563d6f77460f in rr_index_first (info=0x7f0414013c30) at /data/src/10.2-bug/sql/records.cc:401 #16 0x0000563d6f4058e2 in join_init_read_record (tab=0x7f0414013b68) at /data/src/10.2-bug/sql/sql_select.cc:19560 #17 0x0000563d6f5217fe in JOIN_TAB_SCAN::open (this=0x7f0414014988) at /data/src/10.2-bug/sql/sql_join_cache.cc:3339 #18 0x0000563d6f51fd0c in JOIN_CACHE::join_matching_records (this=0x7f0414014858, skip_last=false) at /data/src/10.2-bug/sql/sql_join_cache.cc:2250 #19 0x0000563d6f51f890 in JOIN_CACHE::join_records (this=0x7f0414014858, skip_last=false) at /data/src/10.2-bug/sql/sql_join_cache.cc:2087 #20 0x0000563d6f40330a in sub_select_cache (join=0x7f0414012150, join_tab=0x7f0414013b68, end_of_records=true) at /data/src/10.2-bug/sql/sql_select.cc:18417 #21 0x0000563d6f40351c in sub_select (join=0x7f0414012150, join_tab=0x7f04140137b8, end_of_records=true) at /data/src/10.2-bug/sql/sql_select.cc:18589 #22 0x0000563d6f402d32 in do_select (join=0x7f0414012150, procedure=0x0) at /data/src/10.2-bug/sql/sql_select.cc:18184 #23 0x0000563d6f3dd3e3 in JOIN::exec_inner (this=0x7f0414012150) at /data/src/10.2-bug/sql/sql_select.cc:3514 #24 0x0000563d6f3dc892 in JOIN::exec (this=0x7f0414012150) at /data/src/10.2-bug/sql/sql_select.cc:3309 #25 0x0000563d6f3dda5b in mysql_select (thd=0x7f0414000b00, tables=0x7f04140113d0, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7f0414012130, unit=0x7f04140046a0, select_lex=0x7f0414004dd8) at /data/src/10.2-bug/sql/sql_select.cc:3709 #26 0x0000563d6f3d22bc in handle_select (thd=0x7f0414000b00, lex=0x7f04140045d8, result=0x7f0414012130, setup_tables_done_option=0) at /data/src/10.2-bug/sql/sql_select.cc:373 #27 0x0000563d6f39e0fc in execute_sqlcom_select (thd=0x7f0414000b00, all_tables=0x7f04140113d0) at /data/src/10.2-bug/sql/sql_parse.cc:6428 #28 0x0000563d6f394159 in mysql_execute_command (thd=0x7f0414000b00) at /data/src/10.2-bug/sql/sql_parse.cc:3462 #29 0x0000563d6f3a1abe in mysql_parse (thd=0x7f0414000b00, rawbuf=0x7f0414011088 "SELECT a1.f1, a1.f2 FROM t1 AS a1, t1 AS a2", length=43, parser_state=0x7f04640e4200, is_com_multi=false, is_next_command=false) at /data/src/10.2-bug/sql/sql_parse.cc:7869 #30 0x0000563d6f38fa4a in dispatch_command (command=COM_QUERY, thd=0x7f0414000b00, packet=0x7f04140088a1 "", packet_length=43, is_com_multi=false, is_next_command=false) at /data/src/10.2-bug/sql/sql_parse.cc:1805 #31 0x0000563d6f38e3a8 in do_command (thd=0x7f0414000b00) at /data/src/10.2-bug/sql/sql_parse.cc:1360 #32 0x0000563d6f4db98d in do_handle_one_connection (connect=0x563d73106c40) at /data/src/10.2-bug/sql/sql_connect.cc:1354 #33 0x0000563d6f4db71a in handle_one_connection (arg=0x563d73106c40) at /data/src/10.2-bug/sql/sql_connect.cc:1260 #34 0x0000563d6f8f8e1a in pfs_spawn_thread (arg=0x563d731a8ad0) at /data/src/10.2-bug/storage/perfschema/pfs.cc:1863 #35 0x00007f046d198494 in start_thread (arg=0x7f04640e5700) at pthread_create.c:333 #36 0x00007f046b57e93f in clone () from /lib/x86_64-linux-gnu/libc.so.6 {noformat} The problem happens in concurrent tests on a normal server (without the sleep below), but very rarely. With the delay, for me it's reproducible reliably enough, although probably not 100%. I suppose it might require different sleep times on other machines. {noformat} diff --git a/storage/innobase/rem/rem0rec.cc b/storage/innobase/rem/rem0rec.cc index 37bf6e6..08cf8b8 100644 --- a/storage/innobase/rem/rem0rec.cc +++ b/storage/innobase/rem/rem0rec.cc @@ -2179,6 +2179,7 @@ rec_get_trx_id( ulint* offsets = offsets_; ut_ad(trx_id_col <= MAX_REF_PARTS); + my_sleep(200000); ut_ad(fil_page_index_page_check(page)); ut_ad(mach_read_from_8(page + PAGE_HEADER + PAGE_INDEX_ID) == index->id); {noformat} Run with {{\-\-mysqld=\-\-innodb_locks_unsafe_for_binlog}} and, if it's not reproducible right away, with {{--repeat=N}}. {code:sql} --source include/have_innodb.inc CREATE TABLE t1 (f1 INT NOT NULL AUTO_INCREMENT PRIMARY KEY, f2 INT) ENGINE=InnoDB; INSERT IGNORE INTO t1 VALUES (5,9),(NULL,3),(NULL,0),(4,105),(197,66),(0,0); ALTER TABLE t1 ADD KEY (f1); --connect (con1,localhost,root,,test) --connection default --send INSERT IGNORE INTO t1 SELECT f1, f2 FROM t1 ORDER BY f1, f2 LIMIT 4; --connection con1 DELETE FROM t1 ORDER BY f1, f2 LIMIT 1; SELECT a1.f1, a1.f2 FROM t1 AS a1, t1 AS a2; --disconnect con1 --connection default --reap # Cleanup DROP TABLE t1; {code} Reproducible on 10.2 and 10.3. I've never encountered it on 10.1 so far. {noformat:title=10.2 0c4d11e8199f4 ASAN} ================================================================= ==23938==ERROR: AddressSanitizer: heap-buffer-overflow on address 0x613000124018 at pc 0x55b828cf4a44 bp 0x7f860123dd40 sp 0x7f860123dd38 READ of size 1 at 0x613000124018 thread T28 #0 0x55b828cf4a43 in mach_read_from_2 /data/src/10.2-asan/storage/innobase/include/mach0data.ic:84 #1 0x55b828d5c961 in fil_page_get_type(unsigned char const*) /data/src/10.2-asan/storage/innobase/include/fil0fil.h:1322 #2 0x55b828f014d7 in rec_get_trx_id(unsigned char const*, dict_index_t const*) /data/src/10.2-asan/storage/innobase/rem/rem0rec.cc:2183 #3 0x55b828fd352d in row_sel_sec_rec_is_for_clust_rec /data/src/10.2-asan/storage/innobase/row/row0sel.cc:188 #4 0x55b828fe0492 in row_sel_get_clust_rec_for_mysql /data/src/10.2-asan/storage/innobase/row/row0sel.cc:3522 #5 0x55b828fe72b2 in row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long) /data/src/10.2-asan/storage/innobase/row/row0sel.cc:5242 #6 0x55b828d22b63 in ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) /data/src/10.2-asan/storage/innobase/handler/ha_innodb.cc:9823 #7 0x55b828d26136 in ha_innobase::index_first(unsigned char*) /data/src/10.2-asan/storage/innobase/handler/ha_innodb.cc:10261 #8 0x55b82858807f in handler::ha_index_first(unsigned char*) /data/src/10.2-asan/sql/handler.cc:2717 #9 0x55b8288fe18c in rr_index_first /data/src/10.2-asan/sql/records.cc:401 #10 0x55b8280b7b5a in join_init_read_record(st_join_table*) /data/src/10.2-asan/sql/sql_select.cc:19560 #11 0x55b8283586a5 in JOIN_TAB_SCAN::open() /data/src/10.2-asan/sql/sql_join_cache.cc:3339 #12 0x55b82835389c in JOIN_CACHE::join_matching_records(bool) /data/src/10.2-asan/sql/sql_join_cache.cc:2250 #13 0x55b828352922 in JOIN_CACHE::join_records(bool) /data/src/10.2-asan/sql/sql_join_cache.cc:2087 #14 0x55b8280b041c in sub_select_cache(JOIN*, st_join_table*, bool) /data/src/10.2-asan/sql/sql_select.cc:18417 #15 0x55b8280b092a in sub_select(JOIN*, st_join_table*, bool) /data/src/10.2-asan/sql/sql_select.cc:18589 #16 0x55b8280af449 in do_select /data/src/10.2-asan/sql/sql_select.cc:18184 #17 0x55b82804f912 in JOIN::exec_inner() /data/src/10.2-asan/sql/sql_select.cc:3514 #18 0x55b82804d5a9 in JOIN::exec() /data/src/10.2-asan/sql/sql_select.cc:3309 #19 0x55b82805098f in mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) /data/src/10.2-asan/sql/sql_select.cc:3709 #20 0x55b828030a3c in handle_select(THD*, LEX*, select_result*, unsigned long) /data/src/10.2-asan/sql/sql_select.cc:373 #21 0x55b827fb42dc in execute_sqlcom_select /data/src/10.2-asan/sql/sql_parse.cc:6428 #22 0x55b827fa1167 in mysql_execute_command(THD*) /data/src/10.2-asan/sql/sql_parse.cc:3462 #23 0x55b827fbc7d1 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2-asan/sql/sql_parse.cc:7869 #24 0x55b827f97cee in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2-asan/sql/sql_parse.cc:1805 #25 0x55b827f94d8d in do_command(THD*) /data/src/10.2-asan/sql/sql_parse.cc:1360 #26 0x55b8282cc7a7 in do_handle_one_connection(CONNECT*) /data/src/10.2-asan/sql/sql_connect.cc:1354 #27 0x55b8282cc1bc in handle_one_connection /data/src/10.2-asan/sql/sql_connect.cc:1260 #28 0x55b828cd21f9 in pfs_spawn_thread /data/src/10.2-asan/storage/perfschema/pfs.cc:1863 #29 0x7f861d702493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493) #30 0x7f861bae893e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e) AddressSanitizer can not describe address in more detail (wild memory access suspected). SUMMARY: AddressSanitizer: heap-buffer-overflow /data/src/10.2-asan/storage/innobase/include/mach0data.ic:84 mach_read_from_2 Shadow bytes around the buggy address: 0x0c268001c7b0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c7c0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c7d0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c7e0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c7f0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa =>0x0c268001c800: fa fa fa[fa]fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c810: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c820: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c830: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c840: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c850: 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 Contiguous container OOB:fc ASan internal: fe Thread T28 created by T0 here: #0 0x7f861d93bbba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba) #1 0x55b828cd27c1 in spawn_thread_v1 /data/src/10.2-asan/storage/perfschema/pfs.cc:1913 #2 0x55b827d9773f in inline_mysql_thread_create /data/src/10.2-asan/include/mysql/psi/mysql_thread.h:1239 #3 0x55b827dac56b in create_thread_to_handle_connection(CONNECT*) /data/src/10.2-asan/sql/mysqld.cc:6445 #4 0x55b827dacc70 in create_new_thread /data/src/10.2-asan/sql/mysqld.cc:6515 #5 0x55b827dadc81 in handle_connections_sockets() /data/src/10.2-asan/sql/mysqld.cc:6790 #6 0x55b827dabab8 in mysqld_main(int, char**) /data/src/10.2-asan/sql/mysqld.cc:6064 #7 0x55b827d95c6f in main /data/src/10.2-asan/sql/main.cc:25 #8 0x7f861ba202b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0) ==23938==ABORTING {noformat} |
| Comment |
[ Fresh occurrence in buildbot
http://buildbot.askmonty.org/buildbot/builders/qa-win-debug/builds/759/steps/crash_tests/logs/stdio ] |
| Attachment | core.gz [ 43946 ] |
| Attachment | data.tar.gz [ 43947 ] |
| Attachment | master.err [ 43948 ] |
| Attachment | master.log [ 43949 ] |
| Attachment | threads_full [ 43950 ] |
| Attachment | threads1 [ 43945 ] |
| Description |
{noformat:title=10.2 0c4d11e8199f4c7a with the injection below}
mysqld: /data/src/10.2-bug/storage/innobase/rem/rem0rec.cc:2183: trx_id_t rec_get_trx_id(const rec_t*, const dict_index_t*): Assertion `(fil_page_get_type(page) == 17855 || fil_page_get_type(page) == 17854)' failed. 171116 17:54:16 [ERROR] mysqld got signal 6 ; #7 0x00007f046b4c1ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x0000563d6fa15548 in rec_get_trx_id (rec=0x7f0414010c7e "\200", index=0x7f041012fc88) at /data/src/10.2-bug/storage/innobase/rem/rem0rec.cc:2183 #9 0x0000563d6fa846bd in row_sel_sec_rec_is_for_clust_rec (sec_rec=0x7f046510407d "\200", sec_index=0x7f0410039ca8, clust_rec=0x7f0414010c7e "\200", clust_index=0x7f041012fc88, thr=0x7f041401e9a0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:188 #10 0x0000563d6fa8b1bf in row_sel_get_clust_rec_for_mysql (prebuilt=0x7f041401e288, sec_index=0x7f0410039ca8, rec=0x7f046510407d "\200", thr=0x7f041401e9a0, out_rec=0x7f04640e1aa8, offsets=0x7f04640e1ac8, offset_heap=0x7f04640e1ac0, vrow=0x0, mtr=0x7f04640e25c0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:3522 #11 0x0000563d6fa8f023 in row_search_mvcc (buf=0x7f041401de28 "\377", mode=PAGE_CUR_G, prebuilt=0x7f041401e288, match_mode=0, direction=0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:5242 #12 0x0000563d6f91c233 in ha_innobase::index_read (this=0x7f041401c6d8, buf=0x7f041401de28 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /data/src/10.2-bug/storage/innobase/handler/ha_innodb.cc:9823 #13 0x0000563d6f91d5d6 in ha_innobase::index_first (this=0x7f041401c6d8, buf=0x7f041401de28 "\377") at /data/src/10.2-bug/storage/innobase/handler/ha_innodb.cc:10261 #14 0x0000563d6f60a63b in handler::ha_index_first (this=0x7f041401c6d8, buf=0x7f041401de28 "\377") at /data/src/10.2-bug/sql/handler.cc:2717 #15 0x0000563d6f77460f in rr_index_first (info=0x7f0414013c30) at /data/src/10.2-bug/sql/records.cc:401 #16 0x0000563d6f4058e2 in join_init_read_record (tab=0x7f0414013b68) at /data/src/10.2-bug/sql/sql_select.cc:19560 #17 0x0000563d6f5217fe in JOIN_TAB_SCAN::open (this=0x7f0414014988) at /data/src/10.2-bug/sql/sql_join_cache.cc:3339 #18 0x0000563d6f51fd0c in JOIN_CACHE::join_matching_records (this=0x7f0414014858, skip_last=false) at /data/src/10.2-bug/sql/sql_join_cache.cc:2250 #19 0x0000563d6f51f890 in JOIN_CACHE::join_records (this=0x7f0414014858, skip_last=false) at /data/src/10.2-bug/sql/sql_join_cache.cc:2087 #20 0x0000563d6f40330a in sub_select_cache (join=0x7f0414012150, join_tab=0x7f0414013b68, end_of_records=true) at /data/src/10.2-bug/sql/sql_select.cc:18417 #21 0x0000563d6f40351c in sub_select (join=0x7f0414012150, join_tab=0x7f04140137b8, end_of_records=true) at /data/src/10.2-bug/sql/sql_select.cc:18589 #22 0x0000563d6f402d32 in do_select (join=0x7f0414012150, procedure=0x0) at /data/src/10.2-bug/sql/sql_select.cc:18184 #23 0x0000563d6f3dd3e3 in JOIN::exec_inner (this=0x7f0414012150) at /data/src/10.2-bug/sql/sql_select.cc:3514 #24 0x0000563d6f3dc892 in JOIN::exec (this=0x7f0414012150) at /data/src/10.2-bug/sql/sql_select.cc:3309 #25 0x0000563d6f3dda5b in mysql_select (thd=0x7f0414000b00, tables=0x7f04140113d0, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7f0414012130, unit=0x7f04140046a0, select_lex=0x7f0414004dd8) at /data/src/10.2-bug/sql/sql_select.cc:3709 #26 0x0000563d6f3d22bc in handle_select (thd=0x7f0414000b00, lex=0x7f04140045d8, result=0x7f0414012130, setup_tables_done_option=0) at /data/src/10.2-bug/sql/sql_select.cc:373 #27 0x0000563d6f39e0fc in execute_sqlcom_select (thd=0x7f0414000b00, all_tables=0x7f04140113d0) at /data/src/10.2-bug/sql/sql_parse.cc:6428 #28 0x0000563d6f394159 in mysql_execute_command (thd=0x7f0414000b00) at /data/src/10.2-bug/sql/sql_parse.cc:3462 #29 0x0000563d6f3a1abe in mysql_parse (thd=0x7f0414000b00, rawbuf=0x7f0414011088 "SELECT a1.f1, a1.f2 FROM t1 AS a1, t1 AS a2", length=43, parser_state=0x7f04640e4200, is_com_multi=false, is_next_command=false) at /data/src/10.2-bug/sql/sql_parse.cc:7869 #30 0x0000563d6f38fa4a in dispatch_command (command=COM_QUERY, thd=0x7f0414000b00, packet=0x7f04140088a1 "", packet_length=43, is_com_multi=false, is_next_command=false) at /data/src/10.2-bug/sql/sql_parse.cc:1805 #31 0x0000563d6f38e3a8 in do_command (thd=0x7f0414000b00) at /data/src/10.2-bug/sql/sql_parse.cc:1360 #32 0x0000563d6f4db98d in do_handle_one_connection (connect=0x563d73106c40) at /data/src/10.2-bug/sql/sql_connect.cc:1354 #33 0x0000563d6f4db71a in handle_one_connection (arg=0x563d73106c40) at /data/src/10.2-bug/sql/sql_connect.cc:1260 #34 0x0000563d6f8f8e1a in pfs_spawn_thread (arg=0x563d731a8ad0) at /data/src/10.2-bug/storage/perfschema/pfs.cc:1863 #35 0x00007f046d198494 in start_thread (arg=0x7f04640e5700) at pthread_create.c:333 #36 0x00007f046b57e93f in clone () from /lib/x86_64-linux-gnu/libc.so.6 {noformat} The problem happens in concurrent tests on a normal server (without the sleep below), but very rarely. With the delay, for me it's reproducible reliably enough, although probably not 100%. I suppose it might require different sleep times on other machines. {noformat} diff --git a/storage/innobase/rem/rem0rec.cc b/storage/innobase/rem/rem0rec.cc index 37bf6e6..08cf8b8 100644 --- a/storage/innobase/rem/rem0rec.cc +++ b/storage/innobase/rem/rem0rec.cc @@ -2179,6 +2179,7 @@ rec_get_trx_id( ulint* offsets = offsets_; ut_ad(trx_id_col <= MAX_REF_PARTS); + my_sleep(200000); ut_ad(fil_page_index_page_check(page)); ut_ad(mach_read_from_8(page + PAGE_HEADER + PAGE_INDEX_ID) == index->id); {noformat} Run with {{\-\-mysqld=\-\-innodb_locks_unsafe_for_binlog}} and, if it's not reproducible right away, with {{--repeat=N}}. {code:sql} --source include/have_innodb.inc CREATE TABLE t1 (f1 INT NOT NULL AUTO_INCREMENT PRIMARY KEY, f2 INT) ENGINE=InnoDB; INSERT IGNORE INTO t1 VALUES (5,9),(NULL,3),(NULL,0),(4,105),(197,66),(0,0); ALTER TABLE t1 ADD KEY (f1); --connect (con1,localhost,root,,test) --connection default --send INSERT IGNORE INTO t1 SELECT f1, f2 FROM t1 ORDER BY f1, f2 LIMIT 4; --connection con1 DELETE FROM t1 ORDER BY f1, f2 LIMIT 1; SELECT a1.f1, a1.f2 FROM t1 AS a1, t1 AS a2; --disconnect con1 --connection default --reap # Cleanup DROP TABLE t1; {code} Reproducible on 10.2 and 10.3. I've never encountered it on 10.1 so far. {noformat:title=10.2 0c4d11e8199f4 ASAN} ================================================================= ==23938==ERROR: AddressSanitizer: heap-buffer-overflow on address 0x613000124018 at pc 0x55b828cf4a44 bp 0x7f860123dd40 sp 0x7f860123dd38 READ of size 1 at 0x613000124018 thread T28 #0 0x55b828cf4a43 in mach_read_from_2 /data/src/10.2-asan/storage/innobase/include/mach0data.ic:84 #1 0x55b828d5c961 in fil_page_get_type(unsigned char const*) /data/src/10.2-asan/storage/innobase/include/fil0fil.h:1322 #2 0x55b828f014d7 in rec_get_trx_id(unsigned char const*, dict_index_t const*) /data/src/10.2-asan/storage/innobase/rem/rem0rec.cc:2183 #3 0x55b828fd352d in row_sel_sec_rec_is_for_clust_rec /data/src/10.2-asan/storage/innobase/row/row0sel.cc:188 #4 0x55b828fe0492 in row_sel_get_clust_rec_for_mysql /data/src/10.2-asan/storage/innobase/row/row0sel.cc:3522 #5 0x55b828fe72b2 in row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long) /data/src/10.2-asan/storage/innobase/row/row0sel.cc:5242 #6 0x55b828d22b63 in ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) /data/src/10.2-asan/storage/innobase/handler/ha_innodb.cc:9823 #7 0x55b828d26136 in ha_innobase::index_first(unsigned char*) /data/src/10.2-asan/storage/innobase/handler/ha_innodb.cc:10261 #8 0x55b82858807f in handler::ha_index_first(unsigned char*) /data/src/10.2-asan/sql/handler.cc:2717 #9 0x55b8288fe18c in rr_index_first /data/src/10.2-asan/sql/records.cc:401 #10 0x55b8280b7b5a in join_init_read_record(st_join_table*) /data/src/10.2-asan/sql/sql_select.cc:19560 #11 0x55b8283586a5 in JOIN_TAB_SCAN::open() /data/src/10.2-asan/sql/sql_join_cache.cc:3339 #12 0x55b82835389c in JOIN_CACHE::join_matching_records(bool) /data/src/10.2-asan/sql/sql_join_cache.cc:2250 #13 0x55b828352922 in JOIN_CACHE::join_records(bool) /data/src/10.2-asan/sql/sql_join_cache.cc:2087 #14 0x55b8280b041c in sub_select_cache(JOIN*, st_join_table*, bool) /data/src/10.2-asan/sql/sql_select.cc:18417 #15 0x55b8280b092a in sub_select(JOIN*, st_join_table*, bool) /data/src/10.2-asan/sql/sql_select.cc:18589 #16 0x55b8280af449 in do_select /data/src/10.2-asan/sql/sql_select.cc:18184 #17 0x55b82804f912 in JOIN::exec_inner() /data/src/10.2-asan/sql/sql_select.cc:3514 #18 0x55b82804d5a9 in JOIN::exec() /data/src/10.2-asan/sql/sql_select.cc:3309 #19 0x55b82805098f in mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) /data/src/10.2-asan/sql/sql_select.cc:3709 #20 0x55b828030a3c in handle_select(THD*, LEX*, select_result*, unsigned long) /data/src/10.2-asan/sql/sql_select.cc:373 #21 0x55b827fb42dc in execute_sqlcom_select /data/src/10.2-asan/sql/sql_parse.cc:6428 #22 0x55b827fa1167 in mysql_execute_command(THD*) /data/src/10.2-asan/sql/sql_parse.cc:3462 #23 0x55b827fbc7d1 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2-asan/sql/sql_parse.cc:7869 #24 0x55b827f97cee in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2-asan/sql/sql_parse.cc:1805 #25 0x55b827f94d8d in do_command(THD*) /data/src/10.2-asan/sql/sql_parse.cc:1360 #26 0x55b8282cc7a7 in do_handle_one_connection(CONNECT*) /data/src/10.2-asan/sql/sql_connect.cc:1354 #27 0x55b8282cc1bc in handle_one_connection /data/src/10.2-asan/sql/sql_connect.cc:1260 #28 0x55b828cd21f9 in pfs_spawn_thread /data/src/10.2-asan/storage/perfschema/pfs.cc:1863 #29 0x7f861d702493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493) #30 0x7f861bae893e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e) AddressSanitizer can not describe address in more detail (wild memory access suspected). SUMMARY: AddressSanitizer: heap-buffer-overflow /data/src/10.2-asan/storage/innobase/include/mach0data.ic:84 mach_read_from_2 Shadow bytes around the buggy address: 0x0c268001c7b0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c7c0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c7d0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c7e0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c7f0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa =>0x0c268001c800: fa fa fa[fa]fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c810: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c820: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c830: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c840: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c850: 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 Contiguous container OOB:fc ASan internal: fe Thread T28 created by T0 here: #0 0x7f861d93bbba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba) #1 0x55b828cd27c1 in spawn_thread_v1 /data/src/10.2-asan/storage/perfschema/pfs.cc:1913 #2 0x55b827d9773f in inline_mysql_thread_create /data/src/10.2-asan/include/mysql/psi/mysql_thread.h:1239 #3 0x55b827dac56b in create_thread_to_handle_connection(CONNECT*) /data/src/10.2-asan/sql/mysqld.cc:6445 #4 0x55b827dacc70 in create_new_thread /data/src/10.2-asan/sql/mysqld.cc:6515 #5 0x55b827dadc81 in handle_connections_sockets() /data/src/10.2-asan/sql/mysqld.cc:6790 #6 0x55b827dabab8 in mysqld_main(int, char**) /data/src/10.2-asan/sql/mysqld.cc:6064 #7 0x55b827d95c6f in main /data/src/10.2-asan/sql/main.cc:25 #8 0x7f861ba202b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0) ==23938==ABORTING {noformat} |
{noformat:title=10.2 0c4d11e8199f4c7a with the injection below}
mysqld: /data/src/10.2-bug/storage/innobase/rem/rem0rec.cc:2183: trx_id_t rec_get_trx_id(const rec_t*, const dict_index_t*): Assertion `(fil_page_get_type(page) == 17855 || fil_page_get_type(page) == 17854)' failed. 171116 17:54:16 [ERROR] mysqld got signal 6 ; #7 0x00007f046b4c1ee2 in __assert_fail () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x0000563d6fa15548 in rec_get_trx_id (rec=0x7f0414010c7e "\200", index=0x7f041012fc88) at /data/src/10.2-bug/storage/innobase/rem/rem0rec.cc:2183 #9 0x0000563d6fa846bd in row_sel_sec_rec_is_for_clust_rec (sec_rec=0x7f046510407d "\200", sec_index=0x7f0410039ca8, clust_rec=0x7f0414010c7e "\200", clust_index=0x7f041012fc88, thr=0x7f041401e9a0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:188 #10 0x0000563d6fa8b1bf in row_sel_get_clust_rec_for_mysql (prebuilt=0x7f041401e288, sec_index=0x7f0410039ca8, rec=0x7f046510407d "\200", thr=0x7f041401e9a0, out_rec=0x7f04640e1aa8, offsets=0x7f04640e1ac8, offset_heap=0x7f04640e1ac0, vrow=0x0, mtr=0x7f04640e25c0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:3522 #11 0x0000563d6fa8f023 in row_search_mvcc (buf=0x7f041401de28 "\377", mode=PAGE_CUR_G, prebuilt=0x7f041401e288, match_mode=0, direction=0) at /data/src/10.2-bug/storage/innobase/row/row0sel.cc:5242 #12 0x0000563d6f91c233 in ha_innobase::index_read (this=0x7f041401c6d8, buf=0x7f041401de28 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /data/src/10.2-bug/storage/innobase/handler/ha_innodb.cc:9823 #13 0x0000563d6f91d5d6 in ha_innobase::index_first (this=0x7f041401c6d8, buf=0x7f041401de28 "\377") at /data/src/10.2-bug/storage/innobase/handler/ha_innodb.cc:10261 #14 0x0000563d6f60a63b in handler::ha_index_first (this=0x7f041401c6d8, buf=0x7f041401de28 "\377") at /data/src/10.2-bug/sql/handler.cc:2717 #15 0x0000563d6f77460f in rr_index_first (info=0x7f0414013c30) at /data/src/10.2-bug/sql/records.cc:401 #16 0x0000563d6f4058e2 in join_init_read_record (tab=0x7f0414013b68) at /data/src/10.2-bug/sql/sql_select.cc:19560 #17 0x0000563d6f5217fe in JOIN_TAB_SCAN::open (this=0x7f0414014988) at /data/src/10.2-bug/sql/sql_join_cache.cc:3339 #18 0x0000563d6f51fd0c in JOIN_CACHE::join_matching_records (this=0x7f0414014858, skip_last=false) at /data/src/10.2-bug/sql/sql_join_cache.cc:2250 #19 0x0000563d6f51f890 in JOIN_CACHE::join_records (this=0x7f0414014858, skip_last=false) at /data/src/10.2-bug/sql/sql_join_cache.cc:2087 #20 0x0000563d6f40330a in sub_select_cache (join=0x7f0414012150, join_tab=0x7f0414013b68, end_of_records=true) at /data/src/10.2-bug/sql/sql_select.cc:18417 #21 0x0000563d6f40351c in sub_select (join=0x7f0414012150, join_tab=0x7f04140137b8, end_of_records=true) at /data/src/10.2-bug/sql/sql_select.cc:18589 #22 0x0000563d6f402d32 in do_select (join=0x7f0414012150, procedure=0x0) at /data/src/10.2-bug/sql/sql_select.cc:18184 #23 0x0000563d6f3dd3e3 in JOIN::exec_inner (this=0x7f0414012150) at /data/src/10.2-bug/sql/sql_select.cc:3514 #24 0x0000563d6f3dc892 in JOIN::exec (this=0x7f0414012150) at /data/src/10.2-bug/sql/sql_select.cc:3309 #25 0x0000563d6f3dda5b in mysql_select (thd=0x7f0414000b00, tables=0x7f04140113d0, wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7f0414012130, unit=0x7f04140046a0, select_lex=0x7f0414004dd8) at /data/src/10.2-bug/sql/sql_select.cc:3709 #26 0x0000563d6f3d22bc in handle_select (thd=0x7f0414000b00, lex=0x7f04140045d8, result=0x7f0414012130, setup_tables_done_option=0) at /data/src/10.2-bug/sql/sql_select.cc:373 #27 0x0000563d6f39e0fc in execute_sqlcom_select (thd=0x7f0414000b00, all_tables=0x7f04140113d0) at /data/src/10.2-bug/sql/sql_parse.cc:6428 #28 0x0000563d6f394159 in mysql_execute_command (thd=0x7f0414000b00) at /data/src/10.2-bug/sql/sql_parse.cc:3462 #29 0x0000563d6f3a1abe in mysql_parse (thd=0x7f0414000b00, rawbuf=0x7f0414011088 "SELECT a1.f1, a1.f2 FROM t1 AS a1, t1 AS a2", length=43, parser_state=0x7f04640e4200, is_com_multi=false, is_next_command=false) at /data/src/10.2-bug/sql/sql_parse.cc:7869 #30 0x0000563d6f38fa4a in dispatch_command (command=COM_QUERY, thd=0x7f0414000b00, packet=0x7f04140088a1 "", packet_length=43, is_com_multi=false, is_next_command=false) at /data/src/10.2-bug/sql/sql_parse.cc:1805 #31 0x0000563d6f38e3a8 in do_command (thd=0x7f0414000b00) at /data/src/10.2-bug/sql/sql_parse.cc:1360 #32 0x0000563d6f4db98d in do_handle_one_connection (connect=0x563d73106c40) at /data/src/10.2-bug/sql/sql_connect.cc:1354 #33 0x0000563d6f4db71a in handle_one_connection (arg=0x563d73106c40) at /data/src/10.2-bug/sql/sql_connect.cc:1260 #34 0x0000563d6f8f8e1a in pfs_spawn_thread (arg=0x563d731a8ad0) at /data/src/10.2-bug/storage/perfschema/pfs.cc:1863 #35 0x00007f046d198494 in start_thread (arg=0x7f04640e5700) at pthread_create.c:333 #36 0x00007f046b57e93f in clone () from /lib/x86_64-linux-gnu/libc.so.6 {noformat} The problem happens in concurrent tests on a normal server (without the sleep below), but very rarely. With the delay, for me it's reproducible reliably enough, although probably not 100%. I suppose it might require different sleep times on other machines. {noformat} diff --git a/storage/innobase/rem/rem0rec.cc b/storage/innobase/rem/rem0rec.cc index 37bf6e6..08cf8b8 100644 --- a/storage/innobase/rem/rem0rec.cc +++ b/storage/innobase/rem/rem0rec.cc @@ -2179,6 +2179,7 @@ rec_get_trx_id( ulint* offsets = offsets_; ut_ad(trx_id_col <= MAX_REF_PARTS); + my_sleep(200000); ut_ad(fil_page_index_page_check(page)); ut_ad(mach_read_from_8(page + PAGE_HEADER + PAGE_INDEX_ID) == index->id); {noformat} {color:red}Run with {{\-\-mysqld=\-\-innodb_locks_unsafe_for_binlog}}{color} and, if it's not reproducible right away, with {{--repeat=N}}. {code:sql} --source include/have_innodb.inc CREATE TABLE t1 (f1 INT NOT NULL AUTO_INCREMENT PRIMARY KEY, f2 INT) ENGINE=InnoDB; INSERT IGNORE INTO t1 VALUES (5,9),(NULL,3),(NULL,0),(4,105),(197,66),(0,0); ALTER TABLE t1 ADD KEY (f1); --connect (con1,localhost,root,,test) --connection default --send INSERT IGNORE INTO t1 SELECT f1, f2 FROM t1 ORDER BY f1, f2 LIMIT 4; --connection con1 DELETE FROM t1 ORDER BY f1, f2 LIMIT 1; SELECT a1.f1, a1.f2 FROM t1 AS a1, t1 AS a2; --disconnect con1 --connection default --reap # Cleanup DROP TABLE t1; {code} Reproducible on 10.2 and 10.3. I've never encountered it on 10.1 so far. {noformat:title=10.2 0c4d11e8199f4 ASAN} ================================================================= ==23938==ERROR: AddressSanitizer: heap-buffer-overflow on address 0x613000124018 at pc 0x55b828cf4a44 bp 0x7f860123dd40 sp 0x7f860123dd38 READ of size 1 at 0x613000124018 thread T28 #0 0x55b828cf4a43 in mach_read_from_2 /data/src/10.2-asan/storage/innobase/include/mach0data.ic:84 #1 0x55b828d5c961 in fil_page_get_type(unsigned char const*) /data/src/10.2-asan/storage/innobase/include/fil0fil.h:1322 #2 0x55b828f014d7 in rec_get_trx_id(unsigned char const*, dict_index_t const*) /data/src/10.2-asan/storage/innobase/rem/rem0rec.cc:2183 #3 0x55b828fd352d in row_sel_sec_rec_is_for_clust_rec /data/src/10.2-asan/storage/innobase/row/row0sel.cc:188 #4 0x55b828fe0492 in row_sel_get_clust_rec_for_mysql /data/src/10.2-asan/storage/innobase/row/row0sel.cc:3522 #5 0x55b828fe72b2 in row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long) /data/src/10.2-asan/storage/innobase/row/row0sel.cc:5242 #6 0x55b828d22b63 in ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function) /data/src/10.2-asan/storage/innobase/handler/ha_innodb.cc:9823 #7 0x55b828d26136 in ha_innobase::index_first(unsigned char*) /data/src/10.2-asan/storage/innobase/handler/ha_innodb.cc:10261 #8 0x55b82858807f in handler::ha_index_first(unsigned char*) /data/src/10.2-asan/sql/handler.cc:2717 #9 0x55b8288fe18c in rr_index_first /data/src/10.2-asan/sql/records.cc:401 #10 0x55b8280b7b5a in join_init_read_record(st_join_table*) /data/src/10.2-asan/sql/sql_select.cc:19560 #11 0x55b8283586a5 in JOIN_TAB_SCAN::open() /data/src/10.2-asan/sql/sql_join_cache.cc:3339 #12 0x55b82835389c in JOIN_CACHE::join_matching_records(bool) /data/src/10.2-asan/sql/sql_join_cache.cc:2250 #13 0x55b828352922 in JOIN_CACHE::join_records(bool) /data/src/10.2-asan/sql/sql_join_cache.cc:2087 #14 0x55b8280b041c in sub_select_cache(JOIN*, st_join_table*, bool) /data/src/10.2-asan/sql/sql_select.cc:18417 #15 0x55b8280b092a in sub_select(JOIN*, st_join_table*, bool) /data/src/10.2-asan/sql/sql_select.cc:18589 #16 0x55b8280af449 in do_select /data/src/10.2-asan/sql/sql_select.cc:18184 #17 0x55b82804f912 in JOIN::exec_inner() /data/src/10.2-asan/sql/sql_select.cc:3514 #18 0x55b82804d5a9 in JOIN::exec() /data/src/10.2-asan/sql/sql_select.cc:3309 #19 0x55b82805098f in mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) /data/src/10.2-asan/sql/sql_select.cc:3709 #20 0x55b828030a3c in handle_select(THD*, LEX*, select_result*, unsigned long) /data/src/10.2-asan/sql/sql_select.cc:373 #21 0x55b827fb42dc in execute_sqlcom_select /data/src/10.2-asan/sql/sql_parse.cc:6428 #22 0x55b827fa1167 in mysql_execute_command(THD*) /data/src/10.2-asan/sql/sql_parse.cc:3462 #23 0x55b827fbc7d1 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2-asan/sql/sql_parse.cc:7869 #24 0x55b827f97cee in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2-asan/sql/sql_parse.cc:1805 #25 0x55b827f94d8d in do_command(THD*) /data/src/10.2-asan/sql/sql_parse.cc:1360 #26 0x55b8282cc7a7 in do_handle_one_connection(CONNECT*) /data/src/10.2-asan/sql/sql_connect.cc:1354 #27 0x55b8282cc1bc in handle_one_connection /data/src/10.2-asan/sql/sql_connect.cc:1260 #28 0x55b828cd21f9 in pfs_spawn_thread /data/src/10.2-asan/storage/perfschema/pfs.cc:1863 #29 0x7f861d702493 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x7493) #30 0x7f861bae893e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe893e) AddressSanitizer can not describe address in more detail (wild memory access suspected). SUMMARY: AddressSanitizer: heap-buffer-overflow /data/src/10.2-asan/storage/innobase/include/mach0data.ic:84 mach_read_from_2 Shadow bytes around the buggy address: 0x0c268001c7b0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c7c0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c7d0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c7e0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c7f0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa =>0x0c268001c800: fa fa fa[fa]fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c810: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c820: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c830: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c840: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa 0x0c268001c850: 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 Contiguous container OOB:fc ASan internal: fe Thread T28 created by T0 here: #0 0x7f861d93bbba in pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.1+0x23bba) #1 0x55b828cd27c1 in spawn_thread_v1 /data/src/10.2-asan/storage/perfschema/pfs.cc:1913 #2 0x55b827d9773f in inline_mysql_thread_create /data/src/10.2-asan/include/mysql/psi/mysql_thread.h:1239 #3 0x55b827dac56b in create_thread_to_handle_connection(CONNECT*) /data/src/10.2-asan/sql/mysqld.cc:6445 #4 0x55b827dacc70 in create_new_thread /data/src/10.2-asan/sql/mysqld.cc:6515 #5 0x55b827dadc81 in handle_connections_sockets() /data/src/10.2-asan/sql/mysqld.cc:6790 #6 0x55b827dabab8 in mysqld_main(int, char**) /data/src/10.2-asan/sql/mysqld.cc:6064 #7 0x55b827d95c6f in main /data/src/10.2-asan/sql/main.cc:25 #8 0x7f861ba202b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0) ==23938==ABORTING {noformat} |
| Attachment | threads_full [ 44545 ] |
| Assignee | Elena Stepanova [ elenst ] | Marko Mäkelä [ marko ] |
| Sprint | 10.2.12 [ 216 ] |
| Affects Version/s | 10.3.1 [ 22532 ] | |
| Affects Version/s | 10.2.7 [ 22543 ] | |
| Affects Version/s | 10.2 [ 14601 ] |
| issue.field.resolutiondate | 2018-01-08 08:59:08.0 | 2018-01-08 08:59:08.536 |
| Fix Version/s | 10.3.4 [ 22904 ] | |
| Fix Version/s | 10.2.13 [ 22910 ] | |
| Fix Version/s | 10.2 [ 14601 ] | |
| Resolution | Fixed [ 1 ] | |
| Status | Open [ 1 ] | Closed [ 6 ] |
| Workflow | MariaDB v3 [ 81980 ] | MariaDB v4 [ 152588 ] |
This is a bogus debug assertion. Since MariaDB 10.2.7, the rec passed to rec_get_trx_id() is not necessarily residing in a buffer pool page. Therefore, we must remove the debug assertions that assume so.