MySQL Bugs: #97844: MTR rpl_gtid.rpl_multi_source_mtr

Bug #97844	MTR rpl_gtid.rpl_multi_source_mtr_includes unstable
Submitted:	2 Dec 2019 8:31	Modified:	1 Jul 2020 2:46
Reporter:	ting du	Email Updates:
Status:	Verified	Impact on me:	None
Category:	Tests: Replication	Severity:	S7 (Test Cases)
Version:	8.0.17, 8.0.20	OS:	CentOS
Assigned to:		CPU Architecture:	x86

Description:
The test case rpl_gtid.rpl_multi_source_mtr_includes is unstatle. There are two results which is different from the result file.
-------------------------------------------------------
One of result:
CURRENT_TEST: rpl_gtid.rpl_multi_source_mtr_includes
--- /root/mysql/mysql-test/suite/rpl_gtid/r/rpl_multi_source_mtr_includes.result
+++ /root/mysql/bld/mysql-test/var/log/rpl_multi_source_mtr_includes.reject
@@ -56,14 +56,10 @@
 include/show_relaylog_events.inc [FOR CHANNEL '']
 Log_name	Pos	Event_type	Server_id	End_log_pos	Info
-slave-relay-bin.000004	#	Rotate	#	#	master-bin.000001;pos=POS
-slave-relay-bin.000004	#	Format_desc	#	#	SERVER_VERSION, BINLOG_VERSION
-slave-relay-bin.000004	#	Rotate	#	#	master-bin.000001;pos=POS
-slave-relay-bin.000004	#	Query	#	#	use `test`; CREATE TABLE t1 (c1 INT PRIMARY KEY) ENGINE=InnoDB
-slave-relay-bin.000004	#	Query	#	#	BEGIN
-slave-relay-bin.000004	#	Query	#	#	use `test`; INSERT INTO t1 VALUES (1)
-slave-relay-bin.000004	#	Xid	#	#	COMMIT /* XID */
-slave-relay-bin.000004	#	Rotate	#	#	slave-relay-bin.000005;pos=POS
+slave-relay-bin.000003	#	Rotate	#	#	master-bin.000001;pos=POS
+slave-relay-bin.000003	#	Format_desc	#	#	SERVER_VERSION, BINLOG_VERSION
+slave-relay-bin.000003	#	Rotate	#	#	master-bin.000001;pos=POS
+slave-relay-bin.000003	#	Rotate	#	#	slave-relay-bin.000004;pos=POS
 include/show_relaylog_events.inc [FOR CHANNEL 'ch1']
Log_name	Pos	Event_type	Server_id	End_log_pos	Info
 slave-relay-bin-ch1.000003	#	Rotate	#	#	master-bin.000001;pos=POS

I think the reason for this result is because the previous relay log(slave-relay-bin.000003) is not deleted when excute SHOW RELAYLOG EVENTS in show_relaylog_events.inc. So it display the first relay log(slave-relay-bin.000003) instead of slave-relay-bin.000004.
-------------------------------------------------------
-------------------------------------------------------
The other result:
CURRENT_TEST: rpl_gtid.rpl_multi_source_mtr_includes
--- /root/mysql/mysql-test/suite/rpl_gtid/r/rpl_multi_source_mtr_includes.result
+++ /root/mysql/bld/mysql-test/var/log/rpl_multi_source_mtr_includes.reject
@@ -67,7 +67,7 @@
 include/show_relaylog_events.inc [FOR CHANNEL 'ch1']
 Log_name   Pos Event_type  Server_id   End_log_pos Info
 slave-relay-bin-ch1.000003 #   Rotate  #   #   master-bin.000001;pos=POS
-slave-relay-bin-ch1.000003 #   Format_desc #   #   SERVER_VERSION, BINLOG_VERSION
+slave-relay-bin-ch1.000003 #   Rotate  #   #   slave-relay-bin-ch1.000004;pos=4
 #
 # Wait for error and skip
 #

