[MDEV-28971] Assertion `total_length + thd->wsrep_sr().log_position() == saved_pos' failed in int wsrep_write_cache_inc(THD*, IO_CACHE*, size_t*) Created: 2022-06-28  Updated: 2023-12-21  Resolved: 2023-12-12

Status: Closed
Project: MariaDB Server
Component/s: Galera
Affects Version/s: 10.4, 10.5, 10.6, 10.7, 10.8, 10.9
Fix Version/s: 10.4.33, 10.5.24, 10.6.17, 10.11.7, 11.0.5, 11.1.4, 11.2.3

Type: Bug Priority: Critical
Reporter: Ramesh Sivaraman Assignee: Julius Goryavsky
Resolution: Fixed Votes: 1
Labels: not-10.2, not-10.3


 Description   

CREATE SEQUENCE SEQ NOCACHE ENGINE=InnoDB;
SET SESSION wsrep_trx_fragment_size=1;
SET collation_connection=utf16_thai_520_w2;
SET autocommit=0;
CREATE TABLE t1 (a BLOB UNIQUE);
INSERT INTO t1 VALUES ('AAF');
SELECT SETVAL (SEQ, 100);
ALTER TABLE t1 ADD CONSTRAINT constraint_1 UNIQUE (a);
INSERT INTO t1 VALUES();
ALTER TABLE t1 ADD KEY(b (50));

Leads to:

10.4.26 96f4b4a55b449a29af7e4b70bebf0ff238ae7f80 (Optimized)

mysqld: /test/10.4_opt/sql/wsrep_binlog.cc:160: int wsrep_write_cache_inc(THD*, IO_CACHE*, size_t*): Assertion `total_length + thd->wsrep_sr().log_position() == saved_pos' failed.

10.4.26 96f4b4a55b449a29af7e4b70bebf0ff238ae7f80 (Optimized)

