[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 - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.2(EOL), 10.3(EOL), 10.4(EOL), 10.5, 10.6
Fix Version/s: 10.4.22, 10.5.13, 10.6.5
Component/s: wsrep
Labels:
- affects-tests

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)

Attachments

Issue Links

relates to

MDEV-22285 Assertion `xid_seqno > wsrep_seqno' failed in trx_rseg_update_wsrep_checkpoint on SET @@global.wsrep_start_position

Closed

MDEV-22422 Assertion `! is_set()' failed in Diagnostics_area::set_eof_status

Closed

MDEV-23045 Assertion `is_open()' failed in MYSQL_BIN_LOG::trx_group_commit_leader

Stalled

Activity

Ascending order - Click to sort in descending order

Roel Van de Paar added a comment - 2020-06-10 10:59

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');

Roel Van de Paar added a comment - 2020-06-10 10:59 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');

Roel Van de Paar added a comment - 2020-11-03 05:24 - edited

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

Roel Van de Paar added a comment - 2020-11-03 05:24 - edited 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

Roel Van de Paar added a comment - 2020-11-03 07:53 - edited

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.

Roel Van de Paar added a comment - 2020-11-03 07:53 - edited 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.

Marko Mäkelä added a comment - 2021-10-05 10:54

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.

Marko Mäkelä added a comment - 2021-10-05 10:54 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.

MariaDB Server

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

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration