[MDEV-22708] Assertion `!mysql_bin_log.is_open() || thd.is_current_stmt_binlog_format_row()' failed in Delayed_insert::handle_inserts and in Diagnostics_area::set_eof_status Created: 2020-05-26  Updated: 2021-10-06  Resolved: 2021-10-04

Status: Closed
Project: MariaDB Server
Component/s: wsrep
Affects Version/s: 10.2, 10.3, 10.4, 10.5, 10.6
Fix Version/s: 10.4.22, 10.5.13, 10.6.5

Type: Bug Priority: Critical
Reporter: Roel Van de Paar Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: affects-tests

Issue Links:
Relates
relates to MDEV-22285 Assertion `xid_seqno > wsrep_seqno' f... Closed
relates to MDEV-22422 Assertion `! is_set()' failed in Diag... Closed
relates to MDEV-23045 Assertion `is_open()' failed in MYSQL... Stalled

 Description   

# mysqld options required for replay: --log-bin 
USE test;
SET GLOBAL wsrep_forced_binlog_format=1;
CREATE TABLE t1(c INT PRIMARY KEY) ENGINE=MEMORY;
INSERT DELAYED INTO t1 VALUES(),(),();
SELECT SLEEP(1);

Leads to:

10.5.4 8569dac1ec9f6853a0b2f3ea9bcbda67644ead24

mysqld: /test/10.5_dbg/sql/sql_insert.cc:3490: bool Delayed_insert::handle_inserts(): Assertion `!mysql_bin_log.is_open() || thd.is_current_stmt_binlog_format_row()' 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 0x145b29e62700 (LWP 3548649))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x000055988acdfd7a in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
#2  0x000055988a485385 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  0x0000145b2863c801 in __GI_abort () at abort.c:79
#6  0x0000145b2862c39a in __assert_fail_base (fmt=0x145b287b37d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55988ae56c98 "!mysql_bin_log.is_open() || thd.is_current_stmt_binlog_format_row()", file=file@entry=0x55988ae56988 "/test/10.5_dbg/sql/sql_insert.cc", line=line@entry=3490, function=function@entry=0x55988ae577a0 <Delayed_insert::handle_inserts()::__PRETTY_FUNCTION__> "bool Delayed_insert::handle_inserts()") at assert.c:92
#7  0x0000145b2862c412 in __GI___assert_fail (assertion=assertion@entry=0x55988ae56c98 "!mysql_bin_log.is_open() || thd.is_current_stmt_binlog_format_row()", file=file@entry=0x55988ae56988 "/test/10.5_dbg/sql/sql_insert.cc", line=line@entry=3490, function=function@entry=0x55988ae577a0 <Delayed_insert::handle_inserts()::__PRETTY_FUNCTION__> "bool Delayed_insert::handle_inserts()") at assert.c:101
#8  0x000055988a19d508 in Delayed_insert::handle_inserts (this=this@entry=0x145b074a6088) at /test/10.5_dbg/sql/sql_insert.cc:3489
#9  0x000055988a19f1a2 in handle_delayed_insert (arg=arg@entry=0x145b074a6088) at /test/10.5_dbg/sql/sql_insert.cc:3282
#10 0x000055988a78d14e in pfs_spawn_thread (arg=0x145b07428388) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
#11 0x0000145b2931f6db in start_thread (arg=0x145b29e62700) at pthread_create.c:463
#12 0x0000145b2871d88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.2.33 (dbg), 10.3.24 (dbg), 10.4.14 (dbg), 10.5.4 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.46 (dbg), 10.1.46 (opt), 10.2.33 (opt), 10.3.24 (opt), 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 Roel Van de Paar [ 2020-06-10 ]

Secondary testcase

# mysqld options required for replay: --log-bin 
USE test;
CREATE TABLE t1 (str VARCHAR(255)) ENGINE=MyISAM;
SET @@GLOBAL.wsrep_forced_binlog_format=STATEMENT;
INSERT DELAYED INTO t1 VALUES('a');
SELECT SLEEP(2);
INSERT DELAYED INTO t1 VALUES('a');  # Server will likely crash here
SELECT SLEEP(2);
INSERT DELAYED INTO t1 VALUES('a');

Comment by Roel Van de Paar [ 2020-11-03 ]

In close connection with MDEV-22422, the following testcase produces the same assertion provided the server is started with --log-bin, otherwise it produces the crash of MDEV-22422. Both on the same statement.

# mysqld options required for replay: --log-bin
SET SQL_MODE='';
SET GLOBAL wsrep_forced_binlog_format='STATEMENT';
HELP '%a';
CREATE TABLE t (c CHAR(8) NOT NULL) ENGINE=MEMORY;
SET max_session_mem_used = 50000;
REPLACE DELAYED t VALUES (5);
HELP 'a%';

Leads to:

10.6.0 5d4599f9750140f92cfdbbe4d292ae1b8dd456f8 (Debug)

mysqld: /test/10.6_dbg/sql/sql_insert.cc:3491: bool Delayed_insert::handle_inserts(): Assertion `!mysql_bin_log.is_open() || thd.is_current_stmt_binlog_format_row()' failed.