I'm not sure if the relay log is in a fixed format like this:
Format_description_event : relay log's Format_description_event
Previous_gtid_event
[Rotate_event]           : In the case rotating relaylog, no Rotate here
Format_description_event : master's Format_description_event
From the result, the master's Format_description_event may not exist in relay log. Or something else result in this result.
-------------------------------------------------------

How to repeat:
run test case rpl_gtid.rpl_multi_source_mtr_includes repeatly:
./mtr rpl_gtid.rpl_multi_source_mtr_includes --repeat=100

Suggested fix:
For the first result, it can set binlog_file=slave-relay-bin.000004 to display slave-relay-bin.000004 which matchs result file.

Hello ting du,

Thank you for the report.
I'm not seeing this issue at my end on 8.0.18 and even with 8.0.17 build.
Could you please share exact cmake options used for the build if you are building from source to reproduce this issue at our end? Thank you.

- Release/Debug - not seen any failures
 ./mtr rpl_gtid.rpl_multi_source_mtr_includes --repeat=100
Logging: ./mtr  rpl_gtid.rpl_multi_source_mtr_includes --repeat=100
MySQL Version 8.0.17
Checking supported features
Using 'all' suites
Collecting tests
 - Adding combinations for rpl_gtid
Checking leftover processes
Removing old var directory
 - WARNING: Using the 'mysql-test/var' symlink
Creating var directory '/export/umesh/server/binaries/GABuilds/mysql-8.0.17/mysql-test/var'
Installing system database
Using parallel: 1

==============================================================================
                  TEST NAME                       RESULT  TIME (ms) COMMENT
------------------------------------------------------------------------------
[  0%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]    889
.
.
[ 34%] rpl_gtid.rpl_multi_source_mtr_includes 'stmt'  [ skipped ]  Doesn't support --binlog-format = 'statement'
------------------------------------------------------------------------------
The servers were restarted 0 times
The servers were reinitialized 0 times
Spent 87.782 of 153 seconds executing testcases

Completed: All 100 tests were successful.

2 tests were skipped, 0 by the test itself.

./mtr --debug-server rpl_gtid.rpl_multi_source_mtr_includes --repeat=100
Logging: ./mtr  --debug-server rpl_gtid.rpl_multi_source_mtr_includes --repeat=100
MySQL Version 8.0.17
Checking supported features
 - Binaries are debug compiled
Using 'all' suites
Collecting tests
 - Adding combinations for rpl_gtid
Checking leftover processes
Removing old var directory
 - WARNING: Using the 'mysql-test/var' symlink
Creating var directory '/export/umesh/server/binaries/GABuilds/mysql-8.0.17/mysql-test/var'
Installing system database
Using parallel: 1

==============================================================================
                  TEST NAME                       RESULT  TIME (ms) COMMENT
