[MDEV-20412] binlog.binlog_stm_binlog fails sporadically in build bot Created: 2019-08-23  Updated: 2023-11-28

Status: Open
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10, 10.11
Fix Version/s: 10.4, 10.5, 10.6, 10.11

Type: Bug Priority: Minor
Reporter: Sujatha Sivakumar (Inactive) Assignee: Andrei Elkin
Resolution: Unresolved Votes: 0
Labels: None

Attachments: File var_20412.tar.gz    

 Description   

This test fails sporadically.

http://buildbot.askmonty.org/buildbot/reports/cross_reference#branch=10.4&revision=&platform=&dt=&bbnum=&typ=&info=&fail_name=^binlog.binlog_stm_binlog&fail_variant=&fail_info_short=&fail_info_full=&limit=100

binlog.binlog_stm_binlog 'innodb,mix'    w3 [ fail ]
 
        Test ended at 2019-08-22 18:07:56
 
 
 
CURRENT_TEST: binlog.binlog_stm_binlog
 
--- /mnt/buildbot/build/mariadb-10.4.8/mysql-test/suite/binlog/r/binlog_stm_binlog.result	2019-08-22 07:15:21.000000000 -0400
 
+++ /mnt/buildbot/build/mariadb-10.4.8/mysql-test/suite/binlog/r/binlog_stm_binlog.reject	2019-08-22 18:07:55.834894345 -0400
 
@@ -525,12 +525,12 @@
 
 master-bin.000001	#	Table_map	#	#	table_id: # (test.t1)
 
 master-bin.000001	#	Write_rows_v1	#	#	table_id: # flags: STMT_END_F
 
 master-bin.000001	#	Query	#	#	COMMIT
 
+master-bin.000001	#	Gtid	#	#	GTID #-#-#
 
+master-bin.000001	#	Query	#	#	use `test`; FLUSH TABLES
 
 master-bin.000001	#	Gtid	#	#	BEGIN GTID #-#-#
 
 master-bin.000001	#	Table_map	#	#	table_id: # (test.t1)
 
 master-bin.000001	#	Write_rows_v1	#	#	table_id: # flags: STMT_END_F
 
 master-bin.000001	#	Query	#	#	COMMIT
 
-master-bin.000001	#	Gtid	#	#	GTID #-#-#
 
-master-bin.000001	#	Query	#	#	use `test`; FLUSH TABLES
 
 RESET MASTER;
 
 insert /* before delayed */ delayed /* after delayed */ into t1 values (null),(null),(null),(null);
 
 insert  /*! delayed */ into t1 values (null),(null),(400),(null);
 
 
 
mysqltest: Result content mismatch
 
 
 
 - saving '/mnt/buildbot/build/mariadb-10.4.8/mysql-test/var/3/log/binlog.binlog_stm_binlog-innodb,mix/' to '/mnt/buildbot/build/mariadb-10.4.8/mysql-test/var/log/binlog.binlog_stm_binlog-innodb,mix/'
 
 
 
Retrying test binlog.binlog_stm_binlog, attempt(2/3)...
 
 
 
worker[3] > Restart  - not started

Error logs of more recent failures show this is known and suppressed in the test:

2022-11-03 12:37:23 18 [ERROR]  BINLOG_BASE64_EVENT: Could not execute Write_rows_v1 event on table test.t1; Duplicate entry '2' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 461, Internal MariaDB error code: 1062



 Comments   
Comment by Angelique Sklavounos (Inactive) [ 2022-11-04 ]
Recent fails

https://buildbot.askmonty.org/buildbot/builders/kvm-deb-buster-amd64/builds/8539
In this build, the failing test was preceded by innodb.innodb, and before that main.ipv6.

https://buildbot.mariadb.org/#/builders/534/builds/817
In this build, the failing test was preceded by sys_vars.host_cache_size_auto , and before that rpl.rpl_start_alter_7 'innodb'.

https://buildbot.mariadb.org/#/builders/328/builds/6216
In this build, the failing test was preceded by binlog.binlog_stm_do_db 'innodb,stmt', and before that sys_vars.autocommit_func4 'innodb'.

Comment by Angelique Sklavounos (Inactive) [ 2022-11-04 ]

I was able to recreate this failure with ./mtr binlog.binlog_stm_binlog --repeat 500 (2bd41fc5bf765b*) while the same machine was running ./mtr --repeat=100 --parallel=2 versioning.rpl_25611{,,,} (fdb873d89d3966). The var dir (var_20412.tar.gz) is attached.

* This has a modified version of binlog.binlog_stm_binlog (not pushed) that places a RESET MASTER at the beginning of the test to avoid MDEV-28970 (without the RESET MASTER, the test fails but has different output for the Result content mismatch).

Comment by Andrei Elkin [ 2023-10-25 ]

The mismatch of

binlog.binlog_stm_binlog 'innodb,mix'    w8 [ fail ]
 
        Test ended at 2023-10-25 15:23:45
 
 
 
CURRENT_TEST: binlog.binlog_stm_binlog
 
--- /home3/MDB/WTs/Review/D/mysql-test/suite/binlog/r/binlog_stm_binlog.result  2023-07-31 20:30:58.188846219 +0
 
300
 
+++ /home3/MDB/WTs/Review/D/mysql-test/suite/binlog/r/binlog_stm_binlog.reject  2023-10-25 15:23:42.821538208 +0
 
300
 
@@ -507,6 +507,7 @@
 
 master-bin.000001      #       Gtid    #       #       BEGIN GTID #-#-#
 
 master-bin.000001      #       Query   #       #       use `mysql`; DELETE FROM db WHERE host='localhost' AND u
 
ser='@#@'
 
 master-bin.000001      #       Query   #       #       COMMIT
 
+master-bin.000001      #       Rotate  #       #       master-bin.000002;pos=POS
 
 drop table t1,t2,t3,tt1;
 
 reset master;
 
 create table t1 (a int not null auto_increment, primary key (a)) engine=myisam;

is reproduced today to suggest the binlog rotation could be natural in this part of the test.
It just need to be ready for that, or makes sure max_binlog_size is high enough to prevent it.

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