[MDEV-23045] Assertion `is_open()' failed in MYSQL_BIN_LOG::trx_group_commit_leader Created: 2020-06-30  Updated: 2024-01-20

Status: Stalled
Project: MariaDB Server
Component/s: Replication, XA
Affects Version/s: 10.5, 10.6, 10.9, 10.10, 10.11, 11.0, 11.1, 11.2, 11.3, 11.4
Fix Version/s: 10.5, 10.6, 10.11, 11.0, 11.1, 11.2, 11.3

Type: Bug Priority: Major
Reporter: Roel Van de Paar Assignee: Andrei Elkin
Resolution: Unresolved Votes: 0
Labels: not-10.1, not-10.2, not-10.3, not-10.4, regression

Issue Links:
Relates
relates to MDEV-17977 FLUSH MASTER fails with ER_NO_UNIQUE_... Stalled
relates to MDEV-22708 Assertion `!mysql_bin_log.is_open() |... Closed
relates to MDEV-30409 SIGSEGV in __memmove_avx_unaligned_er... Open

 Description   

Though this bug looks like MDEV-22708, it would seem to be a different bug, and it affects only 10.5.5 debug.

# mysqld options required for replay: --log-bin 
SET SQL_MODE='';
 
USE test;
 
RESET MASTER TO 5000000000;
 
CREATE TABLE t (c INT);
 
XA BEGIN 'a';
 
INSERT INTO t  VALUES ('a');
 
XA END 'a';
 
XA PREPARE 'a';

Leads to:

10.5.5 e1013725ce0f3f947e728491eef75d9985e8db2f

 
mysqld: /test/10.5_dbg/sql/log.cc:8135: void MYSQL_BIN_LOG::trx_group_commit_leader(MYSQL_BIN_LOG::group_commit_entry*): Assertion `is_open()' failed.

10.5.5 e1013725ce0f3f947e728491eef75d9985e8db2f

 
Core was generated by `/test/MD250620-mariadb-10.5.5-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 0x14885f32e700 (LWP 2489108))]
 
(gdb) bt
 
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
 
#1  0x000055bd67af07d0 in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
 
#2  0x000055bd672a947a 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  0x000014885d60f801 in __GI_abort () at abort.c:79
 
#6  0x000014885d5ff39a in __assert_fail_base (fmt=0x14885d7867d8 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x55bd67fad7c1 "is_open()", file=file@entry=0x55bd67e29967 "/test/10.5_dbg/sql/log.cc", line=line@entry=8135, function=function@entry=0x55bd67e2ebc0 <MYSQL_BIN_LOG::trx_group_commit_leader(MYSQL_BIN_LOG::group_commit_entry*)::__PRETTY_FUNCTION__> "void MYSQL_BIN_LOG::trx_group_commit_leader(MYSQL_BIN_LOG::group_commit_entry*)") at assert.c:92
 
#7  0x000014885d5ff412 in __GI___assert_fail (assertion=assertion@entry=0x55bd67fad7c1 "is_open()", file=file@entry=0x55bd67e29967 "/test/10.5_dbg/sql/log.cc", line=line@entry=8135, function=function@entry=0x55bd67e2ebc0 <MYSQL_BIN_LOG::trx_group_commit_leader(MYSQL_BIN_LOG::group_commit_entry*)::__PRETTY_FUNCTION__> "void MYSQL_BIN_LOG::trx_group_commit_leader(MYSQL_BIN_LOG::group_commit_entry*)") at assert.c:101
 
#8  0x000055bd673eba7c in MYSQL_BIN_LOG::trx_group_commit_leader (this=this@entry=0x55bd68871940 <mysql_bin_log>, leader=leader@entry=0x14885f32c1b0) at /test/10.5_dbg/sql/log.cc:8135
 
#9  0x000055bd673ec7be in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=this@entry=0x55bd68871940 <mysql_bin_log>, entry=entry@entry=0x14885f32c1b0) at /test/10.5_dbg/sql/log.cc:7966
 
