Test rpl.rpl_stop_slave is unstable

Bug #1689988 reported by Laurynas Biveinis
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Status tracked in 5.7
5.5
New
Undecided
Unassigned
5.6
Triaged
Low
Unassigned
5.7
New
Undecided
Unassigned

Bug Description

On 5.6 trunk:

rpl.rpl_stop_slave 'stmt' w3 [ fail ]
        Test ended at 2017-05-03 11:42:32

CURRENT_TEST: rpl.rpl_stop_slave
mysqltest: In included file "./include/wait_for_slave_param.inc":
included from ./include/wait_for_slave_param.inc at line 120:
included from ./include/wait_for_slave_sql_to_start.inc at line 32:
included from ./extra/rpl_tests/rpl_stop_slave.test at line 64:
At line 120: Timeout in include/wait_for_slave_param.inc

The result from queries just before the failure was:
...
# CREATE TEMPORARY TABLE ... SELECT with InnoDB engine
# ----------------------------------------------------

[ On Master ]
BEGIN;
DELETE FROM t1;
CREATE TEMPORARY TABLE tt1(c1 INT) ENGINE = InnoDB
SELECT c1 FROM t2;
INSERT INTO t1 VALUES (1);
DROP TEMPORARY TABLE tt1;
COMMIT;

[ On Slave ]
STOP SLAVE SQL_THREAD;

[ On Slave1 ]
# To resume slave SQL thread
SET DEBUG_SYNC= 'now SIGNAL signal.continue';
SET DEBUG_SYNC= 'RESET';

[ On Slave ]
include/wait_for_slave_sql_to_stop.inc
# Slave should stop after the transaction has committed.
# So t1 on master is same to t1 on slave.
include/diff_tables.inc [master:t1, slave:t1]
START SLAVE SQL_THREAD;
include/wait_for_slave_sql_to_start.inc
**** ERROR: timeout after 300 (2017-05-03 18:42:29 - 2017-05-03 18:34:44) seconds while waiting for slave parameter Slave_SQL_Running = Yes ****
...
Last_Error Error 'Table 'tt1' already exists' on query. Default database: 'test'. Query: 'CREATE TEMPORARY TABLE tt1(c1 INT) ENGINE = InnoDB
...
2017-05-03 18:24:35 15921 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 889, relay log './slave-relay-bin.000003' position: 831
2017-05-03 18:34:39 15921 [ERROR] Slave SQL: Fatal error: ... Slave SQL Thread stopped with incomplete event group having non-transactional changes. If the group consists solely of row-based events, you can try to restart the slave with --slave-exec-mode=IDEMPOTENT, which ignores duplicate key, key not found, and similar errors (see documentation for details). Error_code: 1593
2017-05-03 18:34:39 15921 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 889
2017-05-03 18:34:44 15921 [Warning] Slave SQL: If a crash happens this configuration does not guarantee that the relay log info will be consistent, Error_code: 0
2017-05-03 18:34:44 15921 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 889, relay log './slave-relay-bin.000003' position: 831
2017-05-03 18:34:44 15921 [ERROR] Slave SQL: Error 'Table 'tt1' already exists' on query. Default database: 'test'. Query: 'CREATE TEMPORARY TABLE tt1(c1 INT) ENGINE = InnoDB
SELECT c1 FROM t2', Error_code: 1050
2017-05-03 18:34:44 15921 [Warning] Slave: Table 'tt1' already exists Error_code: 1050
2017-05-03 18:34:44 15921 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'master-bin.000001' position 889

Tags: ci
tags: added: ci
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Easy to make this testcase fail locally with large --repeat. Not sure if the failure cause is the same.

rpl.rpl_stop_slave 'stmt' [ fail ]
        Test ended at 2017-05-11 06:51:18

CURRENT_TEST: rpl.rpl_stop_slave
mysqltest: In included file "./include/diff_tables.inc":
included from ./include/diff_tables.inc at line 192:
included from ./extra/rpl_tests/rpl_stop_slave.test at line 61:
At line 192: command "diff_files" failed with error 2. my_errno=175
...
include/diff_tables.inc [master:t1, slave:t1]
--- /Users/laurynas/percona/obj-percona-5.6-debug/mysql-test/var/mysqld.1/data//diff_table-master-test-t1 2017-05-11 06:51:18.000000000 +0300
+++ /Users/laurynas/percona/obj-percona-5.6-debug/mysql-test/var/mysqld.2/data//diff_table-slave-test-t1 2017-05-11 06:51:18.000000000 +0300
@@ -1 +0,0 @@
-1
safe_process[46070]: Child process: 46071, exit: 1

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3698

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.