MySQL Bugs: #109078: Unstable test's results for rpl_gtid.rpl_mixed_temp_table_stored

Bug #109078	Unstable test's results for rpl_gtid.rpl_mixed_temp_table_stored_function
Submitted:	14 Nov 2022 13:59	Modified:	24 Nov 2022 10:52
Reporter:	Pavel Kopylov	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Tests	Severity:	S7 (Test Cases)
Version:	8.0.30	OS:	CentOS (CentOS Linux release 8.5.2111)
Assigned to:	MySQL Verification Team	CPU Architecture:	x86

Description:
I faced unstable test results for a test "rpl_gtid.rpl_mixed_temp_table_stored_function". Sometimes test passed well, sometimes test didn't pass. 

Please notice that the test is not contained by the main test suite. 

After the test had passed successfully I saw this line in logfiles var/log/mysqld.1.err and var/log/mysqld.2.err: "[SERVER] Received SHUTDOWN from user root". Moreover, there are a lot of messages at the end of the log about termination parts of the mysqld. The time spent on the test was about 20 sec.  

After the test had failed I saw this line in logfiles var/log/mysqld.1.err and var/log/mysqld.2.err: "safe_process[xxxxx]: Child process: yyyyy, killed by signal 9". There aren't any messages about correct mysqld termination. The time spent on the test was about 36 sec.

How to repeat:
./mysql-test-run.pl  --mysqld=--binlog-format=mixed --max-test-fail=5 --report-unstable-tests  --mysqld=--skip-innodb-use-native-aio rpl_gtid.rpl_mixed_temp_table_stored_function

The logs from test that was passed successfully.

Attachment: good-log.tar.gz (application/gzip, text), 6.60 KiB.

The logs from test that was failed.

Attachment: fail1.tar.gz (application/gzip, text), 6.03 KiB.

The logs from test that was failed.

Attachment: fail3.tar.gz (application/gzip, text), 6.02 KiB.

Here is a failed test's output:

==============================================================================
                  TEST NAME                       RESULT  TIME (ms) COMMENT
------------------------------------------------------------------------------
[  9%] rpl_gtid.rpl_mixed_temp_table_stored_function  [ fail ]
        Test ended at 2022-11-14 19:58:53

CURRENT_TEST: rpl_gtid.rpl_mixed_temp_table_stored_function
--- /home/user/rpmbuild/BUILD/mysql-8.0.30/mysql-test/suite/rpl_gtid/r/rpl_mixed_temp_table_stored_function.result	2022-07-07 00:36:34.000000000 +0300
+++ /home/user/rpmbuild/BUILD/mysql-8.0.30/build/mysql-test/var/log/rpl_mixed_temp_table_stored_function.reject	2022-11-14 22:58:53.428493589 +0300
@@ -369,7 +369,6 @@
 master-bin.000001	#	Table_map	#	#	table_id: # (test.t4)
 master-bin.000001	#	Write_rows	#	#	table_id: # flags: STMT_END_F
 master-bin.000001	#	Xid	#	#	COMMIT /* XID */
-master-bin.000001	#	Query	#	#	use `test`; DROP EVENT IF EXISTS`test`.`call_routine_with_temp_table_ddl`
 [connection master]
 DROP TABLE t1, t2, t3, t4;
 DROP TEMPORARY TABLE temp3, temp4, temp5;

mysqltest: Result content mismatch

The result from queries just before the failure was:
master-bin.000001	#	Query	#	#	BEGIN
master-bin.000001	#	Table_map	#	#	table_id: # (test.t4)
master-bin.000001	#	Write_rows	#	#	table_id: # flags: STMT_END_F
master-bin.000001	#	Xid	#	#	COMMIT /* XID */
[connection master]
DROP TABLE t1, t2, t3, t4;
DROP TEMPORARY TABLE temp3, temp4, temp5;
DROP FUNCTION create_temp_table;
DROP FUNCTION create_temp_table_with_dmls;
DROP FUNCTION dmls_on_temp_tables;
DROP FUNCTION dmls_on_temp_and_regular_tables;
DROP FUNCTION drop_temp_table;
DROP FUNCTION drop_temp_table_with_dmls;
DROP FUNCTION dummy_function;
DROP FUNCTION call_drop_temp_table_if_exists;
DROP FUNCTION drop_temp_table_if_exists;
DROP PROCEDURE proc_with_temp_table_ddl;
DROP FUNCTION call_proc_with_temp_table_ddl;
include/sync_slave_sql_with_master.inc
include/rpl_end.inc
safe_process[186445]: Child process: 186446, exit: 1

 - the logfile can be found in '/home/user/rpmbuild/BUILD/mysql-8.0.30/build/mysql-test/var/log/rpl_gtid.rpl_mixed_temp_table_stored_function/rpl_mixed_temp_table_stored_function.log'

Hi Pavel,

Can you retest with 8.0.31 as I cannot reproduce this with 8.0.31

[arhimed@localdev mysql-test]$ ./mysql-test-run.pl --mysqld=--binlog-format=mixed --max-test-fail=5 --report-unstable-tests  --mysqld=--skip-innodb-use-native-aio rpl_gtid.rpl_mixed_temp_table_stored_function
Logging: ./mysql-test-run.pl  --mysqld=--binlog-format=mixed --max-test-fail=5 --report-unstable-tests --mysqld=--skip-innodb-use-native-aio rpl_gtid.rpl_mixed_temp_table_stored_function
MySQL Version 8.0.31
Using binlog format 'mixed'
Path length (115) is longer than maximum supported length (108) and will be truncated at /usr/lib64/perl5/vendor_perl/Socket.pm line 880.
Too long tmpdir path '/home/arhimed/sandboxes/usrlocalmysql/mysql-8.0.31-linux-glibc2.17-x86_64-minimal/mysql-test/var/tmp'  creating a shorter one
 - Using tmpdir: '/tmp/Tmz4p5ICCj'

