[MDEV-28970] Some tests that show binlog events will fail if run after a test with binlogging on Created: 2022-06-28  Updated: 2022-11-09  Resolved: 2022-11-09

Status: Closed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 10.9, 10.10, 10.11
Fix Version/s: 10.11.2, 10.3.38, 10.4.28, 10.5.19, 10.6.12, 10.7.8, 10.8.7, 10.9.5, 10.10.3

Type: Bug Priority: Major
Reporter: Angelique Sklavounos (Inactive) Assignee: Angelique Sklavounos (Inactive)
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Duplicate
Relates
relates to MDEV-29866 binlog.binlog_table_map_optional_meta... Closed

 Description   

Some tests that call --source include/show_binlog_events.inc will fail if run after a test with binary logging. For example:

./mtr binlog.binlog_empty_xa_prepared --repeat 2


binlog.binlog_empty_xa_prepared 'innodb,mix' [ pass ]   1963
 
binlog.binlog_empty_xa_prepared 'innodb,mix' [ 2 fail ]
 
        Test ended at 2022-06-28 09:15:03
 
 
 
CURRENT_TEST: binlog.binlog_empty_xa_prepared
 
--- /home/parallels/dev/build-test/build1/mysql-test/suite/binlog/r/binlog_empty_xa_prepared.result	2022-06-13 09:20:12.000000000 +0100
 
+++ /home/parallels/dev/build-test/build1/mysql-test/suite/binlog/r/binlog_empty_xa_prepared.reject	2022-06-28 09:15:03.124868610 +0100
 
@@ -20,6 +20,31 @@
 
 include/show_binlog_events.inc
 
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
 
 master-bin.000001	#	Gtid	#	#	GTID #-#-#
 
+master-bin.000001	#	Query	#	#	use `test`; CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=InnoDB
 
+master-bin.000001	#	Gtid	#	#	BEGIN GTID #-#-#
 
+master-bin.000001	#	Annotate_rows	#	#	INSERT INTO t1 VALUES (1)
 
+master-bin.000001	#	Table_map	#	#	table_id: # (test.t1)
 
+master-bin.000001	#	Write_rows_v1	#	#	table_id: # flags: STMT_END_F
 
+master-bin.000001	#	Xid	#	#	COMMIT /* XID */
 
+master-bin.000001	#	Gtid	#	#	GTID #-#-#
 
+master-bin.000001	#	Query	#	#	use `test`; CREATE SEQUENCE s ENGINE=InnoDB
 
+master-bin.000001	#	Gtid	#	#	BEGIN GTID #-#-#
 
+master-bin.000001	#	Annotate_rows	#	#	SELECT NEXT VALUE FOR s
 
+master-bin.000001	#	Table_map	#	#	table_id: # (test.s)
 
+master-bin.000001	#	Write_rows_v1	#	#	table_id: # flags: STMT_END_F
 
+master-bin.000001	#	Query	#	#	COMMIT
 
+master-bin.000001	#	Gtid	#	#	XA START X'32',X'',1 GTID #-#-#
 
+master-bin.000001	#	Query	#	#	XA END X'32',X'',1
 
+master-bin.000001	#	XA_prepare	#	#	XA PREPARE X'32',X'',1
 
+master-bin.000001	#	Gtid	#	#	GTID #-#-#
 
+master-bin.000001	#	Query	#	#	XA ROLLBACK X'32',X'',1
 
+master-bin.000001	#	Gtid	#	#	GTID #-#-#
 
+master-bin.000001	#	Query	#	#	use `test`; DROP SEQUENCE `s` /* generated by server */
 
+master-bin.000001	#	Gtid	#	#	GTID #-#-#
 
+master-bin.000001	#	Query	#	#	use `test`; DROP TABLE `t1` /* generated by server */
 
+master-bin.000001	#	Gtid	#	#	GTID #-#-#
 