10.6.0 5d4599f9750140f92cfdbbe4d292ae1b8dd456f8 (Debug)

Core was generated by `/test/MD211020-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
[Current thread is 1 (Thread 0x1480dc0ff700 (LWP 2385962))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00001480f2de0859 in __GI_abort () at abort.c:79
#2  0x00001480f2de0729 in __assert_fail_base (fmt=0x1480f2f76588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x564086252b69 "! is_set()", file=0x564086252638 "/test/10.6_dbg/sql/sql_error.cc", line=374, function=<optimized out>) at assert.c:92
#3  0x00001480f2df1f36 in __GI___assert_fail (assertion=assertion@entry=0x564086252b69 "! is_set()", file=file@entry=0x564086252638 "/test/10.6_dbg/sql/sql_error.cc", line=line@entry=374, function=function@entry=0x5640862527d8 "void Diagnostics_area::set_eof_status(THD*)") at assert.c:101
#4  0x000056408551bce1 in Diagnostics_area::set_eof_status (this=0x1480a0006a30, thd=thd@entry=0x1480a0000db8) at /test/10.6_dbg/sql/sql_error.h:1005
#5  0x0000564085a39cb1 in my_eof (thd=0x1480a0000db8) at /test/10.6_dbg/sql/sql_class.h:5238
#6  mysqld_help_internal (thd=thd@entry=0x1480a0000db8, mask=<optimized out>) at /test/10.6_dbg/sql/sql_help.cc:845
#7  0x0000564085a3aac1 in mysqld_help (thd=thd@entry=0x1480a0000db8, mask=<optimized out>) at /test/10.6_dbg/sql/sql_help.cc:863
#8  0x0000564085576c29 in mysql_execute_command (thd=thd@entry=0x1480a0000db8) at /test/10.6_dbg/sql/sql_parse.cc:3821
#9  0x0000564085562fd2 in mysql_parse (thd=thd@entry=0x1480a0000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1480dc0fe3d0) at /test/10.6_dbg/sql/sql_parse.cc:7833
#10 0x00005640855710c7 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x1480a0000db8, packet=packet@entry=0x1480a0008e09 "", packet_length=packet_length@entry=9) at /test/10.6_dbg/sql/sql_class.h:1253
#11 0x00005640855743d2 in do_command (thd=0x1480a0000db8) at /test/10.6_dbg/sql/sql_parse.cc:1343
#12 0x00005640856ce994 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x5640896b2d38, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1410
#13 0x00005640856cf09b in handle_one_connection (arg=arg@entry=0x5640896b2d38) at /test/10.6_dbg/sql/sql_connect.cc:1312
#14 0x0000564085b82abb in pfs_spawn_thread (arg=0x564089617768) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
#15 0x00001480f32ee609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#16 0x00001480f2edd293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.1.48 (dbg), 10.2.35 (dbg), 10.3.26 (dbg), 10.4.16 (dbg), 10.5.7 (dbg), 10.6.0 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.48 (opt), 10.2.35 (opt), 10.3.26 (opt), 10.4.16 (opt), 10.5.7 (opt), 10.6.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.50 (dbg), 5.6.50 (opt), 5.7.32 (dbg), 5.7.32 (opt), 8.0.22 (dbg), 8.0.22 (opt)

The stack is slightly different. Unique ID's seen thus far:

!mysql_bin_log.is_open() || thd.is_current_stmt_binlog_format_row()|SIGABRT|Delayed_insert::handle_inserts|handle_delayed_insert|pfs_spawn_thread|start_thread
!mysql_bin_log.is_open() || thd.is_current_stmt_binlog_format_row()|SIGABRT|Diagnostics_area::set_eof_status|my_eof|mysqld_help_internal|mysqld_help
!mysql_bin_log.is_open() || thd.is_current_stmt_binlog_format_row()|SIGABRT|trx_rseg_update_wsrep_checkpoint|trx_rseg_update_wsrep_checkpoint|trx_rseg_update_wsrep_checkpoint|innobase_wsrep_set_checkpoint

Comment by Roel Van de Paar [ 2020-11-03 ]

Another such occurrence. In connection with MDEV-22285 this time, the following testcase produces the same assertion, provided the server is started with --log-bin, otherwise it produces the crash of MDEV-22285. Both on the same statement.

# mysqld options required for replay: --log-bin 
SET SQL_MODE='';
CREATE TABLE t (c INT) ENGINE=MEMORY;
SET GLOBAL wsrep_forced_binlog_format='STATEMENT';
INSERT DELAYED INTO t VALUES(1);
SET GLOBAL wsrep_start_position='00000000-0000-0000-0000-000000000000:-2';

Leads to:

10.6.0 5d4599f9750140f92cfdbbe4d292ae1b8dd456f8 (Debug)

mysqld: /test/10.6_dbg/sql/sql_insert.cc:3491: bool Delayed_insert::handle_inserts(): Assertion `!mysql_bin_log.is_open() || thd.is_current_stmt_binlog_format_row()' failed.

