[MDEV-18451] Server crashes in maria_create_trn_for_mysql upon ALTER TABLE Created: 2019-02-01  Updated: 2019-10-28  Resolved: 2019-10-16

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Alter Table, Locking, Storage Engine - Aria
Affects Version/s: 10.1, 10.2, 10.3
Fix Version/s: 10.2.28, 10.3.19

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: not-10.4

Attachments: Zip Archive data-test007.zip     File mysql.err     HTML File threads     HTML File threads_full    
Issue Links:
Relates
relates to MDEV-15572 view.test, server crash with --big-ta... Closed

 Description    

CREATE TABLE t1 (a INT) ENGINE=Aria;
 
CREATE TABLE t2 (b INT) ENGINE=Aria;
 
CREATE OR REPLACE VIEW v2 AS SELECT * FROM t2 ;
 
 
 
LOCK TABLES t1 WRITE, t2 AS t2a WRITE, v2 WRITE CONCURRENT, t2 WRITE;
 
 
 
ALTER TABLE t1 FORCE;
 
ALTER TABLE t2 CHANGE b c VARBINARY(30000), ALGORITHM=INPLACE;
 
 
 
# Cleanup
 
UNLOCK TABLES;
 
DROP VIEW v2;
 
DROP TABLE t1, t2;

10.2 bc8d173b

 
#3  <signal handler called>
 
#4  0x000055a3c1c05381 in maria_create_trn_for_mysql (info=0x7f3f9405fb60) at /data/src/10.2/storage/maria/ha_maria.cc:925
 
#5  0x000055a3c1bf437a in _ma_setup_live_state (info=0x7f3f9405fb60) at /data/src/10.2/storage/maria/ma_state.c:65
 
#6  0x000055a3c1c0abf7 in ha_maria::implicit_commit (thd=0x7f3f94000b00, new_trn=true) at /data/src/10.2/storage/maria/ha_maria.cc:2943
 
#7  0x000055a3c19fcb1b in ha_commit_trans (thd=0x7f3f94000b00, all=true) at /data/src/10.2/sql/handler.cc:1356
 
#8  0x000055a3c18e1af1 in trans_commit_implicit (thd=0x7f3f94000b00) at /data/src/10.2/sql/transaction.cc:368
 
#9  0x000055a3c1787b69 in mysql_execute_command (thd=0x7f3f94000b00) at /data/src/10.2/sql/sql_parse.cc:6339
 
#10 0x000055a3c178c565 in mysql_parse (thd=0x7f3f94000b00, rawbuf=0x7f3f94012458 "ALTER TABLE t2 CHANGE b c VARBINARY(30000), ALGORITHM=INPLACE", length=61, parser_state=0x7f3fa41d3200, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:8013
 
#11 0x000055a3c177a062 in dispatch_command (command=COM_QUERY, thd=0x7f3f94000b00, packet=0x7f3f9408d761 "ALTER TABLE t2 CHANGE b c VARBINARY(30000), ALGORITHM=INPLACE", packet_length=61, is_com_multi=false, is_next_command=false) at /data/src/10.2/sql/sql_parse.cc:1832
 
#12 0x000055a3c177897f in do_command (thd=0x7f3f94000b00) at /data/src/10.2/sql/sql_parse.cc:1386
 
#13 0x000055a3c18cc069 in do_handle_one_connection (connect=0x55a3c3c79b00) at /data/src/10.2/sql/sql_connect.cc:1335
 
#14 0x000055a3c18cbdf6 in handle_one_connection (arg=0x55a3c3c79b00) at /data/src/10.2/sql/sql_connect.cc:1241
 
#15 0x000055a3c1cf40fa in pfs_spawn_thread (arg=0x55a3c3bdd870) at /data/src/10.2/storage/perfschema/pfs.cc:1862
 
#16 0x00007f3fabfec494 in start_thread (arg=0x7f3fa41d4700) at pthread_create.c:333
 
#17 0x00007f3fa9fb493f in clone () from /lib/x86_64-linux-gnu/libc.so.6

