[MDEV-31584] Assertion `thd->transaction->stmt.is_empty() || thd->in_sub_stmt' failed in mysql_execute_command from spider_table_bg_sts_action on INSTALL PLUGIN Created: 2023-06-29  Updated: 2023-11-28

Status: Confirmed
Project: MariaDB Server
Component/s: Server
Affects Version/s: 10.4, 10.5, 10.6, 10.9, 10.10, 10.11, 11.0, 11.1
Fix Version/s: 10.4, 10.5, 10.6, 10.11, 11.0, 11.1

Type: Bug Priority: Minor
Reporter: Roel Van de Paar Assignee: Oleksandr Byelkin
Resolution: Unresolved Votes: 1
Labels: None

Issue Links:
Relates
relates to MDEV-24706 Assertion `thd->transaction->stmt.is_... Confirmed
relates to MDEV-26373 Various crashes & asserts and UBSAN n... Confirmed

 Description   

Possibly related to MDEV-24706. (See the first comment for an mtr case)

SET SESSION sql_log_off=1;
 
CREATE OR REPLACE TABLE mysql.general_log (a INT);
 
SET GLOBAL general_log=ON,log_output='TABLE';
 
INSTALL PLUGIN Spider SONAME 'ha_spider.so';
 
SELECT SLEEP(1);  # Shows server is gone

Leads to:

11.1.2 3883eb63dc5e663558571c33d086c9fd3aa0cf8f (Debug)

 
mariadbd: /test/11.1_dbg/sql/sql_parse.cc:3476: int mysql_execute_command(THD*, bool): Assertion `thd->transaction->stmt.is_empty() || thd->in_sub_stmt' failed.

11.1.2 3883eb63dc5e663558571c33d086c9fd3aa0cf8f (Debug)

 
Core was generated by `/test/MD220623-mariadb-11.1.2-linux-x86_64-dbg/bin/mariadbd --no-defaults --cor'.
 
Program terminated with signal SIGABRT, Aborted.
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=23210700998208)
 
    at ./nptl/pthread_kill.c:44
 
[Current thread is 1 (Thread 0x151c29968640 (LWP 3607795))]
 
(gdb) bt
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=23210700998208) at ./nptl/pthread_kill.c:44
 
#1  __pthread_kill_internal (signo=6, threadid=23210700998208) at ./nptl/pthread_kill.c:78
 
#2  __GI___pthread_kill (threadid=23210700998208, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
 
#3  0x0000151c4f242476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
 
#4  0x0000151c4f2287f3 in __GI_abort () at ./stdlib/abort.c:79
 
#5  0x0000151c4f22871b in __assert_fail_base (fmt=0x151c4f3dd150 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55fc95f564e8 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=0x55fc95f55090 "/test/11.1_dbg/sql/sql_parse.cc", line=3476, function=<optimized out>) at ./assert/assert.c:92
 
#6  0x0000151c4f239e96 in __GI___assert_fail (assertion=0x55fc95f564e8 "thd->transaction->stmt.is_empty() || thd->in_sub_stmt", file=0x55fc95f55090 "/test/11.1_dbg/sql/sql_parse.cc", line=3476, function=0x55fc95f56468 "int mysql_execute_command(THD*, bool)") at ./assert/assert.c:101
 
#7  0x000055fc95425e27 in mysql_execute_command (thd=thd@entry=0x151bb0002168, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/11.1_dbg/sql/sql_parse.cc:3476
 
#8  0x000055fc95426849 in mysql_parse (thd=thd@entry=0x151bb0002168, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x151c29967290) at /test/11.1_dbg/sql/sql_parse.cc:7769
 
#9  0x000055fc954289dd in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x151bb0002168, packet=0x151c29a64f68 "create table if not exists mysql.spider_xa(  format_id int not null default 0,  gtrid_length int not null default 0,  bqual_length int not null default 0,  data char(128) charset binary not null defau"..., packet_length=<optimized out>, blocking=blocking@entry=true) at /test/11.1_dbg/sql/sql_class.h:242
 
#10 0x0000151c299f8b5e in spider_table_bg_sts_action (arg=0x151bd4099e78) at /test/11.1_dbg/storage/spider/spd_table.cc:8773
 