#10 0x000055bd673ecc42 in MYSQL_BIN_LOG::write_transaction_to_binlog (this=this@entry=0x55bd68871940 <mysql_bin_log>, thd=thd@entry=0x14883b415088, cache_mngr=cache_mngr@entry=0x14883b4cd088, end_ev=end_ev@entry=0x14885f32c490, all=all@entry=true, using_stmt_cache=using_stmt_cache@entry=true, using_trx_cache=true) at /test/10.5_dbg/sql/log.cc:7614
 
#11 0x000055bd673ecf00 in binlog_flush_cache (thd=thd@entry=0x14883b415088, cache_mngr=cache_mngr@entry=0x14883b4cd088, end_ev=end_ev@entry=0x14885f32c490, all=all@entry=true, using_stmt=using_stmt@entry=true, using_trx=using_trx@entry=true) at /test/10.5_dbg/sql/log.cc:1797
 
#12 0x000055bd673ed5ca in binlog_commit_flush_xa_prepare (thd=thd@entry=0x14883b415088, all=all@entry=true, cache_mngr=cache_mngr@entry=0x14883b4cd088) at /test/10.5_dbg/sql/log.cc:2122
 
#13 0x000055bd673ed9a0 in write_empty_xa_prepare (cache_mngr=0x14883b4cd088, thd=0x14883b415088) at /test/10.5_dbg/sql/log.cc:10121
 
#14 MYSQL_BIN_LOG::unlog_xa_prepare (this=0x55bd68871940 <mysql_bin_log>, thd=0x14883b415088, all=<optimized out>) at /test/10.5_dbg/sql/log.cc:10162
 
#15 0x000055bd672c1cd4 in ha_prepare (thd=thd@entry=0x14883b415088) at /test/10.5_dbg/sql/handler.cc:1399
 
#16 0x000055bd67214bf2 in trans_xa_prepare (thd=thd@entry=0x14883b415088) at /test/10.5_dbg/sql/xa.cc:531
 
#17 0x000055bd67003740 in mysql_execute_command (thd=thd@entry=0x14883b415088) at /test/10.5_dbg/sql/sql_parse.cc:5805
 
#18 0x000055bd6700b638 in mysql_parse (thd=thd@entry=0x14883b415088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x14885f32d350, 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:7995
 
#19 0x000055bd66ff8110 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x14883b415088, packet=packet@entry=0x14883b467089 "XA PREPARE 'a'", packet_length=packet_length@entry=14, 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
 
#20 0x000055bd66ff68ea in do_command (thd=0x14883b415088) at /test/10.5_dbg/sql/sql_parse.cc:1355
 
#21 0x000055bd6715215f in do_handle_one_connection (connect=<optimized out>, connect@entry=0x14883e4d9f08, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1411
 
#22 0x000055bd6715287b in handle_one_connection (arg=arg@entry=0x14883e4d9f08) at /test/10.5_dbg/sql/sql_connect.cc:1313
 
#23 0x000055bd675b511c in pfs_spawn_thread (arg=0x14885c046788) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
 
#24 0x000014885e2f26db in start_thread (arg=0x14885f32e700) at pthread_create.c:463
 
#25 0x000014885d6f088f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.5.5 (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.5 (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 Alice Sherepa [ 2020-07-06 ]

looks like with the bug, that sujatha.sivakumar found in MDEV-17977

Comment by Roel Van de Paar [ 2023-10-13 ]

11.3.0 905c3d61e18ae6222d0d195c43d335046eec65d9 (Debug)

 
mariadbd: /test/11.3_dbg/sql/log.cc:8865: void MYSQL_BIN_LOG::trx_group_commit_leader(MYSQL_BIN_LOG::group_commit_entry*): Assertion `is_open()' failed.

11.3.0 905c3d61e18ae6222d0d195c43d335046eec65d9 (Debug)

 
Core was generated by `/test/MD270923-mariadb-11.3.0-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=22387316790848)
 
    at ./nptl/pthread_kill.c:44
 
[Current thread is 1 (Thread 0x145c74109640 (LWP 3681358))]
 
