[MDEV-29038] XA assertions failing in binlog_rollback and binlog_commit #2 Created: 2022-07-05  Updated: 2023-08-16  Resolved: 2023-08-16

Status: Closed
Project: MariaDB Server
Component/s: Data Definition - Alter Table, XA
Affects Version/s: N/A
Fix Version/s: 11.2.1

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Nikita Malyavin
Resolution: Fixed Votes: 0
Labels: online-ddl

Issue Links:
Problem/Incident
is caused by MDEV-16329 Engine-independent online ALTER TABLE Closed
Relates
relates to MDEV-28808 Test MDEV-16329 (ALTER ONLINE TABLE) ... Stalled

 Description    

--source include/have_innodb.inc
 
--source include/have_debug_sync.inc
 
 
 
CREATE TABLE t (a INT) ENGINE=InnoDB;
 
INSERT INTO t VALUES (1);
 
XA BEGIN 'xid';
 
--send
 
  set debug_sync= 'now wait_for downgraded';
 
 
 
--connect (con1,localhost,root,,test)
 
set debug_sync= 'alter_table_online_downgraded signal downgraded wait_for goforit';
 
--send
 
  ALTER TABLE t FORCE, ALGORITHM=COPY, LOCK=NONE;
 
 
 
--connection default
 
--reap
 
INSERT INTO t VALUES (2);
 
set debug_sync= 'now signal goforit';
 
XA END 'xid';
 
XA ROLLBACK 'xid';
 
 
 
# Cleanup
 
DROP TABLE t;
 
set debug_sync= reset;