#11 0x0000151c4f294b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
#12 0x0000151c4f326a00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Bug confirmed present in:
MariaDB: 10.4.31 (dbg), 10.5.22 (dbg), 10.6.15 (dbg), 10.9.8 (dbg), 10.10.6 (dbg), 10.11.5 (dbg), 11.0.3 (dbg), 11.1.2 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.4.31 (opt), 10.5.22 (opt), 10.6.15 (opt), 10.9.8 (opt), 10.10.6 (opt), 10.11.5 (opt), 11.0.3 (opt), 11.1.2 (opt)

 Comments   
Comment by Roel Van de Paar [ 2023-06-29 ]

MTR Testcase

--source include/have_innodb.inc
 
SET SESSION sql_log_off=1;
 
CREATE OR REPLACE TABLE mysql.general_log (a INT) ENGINE=InnoDB;
 
SET GLOBAL general_log=ON,log_output='TABLE';
 
INSTALL PLUGIN Spider SONAME 'ha_spider.so';
 
SELECT SLEEP(1);  # Shows server is gone

Comment by Yuchen Pei [ 2023-06-30 ]

I can confirm this bug is reproducible even with the init bugs fixed,
at commit 11.0 feba4e8a4e9fa3104b265448933fa0668be3bf5c, also
without the last statement `SELECT SLEEP(1);`

Comment by Yuchen Pei [ 2023-06-30 ]

this is not a spider issue. It is either an innodb or a runtime issue.
mysql.general_log is a system table originally with the csv engine
(ha_tina). The SET GLOBAL statement causes the
general_log_handler_list to change from
Log_to_file_event_handler to Log_to_csv_event_handler. Then
during locking innodb calls trans_register_ha() which causes the
ha_list of thd->transaction->stmt in the failing insertion to
be non-null. See the backtrace for when this happens:

Ha_trx_info::register_ha > trans_register_ha > innobase_register_trx > ha_innobase::external_lock > handler::ha_external_lock > mysql_lock_tables > mysql_lock_tables > open_ltable > open_log_table > Log_to_csv_event_handler::log_general > general_log_write > execute_server_code > loc_advanced_command > server_mysql_send_query > spider_init_system_tables > spider_db_init > ha_initialize_handlerton > plugin_do_initialize > finalize_install > mysql_install_plugin > mysql_parse > dispatch_command > do_command > do_handle_one_connection > handle_one_connection

Comment by Marko Mäkelä [ 2023-06-30 ]

MDEV-26373 is somewhat similar, involving the the system table mysql.slow_log instead of mysql.general_log.

Comment by Oleksandr Byelkin [ 2023-09-26 ]

It looke like I can not repeat it (unexpectedly it fails to write in wrong created log):

SET SESSION sql_log_off=1;
 
CREATE OR REPLACE TABLE mysql.general_log (a INT);
 
SET GLOBAL general_log=ON,log_output='TABLE';
 
INSTALL PLUGIN Spider SONAME 'ha_spider.so';
 
SELECT SLEEP(1);
 
SLEEP(1)
 
0
 
main.test                                [ fail ]  Found warnings/errors in server log file!
 
        Test ended at 2023-09-26 09:53:32
 
line
 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
2023-09-26  9:53:30 5 [ERROR] Failed to write to mysql.general_log: 
^ Found warnings in /home/sanja/maria/git/10.4/mysql-test/var/log/mysqld.1.err

Comment by Oleksandr Byelkin [ 2023-09-26 ]

correct test case is (innodb engine is important to trigger assert with problem of transactions):

--source include/have_innodb.inc
 
 
 
SET SESSION sql_log_off=1;
 
CREATE OR REPLACE TABLE mysql.general_log (a INT) engine=innodb;
 
SET GLOBAL general_log=ON,log_output='TABLE';
 
INSTALL PLUGIN Spider SONAME 'ha_spider.so';
 
SELECT SLEEP(1);  # Shows server is gone

Comment by Oleksandr Byelkin [ 2023-09-26 ]

Taking unreaistic malforming log I do not think it is bug of big importance

Generated at Thu Feb 08 10:24:58 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.