[MDEV-32731] Assertion `owning_thread_id_ == wsrep::this_thread::get_id()' failed in int wsrep::client_state::before_rollback() Created: 2023-11-08  Updated: 2023-11-28

Status: Open
Project: MariaDB Server
Component/s: Galera
Affects Version/s: 10.4, 10.5, 10.6, 10.9, 10.10, 10.11, 11.0, 11.1, 11.2, 11.3
Fix Version/s: 10.4, 10.5, 10.6, 10.11, 11.0, 11.1, 11.2, 11.3

Type: Bug Priority: Major
Reporter: Ramesh Sivaraman Assignee: Julius Goryavsky
Resolution: Unresolved Votes: 0
Labels: None

Attachments: File n1.cnf     File n2.cnf    

 Description   

SET sql_mode='';
SET SESSION autocommit=0;
SET SESSION wsrep_trx_fragment_size=512;
CREATE OR REPLACE TABLE ti (a MEDIUMINT NOT NULL, b SMALLINT UNSIGNED NOT NULL, c CHAR(40) NOT NULL, d VARBINARY(57), e VARBINARY(87), f VARBINARY(35) NOT NULL, g TINYBLOB, h LONGBLOB NOT NULL, id BIGINT NOT NULL, KEY(b), KEY(e), PRIMARY KEY(id)) ENGINE=InnoDB;
CREATE TABLE t1 (pk INT PRIMARY KEY) ENGINE=InnoDB;
LOCK TABLE t1 READ;
ALTER TABLE ti CHANGE COLUMN a a CHAR(177);
DROP TABLE t1;
LOCK TABLE test.dummy WRITE;
INSERT INTO t1 VALUES ('1006aaaaaaaaaaaaaaaaaaaaaaaaaa');
CREATE USER READonly@localhost;
INSERT INTO ti VALUES (602995,2228,'nY5','8kDC5qzuvKVwR8CuRguXFHekxP15mDN','ZSt4VbEtqtDCiDbHPaM2JGyR','Gfa2TphpP0iJibwobXFuk9CFGfsp3M4duqwWviqaPdDxv8xsnpdsvfXNK14cVUG8QxUYLPatVhyrU1C2ADBzGQ7SEPhr4vWjhqgeJx0QaOgiL2AOR78W7HLSMYA9iXUtHhl0ulSz7s6kOHsjweEIYKNTpBOEE1VCItUl9HRl7WzntumcyRF2DemJ4qpRrh77liK2R7UJ66pxT7Kh2BNQH','nw','j',13);

Leads to:

10.4.32 952f06aa8bcfad6c62d4c2bbc15ffe6e05f01008 (Optimized)

(gdb) bt
#0  0x000014d453c15c50 in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#1  0x000014d453c1777b in _Unwind_Backtrace () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#2  0x000014d453ec20a6 in __GI___backtrace (array=array@entry=0x14d44015a5e0, size=size@entry=128) at backtrace.c:116
#3  0x0000560b65685612 in my_print_stacktrace (stack_bottom=0x14d4401f2e38 "H\f", thread_stack=299008, silent=silent@entry=0 '\000') at /test/10.4_opt/mysys/stacktrace.c:174
#4  0x0000560b6517cf6d in handle_fatal_signal (sig=11) at /test/10.4_opt/sql/signal_handler.cc:235
#5  <signal handler called>
#6  0x000000000000014a in ?? ()
#7  0x0000560b657f50bf in wsrep::high_priority_switch::~high_priority_switch (this=<synthetic pointer>, __in_chrg=<optimized out>) at /test/10.4_opt/wsrep-lib/include/wsrep/high_priority_service.hpp:257
#8  apply_fragment (server_state=..., high_priority_service=..., streaming_applier=0x14d3b0023f70, ws_handle=..., ws_meta=..., data=...) at /test/10.4_opt/wsrep-lib/src/server_state.cpp:98
#9  0x0000560b657f7bef in apply_write_set (server_state=..., high_priority_service=..., ws_handle=..., ws_meta=..., data=...) at /test/10.4_opt/wsrep-lib/src/server_state.cpp:360
#10 0x0000560b657f8831 in wsrep::server_state::on_apply (this=<optimized out>, high_priority_service=..., ws_handle=..., ws_meta=..., data=...) at /test/10.4_opt/wsrep-lib/src/server_state.cpp:1128
#11 0x0000560b6580897c in wsrep::high_priority_service::apply (data=..., ws_meta=..., ws_handle=..., this=0x14d44015cd70) at /test/10.4_opt/wsrep-lib/include/wsrep/high_priority_service.hpp:47
#12 (anonymous namespace)::apply_cb (ctx=ctx@entry=0x14d44015cd70, wsh=wsh@entry=0x14d44015bda0, flags=<optimized out>, flags@entry=64, buf=buf@entry=0x14d44015bdb0, meta=meta@entry=0x14d44015c060, 
    exit_loop=exit_loop@entry=0x14d44015c01f) at /test/10.4_opt/wsrep-lib/src/wsrep_provider_v26.cpp:507
#13 0x000014d453619925 in galera::TrxHandleSlave::apply (this=this@entry=0x14d3b001cc10, recv_ctx=recv_ctx@entry=0x14d44015cd70, 
    apply_cb=0x560b65808850 <(anonymous namespace)::apply_cb(void*, wsrep_ws_handle_t const*, uint32_t, wsrep_buf_t const*, wsrep_trx_meta_t const*, wsrep_bool_t*)>, meta=..., 
    exit_loop=exit_loop@entry=@0x14d44015c01f: false) at /test/galera_4x/galera/src/trx_handle.cpp:396
#14 0x000014d45362f9fe in galera::ReplicatorSMM::apply_trx (this=0x560b686dd760, recv_ctx=0x14d44015cd70, ts=...) at /test/galera_4x/galera/src/replicator_smm.cpp:516
#15 0x000014d453633fc8 in galera::ReplicatorSMM::process_trx (this=0x560b686dd760, recv_ctx=0x14d44015cd70, ts_ptr=...) at /test/galera_4x/galera/src/replicator_smm.cpp:2124
#16 0x000014d453665989 in galera::GcsActionSource::process_writeset (this=0x560b686d62e0, recv_ctx=0x14d44015cd70, act=..., exit_loop=@0x14d44015c99f: false)
    at /test/galera_4x/galera/src/gcs_action_source.cpp:62
#17 0x000014d4536663c3 in galera::GcsActionSource::dispatch (this=0x560b686d62e0, recv_ctx=0x14d44015cd70, act=..., exit_loop=<optimized out>) at /test/galera_4x/galera/src/gcs_action_source.cpp:110
#18 0x000014d453666982 in galera::GcsActionSource::process (this=0x560b686d62e0, recv_ctx=0x14d44015cd70, exit_loop=@0x14d44015c99f: false) at /test/galera_4x/galera/src/gcs_action_source.cpp:186
#19 0x000014d4536310a0 in galera::ReplicatorSMM::async_recv (this=0x560b686dd760, recv_ctx=0x14d44015cd70) at /test/galera_4x/galera/src/replicator_smm.cpp:402
#20 0x000014d453606061 in galera_recv (gh=<optimized out>, recv_ctx=<optimized out>) at /test/galera_4x/galera/src/wsrep_provider.cpp:264
#21 0x0000560b65808fc2 in wsrep::wsrep_provider_v26::run_applier (this=<optimized out>, applier_ctx=<optimized out>) at /test/10.4_opt/wsrep-lib/src/wsrep_provider_v26.cpp:858
#22 0x0000560b653e7511 in wsrep_replication_process (thd=0x14d3b0000c48, arg=<optimized out>) at /test/10.4_opt/wsrep-lib/include/wsrep/server_state.hpp:320
#23 0x0000560b653d896f in start_wsrep_THD (arg=0x560b68ee7950) at /test/10.4_opt/sql/wsrep_mysqld.h:385
#24 0x000014d4542c8609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#25 0x000014d453eb4133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

11.3.0 905c3d61e18ae6222d0d195c43d335046eec65d9 (Debug)

#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#1  0x0000557832a1b723 in my_write_core (sig=sig@entry=6) at /test/11.3_dbg/mysys/stacktrace.c:424
#2  0x000055783230bd56 in handle_fatal_signal (sig=6) at /test/11.3_dbg/sql/signal_handler.cc:360
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#5  0x0000151aad7f3859 in __GI_abort () at abort.c:79
#6  0x0000151aad7f3729 in __assert_fail_base (fmt=0x151aad989588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x5578331facb8 "owning_thread_id_ == wsrep::this_thread::get_id()", 
    file=0x5578331fa948 "/test/11.3_dbg/wsrep-lib/src/client_state.cpp", line=431, function=<optimized out>) at assert.c:92
#7  0x0000151aad804fd6 in __GI___assert_fail (assertion=assertion@entry=0x5578331facb8 "owning_thread_id_ == wsrep::this_thread::get_id()", 
    file=file@entry=0x5578331fa948 "/test/11.3_dbg/wsrep-lib/src/client_state.cpp", line=line@entry=431, function=function@entry=0x5578331fad70 "int wsrep::client_state::before_rollback()") at assert.c:101
#8  0x0000557832b8eb85 in wsrep::client_state::before_rollback (this=this@entry=0x1519f4027798) at /test/11.3_dbg/wsrep-lib/src/client_state.cpp:434
#9  0x00005578325c01b0 in Wsrep_high_priority_service::log_dummy_write_set (this=0x1519f402abf0, ws_handle=..., ws_meta=..., err=...) at /test/11.3_dbg/sql/wsrep_high_priority_service.cc:496
#10 0x0000557832b9b430 in apply_fragment (server_state=..., high_priority_service=..., streaming_applier=streaming_applier@entry=0x1519f402abf0, ws_handle=..., ws_meta=..., data=...)
    at /test/11.3_dbg/wsrep-lib/src/server_state.cpp:123
#11 0x0000557832ba377c in apply_write_set (server_state=..., high_priority_service=..., ws_handle=..., ws_meta=..., data=...) at /test/11.3_dbg/wsrep-lib/src/server_state.cpp:360
#12 0x0000557832ba4557 in wsrep::server_state::on_apply (this=<optimized out>, high_priority_service=..., ws_handle=..., ws_meta=..., data=...) at /test/11.3_dbg/wsrep-lib/src/server_state.cpp:1128
#13 0x0000557832bb1976 in wsrep::high_priority_service::apply (data=..., ws_meta=..., ws_handle=..., this=0x151a5276bbc0) at /test/11.3_dbg/wsrep-lib/include/wsrep/high_priority_service.hpp:47
#14 (anonymous namespace)::apply_cb (ctx=ctx@entry=0x151a5276bbc0, wsh=wsh@entry=0x151a5276abf0, flags=flags@entry=64, buf=buf@entry=0x151a5276ac00, meta=meta@entry=0x151a5276aeb0, 
    exit_loop=exit_loop@entry=0x151a5276ae6f) at /test/11.3_dbg/wsrep-lib/src/wsrep_provider_v26.cpp:507
#15 0x0000151aad256925 in galera::TrxHandleSlave::apply (this=this@entry=0x1519f4020b60, recv_ctx=recv_ctx@entry=0x151a5276bbc0, 
    apply_cb=0x557832bb17f3 <(anonymous namespace)::apply_cb(void*, wsrep_ws_handle_t const*, uint32_t, wsrep_buf_t const*, wsrep_trx_meta_t const*, wsrep_bool_t*)>, meta=..., 
    exit_loop=exit_loop@entry=@0x151a5276ae6f: false) at /test/galera_4x/galera/src/trx_handle.cpp:396
#16 0x0000151aad26c9fe in galera::ReplicatorSMM::apply_trx (this=0x557834182ca0, recv_ctx=0x151a5276bbc0, ts=...) at /test/galera_4x/galera/src/replicator_smm.cpp:516
#17 0x0000151aad270fc8 in galera::ReplicatorSMM::process_trx (this=0x557834182ca0, recv_ctx=0x151a5276bbc0, ts_ptr=...) at /test/galera_4x/galera/src/replicator_smm.cpp:2124
#18 0x0000151aad2a2989 in galera::GcsActionSource::process_writeset (this=0x55783417b7d0, recv_ctx=0x151a5276bbc0, act=..., exit_loop=@0x151a5276b7ef: false)
    at /test/galera_4x/galera/src/gcs_action_source.cpp:62
#19 0x0000151aad2a33c3 in galera::GcsActionSource::dispatch (this=0x55783417b7d0, recv_ctx=0x151a5276bbc0, act=..., exit_loop=<optimized out>) at /test/galera_4x/galera/src/gcs_action_source.cpp:110
#20 0x0000151aad2a3982 in galera::GcsActionSource::process (this=0x55783417b7d0, recv_ctx=0x151a5276bbc0, exit_loop=@0x151a5276b7ef: false) at /test/galera_4x/galera/src/gcs_action_source.cpp:186
#21 0x0000151aad26e0a0 in galera::ReplicatorSMM::async_recv (this=0x557834182ca0, recv_ctx=0x151a5276bbc0) at /test/galera_4x/galera/src/replicator_smm.cpp:402
#22 0x0000151aad243061 in galera_recv (gh=<optimized out>, recv_ctx=<optimized out>) at /test/galera_4x/galera/src/wsrep_provider.cpp:264
#23 0x0000557832bb264e in wsrep::wsrep_provider_v26::run_applier (this=<optimized out>, applier_ctx=<optimized out>) at /test/11.3_dbg/wsrep-lib/src/wsrep_provider_v26.cpp:858
#24 0x00005578325e010a in wsrep_replication_process (thd=0x1519f4000f88, arg=<optimized out>) at /test/11.3_dbg/sql/wsrep_server_state.h:56
#25 0x00005578325cc564 in start_wsrep_THD (arg=0x5578345d95d0) at /test/11.3_dbg/sql/wsrep_mysqld.h:541
#26 0x0000151aadd04609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#27 0x0000151aad8f0133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Bug confirmed present in:
MariaDB: 10.4.32 (dbg), 10.4.32 (opt), 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.5.23 (opt), 10.6.16 (opt), 10.10.7 (opt), 10.9.8 (opt), 10.11.6 (opt), 11.0.4 (opt), 11.1.3 (opt), 11.2.2 (opt), 11.3.0 (opt)



 Comments   
Comment by Ramesh Sivaraman [ 2023-11-08 ]

sysprg MTR test run failing with data inconsistency error.

./mtr --mysqld=--wsrep_slave_threads=12 galera.galera
 
--source include/galera_cluster.inc
--source include/have_innodb.inc
 
SET SQL_MODE='';
SET SESSION autocommit=0; 
SET SESSION wsrep_trx_fragment_size=512; 
CREATE OR REPLACE TABLE ti (a MEDIUMINT NOT NULL, b SMALLINT UNSIGNED NOT NULL, c CHAR(40) NOT NULL, d VARBINARY(57), e VARBINARY(87), f VARBINARY(35) NOT NULL, g TINYBLOB, h LONGBLOB NOT NULL, id BIGINT NOT NULL, KEY(b), KEY(e), PRIMARY KEY(id)) engine=innodb; 
CREATE TABLE t1 (pk int primary key) engine=InnoDB; 
lock table t1 read;
--error ER_TABLE_NOT_LOCKED
ALTER TABLE ti CHANGE COLUMN a a CHAR(177); 
--error ER_TABLE_NOT_LOCKED_FOR_WRITE
DROP TABLE t1; 
--error ER_NO_SUCH_TABLE
LOCK TABLE test.dummy WRITE; 
INSERT INTO t1 VALUES('1006aaaaaaaaaaaaaaaaaaaaaaaaaa'); 
CREATE USER readonly@localhost; 
INSERT INTO ti VALUES (602995,2228,'nY5','8kDC5qzuvKVwR8CuRguXFHekxP15mDN','ZSt4VbEtqtDCiDbHPaM2JGyR','Gfa2TphpP0iJibwobXFuk9CFGfsp3M4duqwWviqaPdDxv8xsnpdsvfXNK14cVUG8QxUYLPatVhyrU1C2ADBzGQ7SEPhr4vWjhqgeJx0QaOgiL2AOR78W7HLSMYA9iXUtHhl0ulSz7s6kOHsjweEIYKNTpBOEE1VCItUl9HRl7WzntumcyRF2DemJ4qpRrh77liK2R7UJ66pxT7Kh2BNQH','nw','j',13); 

Leads to

galera.galera 'innodb'                   [ fail ]  Found warnings/errors in server log file!
        Test ended at 2023-11-08 13:02:46
line
2023-11-08 13:02:36 10 [Warning] WSREP: BF applier failed to open_and_lock_tables: 1146, fatal: 0 wsrep = (exec_mode: 2 conflict_state: 0 seqno: 7)
2023-11-08 13:02:36 10 [Warning] WSREP: Event 3 Write_rows_v1 apply failed: 1146, seqno 7
2023-11-08 13:02:36 10 [ERROR] WSREP: Inconsistency detected: Inconsistent by consensus on 4e9b52e6-7e26-11ee-9f16-ced5ef1e91ea:7
^ Found warnings in /test/GAL_MD280923-mariadb-11.3.0-linux-x86_64-dbg/mariadb-test/var/log/mysqld.2.err

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