[MDEV-22757] Assertion `!binlog || exist_hton_without_prepare' failed in MYSQL_BIN_LOG::unlog_xa_prepare Created: 2020-05-30  Updated: 2021-04-19  Resolved: 2021-04-19

Status: Closed
Project: MariaDB Server
Component/s: Replication, XA
Affects Version/s: 10.5
Fix Version/s: 10.5.10

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Andrei Elkin
Resolution: Fixed Votes: 0
Labels: regression

Issue Links:
Relates
relates to MDEV-22430 Assertion `ha_info->ht() != binlog_ht... Closed

 Description   

--source include/have_innodb.inc
--source include/have_log_bin.inc
 
CREATE TABLE t1 (a INT) ENGINE=MyISAM;
INSERT INTO t1 VALUES (1),(2);
 
CREATE TABLE t2 (id INT PRIMARY KEY) ENGINE=InnoDB;
INSERT INTO t2 VALUES (1),(2);
 
XA BEGIN 'x';
REPLACE INTO t1 SELECT * FROM t1;
REPLACE INTO t2 SELECT * FROM t2;
XA END 'x';
XA PREPARE 'x';
 
# Cleanup
XA COMMIT 'x';
DROP TABLE t1, t2;

10.5 043828bd

mariadbd: /data/src/10.5/sql/log.cc:10149: virtual int MYSQL_BIN_LOG::unlog_xa_prepare(THD*, bool): Assertion `!binlog || exist_hton_without_prepare' failed.
200530 22:26:14 [ERROR] mysqld got signal 6 ;
 
#7  0x00007f2f370dff12 in __GI___assert_fail (assertion=0x556040115270 "!binlog || exist_hton_without_prepare", file=0x556040111394 "/data/src/10.5/sql/log.cc", line=10149, function=0x556040117aa0 <MYSQL_BIN_LOG::unlog_xa_prepare(THD*, bool)::__PRETTY_FUNCTION__> "virtual int MYSQL_BIN_LOG::unlog_xa_prepare(THD*, bool)") at assert.c:101
#8  0x000055603f5f2974 in MYSQL_BIN_LOG::unlog_xa_prepare (this=0x556040d00120 <mysql_bin_log>, thd=0x7f2f00000b18, all=true) at /data/src/10.5/sql/log.cc:10149
#9  0x000055603f4af35b in ha_prepare (thd=0x7f2f00000b18) at /data/src/10.5/sql/handler.cc:1361
#10 0x000055603f3e4886 in trans_xa_prepare (thd=0x7f2f00000b18) at /data/src/10.5/sql/xa.cc:531
#11 0x000055603f1603f0 in mysql_execute_command (thd=0x7f2f00000b18) at /data/src/10.5/sql/sql_parse.cc:5802
#12 0x000055603f166fb9 in mysql_parse (thd=0x7f2f00000b18, rawbuf=0x7f2f00013a70 "XA PREPARE 'x'", length=14, parser_state=0x7f2f3061b520, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:7991
#13 0x000055603f153365 in dispatch_command (command=COM_QUERY, thd=0x7f2f00000b18, packet=0x7f2f000087c9 "XA PREPARE 'x'", packet_length=14, is_com_multi=false, is_next_command=false) at /data/src/10.5/sql/sql_parse.cc:1875
#14 0x000055603f151a9d in do_command (thd=0x7f2f00000b18) at /data/src/10.5/sql/sql_parse.cc:1356
#15 0x000055603f2f55fb in do_handle_one_connection (connect=0x556043972d58, put_in_cache=true) at /data/src/10.5/sql/sql_connect.cc:1411
#16 0x000055603f2f5363 in handle_one_connection (arg=0x556043972d58) at /data/src/10.5/sql/sql_connect.cc:1313
#17 0x000055603f82c2de in pfs_spawn_thread (arg=0x556043912ed8) at /data/src/10.5/storage/perfschema/pfs.cc:2201
#18 0x00007f2f390684a4 in start_thread (arg=0x7f2f3061c700) at pthread_create.c:456
#19 0x00007f2f3719cd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Not reproducible on 10.4.
No obvious effect on a non-debug build.



 Comments   
Comment by Andrei Elkin [ 2020-06-08 ]

Sergei, the patch is a74e724e061a, which also covers MDEV-22430.

Comment by Roel Van de Paar [ 2020-07-14 ]

# mysqld options required for replay: --log-bin
USE test;
#SET SQL_MODE='';
CREATE TABLE t1 (a INT, KEY(a)) ENGINE=MyISAM;
CREATE TABLE t2 (a INT, b INT) ENGINE=InnoDB;
XA START 'a';
INSERT INTO t2 VALUES (1);
SAVEPOINT sp;
INSERT INTO t2 VALUES (1,1);
ROLLBACK TO sp;
INSERT INTO t1 VALUES (1);
XA END 'a';
XA PREPARE 'a';

Leads to:

10.5.5 e1013725ce0f3f947e728491eef75d9985e8db2f

mysqld: /test/10.5_dbg/sql/log.cc:10156: virtual int MYSQL_BIN_LOG::unlog_xa_prepare(THD*, bool): Assertion `!binlog || exist_hton_without_prepare' 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 0x151831c83700 (LWP 135616))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:57
#1  0x0000561d7d45a7d0 in my_write_core (sig=sig@entry=6) at /test/10.5_dbg/mysys/stacktrace.c:518
#2  0x0000561d7cc1347a 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  0x000015182ff648b1 in __GI_abort () at abort.c:79
#6  0x000015182ff5442a in __assert_fail_base (fmt=0x1518300dba38 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x561d7d797580 "!binlog || exist_hton_without_prepare", file=file@entry=0x561d7d793967 "/test/10.5_dbg/sql/log.cc", line=line@entry=10156, function=function@entry=0x561d7d798640 <MYSQL_BIN_LOG::unlog_xa_prepare(THD*, bool)::__PRETTY_FUNCTION__> "virtual int MYSQL_BIN_LOG::unlog_xa_prepare(THD*, bool)") at assert.c:92
#7  0x000015182ff544a2 in __GI___assert_fail (assertion=assertion@entry=0x561d7d797580 "!binlog || exist_hton_without_prepare", file=file@entry=0x561d7d793967 "/test/10.5_dbg/sql/log.cc", line=line@entry=10156, function=function@entry=0x561d7d798640 <MYSQL_BIN_LOG::unlog_xa_prepare(THD*, bool)::__PRETTY_FUNCTION__> "virtual int MYSQL_BIN_LOG::unlog_xa_prepare(THD*, bool)") at assert.c:101
#8  0x0000561d7cd57990 in MYSQL_BIN_LOG::unlog_xa_prepare (this=0x561d7e1db940 <mysql_bin_log>, thd=0x15180dc15088, all=<optimized out>) at /test/10.5_dbg/sql/log.cc:10156
#9  0x0000561d7cc2bcd4 in ha_prepare (thd=thd@entry=0x15180dc15088) at /test/10.5_dbg/sql/handler.cc:1399
#10 0x0000561d7cb7ebf2 in trans_xa_prepare (thd=thd@entry=0x15180dc15088) at /test/10.5_dbg/sql/xa.cc:531
#11 0x0000561d7c96d740 in mysql_execute_command (thd=thd@entry=0x15180dc15088) at /test/10.5_dbg/sql/sql_parse.cc:5805
#12 0x0000561d7c975638 in mysql_parse (thd=thd@entry=0x15180dc15088, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x151831c82350, 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
#13 0x0000561d7c962110 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x15180dc15088, packet=packet@entry=0x15180dc67089 "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
#14 0x0000561d7c9608ea in do_command (thd=0x15180dc15088) at /test/10.5_dbg/sql/sql_parse.cc:1355
#15 0x0000561d7cabc15f in do_handle_one_connection (connect=<optimized out>, connect@entry=0x151810cd9f08, put_in_cache=put_in_cache@entry=true) at /test/10.5_dbg/sql/sql_connect.cc:1411
#16 0x0000561d7cabc87b in handle_one_connection (arg=arg@entry=0x151810cd9f08) at /test/10.5_dbg/sql/sql_connect.cc:1313
#17 0x0000561d7cf1f11c in pfs_spawn_thread (arg=0x15182e846788) at /test/10.5_dbg/storage/perfschema/pfs.cc:2201
#18 0x0000151830c476db in start_thread (arg=0x151831c83700) at pthread_create.c:463
#19 0x0000151830045a3f 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)

Comment by Roel Van de Paar [ 2020-07-14 ]

Elkin is this bug waiting for you or for serg ?

Comment by Andrei Elkin [ 2020-07-14 ]

Serg, howdy. I got to bounce it back to you, as there's no changes from your round of review
has been requested (as you explained you got to interrupt it actually).

Roel - Salve! This must answer your question . And thank you for heads up!

Comment by Sergei Golubchik [ 2020-10-22 ]

back to Elkin as per slack chat on June 17th

Comment by Andrei Elkin [ 2021-04-18 ]

Roel: Your provision by https://jira.mariadb.org/browse/MDEV-22757?focusedCommentId=159815&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-159815 is really helpful.
Yet it would be close to perfect when a to-be-errored-out statement like

INSERT INTO t2 VALUES (1);

would be marked as such, preferably with the mtr style

--error 1136
INSERT INTO t2 VALUES (1)

Comment by Andrei Elkin [ 2021-04-18 ]

Although an experienced sql-reader might see the error without sending the query to the server,
being fool-proof never hurts but more germane saves our time.

Cheers !

Comment by Andrei Elkin [ 2021-04-19 ]

675c22c065 pushed.

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