bb-10.10-MDEV-16329 49ad875902

 
mariadbd: /data/src/preview-10.10-online-alter-gcov/sql/log.cc:2417: int binlog_rollback(handlerton*, THD*, bool): Assertion `thd->lex->sql_command != SQLCOM_XA_ROLLBACK' failed.
 
220706  0:59:39 [ERROR] mysqld got signal 6 ;
 
 
 
#7  0x00007f835f890662 in __GI___assert_fail (assertion=0x55eae0e2e1e0 "thd->lex->sql_command != SQLCOM_XA_ROLLBACK", file=0x55eae0e2cd80 "/data/src/preview-10.10-online-alter-gcov/sql/log.cc", line=2417, function=0x55eae0e2e160 "int binlog_rollback(handlerton*, THD*, bool)") at assert.c:101
 
No locals.
 
#8  0x000055eadfd0082b in binlog_rollback (hton=0x55eae48f4688, thd=0x7f8308000db8, all=true) at /data/src/preview-10.10-online-alter-gcov/sql/log.cc:2417
 
        _db_stack_frame_ = {func = 0x55eae0df8f02 "ha_rollback_trans", file = 0x55eae0df8080 "/data/src/preview-10.10-online-alter-gcov/sql/handler.cc", level = 2147483655, line = -1, prev = 0x7f83485f1b10}
 
        is_ending_trans = true
 
        rollback_online = true
 
        error = 0
 
        cache_mngr = 0x0
 
        __PRETTY_FUNCTION__ = "int binlog_rollback(handlerton*, THD*, bool)"
 
#9  0x000055eadfa90a6f in ha_rollback_trans (thd=0x7f8308000db8, all=true) at /data/src/preview-10.10-online-alter-gcov/sql/handler.cc:2180
 
        err = 2046882558
 
        ht = 0x55eae48f4688
 
        error = 0
 
        trans = 0x7f8308004770
 
        ha_info = 0x7f83080037e8
 
        ha_info_next = 0x55eae0caff60
 
        is_real_trans = true
 
        _db_stack_frame_ = {func = 0x55eae0cb0408 "trans_xa_rollback", file = 0x55eae0cb0018 "/data/src/preview-10.10-online-alter-gcov/sql/xa.cc", level = 2147483654, line = -1, prev = 0x7f83485f1ba0}
 
        __PRETTY_FUNCTION__ = "int ha_rollback_trans(THD*, bool)"
 
#10 0x000055eadf900ca3 in xa_trans_force_rollback (thd=0x7f8308000db8) at /data/src/preview-10.10-online-alter-gcov/sql/xa.cc:393
 
        rc = false
 
#11 0x000055eadf903e6e in trans_xa_rollback (thd=0x7f8308000db8) at /data/src/preview-10.10-online-alter-gcov/sql/xa.cc:821
 
        xid_state = @0x7f83080047a8: {xid_cache_element = 0x7f830819fd78}
 
        _db_stack_frame_ = {func = 0x55eae0c06038 "mysql_execute_command", file = 0x55eae0c052e0 "/data/src/preview-10.10-online-alter-gcov/sql/sql_parse.cc", level = 2147483653, line = 821, prev = 0x7f83485f1f30}
 
        __PRETTY_FUNCTION__ = "bool trans_xa_rollback(THD*)"
 
        mdl_request = {type = 13, duration = MDL_STATEMENT, next_in_list = 0x21, prev_in_list = 0x7f835ef0b640, ticket = 0x7f83081824d0, key = {m_length = 3, m_db_name_length = 0, m_hash_value = 65537, m_ptr = "\000\000\000\340\352U\000\000 \034_H\203\177\000\000\024\002\000\000\000\000\000\000!\000\000\000\000\000\000\000\230\063\341\344\352U\000\000\023\000\000\000\366\005\000\000\236\020\242\340\352U\000\000@\034_H\203\177\000\000\275\022\242\340\352U\000\000@\034_H\203\177\000\000\ba\000\b\203\177\000\000\240\035_H\203\177\000\000\231n8\337\352U\000\000\000Q\000\b\203\177\000\000\270\r\000\b\203\177\000\000\220\034_H\203\177\000\000`\v\000\b\203\177\000\000\220\034_H\203\177\000\000\324\262\242\340\352U\000\000h\206\031_\203\177\000\000\300Y{\344\000\000\000\000#0\301\340\352U\000\000\000\000\000\000\000\000\000\000\300\034_H\203\177\000\000\275\022\242\340\000\000\001\000"...}, m_src_file = 0x55eae0cb0018 "/data/src/preview-10.10-online-alter-gcov/sql/xa.cc", m_src_line = 807}
 
#12 0x000055eadf39b065 in mysql_execute_command (thd=0x7f8308000db8, is_called_from_prepared_stmt=false) at /data/src/preview-10.10-online-alter-gcov/sql/sql_parse.cc:5879
 
        rollback_failed = 32
 
        res = 0
 
        up_result = 0
 
        lex = 0x7f8308005100
 
        select_lex = 0x7f83080059d8
 
        first_table = 0x0
 
        all_tables = 0x0
 
        unit = 0x7f83080051d8
 
        have_table_map_for_update = false
 
        rpl_filter = 0x55eae155d270 <vtable for Internal_error_handler+16>
 
        _db_stack_frame_ = {func = 0x55eae0c073cf "mysql_parse", file = 0x55eae0c052e0 "/data/src/preview-10.10-online-alter-gcov/sql/sql_parse.cc", level = 2147483652, line = -1, prev = 0x7f83485f2380}
 
        __PRETTY_FUNCTION__ = "int mysql_execute_command(THD*, bool)"
 
        ots = {ctx = 0x7f8308004d98, traceable = false}
 
        orig_binlog_format = BINLOG_FORMAT_MIXED
 
        orig_current_stmt_binlog_format = BINLOG_FORMAT_STMT
 
#13 0x000055eadf3a7c10 in mysql_parse (thd=0x7f8308000db8, rawbuf=0x7f8308015460 "XA ROLLBACK 'xid'", length=17, parser_state=0x7f83485f2500) at /data/src/preview-10.10-online-alter-gcov/sql/sql_parse.cc:8036
 
        found_semicolon = 0x0
 
        error = 32643
 
        lex = 0x7f8308005100
 
        err = false
 
        _db_stack_frame_ = {func = 0x55eae0c05879 "dispatch_command", file = 0x55eae0c052e0 "/data/src/preview-10.10-online-alter-gcov/sql/sql_parse.cc", level = 2147483651, line = -1, prev = 0x7f83485f24e0}
 
        __PRETTY_FUNCTION__ = "void mysql_parse(THD*, char*, uint, Parser_state*)"
 
#14 0x000055eadf37ef11 in dispatch_command (command=COM_QUERY, thd=0x7f8308000db8, packet=0x7f830800b9e9 "XA ROLLBACK 'xid'", packet_length=17, blocking=true) at /data/src/preview-10.10-online-alter-gcov/sql/sql_parse.cc:1894
 
        packet_end = 0x7f8308015471 ""
 
        parser_state = {m_lip = {lookahead_token = -1, lookahead_yylval = 0x0, m_thd = 0x7f8308000db8, m_ptr = 0x7f8308015472 "\004", m_tok_start = 0x7f8308015472 "\004", m_tok_end = 0x7f8308015472 "\004", m_end_of_query = 0x7f8308015471 "", m_tok_start_prev = 0x7f8308015471 "", m_buf = 0x7f8308015460 "XA ROLLBACK 'xid'", m_buf_length = 17, m_echo = true, m_echo_saved = false, m_cpp_buf = 0x7f83080154c8 "XA ROLLBACK 'xid'", m_cpp_ptr = 0x7f83080154d9 "", m_cpp_tok_start = 0x7f83080154d9 "", m_cpp_tok_start_prev = 0x7f83080154d9 "", m_cpp_tok_end = 0x7f83080154d9 "", m_body_utf8 = 0x0, m_body_utf8_ptr = 0x108000cb8 <error: Cannot access memory at address 0x108000cb8>, m_cpp_utf8_processed_ptr = 0x0, next_state = MY_LEX_END, found_semicolon = 0x0, ignore_space = false, stmt_prepare_mode = false, multi_statements = true, yylineno = 1, m_digest = 0x0, in_comment = NO_COMMENT, in_comment_saved = (unknown: 0x10000), m_cpp_text_start = 0x7f83080154d5 "xid'", m_cpp_text_end = 0x7f83080154d8 "'", m_underscore_cs = 0x0}, m_yacc = {yacc_yyss = 0x0, yacc_yyvs = 0x0, m_set_signal_info = {m_item = {0x0 <repeats 13 times>}}, m_lock_type = TL_READ_DEFAULT, m_mdl_type = MDL_SHARED_READ}, m_digest_psi = 0x7f8308004b28}
 
        net = 0x7f83080010f0
 
        error = false
 
        do_end_of_statement = true
 
        _db_stack_frame_ = {func = 0x55eae0c054fd "do_command", file = 0x55eae0c052e0 "/data/src/preview-10.10-online-alter-gcov/sql/sql_parse.cc", level = 2147483650, line = -1, prev = 0x7f83485f2dc0}
 
        drop_more_results = false
 
        __PRETTY_FUNCTION__ = "dispatch_command_return dispatch_command(enum_server_command, THD*, char*, uint, bool)"
 
        __FUNCTION__ = "dispatch_command"
 
        res = <optimized out>
 
#15 0x000055eadf37c0ea in do_command (thd=0x7f8308000db8, blocking=true) at /data/src/preview-10.10-online-alter-gcov/sql/sql_parse.cc:1407
 
        return_value = DISPATCH_COMMAND_SUCCESS
 
        packet = 0x7f830800b9e8 "\003XA ROLLBACK 'xid'"
 
        packet_length = 18
 
        net = 0x7f83080010f0
 
        command = COM_QUERY
 
        _db_stack_frame_ = {func = 0x55eae107d52b "?func", file = 0x55eae107d531 "?file", level = 2147483649, line = -1, prev = 0x0}
 
        __PRETTY_FUNCTION__ = "dispatch_command_return do_command(THD*, bool)"
 
        __FUNCTION__ = "do_command"
 
#16 0x000055eadf6e821b in do_handle_one_connection (connect=0x55eae50438b8, put_in_cache=true) at /data/src/preview-10.10-online-alter-gcov/sql/sql_connect.cc:1418
 
        create_user = true
 
        thr_create_utime = 3480491481792
 
        thd = 0x7f8308000db8
 
        __PRETTY_FUNCTION__ = "void do_handle_one_connection(CONNECT*, bool)"
 
#17 0x000055eadf6e7a22 in handle_one_connection (arg=0x55eae5059308) at /data/src/preview-10.10-online-alter-gcov/sql/sql_connect.cc:1312
 
        connect = 0x55eae5059308
 
#18 0x000055eadfff6113 in pfs_spawn_thread (arg=0x55eae5043428) at /data/src/preview-10.10-online-alter-gcov/storage/perfschema/pfs.cc:2201
 
        typed_arg = 0x55eae5043428
 
        user_arg = 0x55eae5059308
 
        user_start_routine = 0x55eadf6e796d <handle_one_connection(void*)>
 
        pfs = 0x7f835f196700
 
        klass = 0x55eae47d3580
 
#19 0x00007f835fd5aea7 in start_thread (arg=<optimized out>) at pthread_create.c:477
 
        ret = <optimized out>
 
        pd = <optimized out>
 
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140201831642880, 6759536943321734637, 140736881142638, 140736881142639, 140201831640960, 311296, -6717079575113605651, -6717104954092790291}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
 
        not_first_call = 0
 