Couldn't reproduce on 10.4, and there is no evidence that it happens there.
Couldn't reproduce with the test case above on 10.1, although the failure has been seen earlier in concurrent tests on 10.1, see the stack trace below.

The test case is fragile, even small changes often make MDEV-15572 start happening instead.

10.1 6e2af7d0

 
#3  <signal handler called>
 
#4  0x00005644c5bdcbb5 in maria_create_trn_for_mysql (info=0x7ff8740a4620) at /home/vsts/src/storage/maria/ha_maria.cc:914
 
#5  0x00005644c5bcbe0a in _ma_setup_live_state (info=0x7ff8740a4620) at /home/vsts/src/storage/maria/ma_state.c:65
 
#6  0x00005644c5be22b0 in ha_maria::implicit_commit (thd=0x5644c86dcc70, new_trn=true) at /home/vsts/src/storage/maria/ha_maria.cc:2929
 
#7  0x00005644c5a0f8dd in ha_commit_trans (thd=0x5644c86dcc70, all=true) at /home/vsts/src/sql/handler.cc:1357
 
#8  0x00005644c59172a4 in trans_commit_implicit (thd=0x5644c86dcc70) at /home/vsts/src/sql/transaction.cc:294
 
#9  0x00005644c57d5ab2 in mysql_execute_command (thd=0x5644c86dcc70) at /home/vsts/src/sql/sql_parse.cc:5814
 
#10 0x00005644c57d9f13 in mysql_parse (thd=0x5644c86dcc70, rawbuf=0x7ff868012828 "ALTER IGNORE TABLE `table0_aria_int_autoinc` DROP FOREIGN KEY f /* 100307, ALGORITHM=NOCOPY */, LOCK=SHARED /* QNO 387 CON_ID 11 */", length=131, parser_state=0x7ff8cc151670) at /home/vsts/src/sql/sql_parse.cc:7468
 
#11 0x00005644c57c8437 in dispatch_command (command=COM_QUERY, thd=0x5644c86dcc70, packet=0x5644c86e4111 "ALTER IGNORE TABLE `table0_aria_int_autoinc` DROP FOREIGN KEY f /*!100307, ALGORITHM=NOCOPY */, LOCK=SHARED /* QNO 387 CON_ID 11 */ ", packet_length=132) at /home/vsts/src/sql/sql_parse.cc:1496
 
#12 0x00005644c57c71a9 in do_command (thd=0x5644c86dcc70) at /home/vsts/src/sql/sql_parse.cc:1124
 
#13 0x00005644c59028f2 in do_handle_one_connection (thd_arg=0x5644c86dcc70) at /home/vsts/src/sql/sql_connect.cc:1330
 
#14 0x00005644c5902641 in handle_one_connection (arg=0x5644c86dcc70) at /home/vsts/src/sql/sql_connect.cc:1242
 
#15 0x00007ff8cffd46ba in start_thread (arg=0x7ff8cc152b00) at pthread_create.c:333
 
#16 0x00007ff8cf67f41d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
 
 
 
Query (0x7ff868012828): ALTER IGNORE TABLE `table0_aria_int_autoinc` DROP FOREIGN KEY f /* 100307, ALGORITHM=NOCOPY */, LOCK=SHARED /* QNO 387 CON_ID 11 */
 
Connection ID (thread ID): 11
 
Status: NOT_KILLED

Logs and data from 10.1 occurrence are attached.

 Comments   
Comment by Michael Widenius [ 2019-10-16 ]

Problem was that when table was locked many times, not all instances where removed from the transaction by
_ma_remove_table_from_trnman()

Comment by Michael Widenius [ 2019-10-16 ]

Pushed into 10.2

Comment by Elena Stepanova [ 2019-10-28 ]

A somewhat simpler test case and failure still present on 10.1 (expectedly, since it was only fixed in 10.2+), adding for the purpose of future JIRA searches.

CREATE  TABLE t1 (a INT) ENGINE=Aria;
 