------------------------------------------------------------------------------
[  0%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2011
[  0%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   1961
.
.
[ 34%] rpl_gtid.rpl_multi_source_mtr_includes 'stmt'  [ skipped ]  Doesn't support --binlog-format = 'statement'
------------------------------------------------------------------------------
The servers were restarted 0 times
The servers were reinitialized 0 times
Spent 190.575 of 344 seconds executing testcases

Completed: All 100 tests were successful.

2 tests were skipped, 0 by the test itself.

regards,
Umesh

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Hello, Umesh Shastry
I test 8.0.17 with cmake like this:
cmake .. -DCMAKE_INSTALL_PREFIX=xxx -DMYSQL_DATADIR=xxx -DWITH_DEBUG=1 -DWITH_BOOST=xxx
and run in build directory:
./mtr rpl_gtid.rpl_multi_source_mtr_includes --repeat=100
The same problem occurs:
Logging: /home/duting/mysql/mysql-test/mysql-test-run.pl  rpl_gtid.rpl_multi_source_mtr_includes --repeat=100
MySQL Version 8.0.17
Checking supported features
 - Binaries are debug compiled
Using 'all' suites
Collecting tests
 - Adding combinations for rpl_gtid
Removing old var directory
Creating var directory '/home/duting/mysql/bld/mysql-test/var'
Installing system database
Using parallel: 1

==============================================================================
                  TEST NAME                       RESULT  TIME (ms) COMMENT
------------------------------------------------------------------------------
[  0%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5051
[  0%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5200
[  1%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   4975
[  1%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   4683
[  1%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   3900
[  2%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   4010
[  2%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5041
[  2%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5470
[  3%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5192
[  3%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   4992
[  3%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5115
[  4%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5082
[  4%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   4981
[  4%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5054
[  5%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   4877
[  5%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5366
[  5%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5118
[  6%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5036
[  6%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5483
[  6%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   4954
[  7%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5005
[  7%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5142
[  7%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5142
[  8%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5319
[  8%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5141
[  8%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   4946
[  9%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5044
[  9%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5265
[  9%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5107
[ 10%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5449
[ 10%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5397
[ 10%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5029
[ 11%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5078
[ 11%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   4932
[ 11%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5424
[ 12%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   5086
[ 12%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   4808
[ 12%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   6146
[ 13%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   7096
[ 13%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ fail ]
        Test ended at 2020-05-22 23:43:20

CURRENT_TEST: rpl_gtid.rpl_multi_source_mtr_includes
--- /home/duting/mysql/mysql-test/suite/rpl_gtid/r/rpl_multi_source_mtr_includes.result   2020-05-18 22:21:13.682669056 +0300
+++ /home/duting/mysql/bld/mysql-test/var/log/rpl_multi_source_mtr_includes.reject        2020-05-22 18:43:19.864503489 +0300
@@ -56,14 +56,10 @@
 #
 include/show_relaylog_events.inc [FOR CHANNEL '']
 Log_name       Pos     Event_type      Server_id       End_log_pos     Info
-slave-relay-bin.000004 #       Rotate  #       #       master-bin.000001;pos=POS
-slave-relay-bin.000004 #       Format_desc     #       #       SERVER_VERSION, BINLOG_VERSION
-slave-relay-bin.000004 #       Rotate  #       #       master-bin.000001;pos=POS
-slave-relay-bin.000004 #       Query   #       #       use `test`; CREATE TABLE t1 (c1 INT PRIMARY KEY) ENGINE=InnoDB
-slave-relay-bin.000004 #       Query   #       #       BEGIN
-slave-relay-bin.000004 #       Query   #       #       use `test`; INSERT INTO t1 VALUES (1)
-slave-relay-bin.000004 #       Xid     #       #       COMMIT /* XID */
-slave-relay-bin.000004 #       Rotate  #       #       slave-relay-bin.000005;pos=POS
+slave-relay-bin.000003 #       Rotate  #       #       master-bin.000001;pos=POS
+slave-relay-bin.000003 #       Format_desc     #       #       SERVER_VERSION, BINLOG_VERSION
+slave-relay-bin.000003 #       Rotate  #       #       master-bin.000001;pos=POS
+slave-relay-bin.000003 #       Rotate  #       #       slave-relay-bin.000004;pos=POS
 include/show_relaylog_events.inc [FOR CHANNEL 'ch1']
 Log_name       Pos     Event_type      Server_id       End_log_pos     Info
 slave-relay-bin-ch1.000003     #       Rotate  #       #       master-bin.000001;pos=POS

mysqltest: Result content mismatch

safe_process[7860]: Child process: 7861, exit: 1

 - the logfile can be found in '/home/duting/mysql/bld/mysql-test/var/log/rpl_gtid.rpl_multi_source_mtr_includes-mix/rpl_multi_source_mtr_includes.log'

Only  1  of 3 completed.
mysql-test-run: *** ERROR: Not all tests completed

Thank you for the feedback.
I'm able to reproduce using 8.0.20 source build:

rm -rf bld/
mkdir bld && cd bld
rm -rf CMakeCache.txt
/export/umesh/utils/cmake-3.14.4/bin/cmake .. -DWITH_DEBUG=1 \
-DCMAKE_INSTALL_PREFIX=$PWD                   \
-DWITH_BOOST=../boost
make -j32
make install
cd mysql-test
./mtr rpl_gtid.rpl_multi_source_mtr_includes --repeat=100
Logging: /export/umesh/server/source/bugs/src_build/fb_builds/97844/mysql-8.0.20/mysql-test/mysql-test-run.pl  rpl_gtid.rpl_multi_source_mtr_includes --repeat=100
MySQL Version 8.0.20
Too long tmpdir path '/export/umesh/server/source/bugs/src_build/fb_builds/97844/mysql-8.0.20/bld/mysql-test/var/tmp'  creating a shorter one
 - Using tmpdir: '/tmp/P8pUeVIGS7'

Checking supported features
 - Binaries are debug compiled
Using 'all' suites
Collecting tests
 - Adding combinations for rpl_gtid
Removing old var directory
Creating var directory '/export/umesh/server/source/bugs/src_build/fb_builds/97844/mysql-8.0.20/bld/mysql-test/var'
Installing system database
Using parallel: 1

==============================================================================
                  TEST NAME                       RESULT  TIME (ms) COMMENT
------------------------------------------------------------------------------
[  0%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2978
[  0%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2868
[  1%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2819
[  1%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2865
[  1%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2877
[  2%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2922
[  2%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2945
[  2%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2842
[  3%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2751
[  3%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2935
[  3%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2886
[  4%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2858
[  4%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2879
[  4%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   3007
[  5%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2833
[  5%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2871
[  5%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2870
[  6%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2916
[  6%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2892
[  6%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2868
[  7%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2766
[  7%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2879
[  7%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2874
[  8%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2869
[  8%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2932
[  8%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2904
[  9%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2949
[  9%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2868
[  9%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2879
[ 10%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2955
[ 10%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ pass ]   2890
[ 10%] rpl_gtid.rpl_multi_source_mtr_includes 'mix'  [ fail ]
        Test ended at 2020-06-30 14:26:14

CURRENT_TEST: rpl_gtid.rpl_multi_source_mtr_includes
--- /export/umesh/server/source/bugs/src_build/fb_builds/97844/mysql-8.0.20/mysql-test/suite/rpl_gtid/r/rpl_multi_source_mtr_includes.result    2020-03-26 16:31:45.000000000 +0300
+++ /export/umesh/server/source/bugs/src_build/fb_builds/97844/mysql-8.0.20/bld/mysql-test/var/log/rpl_multi_source_mtr_includes.reject 2020-06-30 15:26:14.078343513 +0300
@@ -67,7 +67,7 @@
 include/show_relaylog_events.inc [FOR CHANNEL 'ch1']
 Log_name       Pos     Event_type      Server_id       End_log_pos     Info
 slave-relay-bin-ch1.000003     #       Rotate  #       #       master-bin.000001;pos=POS
-slave-relay-bin-ch1.000003     #       Format_desc     #       #       SERVER_VERSION, BINLOG_VERSION
+slave-relay-bin-ch1.000003     #       Rotate  #       #       slave-relay-bin-ch1.000004;pos=4
 #
 # Wait for error and skip
 #

mysqltest: Result content mismatch

safe_process[10482]: Child process: 10483, exit: 1

 - the logfile can be found in '/export/umesh/server/source/bugs/src_build/fb_builds/97844/mysql-8.0.20/bld/mysql-test/var/log/rpl_gtid.rpl_multi_source_mtr_includes-mix/rpl_multi_source_mtr_includes.log'

Only  1  of 3 completed.
mysql-test-run: *** ERROR: Not all tests completed

Oh, thank you.  
If so, Is there any repair suggestions?