10.6.0 5d4599f9750140f92cfdbbe4d292ae1b8dd456f8 (Debug)

Core was generated by `/test/MD211020-mariadb-10.6.0-linux-x86_64-dbg/bin/mysqld --no-defaults --core-'.
Program terminated with signal SIGABRT, Aborted.
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
[Current thread is 1 (Thread 0x1513b45f8700 (LWP 1271953))]
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00001513b7205859 in __GI_abort () at abort.c:79
#2  0x00001513b7205729 in __assert_fail_base (fmt=0x1513b739b588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55e434be0898 "xid_seqno > wsrep_seqno", file=0x55e434be0a40 "/test/10.6_dbg/storage/innobase/trx/trx0rseg.cc", line=108, function=<optimized out>) at assert.c:92
#3  0x00001513b7216f36 in __GI___assert_fail (assertion=assertion@entry=0x55e434be0898 "xid_seqno > wsrep_seqno", file=file@entry=0x55e434be0a40 "/test/10.6_dbg/storage/innobase/trx/trx0rseg.cc", line=line@entry=108, function=function@entry=0x55e434be0d80 "void trx_rseg_update_wsrep_checkpoint(buf_block_t*, const XID*, mtr_t*)") at assert.c:101
#4  0x000055e43456f85d in trx_rseg_update_wsrep_checkpoint (rseg_header=rseg_header@entry=0x151394000a10, xid=xid@entry=0x1513b45f6680, mtr=mtr@entry=0x1513b45f5ff0) at /test/10.6_dbg/storage/innobase/trx/trx0rseg.cc:108
#5  0x000055e4345706ed in trx_rseg_update_wsrep_checkpoint (xid=xid@entry=0x1513b45f6680, mtr=mtr@entry=0x1513b45f5ff0) at /test/10.6_dbg/storage/innobase/trx/trx0rseg.cc:146
#6  0x000055e4345719ad in trx_rseg_update_wsrep_checkpoint (xid=xid@entry=0x1513b45f6680) at /test/10.6_dbg/storage/innobase/trx/trx0rseg.cc:176
#7  0x000055e434308295 in innobase_wsrep_set_checkpoint (hton=0x55e436645958, xid=0x1513b45f6680) at /test/10.6_dbg/storage/innobase/handler/ha_innodb.cc:18526
#8  0x000055e4342d1b54 in set_SE_checkpoint (unused=unused@entry=0x0, plugin=<optimized out>, arg=arg@entry=0x1513b45f6680) at /test/10.6_dbg/sql/wsrep_xid.cc:127
#9  0x000055e433c651d7 in plugin_foreach_with_mask (thd=thd@entry=0x0, func=func@entry=0x55e4342d1ac5 <set_SE_checkpoint(THD*, plugin_ref, void*)>, type=type@entry=1, state_mask=state_mask@entry=8, arg=arg@entry=0x1513b45f6680) at /test/10.6_dbg/sql/sql_plugin.cc:2505
#10 0x000055e4342d1c9d in wsrep_set_SE_checkpoint (xid=@0x1513b45f6680: {formatID = 1, gtrid_length = 48, bqual_length = 0, data = "WSREPXif", '\000' <repeats 16 times>, "\376\377\377\377\377\377\377\377", '\000' <repeats 95 times>}) at /test/10.6_dbg/sql/wsrep_xid.cc:134
#11 0x000055e4342d1cdd in wsrep_set_SE_checkpoint (wsgtid=@0x1513b45f6750: {static undefined_ = {static undefined_ = <same as static member of an already seen type>, id_ = {static undefined_ = {static undefined_ = <same as static member of an already seen type>, data_ = {buf = '\000' <repeats 15 times>}}, data_ = {buf = '\000' <repeats 15 times>}}, seqno_ = {seqno_ = -1}}, id_ = {static undefined_ = {static undefined_ = <same as static member of an already seen type>, data_ = {buf = '\000' <repeats 15 times>}}, data_ = {buf = '\000' <repeats 15 times>}}, seqno_ = {seqno_ = -2}}, gtid=@0x1513b45f6740: {domain_id = 0, server_id = 0, seqno = 0}) at /test/10.6_dbg/sql/wsrep_xid.cc:142
#12 0x000055e4342e14e4 in wsrep_sst_received (thd=thd@entry=0x151360000db8, uuid=@0x1513b45f67c0: {data = '\000' <repeats 15 times>, alignment = 0}, seqno=seqno@entry=-2, state=state@entry=0x0, state_len=state_len@entry=0) at /test/10.6_dbg/sql/wsrep_mysqld.h:421
#13 0x000055e4342e4b47 in wsrep_set_local_position (thd=thd@entry=0x151360000db8, value=<optimized out>, length=<optimized out>, sst=sst@entry=true) at /test/10.6_dbg/sql/wsrep_var.cc:257
#14 0x000055e4342e5043 in wsrep_start_position_check (self=<optimized out>, thd=0x151360000db8, var=0x151360012990) at /test/10.6_dbg/sql/wsrep_var.cc:285
#15 0x000055e433b5777c in sys_var::check (this=0x55e435289ac0 <Sys_wsrep_start_position>, thd=thd@entry=0x151360000db8, var=var@entry=0x151360012990) at /test/10.6_dbg/sql/set_var.cc:246
#16 0x000055e433b587e7 in set_var::check (this=0x151360012990, thd=0x151360000db8) at /test/10.6_dbg/sql/set_var.cc:811
#17 0x000055e433b58f2b in sql_set_variables (thd=thd@entry=0x151360000db8, var_list=var_list@entry=0x151360005e50, free=free@entry=true) at /test/10.6_dbg/sql/set_var.cc:739
#18 0x000055e433c5ba96 in mysql_execute_command (thd=thd@entry=0x151360000db8) at /test/10.6_dbg/sql/sql_parse.cc:4861
#19 0x000055e433c44fd2 in mysql_parse (thd=thd@entry=0x151360000db8, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x1513b45f73d0) at /test/10.6_dbg/sql/sql_parse.cc:7833
#20 0x000055e433c530c7 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x151360000db8, packet=packet@entry=0x151360008e09 "SET GLOBAL wsrep_start_position='00000000-0000-0000-0000-", '0' <repeats 12 times>, ":-2'", packet_length=packet_length@entry=73) at /test/10.6_dbg/sql/sql_class.h:1253
#21 0x000055e433c563d2 in do_command (thd=0x151360000db8) at /test/10.6_dbg/sql/sql_parse.cc:1343
#22 0x000055e433db0994 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x55e43711a2b8, put_in_cache=put_in_cache@entry=true) at /test/10.6_dbg/sql/sql_connect.cc:1410
#23 0x000055e433db109b in handle_one_connection (arg=arg@entry=0x55e43711a2b8) at /test/10.6_dbg/sql/sql_connect.cc:1312
#24 0x000055e434264abb in pfs_spawn_thread (arg=0x55e437095e78) at /test/10.6_dbg/storage/perfschema/pfs.cc:2201
#25 0x00001513b7713609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#26 0x00001513b7302293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.1.48 (dbg), 10.2.35 (dbg), 10.3.26 (dbg), 10.4.16 (dbg), 10.5.7 (dbg), 10.6.0 (dbg)

Bug confirmed not present in:
MariaDB: 10.1.48 (opt), 10.2.35 (opt), 10.3.26 (opt), 10.4.16 (opt), 10.5.7 (opt), 10.6.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.50 (dbg), 5.6.50 (opt), 5.7.32 (dbg), 5.7.32 (opt), 8.0.22 (dbg), 8.0.22 (opt)

Raised to critical as this is now cross-affecting bugs and testing.

Comment by Marko Mäkelä [ 2021-10-05 ]

mkaruza, this seems to have broken the test binlog.binlog_unsafe. Here is an excerpt from a debug builder:

10.4 86a2e2ba9051888d457b6a5d0b4fb2879e24beb5

binlog.binlog_unsafe 'stmt'              w1 [ fail ]
        Test ended at 2021-10-04 06:31:07
 
CURRENT_TEST: binlog.binlog_unsafe
mysqltest: At line 351: Wrong events in binlog.

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