MySQL Bugs: #91634: rpl_gtid.rpl_wait_for_executed_gtid

Bug #91634	rpl_gtid.rpl_wait_for_executed_gtid_set is flakey
Submitted:	13 Jul 2018 22:42	Modified:	13 Jul 2018 23:01
Reporter:	Manuel Ung	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Tests	Severity:	S3 (Non-critical)
Version:	8.0.11	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
rpl_gtid.rpl_wait_for_executed_gtid_set fails sporadically as described below.

How to repeat:

./mtr --parallel=32 --repeat=32 rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set
Logging: /data/users/mung/mysql-server/mysql-test/mysql-test-run.pl  --parallel=32 --repeat=32 rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set

Result:
rpl_gtid.rpl_wait_for_executed_gtid_set 'stmt' w5 [ fail ]
        Test ended at 2018-07-13 15:41:05

CURRENT_TEST: rpl_gtid.rpl_wait_for_executed_gtid_set
mysqltest: In included file ./include/rpl_set_gtid_mode.inc at line 160:
included from /.../mysql-test/suite/rpl_gtid/t/rpl_wait_for_executed_gtid_set.test at line 220:
At line 156: query 'SET @@GLOBAL.GTID_MODE= $_rsgm_current_mode' failed: 3111: SET @@GLOBAL.GTID_MODE = OFF is not allowed because there are ongoing transactions that have a GTID. Before you set @@GLOBAL.GTID_MODE = OFF, wait until SELECT @@GLOBAL.GTID_OWNED is empty on all servers. Then wait for all GTID-transactions to replicate to all servers, and then execute SET @@GLOBAL.GTID_MODE = OFF on all servers. See the Manual for details.

The result from queries just before the failure was:
< snip >
SELECT WAIT_FOR_EXECUTED_GTID_SET('bbbbbbbb-bbbb-bbbb-bbbb-bbbbbbbbbbbb:1');
WAIT_FOR_EXECUTED_GTID_SET('bbbbbbbb-bbbb-bbbb-bbbb-bbbbbbbbbbbb:1')
0
SELECT WAIT_FOR_EXECUTED_GTID_SET('cccccccc-cccc-cccc-cccc-cccccccccccc:1');
ERROR HY000: The client holds ownership of the GTID cccccccc-cccc-cccc-cccc-cccccccccccc:1. Therefore, WAIT_FOR_EXECUTED_GTID_SET cannot wait for this GTID.
ROLLBACK;
SELECT WAIT_FOR_EXECUTED_GTID_SET('cccccccc-cccc-cccc-cccc-cccccccccccc:1', 1);
WAIT_FOR_EXECUTED_GTID_SET('cccccccc-cccc-cccc-cccc-cccccccccccc:1', 1)
1
SET @@SESSION.GTID_NEXT = 'AUTOMATIC';
---- 1.3. Function should return NULL in a replication thread ----
INSERT INTO t1 VALUES (WAIT_FOR_EXECUTED_GTID_SET('aaaaaaaa-aaaa-aaaa-aaaa-aaaaaaaaaaaa:1'));
Warnings:
Note    1592    Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave.
include/assert.inc [t1 should contain 0]
include/sync_slave_sql_with_master.inc
include/assert.inc [t1 should contain NULL]
[connection master]
---- 1.4. Function should generate error if GTID_MODE = OFF ----
include/rpl_set_gtid_mode.inc [off on servers 1,2,3]
safe_process[1688931]: Child process: 1688935, exit: 1

 - the logfile can be found in '/.../mysql-test/var/log/rpl_gtid.rpl_wait_for_executed_gtid_set-stmt/rpl_wait_for_executed_gtid_set.log'

Suggested fix:
Fix the test.

Thank you for the bug report.

xecuted_gtid_set rpl_gtid.rpl_wait_for_executed_gtid_set
MySQL Version 8.0.13
Checking supported features...
 - SSL connections supported
Collecting tests...
 - adding combinations for rpl_gtid
Removing old var directory...
Creating var directory '/home/miguel/dbs/8.0/mysql-test/var'...
Installing system database...
Using parallel: 32
<CUT>

worker[5] mysql-test-run: WARNING: Timeout after mysql-test-run waited 180 seconds for the process [mysqld.3 - pid 5053, winpid: 5053] to create a pid file.
rpl_gtid.rpl_wait_for_executed_gtid_set 'stmt' w5 [ fail ]
        Test ended at 2018-07-13 19:58:43