[MDEV-22726] Add check to ensure one can't change general or slow log to a transactional engine Created: 2020-05-27  Updated: 2021-12-20  Resolved: 2020-10-21

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - Aria
Affects Version/s: 10.1, 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.2.33, 10.3.24, 10.4.14, 10.5.5

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Vladislav Lesin
Resolution: Fixed Votes: 0
Labels: affects-tests

Issue Links:
Duplicate
is duplicated by MDEV-22857 Assertion `!thd->get_stmt_da()->is_se... Open
Relates
relates to MDEV-23046 InnoDB: Assertion failure in file inn... Confirmed

 Description    

ALTER TABLE mysql.general_log ENGINE=Aria;
 
SET GLOBAL log_output='TABLE';
 
SET GLOBAL general_log=TRUE;
 
SET SESSION OPTIMIZER_SWITCH="derived_merge=OFF";

Leads to:

10.5.4 8569dac1ec9f6853a0b2f3ea9bcbda67644ead24

 
mysqld: /test/10.5_dbg/sql/sql_parse.cc:3361: int mysql_execute_command(THD*): Assertion `thd->transaction->stmt.is_empty() || thd->in_sub_stmt' failed.

10.5.4 8569dac1ec9f6853a0b2f3ea9bcbda67644ead24

 
Core was generated by `/test/MD260520-mariadb-10.5.4-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
[Current thread is 1 (Thread 0x15086fee6700 (LWP 2274707))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x00005575bb63dd7a in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
 
#2  0x00005575bade3385 in handle_fatal_signal (sig=6) at /test/10.5_dbg/sql/signal_handler.cc:330
 
#3  <signal handler called>
 
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
 
#5  0x000015086e62a801 in __GI_abort () at abort.c:79
 
#6  0x000015086e61a39a in __assert_fail_base (fmt=0x15086e7a17d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x5575bb7bd538 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=file@entry=0x5575bb7bc568 "/test/10.5_dbg/sql/sql_parse.cc", line=line@entry=3361, function=function@entry=0x5575bb7bfc00 <mysql_execute_command(THD*)::__PRETTY_FUNCTION__> "int mysql_execute_command(THD*)") at assert.c:92
 
#7  0x000015086e61a412 in __GI___assert_fail (assertion=assertion@entry=0x5575bb7bd538 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=file@entry=0x5575bb7bc568 "/test/10.5_dbg/sql/sql_parse.cc", line=line@entry=3361, function=function@entry=0x5575bb7bfc00 <mysql_execute_command(THD*)::__PRETTY_FUNCTION__> "int mysql_execute_command(THD*)") at assert.c:101
 
#8  0x00005575bab3f89f in mysql_execute_command (thd=thd@entry=0x15084dc15088) at /test/10.5_dbg/sql/sql_parse.cc:3361
 
#9  0x00005575bab4602e in mysql_parse (thd=thd@entry=0x15084dc15088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x15086fee53d0, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:7991
 
#10 0x00005575bab32b42 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x15084dc15088, packet=packet@entry=0x15084dc67089 "SET SESSION OPTIMIZER_SWITCH=\"derived_merge=OFF\"", packet_length=packet_length@entry=48, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_dbg/sql/sql_parse.cc:1874
 
#11 0x00005575bab3131c in do_command (thd=0x15084dc15088) at /test/10.5_dbg/sql/sql_parse.cc:1355
 
#12 0x00005575bac8b73f in do_handle_one_connection (connect=<optimized out>, connect@entry=0x15084e8453a8, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1411
 
#13 0x00005575bac8be5b in handle_one_connection (arg=arg@entry=0x15084e8453a8) at /test/10.5_dbg/sql/sql_connect.cc:1313
 
#14 0x00005575bb0eb14e in pfs_spawn_thread (arg=0x15086d845888) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
 
#15 0x000015086f30d6db in start_thread (arg=0x15086fee6700) at pthread_create.c:463
 
#16 0x000015086e70b88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.5.4 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.46 (dbg), 10.1.46 (opt), 10.2.33 (dbg), 10.2.33 (opt), 10.3.24 (dbg), 10.3.24 (opt), 10.4.14 (dbg), 10.4.14 (opt), 10.5.4 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.47 (dbg), 5.6.47 (opt), 5.7.29 (dbg), 5.7.29 (opt), 8.0.19 (dbg), 8.0.19 (opt)

 Comments   
Comment by Elena Stepanova [ 2020-06-05 ]

Removed Optimizer from components, as it's not guilty here. The last statement can be anything, select 1 will do, it just needs to hit the general log.

Comment by Vladislav Lesin [ 2020-06-08 ]

The assertion is caused by the following commit:

commit 4102f1589c23309de968a5bf9511d3228a1b9319
 
Author: Monty <monty@mariadb.org>
 
Date:   Sat May 2 13:19:53 2020 +0300
 
 
 
    Aria will now register it's transactions
 
    
    MDEV-22531 Remove maria::implicit_commit()
 
    MDEV-22607 Assertion `ha_info->ht() != binlog_hton' failed in
 
               MYSQL_BIN_LOG::unlog_xa_prepare

