Intermittent rpl.percona_bug860910 failures

[Laurynas Biveinis]

http://jenkins.percona.com/view/Percona%20Server%205.5/job/percona-server-5.5-param/222/BUILD_TYPE=release,Host=centos5-32/consoleFull:

rpl.percona_bug860910 'stmt' w1 [ fail ]
        Test ended at 2011-12-14 13:24:10

CURRENT_TEST: rpl.percona_bug860910
mysqltest: In included file "./include/check_slave_param.inc":
included from ./include/check_slave_param.inc at line 32:
At line 31: Wrong value for slave parameter

The result from queries just before the failure was:
< snip >
slave-bin.000001 651 Query 1 725 COMMIT
slave-bin.000001 725 Query 1 834 use `test`; DROP TABLE `t1` /* generated by server */

**** SHOW RELAYLOG EVENTS on server_2 ****
relaylog_name = 'slave-relay-bin.000002'
SHOW RELAYLOG EVENTS IN 'slave-relay-bin.000002';
Log_name Pos Event_type Server_id End_log_pos Info
slave-relay-bin.000002 4 Format_desc 2 107 Server ver: 5.5.17-log, Binlog ver: 4
slave-relay-bin.000002 107 Rotate 1 0 master-bin.000001;pos=4
slave-relay-bin.000002 151 Format_desc 1 107 Server ver: 5.5.17-log, Binlog ver: 4
slave-relay-bin.000002 254 Query 1 197 use `test`; CREATE TABLE t1(a INT)
slave-relay-bin.000002 344 Query 1 270 BEGIN
slave-relay-bin.000002 417 User var 1 315 @`var`=0
slave-relay-bin.000002 462 Query 1 411 use `test`; INSERT INTO t1 VALUES (@var)
slave-relay-bin.000002 558 Query 1 485 COMMIT
slave-relay-bin.000002 632 Query 1 558 BEGIN
slave-relay-bin.000002 705 Query 1 651 use `test`; INSERT INTO t1 VALUES (1)
slave-relay-bin.000002 798 Query 1 725 COMMIT
slave-relay-bin.000002 872 Query 1 834 use `test`; DROP TABLE `t1` /* generated by server */
Wrong value for Exec_Master_Log_Pos. Expected '834', got '485'

More results from queries before failure can be found in /home/jenkins/workspace/percona-server-5.5-param/BUILD_TYPE/release/Host/centos5-32/Percona-Server-5.5.17-rel21.0/mysql-test/var/1/log/percona_bug860910.log

 - saving '/home/jenkins/workspace/percona-server-5.5-param/BUILD_TYPE/release/Host/centos5-32/Percona-Server-5.5.17-rel21.0/mysql-test/var/1/log/rpl.percona_bug860910-stmt/' to '/home/jenkins/workspace/percona-server-5.5-param/BUILD_TYPE/release/Host/centos5-32/Percona-Server-5.5.17-rel21.0/mysql-test/var/log/rpl.percona_bug860910-stmt/'

[Laurynas Biveinis (laurynas-biveinis)]

5.1:

http://jenkins.percona.com/job/percona-server-5.1-param/220/BUILD_TYPE=debug,Host=centos6-32/testReport/junit/%28root%29/rpl/percona_bug860910__mix_/

_StringException: Text attachment: traceback
------------
Comment:

Logfile:
CURRENT_TEST: rpl.percona_bug860910
mysqltest: In included file "./include/check_slave_param.inc":
included from ./include/check_slave_param.inc at line 32:
At line 31: Wrong value for slave parameter

The result from queries just before the failure was:
< snip >
4 system user NULL Connect 0 Waiting for master to send event NULL
5 system user NULL Connect 0 Has read all relay log; waiting for the slave I/O thread to update it NULL
6 root localhost:37707 NULL Binlog Dump 0 Has sent all binlog to slave; waiting for binlog to be updated NULL

**** SHOW BINARY LOGS on server_2 ****
SHOW BINARY LOGS;
Log_name File_size
slave-bin.000001 510

**** SHOW BINLOG EVENTS on server_2 ****
binlog_name = 'slave-bin.000001'
SHOW BINLOG EVENTS IN 'slave-bin.000001';
Log_name Pos Event_type Server_id End_log_pos Info
slave-bin.000001 4 Format_desc 2 106 Server ver: 5.1.60-debug-log, Binlog ver: 4
slave-bin.000001 106 Query 1 196 use `test`; CREATE TABLE t1(a INT)
slave-bin.000001 196 User var 1 240 @`var`=0
slave-bin.000001 240 Query 1 336 use `test`; INSERT INTO t1 VALUES (@var)
slave-bin.000001 336 Query 1 429 use `test`; INSERT INTO t1 VALUES (1)
slave-bin.000001 429 Query 1 510 use `test`; DROP TABLE t1
Wrong value for Exec_Master_Log_Pos. Expected '510', got '106'

More results from queries before failure can be found in /home/jenkins/workspace/percona-server-5.1-param/BUILD_TYPE/debug/Host/centos6-32/Percona-Server/mysql-test/var/3/log/percona_bug860910.log
------------

Help us localize this page

[Laurynas Biveinis (laurynas-biveinis)]

Assigning to Alexey as he originally fixed bug 860910.

[Laurynas Biveinis (laurynas-biveinis)]

New occurrences:
http://jenkins.percona.com/job/percona-server-5.5-param/358/BUILD_TYPE=release,Host=centos5-32/