CREATE  TABLE t2 (b INT) ENGINE=Aria;
 
LOCK TABLES t1 AS x READ, t2 READ, t1 WRITE;
 
ALTER TABLE t1 ADD KEY (a);
 
 
# Cleanup
 
UNLOCK TABLES;
 
DROP TABLE t1, t2;

10.1 ASAN a41d4297

 
==22712==ERROR: AddressSanitizer: heap-use-after-free on address 0x6290000f5280 at pc 0x55cecfc14721 bp 0x7f66f5ea33c0 sp 0x7f66f5ea33b8
 
READ of size 8 at 0x6290000f5280 thread T6
 
    #0 0x55cecfc14720 in ha_maria::implicit_commit(THD*, bool) /data/src/10.1/storage/maria/ha_maria.cc:2922
 
    #1 0x55cecf768e9d in ha_commit_trans(THD*, bool) /data/src/10.1/sql/handler.cc:1391
 
    #2 0x55cecf5747ff in trans_commit_implicit(THD*) /data/src/10.1/sql/transaction.cc:294
 
    #3 0x55cecf2941b2 in mysql_execute_command(THD*) /data/src/10.1/sql/sql_parse.cc:5555
 
    #4 0x55cecf29611b in mysql_parse(THD*, char*, unsigned int, Parser_state*) /data/src/10.1/sql/sql_parse.cc:7209
 
    #5 0x55cecf29d453 in dispatch_command(enum_server_command, THD*, char*, unsigned int) /data/src/10.1/sql/sql_parse.cc:1499
 
    #6 0x55cecf2a25fa in do_command(THD*) /data/src/10.1/sql/sql_parse.cc:1131
 
    #7 0x55cecf547de2 in do_handle_one_connection(THD*) /data/src/10.1/sql/sql_connect.cc:1331
 
    #8 0x55cecf54839a in handle_one_connection /data/src/10.1/sql/sql_connect.cc:1242
 
    #9 0x55cecfead500 in pfs_spawn_thread /data/src/10.1/storage/perfschema/pfs.cc:1861
 
    #10 0x7f670154a4a3 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x74a3)
 
    #11 0x7f66fff60d0e in __clone (/lib/x86_64-linux-gnu/libc.so.6+0xe8d0e)
 
 
 
0x6290000f5280 is located 128 bytes inside of 18420-byte region [0x6290000f5200,0x6290000f99f4)
 
freed by thread T6 here:
 
    #0 0x7f6701821a10 in free (/usr/lib/x86_64-linux-gnu/libasan.so.3+0xc1a10)
 
    #1 0x55ced0557ade in free_memory /data/src/10.1/mysys/safemalloc.c:276
 
 
 
previously allocated by thread T6 here:
 
    #0 0x7f6701821d28 in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.3+0xc1d28)
 
    #1 0x55ced0557c82 in sf_malloc /data/src/10.1/mysys/safemalloc.c:115
 
    #2 0x55ced06b4df2  (/data/bld/10.1-asan/bin/mysqld+0x1dcfdf2)
 
 
 
Thread T6 created by T0 here:
 
    #0 0x7f6701790f59 in __interceptor_pthread_create (/usr/lib/x86_64-linux-gnu/libasan.so.3+0x30f59)
 
    #1 0x55cecfeb8e84 in spawn_thread_v1 /data/src/10.1/storage/perfschema/pfs.cc:1911
 
 
 
SUMMARY: AddressSanitizer: heap-use-after-free /data/src/10.1/storage/maria/ha_maria.cc:2922 in ha_maria::implicit_commit(THD*, bool)
 
Shadow bytes around the buggy address:
 
  0x0c5280016a00: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5280016a10: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5280016a20: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5280016a30: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
 
  0x0c5280016a40: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
=>0x0c5280016a50:[fd]fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5280016a60: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5280016a70: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5280016a80: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5280016a90: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
  0x0c5280016aa0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
 
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
 
==22712==ABORTING

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