(gdb) bt
 
#0  __pthread_kill_implementation (no_tid=0, signo=6, threadid=22387316790848) at ./nptl/pthread_kill.c:44
 
#1  __pthread_kill_internal (signo=6, threadid=22387316790848) at ./nptl/pthread_kill.c:78
 
#2  __GI___pthread_kill (threadid=22387316790848, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
 
#3  0x0000145c8b242476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
 
#4  0x0000145c8b2287f3 in __GI_abort () at ./stdlib/abort.c:79
 
#5  0x0000145c8b22871b in __assert_fail_base (fmt=0x145c8b3dd150 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x559f0a0721b0 "is_open()", file=0x559f09f691bc "/test/11.3_dbg/sql/log.cc", line=8865, function=<optimized out>) at ./assert/assert.c:92
 
#6  0x0000145c8b239e96 in __GI___assert_fail (assertion=0x559f0a0721b0 "is_open()", file=0x559f09f691bc "/test/11.3_dbg/sql/log.cc", line=8865, function=0x559f09f6e0f8 "void MYSQL_BIN_LOG::trx_group_commit_leader(MYSQL_BIN_LOG::group_commit_entry*)") at ./assert/assert.c:101
 
#7  0x0000559f09619835 in MYSQL_BIN_LOG::trx_group_commit_leader (this=this@entry=0x559f0a852140 <mysql_bin_log>, leader=leader@entry=0x145c74107240) at /test/11.3_dbg/sql/log.cc:8865
 
#8  0x0000559f0961a69c in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=this@entry=0x559f0a852140 <mysql_bin_log>, entry=entry@entry=0x145c74107240) at /test/11.3_dbg/sql/log.cc:8694
 
#9  0x0000559f0961accc in MYSQL_BIN_LOG::write_transaction_to_binlog (this=this@entry=0x559f0a852140 <mysql_bin_log>, thd=thd@entry=0x145bd4000d58, cache_mngr=cache_mngr@entry=0x145bd4072fb8, end_ev=end_ev@entry=0x145c74107520, all=all@entry=true, using_stmt_cache=using_stmt_cache@entry=true, using_trx_cache=true, is_ro_1pc=false) at /test/11.3_dbg/sql/log.cc:8291
 
#10 0x0000559f0961aeb0 in binlog_flush_cache (thd=thd@entry=0x145bd4000d58, cache_mngr=cache_mngr@entry=0x145bd4072fb8, end_ev=end_ev@entry=0x145c74107520, all=all@entry=true, using_stmt=using_stmt@entry=true, using_trx=using_trx@entry=true, is_ro_1pc=false) at /test/11.3_dbg/sql/log.cc:1907
 
#11 0x0000559f0961bf95 in binlog_commit_flush_xa_prepare (thd=thd@entry=0x145bd4000d58, all=all@entry=true, cache_mngr=cache_mngr@entry=0x145bd4072fb8) at /test/11.3_dbg/sql/log.cc:2267
 
#12 0x0000559f0961c1a4 in write_empty_xa_prepare (cache_mngr=0x145bd4072fb8, thd=0x145bd4000d58) at /test/11.3_dbg/sql/log.cc:11030
 
#13 MYSQL_BIN_LOG::unlog_xa_prepare (this=0x559f0a852140 <mysql_bin_log>, thd=0x145bd4000d58, all=<optimized out>) at /test/11.3_dbg/sql/log.cc:11056
 
#14 0x0000559f094ba4e6 in ha_prepare (thd=thd@entry=0x145bd4000d58) at /test/11.3_dbg/sql/handler.cc:1548
 
#15 0x0000559f0942689b in trans_xa_prepare (thd=thd@entry=0x145bd4000d58) at /test/11.3_dbg/sql/xa.cc:537
 
#16 0x0000559f091bddcf in mysql_execute_command (thd=thd@entry=0x145bd4000d58, is_called_from_prepared_stmt=is_called_from_prepared_stmt@entry=false) at /test/11.3_dbg/sql/sql_parse.cc:5592
 
