Test rpl.rpl_server_uuid is unstable

Bug #1684078 reported by Laurynas Biveinis on 2017-04-19
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
Fix Released
Low
Laurynas Biveinis
5.7
Fix Released
Low
Laurynas Biveinis

Bug Description

On 5.6 trunk:

rpl.rpl_server_uuid 'mix' w3 [ fail ]
        Test ended at 2017-04-04 09:00:00

CURRENT_TEST: rpl.rpl_server_uuid
mysqltest: In included file "./include/assert_grep.inc":
included from ./include/assert_grep.inc at line 150:
At line 149: assert_grep.inc failed.
...
**** SHOW SLAVE STATUS on server_2 ****
...
Slave_IO_Running No
...
Last_IO_Errno 1236
Last_IO_Error Got fatal error 1236 from master when reading data from binary log: 'A slave with the same server_uuid/server_id as this slave has connected to the master; the first event 'master-bin.000004' at 120, the last event read from './master-bin.000004' at 120, the last byte read from './master-bin.000004' at 120.'
...
**** SHOW SLAVE STATUS on server_3 ****
SHOW SLAVE STATUS;
Slave_IO_State Waiting for master to send event
...
**** SHOW PROCESSLIST on server_1 ****
SHOW PROCESSLIST;
Id User Host db Command Time State Info Rows_sent Rows_examined
1 root localhost test Sleep 8 NULL 411 411
2 root localhost:36026 test Sleep 7 NULL 1 0
3 root localhost:36027 test Sleep 7 NULL 411 411
4 root localhost:36036 test Query 0 init SHOW PROCESSLIST 0 0
5 root localhost:36037 test Sleep 7 NULL 1 0
11 root localhost:36209 NULL Binlog Dump 0 Master has sent all binlog to slave; waiting for binlog to be updated NULL 0 0
...
include/assert_grep.inc failed!
assert_text: 'Found the expected line in master's error log for server 2 disconnection'
assert_file: '/mnt/workspace/percona-server-5.6-trunk/BUILD_TYPE/debug/Host/centos5-64/build/mysql-test/var/3/log/mysqld.1.err'
assert_select: 'found a zombie dump thread with the same UUID'
assert_match: ''
assert_count: '1'
assert_only_after: 'Start binlog_dump to master_thread_id\(9\)'
number of matching lines: 2
...
Server [mysqld.1 - pid: 18799, winpid: 18799] log:
Server log from this test:
----------SERVER LOG START-----------
...
2017-04-04 15:59:53 18800 [Note] Start binlog_dump to master_thread_id(9) slave_server(2), pos(master-bin.000004, 120)
2017-04-04 15:59:53 18800 [Note] While initializing dump thread for slave with UUID <80fa2b30-1936-11e7-bc99-525400e0d484>, found a zombie dump thread with the same UUID. Master is killing the zombie dump thread(9).
2017-04-04 15:59:53 18800 [Note] Start binlog_dump to master_thread_id(10) slave_server(2), pos(master-bin.000004, 120)
2017-04-04 16:00:00 18800 [Note] While initializing dump thread for slave with UUID <80fa2b30-1936-11e7-bc99-525400e0d484>, found a zombie dump thread with the same UUID. Master is killing the zombie dump thread(10).
2017-04-04 16:00:00 18800 [Note] Start binlog_dump to master_thread_id(11) slave_server(3), pos(master-bin.000003, 120)
----------SERVER LOG END-------------

Server [mysqld.2 - pid: 17691, winpid: 17691] log:
Server log from this test:
----------SERVER LOG START-----------
...
2017-04-04 15:59:53 17692 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:13021',replication started in log 'master-bin.000004' at position 120
2017-04-04 15:59:53 17692 [Warning] Slave SQL: If a crash happens this configuration does not guarantee that the relay log info will be consistent, Error_code: 0
2017-04-04 15:59:53 17692 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000004' at position 120, relay log './slave-relay-bin.000001' position: 4
2017-04-04 16:00:00 17692 [ERROR] Error reading packet from server: A slave with the same server_uuid/server_id as this slave has connected to the master; the first event 'master-bin.000004' at 120, the last event read from './master-bin.000004' at 120, the last byte read from './master-bin.000004' at 120. (server_errno=1236)
2017-04-04 16:00:00 17692 [ERROR] Slave I/O: Got fatal error 1236 from master when reading data from binary log: 'A slave with the same server_uuid/server_id as this slave has connected to the master; the first event 'master-bin.000004' at 120, the last event read from './master-bin.000004' at 120, the last byte read from './master-bin.000004' at 120.', Error_code: 1236
2017-04-04 16:00:00 17692 [Note] Slave I/O thread exiting, read up to log 'master-bin.000004', position 120
----------SERVER LOG END-------------

Server [mysqld.3 - pid: 19039, winpid: 19039] log:
Server log from this test:
----------SERVER LOG START-----------
...
2017-04-04 16:00:00 19040 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:13021',replication started in log 'master-bin.000003' at position 120

The testcase connects server 2 to server 1 as a slave and then server 3 with the same UUID connects, disconnecting server 2. The testcase greps that there is one binlog zombie dump thread kill, but finds two. This can happen if server 3 receives ER_NET_READ_INTERRUPTED soon after its connect and is forced to silently reconnect.

tags: added: ci upstream

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

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

Other bug subscribers