Test rpl.rpl_server_uuid is unstable

Bug #1684078 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
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

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

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
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :
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-2260

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.