[MDEV-14865] Assertion `share->now_transactional == share->base.born_transactional' failed in maria_close Created: 2018-01-04  Updated: 2023-12-05

Status: Stalled
Project: MariaDB Server
Component/s: Storage Engine - Aria
Affects Version/s: 10.2, 10.3, 10.4, 10.5, 10.6, 10.7, 10.8
Fix Version/s: 10.4, 10.5, 10.6

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Michael Widenius
Resolution: Unresolved Votes: 0
Labels: None
Environment:

Ubuntu 17.10 but most probably unimportant


Attachments: File MDEV-14865.tgz     File MDEV-14865_new.tgz     File mysql.log     HTML File threads    
Issue Links:
Relates
relates to MDEV-20518 BACKUP STAGE: Assertion `share->now_t... Stalled

 Description   

10.3 c664c48726cdfa

mysqld: /data/src/10.3/storage/maria/ma_close.c:182: maria_close: Assertion `share->now_transactional == share->base.born_transactional' failed.
180103 11:29:49 [ERROR] mysqld got signal 6 ;
 
Query (0x7fa040013828): ALTER TABLE t1 ADD UNIQUE KEY uidx ( col1 ) /* QNO 536 CON_ID 16 */
Connection ID (thread ID): 16
Status: NOT_KILLED

#5  0x00007fa0c50ba448 in __GI_abort () at abort.c:89
#6  0x00007fa0c50b2266 in __assert_fail_base (fmt=0x7fa0c51eaf18 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x7fa0c86483f0 "share->now_transactional == share->base.born_transactional", file=file@entry=0x7fa0c8648230 "/data/src/10.3/storage/maria/ma_close.c", line=line@entry=182, function=function@entry=0x7fa0c8648463 <__PRETTY_FUNCTION__.15205> "maria_close") at assert.c:92
#7  0x00007fa0c50b2312 in __GI___assert_fail (assertion=0x7fa0c86483f0 "share->now_transactional == share->base.born_transactional", file=0x7fa0c8648230 "/data/src/10.3/storage/maria/ma_close.c", line=182, function=0x7fa0c8648463 <__PRETTY_FUNCTION__.15205> "maria_close") at assert.c:101
#8  0x00007fa0c815a3f5 in maria_close (info=0x7fa03408f490) at /data/src/10.3/storage/maria/ma_close.c:182
#9  0x00007fa0c80d2924 in ha_maria::close (this=0x7fa03408ed08) at /data/src/10.3/storage/maria/ha_maria.cc:1274
#10 0x00007fa0c7a7e0f8 in handler::ha_close (this=0x7fa03408ed08) at /data/src/10.3/sql/handler.cc:2711
#11 0x00007fa0c78b2a7d in closefrm (table=0x7fa03408e0e0) at /data/src/10.3/sql/table.cc:3454
#12 0x00007fa0c79b8940 in intern_close_table (table=0x7fa03408e0e0) at /data/src/10.3/sql/table_cache.cc:222
#13 0x00007fa0c79b8adf in tc_remove_table (table=0x7fa03408e0e0) at /data/src/10.3/sql/table_cache.cc:260
#14 0x00007fa0c79b944c in tc_release_table (table=0x7fa03408e0e0) at /data/src/10.3/sql/table_cache.cc:472
#15 0x00007fa0c7724436 in close_thread_table (thd=0x7fa040000b00, table_ptr=0x7fa040000bc0) at /data/src/10.3/sql/sql_base.cc:906
#16 0x00007fa0c7723c9b in close_all_tables_for_name (thd=0x7fa040000b00, share=0x7fa0300a6998, extra=HA_EXTRA_NOT_USED, skip_table=0x0) at /data/src/10.3/sql/sql_base.cc:674
#17 0x00007fa0c7880c80 in mysql_alter_table (thd=0x7fa040000b00, new_db=0x7fa040013f70 "test", new_name=0x0, create_info=0x7fa0c40ecdb0, table_list=0x7fa040013960, alter_info=0x7fa0c40ecd00, order_num=0, order=0x0, ignore=false) at /data/src/10.3/sql/sql_table.cc:9614
#18 0x00007fa0c790088b in Sql_cmd_alter_table::execute (this=0x7fa040014040, thd=0x7fa040000b00) at /data/src/10.3/sql/sql_alter.cc:331
#19 0x00007fa0c77b18f8 in mysql_execute_command (thd=0x7fa040000b00) at /data/src/10.3/sql/sql_parse.cc:6251
#20 0x00007fa0c77b6308 in mysql_parse (thd=0x7fa040000b00, rawbuf=0x7fa040013828 "ALTER TABLE t1 ADD UNIQUE KEY uidx ( col1 ) /* QNO 536 CON_ID 16 */", length=67, parser_state=0x7fa0c40ee660, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:7966
#21 0x00007fa0c77a3c7d in dispatch_command (command=COM_QUERY, thd=0x7fa040000b00, packet=0x7fa04000b061 "ALTER TABLE t1 ADD UNIQUE KEY uidx ( col1 ) /* QNO 536 CON_ID 16 */ ", packet_length=68, is_com_multi=false, is_next_command=false) at /data/src/10.3/sql/sql_parse.cc:1824
#22 0x00007fa0c77a26b1 in do_command (thd=0x7fa040000b00) at /data/src/10.3/sql/sql_parse.cc:1369
#23 0x00007fa0c78fb400 in do_handle_one_connection (connect=0x7fa0cb7460c0) at /data/src/10.3/sql/sql_connect.cc:1420
#24 0x00007fa0c78fb18d in handle_one_connection (arg=0x7fa0cb7460c0) at /data/src/10.3/sql/sql_connect.cc:1326
#25 0x00007fa0c6d19064 in start_thread (arg=0x7fa0c40ef700) at pthread_create.c:309
#26 0x00007fa0c516c62d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111



 Comments   
Comment by Matthias Leich [ 2018-08-16 ]

Replay with
- 10.3 commit 8716bb3b72b7f5fed69b6dde413c2138f6d175b2 (2018-08-16)
- 10.4 commit ead9a34a3e934f607c2ea7a6c68f7f6d9d29b5bd (2018-08-16)
compiled with debug  (10.3.10-MariaDB-debug-log/10.4.0-MariaDB-debug-log)
 and my MTR based test.
All runs of that test with non debug binaries (same source) did not show issues.
 
How to replay with the test within the archive?
0. Use some Unix because the MTR test calls a shellscript.
1. Make maybe some out of source build like in some directory
   <source>/bld_debug
2. Set MTR_BINDIR if its an out of source build
    export MTR_BINDIR=`pwd`
3. cd <source>/mysql-test
4. tar xvzf <path to MDEV-14865.tgz>
5. ./mysql-test-run.pl --mem --record bug_aria1 2>&1 | tee prt
    ~ 200s runtime required
6. Please do not forget to run   unset MTR_BINDIR  as soon as you are finished with
    experimenting+debugging. I had some ugly experiences with wrong set MTR_BINDIR.
I apologize in advance if the shellscript mysqltest_background.sh makes trouble.
Its a non matured prototype.
 
Content of MDEV-14865.tgz
- main/bug_aria1.test            MTR test script
- mysqltest_background.sh   Shellscript which gets called by the MTR test script
- prt_debug                           Protocol of my test run on 10.3 compiled with debug

Comment by Matthias Leich [ 2018-08-16 ]

The MTR based replay test does roughly the same like the RQG based test.
RQG grammar just as example of the SQL involved
query:
ALTER TABLE t1 ADD INDEX idx1 ( col1 ) ; CHECK TABLE t1 ; DROP INDEX idx1 ON t1 |
ALTER TABLE t1 ADD INDEX idx2 ( col2 ) ; CHECK TABLE t1 ; DROP INDEX idx2 ON t1 |
ALTER TABLE t1 ADD INDEX idx3 ( col3 ) ; CHECK TABLE t1 ; DROP INDEX idx3 ON t1 ;

query_init:
CREATE TABLE IF NOT EXISTS t1 (col1 INT, col2 INT, col3 INT) ENGINE = Aria ;

Comment by Michael Widenius [ 2018-08-24 ]

The problem was that when a mysql.proc table was
opened for reading it was added to the current Aria
transaction context but never properly deleted from
it. Normally this isn't a problem, except if the
mysql.proc table is closed before the transaction
ended, which happened in this test case.

Fixed by removing mysql.proc from the transaction
context before closing the table.

Comment by Michael Widenius [ 2018-11-21 ]

I tried to repeat what you did (without a separate build tree), using your exact command line but was not able to repeat the issue in latest 10.3
I have fixed some things in Aria since your test case, could you please retry again ?

Comment by Matthias Leich [ 2018-12-17 ]

I can confirm that my previous MTR based replay test (in MDEV-14865.tgz) using a 
   ALTER TABLE t1 ADD INDEX idx1 ( col1 ) ;   (quite similar to the ALTER TABLE t1 ADD UNIQUE KEY uidx ( col1 ) mentioned on top of report
   CHECK TABLE t1 ;
   DROP INDEX idx1 ON t1 ;
does no more replay the assert on MariaDB 10.2 32eeed21297f0e5a2836daca058e38dbe3a82bc4 2018-12-17.
But another sequence (three connections run the sequence concurrent)
   ALTER TABLE t1 CHANGE COLUMN col1 col1_copy INT ;
   ALTER TABLE t1 CHANGE COLUMN col1_copy col1 INT ;
   CHECK TABLE t1 ;
shows the same assert (example from MariaDB 10.2 32eeed21297f0e5a2836daca058e38dbe3a82bc4)
Version: '10.2.20-MariaDB-debug-log'  socket: ...
mysqld: storage/maria/ma_close.c:184: maria_close: Assertion `share->now_transactional == share->base.born_transactional' failed.
...
ALTER TABLE t1 CHANGE COLUMN col1 col1_copy INT;
Connection ID (thread ID): 7
Status: NOT_KILLED
...
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
#5  0x00007f8d011d2f5d in __GI_abort () at abort.c:90
#6  0x00007f8d011c8f17 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x56103485e210 "share->now_transactional == share->base.born_transactional", file=file@entry=0x56103485e008 "storage/maria/ma_close.c", line=line@entry=184, function=function@entry=0x56103485e288 <__PRETTY_FUNCTION__.15976> "maria_close") at assert.c:92
#7  0x00007f8d011c8fc2 in __GI___assert_fail (assertion=0x56103485e210 "share->now_transactional == share->base.born_transactional", file=0x56103485e008 "storage/maria/ma_close.c", line=184, function=0x56103485e288 <__PRETTY_FUNCTION__.15976> "maria_close") at assert.c:101
#8  0x00005610343c42c6 in maria_close (info=0x7f8cdc01b158) at storage/maria/ma_close.c:184
#9  0x000056103433fd2c in ha_maria::close (this=0x7f8cdc01a3a0) at storage/maria/ha_maria.cc:1274
#10 0x0000561033d9b3f5 in handler::ha_close (this=0x7f8cdc01a3a0) at sql/handler.cc:2567
#11 0x0000561033c23a77 in closefrm (table=0x7f8cdc019808) at sql/table.cc:3448
#12 0x0000561033d0d860 in intern_close_table (table=0x7f8cdc019808) at sql/table_cache.cc:222
#13 0x0000561033d0da00 in tc_remove_table (table=0x7f8cdc019808) at sql/table_cache.cc:260
#14 0x0000561033d0e24c in tc_release_table (table=0x7f8cdc019808) at sql/table_cache.cc:461
#15 0x0000561033aaaa89 in close_thread_table (thd=0x7f8cdc000ce8, table_ptr=0x7f8cdc000dc8) at sql/sql_base.cc:903
#16 0x0000561033aaa3e0 in close_all_tables_for_name (thd=0x7f8cdc000ce8, share=0x7f8ce4017d40, extra=HA_EXTRA_NOT_USED, skip_table=0x0) at sql/sql_base.cc:677
#17 0x0000561033beee4b in mysql_inplace_alter_table (thd=0x7f8cdc000ce8, table_list=0x7f8cdc010888, table=0x7f8cdc019808, altered_table=0x7f8cdc021e98, ha_alter_info=0x7f8cfc3665e0, inplace_supported=HA_ALTER_INPLACE_NO_LOCK, target_mdl_request=0x7f8cfc366650, alter_ctx=0x7f8cfc367210) at sql/sql_table.cc:7398
#18 0x0000561033bf4305 in mysql_alter_table (thd=0x7f8cdc000ce8, new_db=0x7f8cdc010e98 "test", new_name=0x0, create_info=0x7f8cfc367e30, table_list=0x7f8cdc010888, alter_info=0x7f8cfc367d80, order_num=0, order=0x0, ignore=false) at sql/sql_table.cc:9390
#19 0x0000561033c6ec70 in Sql_cmd_alter_table::execute (this=0x7f8cdc010f98, thd=0x7f8cdc000ce8) at sql/sql_alter.cc:323
#20 0x0000561033b272e2 in mysql_execute_command (thd=0x7f8cdc000ce8) at sql/sql_parse.cc:6227
#21 0x0000561033b2c42e in mysql_parse (thd=0x7f8cdc000ce8, rawbuf=0x7f8cdc010780 "ALTER TABLE t1 CHANGE COLUMN col1 col1_copy INT", length=47, parser_state=0x7f8cfc3691f0, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:8014
#22 0x0000561033b19aaf in dispatch_command (command=COM_QUERY, thd=0x7f8cdc000ce8, packet=0x7f8cdc008469 "ALTER TABLE t1 CHANGE COLUMN col1 col1_copy INT ", packet_length=48, is_com_multi=false, is_next_command=false) at sql/sql_parse.cc:1824
#23 0x0000561033b1844d in do_command (thd=0x7f8cdc000ce8) at sql/sql_parse.cc:1378
#24 0x0000561033c69937 in do_handle_one_connection (connect=0x5610368f79c8) at sql/sql_connect.cc:1335
#25 0x0000561033c696b7 in handle_one_connection (arg=0x5610368f79c8) at sql/sql_connect.cc:1241
#26 0x000056103449b303 in pfs_spawn_thread (arg=0x561036940928) at storage/perfschema/pfs.cc:1862
#27 0x00007f8d01e747fc in start_thread (arg=0x7f8cfc36a700) at pthread_create.c:465
#28 0x00007f8d012aeb5f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
Sequences showing the same problem most probably from same reason
   ALTER TABLE t1 ADD COLUMN col2 INT ;
   ALTER TABLE t1 DROP COLUMN col2 ;
   CHECK TABLE t1 ;