Checking supported features
Using 'all' suites
Collecting tests
 - Adding combinations for rpl_gtid
Checking leftover processes
 - found old pid 144860 in 'mysqld.1.pid', killing it...
   process did not exist!
Removing old var directory
Creating var directory '/home/arhimed/sandboxes/usrlocalmysql/mysql-8.0.31-linux-glibc2.17-x86_64-minimal/mysql-test/var'
Installing system database
Using parallel: 1

==============================================================================
                  TEST NAME                       RESULT  TIME (ms) COMMENT
------------------------------------------------------------------------------
[ 50%] rpl_gtid.rpl_mixed_temp_table_stored_function  [ pass ]   6660
[100%] shutdown_report                           [ pass ]
------------------------------------------------------------------------------
The servers were restarted 0 times
The servers were reinitialized 0 times
Spent 6.660 of 16 seconds executing testcases

Completed: All 2 tests were successful.

[arhimed@localdev mysql-test]$

I've tried the discussed test on mysql-8.0.31.

I started it with this command line:  ./mysql-test-run.pl --repeat=20  --mysqld=--binlog-format=mixed --max-test-fail=5 --report-unstable-tests  --mysqld=--skip-innodb-use-native-aio rpl_gtid.rpl_mixed_temp_table_stored_function

And I got this results: 

[user@localhost mysql-test]$ ./mysql-test-run.pl --repeat=20  --mysqld=--binlog-format=mixed --max-test-fail=5 --report-unstable-tests  --mysqld=--skip-innodb-use-native-aio rpl_gtid.rpl_mixed_temp_table_stored_function
Logging: /home/user/rpmbuild/BUILD/mysql-8.0.31/mysql-test/mysql-test-run.pl  --repeat=20 --mysqld=--binlog-format=mixed --max-test-fail=5 --report-unstable-tests --mysqld=--skip-innodb-use-native-aio rpl_gtid.rpl_mixed_temp_table_stored_function
MySQL Version 8.0.31
Using binlog format 'mixed'
Checking supported features
Using 'all' suites
Collecting tests
 - Adding combinations for rpl_gtid
Checking leftover processes
Removing old var directory
Creating var directory '/home/user/rpmbuild/BUILD/mysql-8.0.31/build/mysql-test/var'
Installing system database
Using parallel: 1

==============================================================================
                  TEST NAME                       RESULT  TIME (ms) COMMENT
------------------------------------------------------------------------------
[  4%] rpl_gtid.rpl_mixed_temp_table_stored_function  [ pass ]  54996
[  9%] rpl_gtid.rpl_mixed_temp_table_stored_function  [ pass ]  11353
[ 14%] rpl_gtid.rpl_mixed_temp_table_stored_function  [ pass ]  11384
[ 19%] rpl_gtid.rpl_mixed_temp_table_stored_function  [ fail ]
        Test ended at 2022-11-24 10:49:24

CURRENT_TEST: rpl_gtid.rpl_mixed_temp_table_stored_function
--- /home/user/rpmbuild/BUILD/mysql-8.0.31/mysql-test/suite/rpl_gtid/r/rpl_mixed_temp_table_stored_function.result	2022-09-13 19:15:16.000000000 +0300
+++ /home/user/rpmbuild/BUILD/mysql-8.0.31/build/mysql-test/var/log/rpl_mixed_temp_table_stored_function.reject	2022-11-24 13:49:24.290543431 +0300
@@ -369,7 +369,6 @@
 master-bin.000001	#	Table_map	#	#	table_id: # (test.t4)
 master-bin.000001	#	Write_rows	#	#	table_id: # flags: STMT_END_F
 master-bin.000001	#	Xid	#	#	COMMIT /* XID */
-master-bin.000001	#	Query	#	#	use `test`; DROP EVENT IF EXISTS`test`.`call_routine_with_temp_table_ddl`
 [connection master]
 DROP TABLE t1, t2, t3, t4;
 DROP TEMPORARY TABLE temp3, temp4, temp5;

mysqltest: Result content mismatch

The result from queries just before the failure was:
master-bin.000001	#	Query	#	#	BEGIN
master-bin.000001	#	Table_map	#	#	table_id: # (test.t4)
master-bin.000001	#	Write_rows	#	#	table_id: # flags: STMT_END_F
master-bin.000001	#	Xid	#	#	COMMIT /* XID */
[connection master]
DROP TABLE t1, t2, t3, t4;
DROP TEMPORARY TABLE temp3, temp4, temp5;
DROP FUNCTION create_temp_table;
DROP FUNCTION create_temp_table_with_dmls;
DROP FUNCTION dmls_on_temp_tables;
DROP FUNCTION dmls_on_temp_and_regular_tables;
DROP FUNCTION drop_temp_table;
DROP FUNCTION drop_temp_table_with_dmls;
DROP FUNCTION dummy_function;
DROP FUNCTION call_drop_temp_table_if_exists;
DROP FUNCTION drop_temp_table_if_exists;
DROP PROCEDURE proc_with_temp_table_ddl;
DROP FUNCTION call_proc_with_temp_table_ddl;
include/sync_slave_sql_with_master.inc
include/rpl_end.inc
safe_process[341808]: Child process: 341809, exit: 1

 - the logfile can be found in '/home/user/rpmbuild/BUILD/mysql-8.0.31/build/mysql-test/var/log/rpl_gtid.rpl_mixed_temp_table_stored_function/rpl_mixed_temp_table_stored_function.log'

Only  4  of 20 completed.
mysql-test-run: *** ERROR: Not all tests completed: rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function rpl_gtid.rpl_mixed_temp_table_stored_function