Not the answer you need?
Register and ask your own question!

is this a bug?

zhaogongpozhaogongpo ContributorInactive User Role Beginner
i have met a replication error:

the slave server crashed
when it started again,
I execute the command: "show slave status"

*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: xx.xx.xx.xx
Master_User: repl
Master_Port: xxxx
Connect_Retry: 60
Master_Log_File: mysql-bin.000858
Read_Master_Log_Pos: 379908871
Relay_Log_File: relay-bin.000620
Relay_Log_Pos: 724847546
Relay_Master_Log_File: mysql-bin.000806
Slave_IO_Running: Yes
Slave_SQL_Running: No
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 1062
Last_Error: Error 'Duplicate entry '1544846670' for key 'PRIMARY'' on query. Default database: 'xxxxxx_databasename'. Query: 'INSERT INTO xxx_tabname (......) VALUES ( 1165305, 17120165, 10, 100301, 81003010003, 2005, 1005, 50, 0, NULL, '2013-04-28 18:24:48', '2013-07-28 23:59:59', 1000, 1000, NULL, 1000, NULL, NULL, 0, NULL,
Skip_Counter: 0
Exec_Master_Log_Pos: 724847400
Relay_Log_Space: 56238889769
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: NULL
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 1062
Last_SQL_Error: Error 'Duplicate entry '1544846670' for key 'PRIMARY'' on query. Default database: 'xxxxxx_databasename'. Query: 'INSERT INTO xxx_tabname (......) VALUES ( 1165305, 17120165, 10, 100301, 81003010003, 2005, 1005, 50, 0, NULL, '2013-04-28 18:24:48', '2013-07-28 23:59:59', 1000, 1000, NULL, 1000, NULL, NULL, 0, NULL,
Replicate_Ignore_Server_Ids:
Master_Server_Id: 4
1 row in set (0.00 sec)

but i found that the slave did not contain a row that the id = 1544846670;

then I executed 'start slave'
and show slave status again:
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: xx.xx.xx.xx
Master_User: repl
Master_Port: xxxx
Connect_Retry: 60
Master_Log_File: mysql-bin.000858
Read_Master_Log_Pos: 379935147
Relay_Log_File: relay-bin.000620
Relay_Log_Pos: 724847546
Relay_Master_Log_File: mysql-bin.000806
Slave_IO_Running: Yes
Slave_SQL_Running: No
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 1062
Last_Error: Error 'Duplicate entry '1544846671' for key 'PRIMARY'' on query. Default database: 'xxxxxx_databasename'. Query: 'INSERT INTO xxx_tabname (......) VALUES ( 1165306, 14765802804742, 10, 100301, 81003010003, 2005, 1000, 50, 0, NULL, '2013-04-28 17:45:12', '2014-04-27 23:59:59', 6000, 5000, NULL, 5000, NULL, NULL, 0, N
Skip_Counter: 0
Exec_Master_Log_Pos: 724847400
Relay_Log_Space: 56238916045
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: NULL
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 1062
Last_SQL_Error: Error 'Duplicate entry '1544846671' for key 'PRIMARY'' on query. Default database: 'dxxxxxx_databasename'. Query: 'INSERT INTO xxx_tabname (......) VALUES ( 1165306, 14765802804742, 10, 100301, 81003010003, 2005, 1000, 50, 0, NULL, '2013-04-28 17:45:12', '2014-04-27 23:59:59', 6000, 5000, NULL, 5000, NULL, NULL, 0, N
Replicate_Ignore_Server_Ids:
Master_Server_Id: 4
1 row in set (0.00 sec)


the error record became the next one;
but I did nothing else! except the "start slave" command
then I found that the record(id='1544846671') didnot exist too.


Now the slave had been recreated.




mysql-error.log:

141211 18:56:11 [ERROR] Slave SQL: Error 'Duplicate entry '1544846670' for key 'PRIMARY'' on query. Default database: 'xxxx_databasename'. Query: 'INSERT INTO tabname (......) VALUES ( 1165305, 17120165, 10, 100301, 81003010003, 2005, 1005, 50, 0, NULL, '2013-04-28 18:24:48', '2013-07-28 23:59:59', 1000, 1000, NULL, 1000, NULL, NULL,
141211 18:56:11 [Warning] Slave: Duplicate entry '1544846670' for key 'PRIMARY' Error_code: 1062
141211 18:56:11 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.000806' position 724847400
141212 9:35:01 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000806' at position 724847400, relay log '/var/lib/mysql/relay-bin.000620' position: 724847546
141212 9:35:01 [ERROR] Slave SQL: Error 'Duplicate entry '1544846671' for key 'PRIMARY'' on query. Default database: 'xxxx_databasename'. Query: 'INSERT INTO tabname (......) VALUES ( 1165306, 14765802804742, 10, 100301, 81003010003, 2005, 1000, 50, 0, NULL, '2013-04-28 17:45:12', '2014-04-27 23:59:59', 6000, 5000, NULL, 5000, NULL, N
141212 9:35:01 [Warning] Slave: Duplicate entry '1544846671' for key 'PRIMARY' Error_code: 1062
141212 9:35:01 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.000806' position 724847400
141212 9:35:56 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000806' at position 724847400, relay log '/var/lib/mysql/relay-bin.000620' position: 724847546
141212 9:35:56 [ERROR] Slave SQL: Error 'Duplicate entry '1544846672' for key 'PRIMARY'' on query. Default database: 'xxxx_databasename'. Query: 'INSERT INTO tabname (......) VALUES ( 1165306, 36659631, 10, 100301, 81003010003, 2005, 1000, 50, 0, NULL, '2013-04-28 17:45:15', '2014-04-27 23:59:59', 6000, 5000, NULL, 5000, NULL, NULL,
141212 9:35:56 [Warning] Slave: Duplicate entry '1544846672' for key 'PRIMARY' Error_code: 1062
141212 9:35:56 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.000806' position 724847400

Comments

  • zhaogongpozhaogongpo Contributor Inactive User Role Beginner
    Server version: 5.5.35-rel33.0-log Percona Server with XtraDB (GPL), Release rel33.0, Revision 611
  • psongpsong Contributor Inactive User Role Beginner
    This is surprising. The INSERT statement is truncated, does it include the PK value or is the PK an auto_increment column? If you check the rows in the slave for PK 1544846670, 1544846671, are those the rows inserted by the statements that once failed? Can you run SHOW CREATE TABLE on both master and slave? Also SELECT <pk column> FROM <table> WHERE pk_column > 1544846672;
  • zhaogongpozhaogongpo Contributor Inactive User Role Beginner
    psong wrote: »
    This is surprising. The INSERT statement is truncated, does it include the PK value or is the PK an auto_increment column? If you check the rows in the slave for PK 1544846670, 1544846671, are those the rows inserted by the statements that once failed? Can you run SHOW CREATE TABLE on both master and slave? Also SELECT <pk column> FROM <table> WHERE pk_column > 1544846672;

    The primary key is auto_increment , and PK 1544846670, 1544846671 did not exists in the slave.
    but I found that the table's auto_increment changed:

    when PK 1544846670 faild , the table's auto_increment number of the slave was 1544846671;
    but after I executed "start slave",
    the auto_increment number changed to 1544846672;

    but the PK 1544846670 or PK 1544846671 did not insert into the slave.

    I tried change the auto_increment number to the corrent filed PK,
    but it maked no sense.
  • psongpsong Contributor Inactive User Role Beginner
    The fact that auto_increment number increased and a different row showed in the SHOW SLAVE STATUS suggested that the previous row was inserted, but you didn't see the row in the table. Is there any trigger defined or other jobs that might interfere? I'd suggest to track queries:

    > show slave status\G
    > select * from <tbl> where pk_col > 1544846671;
    > set global general_log = 1;
    > stop slave;
    > start slave;
    > show slave status\G
    > select * from <tbl> where pk_col > 1544846671;
    $ cat /path/to/datadir/hostname.log

    To stop capturing general queries:
    > set global general_log = 0;
    > stop slave;
    > start slave;
  • zhaogongpozhaogongpo Contributor Inactive User Role Beginner
    psong wrote: »
    The fact that auto_increment number increased and a different row showed in the SHOW SLAVE STATUS suggested that the previous row was inserted, but you didn't see the row in the table. Is there any trigger defined or other jobs that might interfere? I'd suggest to track queries:

    > show slave status\G
    > select * from <tbl> where pk_col > 1544846671;
    > set global general_log = 1;
    > stop slave;
    > start slave;
    > show slave status\G
    > select * from <tbl> where pk_col > 1544846671;
    $ cat /path/to/datadir/hostname.log

    To stop capturing general queries:
    > set global general_log = 0;
    > stop slave;
    > start slave;


    Thank you for reply, but I am sure there is no trigger or other jobs ,
    the database had been recreated with xtrabackup., and the slave returns to normal. I think it maybe a bug.
Sign In or Register to comment.

MySQL, InnoDB, MariaDB and MongoDB are trademarks of their respective owners.
Copyright ©2005 - 2020 Percona LLC. All rights reserved.