#17 0x0000559f091bf5f7 in mysql_parse (thd=thd@entry=0x145bd4000d58, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x145c741081e0) at /test/11.3_dbg/sql/sql_parse.cc:7744
 
#18 0x0000559f091c196d in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x145bd4000d58, packet=packet@entry=0x145bd400b229 "XA PREPARE 'a'", packet_length=packet_length@entry=14, blocking=blocking@entry=true) at /test/11.3_dbg/sql/sql_class.h:247
 
#19 0x0000559f091c3a8d in do_command (thd=0x145bd4000d58, blocking=blocking@entry=true) at /test/11.3_dbg/sql/sql_parse.cc:1406
 
#20 0x0000559f09323cb5 in do_handle_one_connection (connect=<optimized out>, connect@entry=0x559f0ca6d408, put_in_cache=put_in_cache@entry=true) at /test/11.3_dbg/sql/sql_connect.cc:1445
 
#21 0x0000559f09323faa in handle_one_connection (arg=arg@entry=0x559f0ca6d408) at /test/11.3_dbg/sql/sql_connect.cc:1347
 
#22 0x0000559f0976620a in pfs_spawn_thread (arg=0x559f0ca36a68) at /test/11.3_dbg/storage/perfschema/pfs.cc:2201
 
#23 0x0000145c8b294ac3 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
#24 0x0000145c8b326a40 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Bug confirmed present in:
MariaDB: 10.5.23 (dbg), 10.6.16 (dbg), 10.9.8 (dbg), 10.10.7 (dbg), 10.11.6 (dbg), 11.0.4 (dbg), 11.1.3 (dbg), 11.2.2 (dbg), 11.3.0 (dbg)

Bug (or feature/syntax) confirmed not present in:
MariaDB: 10.4.32 (dbg), 10.4.32 (opt), 10.5.23 (opt), 10.6.16 (opt), 10.9.8 (opt), 10.10.7 (opt), 10.11.6 (opt), 11.0.4 (opt), 11.1.3 (opt), 11.2.2 (opt), 11.3.0 (opt)
MySQL: 5.5.62 (dbg), 5.5.62 (opt), 5.6.51 (dbg), 5.6.51 (opt), 5.7.40 (dbg), 8.0.33 (dbg), 8.0.33 (opt)

Comment by Roel Van de Paar [ 2024-01-20 ]

Please also test any fixes with

# mysqld options required for replay: --log-bin --sql_mode=
 
CREATE TABLE ti (a TINYINT UNSIGNED, b SMALLINT, c CHAR(1), d VARBINARY(81), e VARBINARY(46), f VARBINARY(13), g TINYBLOB, h TINYBLOB NOT NULL, id BIGINT NOT NULL, KEY(b), KEY(e), PRIMARY KEY(id)) ENGINE=TokuDB;
 
RESET MASTER TO 2147483648;
 
XA BEGIN 'xid1';
 
INSERT INTO ti VALUES (-3287634876136105235,-77,'hN8','xo3nX9RlofhOYkXfx1OwJRHru4bgh3ZSpWTEKcrfowMBnIubIxGDZ4HyhT7sGwxOR2YHwUoHvoqZBbBuOnOhew7BVbA93gTfHxjNYLxE2ejQUsMnpalJxddUJEwa2aU2E2PYJQk3MWuAvYVx3FKeRPIX4TuL1rQLgLhFRDlzVebO1FOpfoIAQ3mtkD9Rl80DsjhPwEmI4WiHx1x0M6Rv1cKJmlYHWSB1gxKwRtlSRI9LtZLpYWjBBOqm3','wajqNaIEhg0QO4sab1hjaqnqNDLP','cdjHBp2VN5hg2sBX1sYymEAsgdqVlONIkKfEZIhWW7ISCGKInNu6TF6NPbVGIBGGGzyKY2yMLKpXOBtIA5pVLmeCL2yzsOzeC939c2yt','j','oQs',15);
 
XA END 'xid1';
 
XA PREPARE 'xid1';

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