---
   ALTER TABLE t1 MODIFY COLUMN col2 BIGINT;
   ALTER TABLE t1 MODIFY COLUMN col2 INT;
   CHECK TABLE t1 ;
----
   ALTER TABLE t1 MODIFY COLUMN col2 INT FIRST;
   ALTER TABLE t1 MODIFY COLUMN col2 INT AFTER col1;
  CHECK TABLE t1 ; 
----
   ALTER TABLE t1 ALTER COLUMN col2 SET DEFAULT NULL;
   ALTER TABLE t1 ALTER COLUMN col2 SET DEFAULT NOT NULL;
   CHECK TABLE t1 ;

Comment by Matthias Leich [ 2018-12-17 ]

How to install and run the new tests.
- I had a debug build.
- cd <source tree>/mysql-test
  tar xvzf MDEV-14865_new.tgz
- cd <tree with compile>/mysql-test
  ./mysql-test-run.pl --mem bug_aria4
         or bug_aria4b or bug_aria4c or bug_aria4d or bug_aria4e

Comment by Matthias Leich [ 2020-04-24 ]

This bug was also observed in some 10.5 development tree.
mysqld: /home/mleich/10.5-kevgs/storage/maria/ma_close.c:177: maria_close: Assertion `share->now_transactional == share->base.born_transactional' failed.
during   a  ALTER TABLE t5 DISABLE KEYS

Comment by Alice Sherepa [ 2020-05-14 ]

also on 10.2

mysqld: /10.2/storage/maria/ma_close.c:171: maria_close: Assertion `share->now_transactional == share->base.born_transactional' failed.
200514 13:59:45 [ERROR] mysqld got signal 6 ;
 