+master-bin.000001	#	Query	#	#	use `test`; DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `tmp_1`,`seq_1`
 
+master-bin.000001	#	Gtid	#	#	GTID #-#-#
 
 master-bin.000001	#	Query	#	#	use `test`; CREATE TEMPORARY SEQUENCE seq_1
 
 master-bin.000001	#	Gtid	#	#	BEGIN GTID #-#-#
 
 master-bin.000001	#	Query	#	#	use `test`; CREATE TEMPORARY TABLE tmp_1(c INT)
 
 
 
mysqltest: Result length mismatch

Tests with this problem include:
binlog.binlog_empty_xa_prepared
binlog.binlog_stm_binlog.test
binlog.binlog_stm_datetime_ranges_mdev15289.test
binlog.binlog_stm_do_db.test
binlog.innodb_autoinc_lock_mode_binlog.test
main.mysql_upgrade_view
main.stat_tables_rbr
maria.rollback.test
plugins.test_sql_service.test

 Comments   
Comment by Elena Stepanova [ 2022-07-26 ]

Note that there are likely to be many MTR test cases, specifically among those which enable binary log, which reliably fail upon the 2nd repeat after the first success. It happens because they rely on specific contents of binary logs, but don't ensure that the log is clean at the start of the test; and MTR itself, in turn, doesn't do it in its post-test check.

It would be very good to do a sweep to fix such tests, because the problem isn't as innocent as a failure on repeat. In reality it will happen whenever MTR sorts the test cases in such a way that the guilty test case is run after another one before the server restart. It's pure luck that it isn't happening with this one.

For example, if you do something like

cat << EOF > main/t.test
 
--source include/have_innodb.inc
 
--source include/have_binlog_format_mixed.inc
 
 
 
CREATE TABLE t (a INT);
 
DROP TABLE t;
 
EOF
 
 
 
perl ./mtr main.t binlog.binlog_empty_xa_prepared --noreorder

You will surely get the failure too.

In most cases it can be fixed by just adding RESET MASTER at the beginning of the test.

Comment by Angelique Sklavounos (Inactive) [ 2022-08-25 ]

Thanks for the tips, Elena!

It would be very good to do a sweep to fix such tests, because the problem isn't as innocent as a failure on repeat.

I will do this, so for now the Affects and Fix versions are for binlog.binlog_empty_xa_prepared only.

Comment by Angelique Sklavounos (Inactive) [ 2022-10-27 ]

Testing shows a RESET MASTER at the start of the culprit tests solves the issue, as suggested by Elena.

I considered a RESET MASTER at the end of the test (binlog.binlog_table_map_optional_metadata_binary has one), but for binlog.binlog_empty_xa_prepared, a RESET MASTER at the end of the test does not completely eliminate the Result mismatch:

CURRENT_TEST: binlog.binlog_empty_xa_prepared
 
--- /home/parallels/dev/build-25611/build1/mysql-test/suite/binlog/r/binlog_empty_xa_prepared.result	2022-10-27 18:09:18.691777525 +0100
 
+++ /home/parallels/dev/build-25611/build1/mysql-test/suite/binlog/r/binlog_empty_xa_prepared.reject	2022-10-27 18:10:59.924004150 +0100
 
@@ -20,6 +20,8 @@
 
 include/show_binlog_events.inc
 
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
 
 master-bin.000001	#	Gtid	#	#	GTID #-#-#
 
+master-bin.000001	#	Query	#	#	use `test`; DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `tmp_1`,`seq_1`
 
+master-bin.000001	#	Gtid	#	#	GTID #-#-#
 
 master-bin.000001	#	Query	#	#	use `test`; CREATE TEMPORARY SEQUENCE seq_1
 
 master-bin.000001	#	Gtid	#	#	BEGIN GTID #-#-#
 
 master-bin.000001	#	Query	#	#	use `test`; CREATE TEMPORARY TABLE tmp_1(c INT)

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