[Laurynas Biveinis (laurynas-biveinis)]

Still seen somewhat recently (5.1 in August, 5.5 in October, 5.6 in December):

http://jenkins.percona.com/job/percona-server-5.1-trunk/714/BUILD_TYPE=debug,Host=centos5-64/testReport/junit/%28root%29/rpl/percona_bug860910__stmt_/

http://jenkins.percona.com/job/percona-server-5.5-trunk/361/BUILD_TYPE=debug,Host=centos5-64/testReport/junit/%28root%29/rpl/percona_bug860910__mix_/

http://jenkins.percona.com/job/percona-server-5.6-trunk/196/BUILD_TYPE=release,Host=centos5-64/testReport/junit/%28root%29/rpl/percona_bug860910__stmt_/

[Laurynas Biveinis (laurynas-biveinis)]

An instance of failure:

CURRENT_TEST: rpl.percona_bug860910
mysqltest: In included file "./include/check_slave_param.inc":
included from ./include/check_slave_param.inc at line 32:
At line 31: Wrong value for slave parameter

The result from queries just before the failure was:
*** Set up master (server_1) <-> master (server_2) replication ***
include/rpl_init.inc [topology=1->2->1]

SELECT @@global.log_slave_updates;
@@global.log_slave_updates
1
SELECT @@global.log_slave_updates;
@@global.log_slave_updates
1
CREATE TABLE t1(a INT);
SET @var:=0;
INSERT INTO t1 VALUES (@var);
INSERT INTO t1 VALUES (1);
DROP TABLE t1;
include/rpl_sync.inc
include/check_slave_param.inc [Exec_Master_Log_Pos]

############################## server_1 ##############################

**** SHOW WARNINGS on server_1 ****
SHOW WARNINGS;
Level Code Message

**** SELECT replication-related variables on server_1 ****
SELECT NOW(), @@SERVER_ID;
NOW() @@SERVER_ID
2016-08-30 19:44:31 1

**** SHOW SLAVE STATUS on server_1 ****
SHOW SLAVE STATUS;
Slave_IO_State Waiting for master to send event
Master_Host 127.0.0.1
Master_User root
Master_Port 13022
Connect_Retry 1
Master_Log_File slave-bin.000001
Read_Master_Log_Pos 107
Relay_Log_File mysqld-relay-bin.000002
Relay_Log_Pos 253
Relay_Master_Log_File slave-bin.000001
Slave_IO_Running Yes
Slave_SQL_Running Yes
Replicate_Do_DB
Replicate_Ignore_DB
Replicate_Do_Table
Replicate_Ignore_Table
Replicate_Wild_Do_Table
Replicate_Wild_Ignore_Table
Last_Errno 0
Last_Error
Skip_Counter 0
Exec_Master_Log_Pos 107
Relay_Log_Space 410
Until_Condition None
Until_Log_File
Until_Log_Pos 0
Master_SSL_Allowed No
Master_SSL_CA_File
Master_SSL_CA_Path
Master_SSL_Cert
Master_SSL_Cipher
Master_SSL_Key
Seconds_Behind_Master 0
Master_SSL_Verify_Server_Cert No
Last_IO_Errno 0
Last_IO_Error
Last_SQL_Errno 0
Last_SQL_Error
Replicate_Ignore_Server_Ids
Master_Server_Id 2

**** SHOW MASTER STATUS on server_1 ****
SHOW MASTER STATUS;
File master-bin.000001
Position 720
Binlog_Do_DB
Binlog_Ignore_DB

**** SHOW SLAVE HOSTS on server_1 ****
SHOW SLAVE HOSTS;
Server_id 2
Host 127.0.0.1
Port 13022
Master_id 1

**** SHOW PROCESSLIST on server_1 ****
SHOW PROCESSLIST;
Id User Host db Command Time State Info Rows_sent Rows_examined Rows_read
11 root localhost test Sleep 0 NULL 1 0 0
12 root localhost:40023 test Query 0 NULL SHOW PROCESSLIST 0 0 0
13 root localhost:40024 test Sleep 0 NULL 1 0 0
14 root localhost:40025 NULL Binlog Dump 0 Master has sent all binlog to slave; waiting for binlog to be updated NULL 0 0 0
15 system user NULL Connect 0 Waiting for master to send event NULL 0 0 0
16 system user NULL Connect 0 Slave has read all relay log; waiting for the slave I/O thread to update it NULL 0 0 0

**** SHOW BINARY LOGS on server_1 ****
SHOW BINARY LOGS;
Log_name File_size
master-bin.000001 720

**** SHOW BINLOG EVENTS on server_1 ****
binlog_name = 'master-bin.000001'
SHOW BINLOG EVENTS IN 'master-bin.000001';
Log_name Pos Event_type Server_id End_log_pos Info
master-bin.000001 4 Format_desc 1 107 Server ver: 5.5.51-38.1-log, Binlog ver: 4
master-bin.000001 107 Query 1 192 use `test`; CREATE TABLE t1(a INT)
master-bin.000001 192 Query 1 260 ...

[Laurynas Biveinis (laurynas-biveinis)]

     https://github.com/percona/percona-server/pull/958
     https://github.com/percona/percona-server/pull/959
     https://github.com/percona/percona-server/pull/960

[Shahriyar Rzayev (rzayev-sehriyar)]

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