#20 0x00007f835f959def in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Same in binlog_commit with COMMIT 'xid' ONE PHASE instead of ROLLBACK.

 Comments   
Comment by Nikita Malyavin [ 2022-07-25 ]

Please review "MDEV-29038 XA assertions failing in binlog_rollback and binlog_commit" on bb-10.10-ddl-nikita

Comment by Sergei Golubchik [ 2022-08-25 ]

2b7891399ee is ok

Comment by Elena Stepanova [ 2023-04-04 ]

Same test case but with COMMIT ... ONE PHASE instead of ROLLBACK still fails.

--source include/have_innodb.inc
 
--source include/have_debug_sync.inc
 
 
 
CREATE TABLE t (a INT) ENGINE=InnoDB;
 
INSERT INTO t VALUES (1);
 
XA BEGIN 'xid';
 
--send
 
  set debug_sync= 'now wait_for downgraded';
 
 
 
--connect (con1,localhost,root,,test)
 
set debug_sync= 'alter_table_online_downgraded signal downgraded wait_for goforit';
 
--send
 
  ALTER TABLE t FORCE, ALGORITHM=COPY, LOCK=NONE;
 
 
 
--connection default
 
--reap
 
INSERT INTO t VALUES (2);
 
set debug_sync= 'now signal goforit';
 
