percona-discussion team mailing list archive
-
percona-discussion team
-
Mailing list archive
-
Message #00338
[Bug 335122] [NEW] overwrite_relay_log_info: Replication relay-info isn't overwritten
Public bug reported:
I am trying to check how overwrite relay-info works, and there is
problem.
I use NFS server to store mysql and replication files, and I do break
NFS connection to emulate failure.
Here relay-log.info after crash:
./w3-relay-bin.000011
85062120
fdb3-bin.000004
362364030
Now I start mysqld and error.log is:
InnoDB: Warning: innodb_overwrite_relay_log_info is enabled. Updates of other storage engines may have problem of consistency.
InnoDB: relay-log.info is detected.
InnoDB: relay log: position 85062120, file name ./w3-relay-bin.000011
InnoDB: master log: position 362364030, file name fdb3-bin.000004
090226 13:40:09 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 428690885
090226 13:40:09 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
090226 13:40:10 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 429928722
090226 13:40:11 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: In a MySQL replication slave the last master binlog file
InnoDB: position 0 362812282, file name fdb3-bin.000004
InnoDB: and relay log file
InnoDB: position 0 85510372, file name ./w3-relay-bin.000011
090226 13:40:11 InnoDB Plugin 1.0.2-3 started; log sequence number 429928722
InnoDB: relay-log.info have been overwritten.
090226 13:40:11 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=w3-relay-bin' to avoid this problem.
090226 13:40:11 [Note] Event Scheduler: Loaded 0 events
090226 13:40:11 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.1.31' socket: '/tmp/mysql.sock' port: 3306 Source distribution
090226 13:41:54 [Note] Slave I/O thread: connected to master 'root@10.11.12.58:3306',replication started in log 'fdb3-bin.000004' at position 362364030
090226 13:41:54 [Note] Slave SQL thread initialized, starting replication in log 'fdb3-bin.000004' at position 362812282, relay log './w3-relay-bin.000011' position: 85510372
090226 13:41:55 [ERROR] Slave SQL: Error 'Duplicate entry '40846' for key 'PRIMARY'' on query. Default database: 'test'. Query: 'insert into t1(name) values('6691')', Error_code: 1062
090226 13:41:55 [Warning] Slave: Duplicate entry '40846' for key 'PRIMARY' Error_code: 1062
090226 13:41:55 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'fdb3-bin.000004' position 362364030
Note:
nnoDB: In a MySQL replication slave the last master binlog file
InnoDB: position 0 362812282, file name fdb3-bin.000004
InnoDB: and relay log file
InnoDB: position 0 85510372, file name ./w3-relay-bin.000011
090226 13:40:11 InnoDB Plugin 1.0.2-3 started; log sequence number 429928722
InnoDB: relay-log.info have been overwritten.
...
090226 13:41:54 [Note] Slave SQL thread initialized, starting replication in log 'fdb3-bin.000004' at position 362812282, relay log './w3-relay-bin.000011' position: 85510372
but later I see error
090226 13:41:55 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'fdb3-bin.000004' position 362364030
and position 362364030 is earlier than 362812282 !!
and relay-log.info is still
./w3-relay-bin.000013
250
fdb3-bin.000004
362364030
2282
SHOW SLAVE STATUS is
Slave_IO_State: Waiting for master to send event
Master_Host: 10.11.12.58
Master_User: root
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: fdb3-bin.000004
Read_Master_Log_Pos: 460743877
Relay_Log_File: w3-relay-bin.000013
Relay_Log_Pos: 250
Relay_Master_Log_File: fdb3-bin.000004
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 '40846' for key 'PRIMARY'' on query. Default database: 'test'. Query: 'insert into t1(name) values('6691')'
Skip_Counter: 0
Exec_Master_Log_Pos: 362364030
Relay_Log_Space: 98380249
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 '40846' for key 'PRIMARY'' on query. Default database: 'test'. Query: 'insert into t1(name) values('6691')'
,
position
Exec_Master_Log_Pos: 362364030
This means relay-log.info was NOT overwritten by some reason, or previous information was reused somehow.
** Affects: percona-xtradb
Importance: Undecided
Status: New
--
overwrite_relay_log_info: Replication relay-info isn't overwritten
https://bugs.launchpad.net/bugs/335122
You received this bug notification because you are a member of Percona
developers, which is the registrant for Percona-XtraDB.
Status in Percona XtraDB Storage Engine for MySQL: New
Bug description:
I am trying to check how overwrite relay-info works, and there is problem.
I use NFS server to store mysql and replication files, and I do break NFS connection to emulate failure.
Here relay-log.info after crash:
./w3-relay-bin.000011
85062120
fdb3-bin.000004
362364030
Now I start mysqld and error.log is:
InnoDB: Warning: innodb_overwrite_relay_log_info is enabled. Updates of other storage engines may have problem of consistency.
InnoDB: relay-log.info is detected.
InnoDB: relay log: position 85062120, file name ./w3-relay-bin.000011
InnoDB: master log: position 362364030, file name fdb3-bin.000004
090226 13:40:09 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 428690885
090226 13:40:09 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
090226 13:40:10 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 429928722
090226 13:40:11 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: In a MySQL replication slave the last master binlog file
InnoDB: position 0 362812282, file name fdb3-bin.000004
InnoDB: and relay log file
InnoDB: position 0 85510372, file name ./w3-relay-bin.000011
090226 13:40:11 InnoDB Plugin 1.0.2-3 started; log sequence number 429928722
InnoDB: relay-log.info have been overwritten.
090226 13:40:11 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=w3-relay-bin' to avoid this problem.
090226 13:40:11 [Note] Event Scheduler: Loaded 0 events
090226 13:40:11 [Note] /usr/libexec/mysqld: ready for connections.
Version: '5.1.31' socket: '/tmp/mysql.sock' port: 3306 Source distribution
090226 13:41:54 [Note] Slave I/O thread: connected to master 'root@10.11.12.58:3306',replication started in log 'fdb3-bin.000004' at position 362364030
090226 13:41:54 [Note] Slave SQL thread initialized, starting replication in log 'fdb3-bin.000004' at position 362812282, relay log './w3-relay-bin.000011' position: 85510372
090226 13:41:55 [ERROR] Slave SQL: Error 'Duplicate entry '40846' for key 'PRIMARY'' on query. Default database: 'test'. Query: 'insert into t1(name) values('6691')', Error_code: 1062
090226 13:41:55 [Warning] Slave: Duplicate entry '40846' for key 'PRIMARY' Error_code: 1062
090226 13:41:55 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'fdb3-bin.000004' position 362364030
Note:
nnoDB: In a MySQL replication slave the last master binlog file
InnoDB: position 0 362812282, file name fdb3-bin.000004
InnoDB: and relay log file
InnoDB: position 0 85510372, file name ./w3-relay-bin.000011
090226 13:40:11 InnoDB Plugin 1.0.2-3 started; log sequence number 429928722
InnoDB: relay-log.info have been overwritten.
...
090226 13:41:54 [Note] Slave SQL thread initialized, starting replication in log 'fdb3-bin.000004' at position 362812282, relay log './w3-relay-bin.000011' position: 85510372
but later I see error
090226 13:41:55 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'fdb3-bin.000004' position 362364030
and position 362364030 is earlier than 362812282 !!
and relay-log.info is still
./w3-relay-bin.000013
250
fdb3-bin.000004
362364030
2282
SHOW SLAVE STATUS is
Slave_IO_State: Waiting for master to send event
Master_Host: 10.11.12.58
Master_User: root
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: fdb3-bin.000004
Read_Master_Log_Pos: 460743877
Relay_Log_File: w3-relay-bin.000013
Relay_Log_Pos: 250
Relay_Master_Log_File: fdb3-bin.000004
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 '40846' for key 'PRIMARY'' on query. Default database: 'test'. Query: 'insert into t1(name) values('6691')'
Skip_Counter: 0
Exec_Master_Log_Pos: 362364030
Relay_Log_Space: 98380249
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 '40846' for key 'PRIMARY'' on query. Default database: 'test'. Query: 'insert into t1(name) values('6691')'
,
position
Exec_Master_Log_Pos: 362364030
This means relay-log.info was NOT overwritten by some reason, or previous information was reused somehow.
Follow ups
References
