[#MDEV-23770] s3.replication_stmt and s3.replication_mixed fail with SQL thread failure

Note: From the test logic, I assume these tests are meant to run with master and slave operating on the same S3 storage. If it's configured to use separate storages, the tests fail too, just differently.

10.5 2bac9782
s3.replication_mixed 'mix' [ fail ]
Test ended at 2020-09-20 17:00:15

CURRENT_TEST: s3.replication_mixed
analyze: sync_with_master
mysqltest: In included file "/data/bld/10.5-s3/mysql-test/suite/s3/replication.inc":
included from /data/bld/10.5-s3/mysql-test/suite/s3/replication_mixed.test at line 12:
At line 35: sync_slave_with_master failed: 'select master_pos_wait('master-bin.000001', 1365, 300, '')' returned NULL indicating slave SQL thread failure

The result from queries just before the failure was:
< snip >
#
# Test ALTER TABLE ENGINE S3
#
create table t1 (a int, b int) engine=aria;
insert into t1 select seq,seq+10 from seq_1_to_10;
alter table t1 engine=s3;
show create table t1;
Table Create Table
t1 CREATE TABLE `t1` (
`a` int(11) DEFAULT NULL,
`b` int(11) DEFAULT NULL
) ENGINE=S3 DEFAULT CHARSET=latin1 PAGE_CHECKSUM=1
connection slave;
use database;
select * from t1 limit 2;
a b
1 11
2 12
connection master;
alter table t1 add column c int;

More results from queries before failure can be found in /data/bld/10.5-s3/mysql-test/var/log/replication_mixed.log


== /data/bld/10.5-s3/mysql-test/var/tmp/analyze-sync_with_master-mysqld.1.err ==

############################## default ##############################

** SHOW WARNINGS on default **
SHOW WARNINGS;
Level Code Message

** SELECT replication-related variables on default **
SELECT NOW(), @@SERVER_ID;
NOW() @@SERVER_ID
2020-09-20 17:00:15 1

** SHOW SLAVE STATUS on default **
SHOW SLAVE STATUS;

** SHOW MASTER STATUS on default **
SHOW MASTER STATUS;
File master-bin.000001
Position 1365
Binlog_Do_DB
Binlog_Ignore_DB

** SHOW SLAVE HOSTS on default **
SHOW SLAVE HOSTS;
Server_id 2
Host 127.0.0.1
Port 16001
Master_id 1

** SHOW PROCESSLIST on default **
SHOW PROCESSLIST;
Id User Host db Command Time State Info Progress
11 root localhost:55844 NULL Binlog Dump 3 Master has sent all binlog to slave; waiting for more updates NULL 0.000
12 root localhost NULL Query 0 starting SHOW PROCESSLIST 0.000

** SHOW BINARY LOGS on default **
SHOW BINARY LOGS;
Log_name File_size
master-bin.000001 1365

** SHOW BINLOG EVENTS on default **
binlog_name = 'master-bin.000001'
SHOW BINLOG EVENTS IN 'master-bin.000001';
Log_name Pos Event_type Server_id End_log_pos Info
master-bin.000001 4 Format_desc 1 256 Server ver: 10.5.6-MariaDB-debug-log, Binlog ver: 4
master-bin.000001 256 Gtid_list 1 285 []
master-bin.000001 285 Binlog_checkpoint 1 329 master-bin.000001
master-bin.000001 329 Gtid 1 371 GTID 0-1-1
master-bin.000001 371 Query 1 530 create database s3_test_9996ac32fb4911eaaf608cc681cdd877
master-bin.000001 530 Gtid 1 572 GTID 0-1-2
master-bin.000001 572 Query 1 717 use `s3_test_9996ac32fb4911eaaf608cc681cdd877`; create table t1 (a int, b int) engine=aria
master-bin.000001 717 Gtid 1 759 BEGIN GTID 0-1-3
master-bin.000001 759 Query 1 911 use `s3_test_9996ac32fb4911eaaf608cc681cdd877`; insert into t1 select seq,seq+10 from seq_1_to_10
master-bin.000001 911 Query 1 1020 COMMIT
master-bin.000001 1020 Gtid 1 1062 GTID 0-1-4
master-bin.000001 1062 Query 1 1189 use `s3_test_9996ac32fb4911eaaf608cc681cdd877`; alter table t1 engine=s3
master-bin.000001 1189 Gtid 1 1231 GTID 0-1-5
master-bin.000001 1231 Query 1 1365 use `s3_test_9996ac32fb4911eaaf608cc681cdd877`; set @@sql_if_exists=1; alter table t1 add column c int

** SHOW RELAYLOG EVENTS on default **
relaylog_name = 'No such row'
SHOW RELAYLOG EVENTS IN 'No such row';
Log_name Pos Event_type Server_id End_log_pos Info
connection default;

== /data/bld/10.5-s3/mysql-test/var/tmp/analyze-sync_with_master-mysqld.2.err ==

############################## default ##############################

** SHOW WARNINGS on default **
SHOW WARNINGS;
Level Code Message

** SELECT replication-related variables on default **
SELECT NOW(), @@SERVER_ID;
NOW() @@SERVER_ID
2020-09-20 17:00:15 2

** SHOW SLAVE STATUS on default **
SHOW SLAVE STATUS;
Slave_IO_State Waiting for master to send event
Master_Host 127.0.0.1
Master_User root
Master_Port 16000
Connect_Retry 1
Master_Log_File master-bin.000001
Read_Master_Log_Pos 1365
Relay_Log_File slave-relay-bin.000003
Relay_Log_Pos 1416
Relay_Master_Log_File master-bin.000001
Slave_IO_Running Yes
Slave_SQL_Running No
Replicate_Do_DB
Replicate_Ignore_DB
Replicate_Do_Table
Replicate_Ignore_Table
Replicate_Wild_Do_Table
Replicate_Wild_Ignore_Table
Last_Errno 1060
Last_Error Error 'Duplicate column name 'c'' on query. Default database: 's3_test_9996ac32fb4911eaaf608cc681cdd877'. Query: 'alter table t1 add column c int'
Skip_Counter 0
Exec_Master_Log_Pos 1189
Relay_Log_Space 2274
Until_Condition None
Until_Log_File
Until_Log_Pos 0
Master_SSL_Allowed No
Master_SSL_CA_File
Master_SSL_CA_Path
Master_SSL_Cert
Master_SSL_Cipher
Master_SSL_Key
Seconds_Behind_Master NULL
Master_SSL_Verify_Server_Cert No
Last_IO_Errno 0
Last_IO_Error
Last_SQL_Errno 1060
Last_SQL_Error Error 'Duplicate column name 'c'' on query. Default database: 's3_test_9996ac32fb4911eaaf608cc681cdd877'. Query: 'alter table t1 add column c int'
Replicate_Ignore_Server_Ids
Master_Server_Id 1
Master_SSL_Crl
Master_SSL_Crlpath
Using_Gtid No
Gtid_IO_Pos
Replicate_Do_Domain_Ids
Replicate_Ignore_Domain_Ids
Parallel_Mode optimistic
SQL_Delay 0
SQL_Remaining_Delay NULL
Slave_SQL_Running_State
Slave_DDL_Groups 4
Slave_Non_Transactional_Groups 1
Slave_Transactional_Groups 0

** SHOW MASTER STATUS on default **
SHOW MASTER STATUS;
File slave-bin.000001
Position 1188
Binlog_Do_DB
Binlog_Ignore_DB

** SHOW SLAVE HOSTS on default **
SHOW SLAVE HOSTS;

** SHOW PROCESSLIST on default **
SHOW PROCESSLIST;
Id User Host db Command Time State Info Progress
7 system user NULL Slave_IO 3 Waiting for master to send event NULL 0.000
11 root localhost NULL Query 0 starting SHOW PROCESSLIST 0.000

** SHOW BINARY LOGS on default **
SHOW BINARY LOGS;
Log_name File_size
slave-bin.000001 1188

** SHOW BINLOG EVENTS on default **
binlog_name = 'slave-bin.000001'
SHOW BINLOG EVENTS IN 'slave-bin.000001';
Log_name Pos Event_type Server_id End_log_pos Info
slave-bin.000001 4 Format_desc 2 256 Server ver: 10.5.6-MariaDB-debug-log, Binlog ver: 4
slave-bin.000001 256 Gtid_list 2 285 []
slave-bin.000001 285 Binlog_checkpoint 2 328 slave-bin.000001
slave-bin.000001 328 Gtid 1 370 GTID 0-1-1
slave-bin.000001 370 Query 1 529 create database s3_test_9996ac32fb4911eaaf608cc681cdd877
slave-bin.000001 529 Gtid 1 571 GTID 0-1-2
slave-bin.000001 571 Query 1 716 use `s3_test_9996ac32fb4911eaaf608cc681cdd877`; create table t1 (a int, b int) engine=aria
slave-bin.000001 716 Gtid 1 758 BEGIN GTID 0-1-3
slave-bin.000001 758 Query 1 910 use `s3_test_9996ac32fb4911eaaf608cc681cdd877`; insert into t1 select seq,seq+10 from seq_1_to_10
slave-bin.000001 910 Query 1 1019 COMMIT
slave-bin.000001 1019 Gtid 1 1061 GTID 0-1-4
slave-bin.000001 1061 Query 1 1188 use `s3_test_9996ac32fb4911eaaf608cc681cdd877`; alter table t1 engine=s3

** SHOW RELAYLOG EVENTS on default **
relaylog_name = 'slave-relay-bin.000003'
SHOW RELAYLOG EVENTS IN 'slave-relay-bin.000003';
Log_name Pos Event_type Server_id End_log_pos Info
slave-relay-bin.000003 4 Format_desc 2 256 Server ver: 10.5.6-MariaDB-debug-log, Binlog ver: 4
slave-relay-bin.000003 256 Rotate 1 0 master-bin.000001;pos=329
slave-relay-bin.000003 304 Format_desc 1 0 Server ver: 10.5.6-MariaDB-debug-log, Binlog ver: 4
slave-relay-bin.000003 556 Gtid 1 371 GTID 0-1-1
slave-relay-bin.000003 598 Query 1 530 create database s3_test_9996ac32fb4911eaaf608cc681cdd877
slave-relay-bin.000003 757 Gtid 1 572 GTID 0-1-2
slave-relay-bin.000003 799 Query 1 717 use `s3_test_9996ac32fb4911eaaf608cc681cdd877`; create table t1 (a int, b int) engine=aria
slave-relay-bin.000003 944 Gtid 1 759 BEGIN GTID 0-1-3
slave-relay-bin.000003 986 Query 1 911 use `s3_test_9996ac32fb4911eaaf608cc681cdd877`; insert into t1 select seq,seq+10 from seq_1_to_10
slave-relay-bin.000003 1138 Query 1 1020 COMMIT
slave-relay-bin.000003 1247 Gtid 1 1062 GTID 0-1-4
slave-relay-bin.000003 1289 Query 1 1189 use `s3_test_9996ac32fb4911eaaf608cc681cdd877`; alter table t1 engine=s3
slave-relay-bin.000003 1416 Gtid 1 1231 GTID 0-1-5
slave-relay-bin.000003 1458 Query 1 1365 use `s3_test_9996ac32fb4911eaaf608cc681cdd877`; set @@sql_if_exists=1; alter table t1 add column c int
connection default;



- saving '/data/bld/10.5-s3/mysql-test/var/log/s3.replication_mixed-mix/' to '/data/bld/10.5-s3/mysql-test/var/log/s3.replication_mixed-mix/'

[MDEV-23770] s3.replication_stmt and s3.replication_mixed fail with SQL thread failure Created: 2020-09-20 Updated: 2020-10-30 Resolved: 2020-10-30
Status:	Closed
Project:	MariaDB Server
Component/s:	Replication, Storage Engine - S3, Tests
Affects Version/s:	10.5
Fix Version/s:	10.5.7

[MDEV-23770] s3.replication_stmt and s3.replication_mixed fail with SQL thread failure Created: 2020-09-20 Updated: 2020-10-30 Resolved: 2020-10-30