Core was generated by `/test/GAL_MD070622-mariadb-10.4.26-linux-x86_64-opt/bin/mysqld --defaults-file='.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
[Current thread is 1 (Thread 0x147f15af1700 (LWP 649112))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#1  0x000055deb176ae3f in my_write_core (sig=sig@entry=6) at /test/10.4_opt/mysys/stacktrace.c:386
#2  0x000055deb12679b8 in handle_fatal_signal (sig=6) at /test/10.4_opt/sql/signal_handler.cc:356
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#5  0x0000147f4db48859 in __GI_abort () at abort.c:79
#6  0x0000147f4db48729 in __assert_fail_base (fmt=0x147f4dcde588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x55deb1a50ba8 "total_length + thd->wsrep_sr().log_position() == saved_pos", file=0x55deb1a50b80 "/test/10.4_opt/sql/wsrep_binlog.cc", line=160, function=<optimized out>) at assert.c:92
#7  0x0000147f4db59f36 in __GI___assert_fail (assertion=assertion@entry=0x55deb1a50ba8 "total_length + thd->wsrep_sr().log_position() == saved_pos", file=file@entry=0x55deb1a50b80 "/test/10.4_opt/sql/wsrep_binlog.cc", line=line@entry=160, function=function@entry=0x55deb1a50b48 "int wsrep_write_cache_inc(THD*, IO_CACHE*, size_t*)") at assert.c:101
#8  0x000055deb14cc907 in wsrep_write_cache_inc (len=<optimized out>, cache=0x147ed006de38, thd=0x147ed0000c48) at /test/10.4_opt/sql/wsrep_binlog.cc:138
#9  wsrep_write_cache (thd=0x147ed0000c48, cache=cache@entry=0x147ed006de38, len=len@entry=0x147f15aedff8) at /test/10.4_opt/sql/wsrep_binlog.cc:183
#10 0x000055deb14b58fc in Wsrep_client_service::prepare_data_for_replication (this=0x147ed0006a38) at /test/10.4_opt/sql/sql_error.h:1046
#11 0x000055deb18cf604 in wsrep::transaction::certify_commit (this=0x147ed0006ab8, lock=@0x147f15aee270: {_M_device = 0x147ed0006a18, _M_owns = false}) at /test/10.4_opt/wsrep-lib/src/transaction.cpp:1755
#12 0x000055deb18d1a66 in wsrep::transaction::before_prepare (this=0x147ed0006ab8, lock=@0x147f15aee270: {_M_device = 0x147ed0006a18, _M_owns = false}) at /test/10.4_opt/wsrep-lib/src/transaction.cpp:342
#13 0x000055deb18d1def in wsrep::transaction::before_commit (this=this@entry=0x147ed0006ab8) at /test/10.4_opt/wsrep-lib/src/transaction.cpp:458
#14 0x000055deb126bd16 in wsrep::client_state::before_commit (this=0x147ed0006a50) at /test/10.4_opt/wsrep-lib/include/wsrep/client_state.hpp:503
#15 wsrep_before_commit (all=true, thd=0x147ed0000c48) at /test/10.4_opt/sql/wsrep_trans_observer.h:277
#16 ha_commit_trans (thd=thd@entry=0x147ed0000c48, all=all@entry=true) at /test/10.4_opt/sql/handler.cc:1609
#17 0x000055deb11790cd in trans_commit_implicit (thd=thd@entry=0x147ed0000c48) at /test/10.4_opt/sql/transaction.cc:302
#18 0x000055deb1074718 in mysql_execute_command (thd=0x147ed0000c48) at /test/10.4_opt/sql/sql_parse.cc:3771
#19 0x000055deb107ba92 in mysql_parse (thd=thd@entry=0x147ed0000c48, rawbuf=rawbuf@entry=0x147ed000fe60 "ALTER TABLE t1 ADD KEY(b(50))", length=length@entry=29, parser_state=parser_state@entry=0x147f15af0530, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.4_opt/sql/sql_parse.cc:7995
#20 0x000055deb107c299 in wsrep_mysql_parse (thd=0x147ed0000c48, rawbuf=0x147ed000fe60 "ALTER TABLE t1 ADD KEY(b(50))", length=29, parser_state=0x147f15af0530, is_com_multi=false, is_next_command=false) at /test/10.4_opt/sql/sql_parse.cc:7799
#21 0x000055deb107eee5 in dispatch_command (command=COM_QUERY, thd=0x147ed0000c48, packet=<optimized out>, packet_length=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /test/10.4_opt/sql/sql_parse.cc:1943
#22 0x000055deb108002f in do_command (thd=0x147ed0000c48) at /test/10.4_opt/sql/sql_parse.cc:1378
#23 0x000055deb116b9de in do_handle_one_connection (connect=0x55deb474bf88) at /test/10.4_opt/sql/sql_connect.cc:1420
#24 0x000055deb116ba6d in handle_one_connection (arg=<optimized out>) at /test/10.4_opt/sql/sql_connect.cc:1316
#25 0x0000147f4e057609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#26 0x0000147f4dc45293 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95



 Comments   
Comment by Jan Lindström (Inactive) [ 2022-08-05 ]

I see different assertion using Debug builds:

jan@jan-HP-ZBook-15u-G5:~/mysql/10.4/mysql-test$ ./mtr galera.jan --mysqld=--wsrep-debug=1
Logging: ./mtr  galera.jan --mysqld=--wsrep-debug=1
VS config: 
vardir: /home/jan/mysql/10.4/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/jan/mysql/10.4/mysql-test/var'...
Checking supported features...
MariaDB Version 10.4.26-MariaDB-debug
 - SSL connections supported
 - binaries are debug compiled
 - binaries built with wsrep patch
Collecting tests...
Installing system database...
 
==============================================================================
 
TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------
 
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
connection node_2;
connection node_1;
CREATE SEQUENCE SEQ NOCACHE ENGINE=InnoDB;
SET SESSION wsrep_trx_fragment_size=1;
SET collation_connection=utf16_thai_520_w2;
SET autocommit=0;
CREATE TABLE t1 (a BLOB UNIQUE);
INSERT INTO t1 VALUES ('AAF');
SELECT SETVAL (SEQ, 100);
SETVAL (SEQ, 100)
100
ALTER TABLE t1 ADD CONSTRAINT constraint_1 UNIQUE (a);
Warnings:
Note	1831	Duplicate index `constraint_1`. This is deprecated and will be disallowed in a future release
INSERT INTO t1 VALUES();
ALTER TABLE t1 ADD KEY(b (50));
ERROR 42000: Key column 'b' doesn't exist in table
galera.jan 'innodb'                      [ fail ]  Found warnings/errors in server log file!
        Test ended at 2022-08-05 14:08:41
line
2022-08-05 14:08:39 17 [ERROR] Error in Log_event::read_log_event(): 'Sanity check failed', data_len: 1, event_type: -1
2022-08-05 14:08:39 17 [ERROR] WSREP: applier could not read binlog event, seqno: 6, len: 41
2022-08-05 14:08:39 2 [ERROR] WSREP: Failed to apply write set: gtid: f1d53a46-14ae-11ed-b74f-93fe6583ab39:6 server_id: f1d46cb6-14ae-11ed-82fe-b2bd1b74d82d client_id: 17 trx_id: 51 flags: 18 (commit | pa_unsafe)
mysqld: /home/jan/mysql/10.4/wsrep-lib/src/transaction.cpp:212: int wsrep::transaction::prepare_for_ordering(const wsrep::ws_handle&, const wsrep::ws_meta&, bool): Assertion `active()' failed.
Attempting backtrace. You can use the following information to find out
^ Found warnings in /home/jan/mysql/10.4/mysql-test/var/log/mysqld.2.err
ok