Server version: 10.2.32-MariaDB-debug-log
linux/raise.c:51(__GI_raise)[0x7f49de730535]
stdlib/abort.c:81(__GI_abort)[0x7f49de73040f]
intl/loadmsgcat.c:1177(_nl_load_domain)[0x7f49de73e102]
/10.2/sql/mysqld(+0xe5e0a7)[0x557486d3c0a7]
maria/ma_close.c:176(maria_close)[0x557486cb79ec]
maria/ha_maria.cc:1277(ha_maria::close())[0x55748673fc67]
sql/handler.cc:2656(handler::ha_close())[0x5574865cc8b8]
sql/table.cc:3490(closefrm(TABLE*))[0x5574866b2120]
sql/table_cache.cc:223(intern_close_table(TABLE*))[0x5574866b22c0]
sql/table_cache.cc:261(tc_remove_table(TABLE*))[0x5574866b2b0c]
sql/table_cache.cc:470(tc_release_table(TABLE*))[0x5574864520a7]
sql/sql_base.cc:912(close_thread_table(THD*, TABLE**))[0x5574864519fe]
sql/sql_base.cc:685(close_all_tables_for_name(THD*, TABLE_SHARE*, ha_extra_function, TABLE*))[0x55748659cb18]
sql/sql_table.cc:9787(mysql_alter_table(THD*, char*, char*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool))[0x557486618002]
sql/sql_alter.cc:333(Sql_cmd_alter_table::execute(THD*))[0x5574864cd453]
sql/sql_parse.cc:5972(mysql_execute_command(THD*))[0x5574864d237b]
sql/sql_parse.cc:7740(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x5574864c07bc]
sql/sql_parse.cc:1834(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x5574864bf241]
sql/sql_connect.cc:1336(do_handle_one_connection(CONNECT*))[0x557486612bf0]
sql/sql_connect.cc:1242(handle_one_connection)[0x55748661295b]
nptl/pthread_create.c:487(start_thread)[0x7f49dee83fa3]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f49de8074cf]
 
Query (0x7f493c013538): ALTER TABLE t1 ADD KEY idx ( col3 )

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