The transaction is registered with the following call stack:

#0  Ha_trx_info::register_ha (this=0x7fffc0003490, trans=0x7fffc0004378, ht_arg=0x5555583e45b8)
 
    at ./sql/handler.h:1901
 
#1  0x000055555616fc90 in trans_register_ha (thd=0x7fffc0000d78, all=false, ht_arg=0x5555583e45b8, trxid=53)
 
    at ./sql/handler.cc:1262
 
#2  0x00005555563fd8a2 in maria_create_trn_for_mysql (info=0x7fffc01f9888) at ./storage/maria/ha_maria.cc:972
 
#3  0x00005555563eae18 in _ma_setup_live_state (info=0x7fffc01f9888) at ./storage/maria/ma_state.c:66
 
#4  0x00005555563ec30c in _ma_block_start_trans (param=0x7fffc01f9888) at ./storage/maria/ma_state.c:666
 
#5  0x0000555556ac211e in thr_multi_lock (data=0x7fffc0013ea8, count=1, owner=0x7fffc0002918, lock_wait_timeout=31536000)
 
    at ./mysys/thr_lock.c:1318
 
#6  0x00005555562baf93 in mysql_lock_tables (thd=0x7fffc0000d78, sql_lock=0x7fffc0013e80, flags=2075)
 
    at ./sql/lock.cc:349
 
#7  0x00005555562bad95 in mysql_lock_tables (thd=0x7fffc0000d78, tables=0x7ffff0485aa8, count=1, flags=2075)
 
    at ./sql/lock.cc:301
 
#8  0x0000555555d777c1 in open_ltable (thd=0x7fffc0000d78, table_list=0x7ffff04859b0, lock_type=TL_WRITE_CONCURRENT_INSERT, lock_flags=2075)
 
    at ./sql/sql_base.cc:5103
 
#9  0x0000555555d82246 in open_log_table (thd=0x7fffc0000d78, one_table=0x7ffff04859b0, backup=0x7ffff0485740)
 
    at ./sql/sql_base.cc:9080
 
#10 0x00005555562997f1 in Log_to_csv_event_handler::log_general (this=0x55555880c820, thd=0x7fffc0000d78, event_time=..., 
    user_host=0x7ffff0486130 "root[root] @ localhost []", user_host_len=25, thread_id_arg=4, command_type=0x555556bc352a "Query", command_type_len=5, 
    sql_text=0x7fffc0013df0 "SET SESSION OPTIMIZER_SWITCH=\"derived_merge=OFF\"", sql_text_len=48, client_cs=0x555557883460 <my_charset_latin1>)
 
    at ./sql/log.cc:749
 
#11 0x000055555629bcf5 in LOGGER::general_log_write (this=0x5555579d3ec0 <logger>, thd=0x7fffc0000d78, command=COM_QUERY, 
    query=0x7fffc0013df0 "SET SESSION OPTIMIZER_SWITCH=\"derived_merge=OFF\"", query_length=48)
 
    at ./sql/log.cc:1402
 
#12 0x00005555562ac753 in general_log_write (thd=0x7fffc0000d78, command=COM_QUERY, 
    query=0x7fffc0013df0 "SET SESSION OPTIMIZER_SWITCH=\"derived_merge=OFF\"", query_length=48)
 
    at ./sql/log.cc:6843
 
#13 0x0000555555e140df in dispatch_command (command=COM_QUERY, thd=0x7fffc0000d78, 
    packet=0x7fffc0008f69 "SET SESSION OPTIMIZER_SWITCH=\"derived_merge=OFF\"", packet_length=48, is_com_multi=false, is_next_command=false)
 
    at ./sql/sql_parse.cc:1845

So thd->transaction->stmt.ha_list is set in Ha_trx_info::register_ha().

As transaction is neither committed nor rolled back, thd->transaction->stmt.ha_list is not empty when mysql_execute_command() is invoked from dispatch_command(), and the assertion aborts execution.

Comment by Michael Widenius [ 2020-06-08 ]

General log files can't be in a transactional engine (and should not be as logs should never roll back)!

Fix is to use:
ALTER TABLE mysql.general_log ENGINE=Aria transactional=0

We should probably add a check that one can't change any of the logs (general or slow-log) to be non transactional

Comment by Roel Van de Paar [ 2020-06-10 ]