XA END 'xid';
 
XA COMMIT 'xid' ONE PHASE;
 
 
 
# Cleanup
 
DROP TABLE t;
 
set debug_sync= reset;

bb-11.0-oalter e599b8b45

 
mariadbd: /data/src/bb-11.0-oalter-debug/sql/log.cc:2343: int binlog_commit(THD*, bool, bool): Assertion `(thd && (WSREP_PROVIDER_EXISTS_ && thd->variables.wsrep_on)) || (thd->lex->sql_command != SQLCOM_XA_PREPARE && !(thd->lex->sql_command == SQLCOM_XA_COMMIT && thd->lex->xa_opt == XA_ONE_PHASE))' failed.
 
230404 18:30:14 [ERROR] mysqld got signal 6 ;
 
 
 
#9  0x00007f29dae53df2 in __GI___assert_fail (assertion=0x564e692a3aa0 "(thd && (WSREP_PROVIDER_EXISTS_ && thd->variables.wsrep_on)) || (thd->lex->sql_command != SQLCOM_XA_PREPARE && !(thd->lex->sql_command == SQLCOM_XA_COMMIT && thd->lex->xa_opt == XA_ONE_PHASE))", file=0x564e692a27a8 "/data/src/bb-11.0-oalter-debug/sql/log.cc", line=2343, function=0x564e692a3a78 "int binlog_commit(THD*, bool, bool)") at ./assert/assert.c:101
 
#10 0x0000564e687c45e2 in binlog_commit (thd=0x7f2944000dc8, all=true, ro_1pc=false) at /data/src/bb-11.0-oalter-debug/sql/log.cc:2343
 
#11 0x0000564e6866ad03 in commit_one_phase_2 (thd=0x7f2944000dc8, all=true, trans=0x7f29440047a8, is_real_trans=true) at /data/src/bb-11.0-oalter-debug/sql/handler.cc:2116
 
#12 0x0000564e6866ab23 in ha_commit_one_phase (thd=0x7f2944000dc8, all=true) at /data/src/bb-11.0-oalter-debug/sql/handler.cc:2078
 
#13 0x0000564e68669bac in ha_commit_trans (thd=0x7f2944000dc8, all=true) at /data/src/bb-11.0-oalter-debug/sql/handler.cc:1872
 
#14 0x0000564e68594d5a in trans_xa_commit (thd=0x7f2944000dc8) at /data/src/bb-11.0-oalter-debug/sql/xa.cc:670
 
#15 0x0000564e6828021b in mysql_execute_command (thd=0x7f2944000dc8, is_called_from_prepared_stmt=false) at /data/src/bb-11.0-oalter-debug/sql/sql_parse.cc:5867
 
#16 0x0000564e68286c14 in mysql_parse (thd=0x7f2944000dc8, rawbuf=0x7f29440154d0 "XA COMMIT 'xid' ONE PHASE", length=25, parser_state=0x7f29cc1ed370) at /data/src/bb-11.0-oalter-debug/sql/sql_parse.cc:8000
 
#17 0x0000564e6827287f in dispatch_command (command=COM_QUERY, thd=0x7f2944000dc8, packet=0x7f294400ba59 "XA COMMIT 'xid' ONE PHASE", packet_length=25, blocking=true) at /data/src/bb-11.0-oalter-debug/sql/sql_parse.cc:1894
 
#18 0x0000564e682711e6 in do_command (thd=0x7f2944000dc8, blocking=true) at /data/src/bb-11.0-oalter-debug/sql/sql_parse.cc:1407
 
#19 0x0000564e68463a52 in do_handle_one_connection (connect=0x564e6c72fdc8, put_in_cache=true) at /data/src/bb-11.0-oalter-debug/sql/sql_connect.cc:1416
 
#20 0x0000564e684637c7 in handle_one_connection (arg=0x564e6c776048) at /data/src/bb-11.0-oalter-debug/sql/sql_connect.cc:1318
 
#21 0x0000564e68983258 in pfs_spawn_thread (arg=0x564e6c72f938) at /data/src/bb-11.0-oalter-debug/storage/perfschema/pfs.cc:2201
 
#22 0x00007f29daea7fd4 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
 
#23 0x00007f29daf2866c in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Comment by Nikita Malyavin [ 2023-04-05 ]

elenst

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