Comment by Ramesh Sivaraman [ 2022-11-21 ]

Found another reduced test case.

CREATE TABLE t (b BINARY (1)) ENGINE=InnoDB;
SET SESSION wsrep_trx_fragment_size=1;
CREATE SEQUENCE s_t START WITH 1 MINVALUE 1 MAXVALUE 20 INCREMENT BY 1  ENGINE=InnoDB;
INSERT INTO t SELECT NEXT VALUE FOR s_t;
INSERT INTO t (b) VALUES ('');

10.5.19 fe330b63fe4ee51a26ac6e222d8eb4ee44a73d50 (Optimized)

mysqld: /test/10.5_opt/sql/wsrep_binlog.cc:160: int wsrep_write_cache_inc(THD*, IO_CACHE*, size_t*): Assertion `total_length + thd->wsrep_sr().log_position() == saved_pos' failed.

10.5.19 fe330b63fe4ee51a26ac6e222d8eb4ee44a73d50 (Optimized)

Core was generated by `/test/GAL_MD081122-mariadb-10.5.19-linux-x86_64-opt/bin/mysqld --defaults-file='.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6)
    at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
[Current thread is 1 (Thread 0x14e9a80bf700 (LWP 1990440))]
(gdb) bt
#0  __pthread_kill (threadid=<optimized out>, signo=signo@entry=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:56
#1  0x0000561edb0c6b4f in my_write_core (sig=sig@entry=6) at /test/10.5_opt/mysys/stacktrace.c:424
#2  0x0000561edab9c0e0 in handle_fatal_signal (sig=6) at /test/10.5_opt/sql/signal_handler.cc:354
#3  <signal handler called>
#4  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#5  0x000014e9dd4f2859 in __GI_abort () at abort.c:79
#6  0x000014e9dd4f2729 in __assert_fail_base (fmt=0x14e9dd688588 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=0x561edb3e5af8 "total_length + thd->wsrep_sr().log_position() == saved_pos", file=0x561edb3e5ad0 "/test/10.5_opt/sql/wsrep_binlog.cc", line=160, function=<optimized out>) at assert.c:92
#7  0x000014e9dd503fd6 in __GI___assert_fail (assertion=assertion@entry=0x561edb3e5af8 "total_length + thd->wsrep_sr().log_position() == saved_pos", file=file@entry=0x561edb3e5ad0 "/test/10.5_opt/sql/wsrep_binlog.cc", line=line@entry=160, function=function@entry=0x561edb3e5a98 "int wsrep_write_cache_inc(THD*, IO_CACHE*, size_t*)") at assert.c:101
#8  0x0000561edae20787 in wsrep_write_cache_inc (len=<optimized out>, cache=0x14e954056018, thd=0x14e954000c58) at /test/10.5_opt/sql/wsrep_binlog.cc:138
#9  wsrep_write_cache (thd=0x14e954000c58, cache=cache@entry=0x14e954056018, len=len@entry=0x14e9a80bd278) at /test/10.5_opt/sql/wsrep_binlog.cc:183
#10 0x0000561edae0794c in Wsrep_client_service::prepare_data_for_replication (this=0x14e954006cc0) at /test/10.5_opt/sql/sql_error.h:1058
#11 0x0000561edb2405c4 in wsrep::transaction::certify_commit (this=0x14e954006d40, lock=@0x14e9a80bd4f0: {_M_device = 0x14e954006ca0, _M_owns = false}) at /test/10.5_opt/wsrep-lib/src/transaction.cpp:1755
#12 0x0000561edb242a26 in wsrep::transaction::before_prepare (this=0x14e954006d40, lock=@0x14e9a80bd4f0: {_M_device = 0x14e954006ca0, _M_owns = false}) at /test/10.5_opt/wsrep-lib/src/transaction.cpp:342
#13 0x0000561edb242daf in wsrep::transaction::before_commit (this=this@entry=0x14e954006d40) at /test/10.5_opt/wsrep-lib/src/transaction.cpp:458
#14 0x0000561edaba02f1 in wsrep::client_state::before_commit (this=0x14e954006cd8) at /test/10.5_opt/wsrep-lib/include/wsrep/client_state.hpp:503
#15 wsrep_before_commit (all=false, thd=0x14e954000c58) at /test/10.5_opt/sql/wsrep_trans_observer.h:281
#16 ha_commit_trans (thd=thd@entry=0x14e954000c58, all=all@entry=false) at /test/10.5_opt/sql/handler.cc:1736
#17 0x0000561edaaa8e57 in trans_commit_stmt (thd=thd@entry=0x14e954000c58) at /test/10.5_opt/sql/transaction.cc:472
#18 0x0000561eda99e2de in mysql_execute_command (thd=0x14e954000c58) at /test/10.5_opt/sql/sql_parse.cc:6117
#19 0x0000561eda98e8a4 in mysql_parse (thd=thd@entry=0x14e954000c58, rawbuf=rawbuf@entry=0x14e954010440 "INSERT INTO t (b) VALUES ('')", length=length@entry=29, parser_state=parser_state@entry=0x14e9a80be460, is_com_multi=is_com_multi@entry=false, is_next_command=is_next_command@entry=false) at /test/10.5_opt/sql/sql_parse.cc:8087
#20 0x0000561eda98e111 in wsrep_mysql_parse (thd=0x14e954000c58, rawbuf=0x14e954010440 "INSERT INTO t (b) VALUES ('')", length=29, parser_state=0x14e9a80be460, is_com_multi=false, is_next_command=false) at /test/10.5_opt/sql/sql_parse.cc:7888
#21 0x0000561eda99be55 in dispatch_command (command=COM_QUERY, thd=0x14e954000c58, packet=<optimized out>, packet_length=<optimized out>, is_com_multi=<optimized out>, is_next_command=<optimized out>) at /test/10.5_opt/sql/sql_parse.cc:1975
#22 0x0000561eda99d023 in do_command (thd=0x14e954000c58) at /test/10.5_opt/sql/sql_parse.cc:1375
#23 0x0000561edaa9a17e in do_handle_one_connection (connect=<optimized out>, connect@entry=0x561edd5f73b8, put_in_cache=put_in_cache@entry=true) at /test/10.5_opt/sql/sql_connect.cc:1416
#24 0x0000561edaa9a43d in handle_one_connection (arg=0x561edd5f73b8) at /test/10.5_opt/sql/sql_connect.cc:1318
#25 0x000014e9dda03609 in start_thread (arg=<optimized out>) at pthread_create.c:477
#26 0x000014e9dd5ef133 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Comment by Daniele Sciascia [ 2023-11-29 ]

A pull request has been submitted, and is ready for review.

Comment by Julius Goryavsky [ 2023-12-12 ]

Fix merged with head revision: https://github.com/MariaDB/server/commit/9ab7dbc3bec4e7d6083c03aa7cbabbd1d695a131

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