Please fix this together with MDEV-22857.

Comment by Vladislav Lesin [ 2020-06-15 ]

General log files can't be in transactional engine not only for 10.5+ but also for 10.2+, that is why I am changing "fix versions" to 10.2+.

Comment by Vladislav Lesin [ 2020-06-16 ]

Branch https://github.com/MariaDB/server/tree/bb-10.2-MDEV-22726-aria-non-trans-log.

Comment by Roel Van de Paar [ 2020-06-25 ]

I found the following testcase, which on debug results in the same crash, but also crashes optimized builds 10.1-10.5 with a SIGSEGV in PolicyMutex

USE test;
 
SET SQL_MODE='';
 
CREATE TABLE t (i INT AUTO_INCREMENT, KEY(i)) ENGINE=InnoDB;
 
SET SESSION enforce_storage_engine=INNODB;
 
ALTER table mysql.general_log engine=MyISAM;
 
SET GLOBAL GENERAL_LOG=ON;
 
SET GLOBAL log_output=6;
 
SET SESSION tx_read_only=ON;
 
DROP DATABASE test;

Leads to:

10.5.5 e1013725ce0f3f947e728491eef75d9985e8db2f

 
Core was generated by `/test/MD250620-mariadb-10.5.5-linux-x86_64-opt/bin/mysqld --no-defaults --core-'.
 
Program terminated with signal SIGSEGV, Segmentation fault.
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=11)
 
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
[Current thread is 1 (Thread 0x153f9fe15700 (LWP 1452378))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=11) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x0000558b2558c0e7 in my_write_core (sig=sig@entry=11) at /test/10.5_opt/mysys/stacktrace.c:518
 
#2  0x0000558b24f564ca in handle_fatal_signal (sig=11) at /test/10.5_opt/sql/signal_handler.cc:330
 
#3  <signal handler called>
 
#4  PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (line=<optimized out>, name=<optimized out>, n_delay=<optimized out>, n_spins=<optimized out>, this=<optimized out>) at /test/10.5_opt/storage/innobase/include/ib0mutex.h:585
 
#5  trx_undo_assign_low (trx=0x153f8a8021b0, rseg=0x0, undo=undo@entry=0x153f8a803188, err=err@entry=0x153f9fe109dc, mtr=mtr@entry=0x153f9fe10a50) at /test/10.5_opt/storage/innobase/trx/trx0undo.cc:1227
 
#6  0x0000558b253afc65 in trx_undo_report_row_operation (thr=thr@entry=0x153f7b8c49c8, index=index@entry=0x153f7b833500, clust_entry=clust_entry@entry=0x153f7b832380, update=update@entry=0x0, cmpl_info=cmpl_info@entry=0, rec=rec@entry=0x0, offsets=0x0, roll_ptr=0x153f9fe11bf0) at /test/10.5_opt/storage/innobase/trx/trx0rec.cc:1990
 
#7  0x0000558b25403b7b in btr_cur_ins_lock_and_undo (inherit=0x153f9fe11bd7, mtr=0x153f9fe12890, thr=0x153f7b8c49c8, entry=0x153f7b832380, cursor=0x153f9fe11ed0, flags=<optimized out>) at /test/10.5_opt/storage/innobase/btr/btr0cur.cc:3279
 
#8  btr_cur_optimistic_insert (flags=flags@entry=0, cursor=cursor@entry=0x153f9fe11ed0, offsets=offsets@entry=0x153f9fe11e68, heap=heap@entry=0x153f9fe11e60, entry=entry@entry=0x153f7b832380, rec=rec@entry=0x153f9fe12330, big_rec=0x153f9fe11e58, n_ext=<optimized out>, thr=0x153f7b8c49c8, mtr=0x153f9fe12890) at /test/10.5_opt/storage/innobase/btr/btr0cur.cc:3479
 
#9  0x0000558b253379f1 in row_ins_clust_index_entry_low (flags=flags@entry=0, mode=<optimized out>, mode@entry=2, index=index@entry=0x153f7b833500, n_uniq=n_uniq@entry=0, entry=entry@entry=0x153f7b832380, n_ext=n_ext@entry=0, thr=0x153f7b8c49c8) at /test/10.5_opt/storage/innobase/row/row0ins.cc:2714
 
#10 0x0000558b2533c454 in row_ins_clust_index_entry (index=index@entry=0x153f7b833500, entry=0x153f7b832380, thr=thr@entry=0x153f7b8c49c8, n_ext=n_ext@entry=0) at /test/10.5_opt/storage/innobase/row/row0ins.cc:3186
 
#11 0x0000558b2533cfbc in row_ins_index_entry (thr=0x153f7b8c49c8, entry=<optimized out>, index=<optimized out>) at /test/10.5_opt/storage/innobase/row/row0ins.cc:3311
 
#12 row_ins_index_entry_step (thr=0x153f7b8c49c8, node=0x153f7b8c4658) at /test/10.5_opt/storage/innobase/row/row0ins.cc:3480
 
#13 row_ins (thr=<optimized out>, node=<optimized out>) at /test/10.5_opt/storage/innobase/row/row0ins.cc:3617
 
#14 row_ins_step (thr=thr@entry=0x153f7b8c49c8) at /test/10.5_opt/storage/innobase/row/row0ins.cc:3756
 
#15 0x0000558b2534fda4 in row_insert_for_mysql (mysql_rec=mysql_rec@entry=0x153f7b855440 "^\364;\305\bC\322\031", prebuilt=0x153f7b8c4080, ins_mode=<optimized out>) at /test/10.5_opt/storage/innobase/row/row0mysql.cc:1461
 
#16 0x0000558b25284575 in ha_innobase::write_row (this=0x153f7b866830, record=0x153f7b855440 "^\364;\305\bC\322\031") at /test/10.5_opt/storage/innobase/handler/ha_innodb.cc:7728
 
#17 0x0000558b24f6270f in handler::ha_write_row (this=0x153f7b866830, buf=0x153f7b855440 "^\364;\305\bC\322\031") at /test/10.5_opt/sql/handler.cc:7140
 
#18 0x0000558b25037318 in Log_to_csv_event_handler::log_general (this=<optimized out>, thd=<optimized out>, event_time=<optimized out>, user_host=0x153f9fe14130 "root[root] @ localhost []", user_host_len=25, thread_id_arg=4, command_type=0x558b256fda72 "Query", command_type_len=5, sql_text=0x153f7b847030 "DROP DATABASE test", sql_text_len=18, client_cs=0x558b260e5700 <my_charset_utf8mb3_general_ci>) at /test/10.5_opt/sql/log.cc:811
 
#19 0x0000558b25038f55 in LOGGER::general_log_write (this=this@entry=0x558b2612c260 <logger>, thd=thd@entry=0x153f7b812018, command=command@entry=COM_QUERY, query=0x153f7b847030 "DROP DATABASE test", query_length=18) at /test/10.5_opt/sql/log.cc:1402
 
#20 0x0000558b25039183 in general_log_write (thd=thd@entry=0x153f7b812018, command=command@entry=COM_QUERY, query=<optimized out>, query_length=<optimized out>) at /test/10.5_opt/sql/log.cc:6850
 
#21 0x0000558b24d5ab4e in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x153f7b812018, packet=packet@entry=0x153f7b83a019 "DROP DATABASE test", packet_length=packet_length@entry=18, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_opt/sql/sql_parse.cc:1845
 
#22 0x0000558b24d59034 in do_command (thd=0x153f7b812018) at /test/10.5_opt/sql/sql_parse.cc:1355
 
#23 0x0000558b24e4ec51 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x153f9cc338f8, put_in_cache=put_in_cache@entry=true) at /test/10.5_opt/sql/sql_connect.cc:1411
 
#24 0x0000558b24e4efb4 in handle_one_connection (arg=arg@entry=0x153f9cc338f8) at /test/10.5_opt/sql/sql_connect.cc:1313
 
#25 0x0000558b251bfdaa in pfs_spawn_thread (arg=0x153f9cc4f218) at /test/10.5_opt/storage/perfschema/pfs.cc:2201
 
#26 0x0000153f9ed8e6db in start_thread (arg=0x153f9fe15700) at pthread_create.c:463
 
#27 0x0000153f9e18c88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.1.46 (dbg), 10.1.46 (opt), 10.2.33 (dbg), 10.2.33 (opt), 10.3.24 (dbg), 10.3.24 (opt), 10.4.14 (dbg), 10.4.14 (opt), 10.5.5 (dbg), 10.5.5 (opt)

Bug confirmed not present in:
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.47 (dbg), 5.6.47 (opt), 5.7.29 (dbg), 5.7.29 (opt), 8.0.19 (dbg), 8.0.19 (opt)

Comment by Roel Van de Paar [ 2020-06-25 ]

marko The SIGSEGV in PolicyMutex may interest you ^

Comment by Vladislav Lesin [ 2020-06-25 ]

I pushed the fix for 

ALTER TABLE mysql.general_log ENGINE=Aria;

before I saw Roel's comment about enforce_storage_engine issue.

I have also fixed enforce_storage_engine case, now it is under testing.

Comment by Roel Van de Paar [ 2020-06-30 ]

Please also see MDEV-23046, initial description.

Comment by Roel Van de Paar [ 2020-09-22 ]

Hi vlad.lesin! What would be involved in closing this one out? Thanks

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