Editing
System-generated Notifications
(section)
Jump to navigation
Jump to search
Warning:
You are not logged in. Your IP address will be publicly visible if you make any edits. If you
log in
or
create an account
, your edits will be attributed to your username, along with other benefits.
Anti-spam check. Do
not
fill this in!
= "replication failing" = replication behind by 0 days, 12 hours, 23 minutes This message serves as a warning that the mysql replication between bwdb and backup1 is not in sync any longer. This could be the result of 1 of 2 things: 1. replication really isn't happening anymore 2. there is a backlog of netflow(s) that bwdb is working it's way through. That's why the latest data in the DB (which is what this notification looks for- stale data) is from hours ago. To rule out #2, on bwdb simply look at the queue of flows to be processed: bwdb /home/flowbin# ls /usr/home/working ft-v05.2012-11-05.113000-0800 bwdb /home/flowbin# You see there's 1 flow there ready to processes. Had there been a backlog you'd see lots of files there. So this message must mean there's a replication failure. Here's how to look at the replication status: On bwdb: <pre>mysql> SHOW MASTER STATUS; +-----------------+-----------+--------------+------------------+ | File | Position | Binlog_Do_DB | Binlog_Ignore_DB | +-----------------+-----------+--------------+------------------+ | bwdb-bin.001551 | 156935084 | | | +-----------------+-----------+--------------+------------------+ 1 row in set (0.02 sec)</pre> On backup1: <pre>mysql> show slave status\G *************************** 1. row *************************** Slave_IO_State: Master_Host: 10.1.4.203 Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: bwdb-bin.001550 Read_Master_Log_Pos: 505039281 Relay_Log_File: mysqld-relay-bin.001527 Relay_Log_Pos: 98 Relay_Master_Log_File: bwdb-bin.001550 Slave_IO_Running: No Slave_SQL_Running: Yes Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: traffic.% Replicate_Wild_Ignore_Table: Last_Errno: 0 Last_Error: Skip_Counter: 0 Exec_Master_Log_Pos: 505039281 Relay_Log_Space: 98 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 1 row in set (0.57 sec) </pre> Our indicators that something is wrong come from looking at these fields from backup1: Read_Master_Log_Pos: 505039281 This doesn't match up with what bwdb shows for log position: <tt>156935084</tt> Relay_Master_Log_File: bwdb-bin.001550 This doesn't match up with what bwdb shows for log file: <tt>bwdb-bin.001551</tt> Slave_IO_Running: No This should say <tt>Yes</tt> Here's how this is resolved: <pre> mysql> stop slave; mysql> reset slave; mysql> start slave; mysql> show slave status\G *************************** 1. row *************************** Slave_IO_State: Queueing master event to the relay log Master_Host: 10.1.4.203 Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: bwdb-bin.001549 Read_Master_Log_Pos: 236696828 Relay_Log_File: mysqld-relay-bin.000003 Relay_Log_Pos: 133842 Relay_Master_Log_File: bwdb-bin.001549 Slave_IO_Running: Yes Slave_SQL_Running: Yes Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: traffic.% Replicate_Wild_Ignore_Table: Last_Errno: 0 Last_Error: Skip_Counter: 0 Exec_Master_Log_Pos: 132576 Relay_Log_Space: 238358016 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: 343413</pre> I'm a little perplexed why it reverted to log file <tt>bwdb-bin.001549</tt>, but we see that <tt>Slave_IO_Running</tt> and <tt>Slave_SQL_Running</tt> are Yes and if you re-run the show slave status command you will see that the <tt>Read_Master_Log_Pos</tt> is incrementing. However after running through all of the log file <tt>bwdb-bin.001550</tt>, it eventually fails: <pre> mysql> show slave status\G *************************** 1. row *************************** Slave_IO_State: Master_Host: 10.1.4.203 Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: bwdb-bin.001550 Read_Master_Log_Pos: 504660170 Relay_Log_File: mysqld-relay-bin.000006 Relay_Log_Pos: 508191412 Relay_Master_Log_File: bwdb-bin.001550 Slave_IO_Running: No Slave_SQL_Running: No Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: traffic.% Replicate_Wild_Ignore_Table: Last_Errno: 1064 Last_Error: Error 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '' at line 1' on query. Default database: ''. Query: '' Skip_Counter: 0 Exec_Master_Log_Pos: 504659938 Relay_Log_Space: 508191646 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 1 row in set (0.00 sec) </pre> Probably cause it got to a corrupted part of the log file. After looking at [http://www.zmonkey.org/blog/node/157 http://www.zmonkey.org/blog/node/157] it looks like i may need to skip over a bad part in the log and go to the next entry for the next log position. However, after performing this on bwdb: <pre> bwdb /usr/home/database# mysqlbinlog bwdb-bin.001550 -j 504659938 /*!40019 SET @@session.max_insert_delayed_threads=0*/; # at 504659938 #121104 20:04:18 server id 1 log_pos 504659938 Query thread_id=15838 exec_time=0 error_code=0 SET TIMESTAMP=1352088258; ; ERROR: Error in Log_event::read_log_event(): 'Event too small', data_len: 0, event_type: 0 Could not read entry at offset 504660170:Error in log format or read error bwdb /usr/home/database# </pre> Which is maybe an indication that this is simply the end of the log file (there's no more output after it), so if we look at the next logfile: <pre> bwdb /usr/home/database# mysqlbinlog bwdb-bin.001551|more /*!40019 SET @@session.max_insert_delayed_threads=0*/; # at 4 #121104 23:04:07 server id 1 log_pos 4 Start: binlog v 3, server v 4.1.10a-log creat ed 121104 23:04:07 at startup # at 79 #121104 23:18:05 server id 1 log_pos 79 Query thread_id=2 exec_time=0 error _code=0 use traffic; SET TIMESTAMP=1352099885; insert into dailyIpTotals_69_55_239 values ('6955239101-20121104-1', '2012-11-04 19:45:00', ' 69.55.239.101', 1, 344, 7) ON DUPLICATE KEY UPDATE octets=octets+344, packets=packets+7; # at 297 #121104 23:18:05 server id 1 log_pos 297 Query thread_id=2 exec_time=0 error _code=0 SET TIMESTAMP=1352099885; insert into dailyIpTotals_69_55_239 values ('6955239102-20121104-1', '2012-11-04 19:45:00', ' 69.55.239.102', 1, 84, 2) ON DUPLICATE KEY UPDATE octets=octets+84, packets=packets+2; </pre> So it looks like this is what we want, and the time stamp correlates with when the server came back online (from a crash in this instance). So we reset the slave to pull from the other log: <pre> mysql> show slave status\G *************************** 1. row *************************** Slave_IO_State: Queueing master event to the relay log Master_Host: 10.1.4.203 Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: bwdb-bin.001551 Read_Master_Log_Pos: 45486292 Relay_Log_File: mysqld-relay-bin.000002 Relay_Log_Pos: 140 Relay_Master_Log_File: bwdb-bin.001551 Slave_IO_Running: Yes Slave_SQL_Running: Yes Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: traffic.% Replicate_Wild_Ignore_Table: Last_Errno: 0 Last_Error: Skip_Counter: 0 Exec_Master_Log_Pos: 4 Relay_Log_Space: 45805720 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: 67238 1 row in set (0.22 sec) mysql> show slave status\G *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 10.1.4.203 Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: bwdb-bin.001551 Read_Master_Log_Pos: 107339149 Relay_Log_File: mysqld-relay-bin.000002 Relay_Log_Pos: 464584 Relay_Master_Log_File: bwdb-bin.001551 Slave_IO_Running: Yes Slave_SQL_Running: Yes Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: traffic.% Replicate_Wild_Ignore_Table: Last_Errno: 0 Last_Error: Skip_Counter: 0 Exec_Master_Log_Pos: 460960 Relay_Log_Space: 108092633 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: 55577 1 row in set (0.00 sec) </pre> And if we continue to show status we see that the position is moving and the <tt>Seconds_Behind_Master</tt> is dropping. So we should be good. After a bit we got: <pre>mysql> show slave status\G *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 10.1.4.203 Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: bwdb-bin.001551 Read_Master_Log_Pos: 196122754 Relay_Log_File: mysqld-relay-bin.000002 Relay_Log_Pos: 1569496 Relay_Master_Log_File: bwdb-bin.001551 Slave_IO_Running: Yes Slave_SQL_Running: No Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: traffic.% Replicate_Wild_Ignore_Table: Last_Errno: 0 Last_Error: Query caused different errors on master and slave. Error on master: 'Incorrect key file for table '%-.200s'; try to repair it' (1034), Error on slave: 'no error' (0). Default database: 'traffic'. Query: 'insert into portTotals_69_55_225 values ('2012-11-04 19:45:00', '69.55.225.225', 1, 6, 99999, 100, 2),('2012-11-04 19:45:00', '69.55.225.225', 2, 1, 0, 12414, 240.5),('2012-11-04 19:45:00', '69.55.225.225', 2, 17, 53, 15156829.5, 64580.5),('2012-11-04 19:45:00', '69.55.225.225', 2, 17, 1024, 387, 2),('2012-11-04 19:45:00', '69.55.225.225', 2, 17, 361, 213, 1),('2012-11-04 19:45:00', '69.55.225.225', 2, 17, 833, 15120, 60),('2012-11-04 19:45:00', '69.55.225.225', 2, 17, 395, 10534, 46),('2012-11-04 19:45:00', '69.55.225.225', 2, 17, 559, 31968, 111),('2012-11-04 19:45:00', '69.55.225.225', 2, 6, 53, 1541, 24),('2012-11-04 19:45:00', '69.55.225.225', 2, 6, 80, 80, 2),('2012-11-04 19:45:00', '69.55.225.225', 2, 6, 81, 40, 1),('2012-11-04 19:45:00', '69.55.225.225', 2, 6, 99999, 120, 3),('2012-11-04 19:45:00', ' Skip_Counter: 0 Exec_Master_Log_Pos: 1558174 Relay_Log_Space: 197497274 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 1 row in set (0.00 sec) </pre> So on bwdb we did: <pre>mysql> repair table portTotals_69_55_225;</pre> Then on backup1 after we stop, reset, start slave it eventually bombs again: <pre> mysql> show slave status\G *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 10.1.4.203 Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: bwdb-bin.001553 Read_Master_Log_Pos: 99377008 Relay_Log_File: mysqld-relay-bin.000002 Relay_Log_Pos: 1569496 Relay_Master_Log_File: bwdb-bin.001551 Slave_IO_Running: Yes Slave_SQL_Running: No Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: traffic.% Replicate_Wild_Ignore_Table: Last_Errno: 0 Last_Error: Query caused different errors on master and slave. Error on master: 'Incorrect key file for table '%-.200s'; try to repair it' (1034), Error on slave: 'no error' (0). Default database: 'traffic'. Query: 'insert into portTotals_69_55_225 values ('2012-11-04 19:45:00', '69.55.225.225', 1, 6, 99999, 100, 2),('2012-11-04 19:45:00', '69.55.225.225', 2, 1, 0, 12414, 240.5),('2012-11-04 19:45:00', '69.55.225.225', 2, 17, 53, 15156829.5, 64580.5),('2012-11-04 19:45:00', '69.55.225.225', 2, 17, 1024, 387, 2),('2012-11-04 19:45:00', '69.55.225.225', 2, 17, 361, 213, 1),('2012-11-04 19:45:00', '69.55.225.225', 2, 17, 833, 15120, 60),('2012-11-04 19:45:00', '69.55.225.225', 2, 17, 395, 10534, 46),('2012-11-04 19:45:00', '69.55.225.225', 2, 17, 559, 31968, 111),('2012-11-04 19:45:00', '69.55.225.225', 2, 6, 53, 1541, 24),('2012-11-04 19:45:00', '69.55.225.225', 2, 6, 80, 80, 2),('2012-11-04 19:45:00', '69.55.225.225', 2, 6, 81, 40, 1),('2012-11-04 19:45:00', '69.55.225.225', 2, 6, 99999, 120, 3),('2012-11-04 19:45:00', ' Skip_Counter: 0 Exec_Master_Log_Pos: 1558174 Relay_Log_Space: 298937975 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 1 row in set (0.00 sec) </pre> So at this point we will revert to the poor man's method: Plan B What we do here is delete all data in both databases in all tables from the day of the outage forward. Restart the sync. Then we re-process the flow files on bwdb from the day of the outage, and given enough time it catch up will rebuild the database (which will properly replicate as the processing continues). So, given an outage on 11/4/12 and today is the 6th: 1. comment out the processing script temporarily: <pre> #process flow data #2,17,32,47 * * * * /usr/home/flowbin/processflows.pl </pre> 2. we create an sql file with all the commands we want to run: <pre> cat rmdata.sql delete from ipTotals_69_55_224 where date >='2011-11-04'; delete from ipTotals_69_55_225 where date >='2011-11-04'; delete from ipTotals_69_55_226 where date >='2011-11-04'; delete from ipTotals_69_55_227 where date >='2011-11-04'; delete from ipTotals_69_55_228 where date >='2011-11-04'; delete from ipTotals_69_55_230 where date >='2011-11-04'; delete from ipTotals_69_55_232 where date >='2011-11-04'; delete from ipTotals_69_55_233 where date >='2011-11-04'; delete from ipTotals_69_55_234 where date >='2011-11-04'; delete from ipTotals_69_55_235 where date >='2011-11-04'; delete from ipTotals_69_55_236 where date >='2011-11-04'; delete from ipTotals_69_55_237 where date >='2011-11-04'; delete from ipTotals_69_55_238 where date >='2011-11-04'; delete from ipTotals_69_55_239 where date >='2011-11-04'; delete from dailyIpTotals_69_55_224 where date >='2011-11-04'; delete from dailyIpTotals_69_55_225 where date >='2011-11-04'; delete from dailyIpTotals_69_55_226 where date >='2011-11-04'; delete from dailyIpTotals_69_55_227 where date >='2011-11-04'; delete from dailyIpTotals_69_55_228 where date >='2011-11-04'; delete from dailyIpTotals_69_55_230 where date >='2011-11-04'; delete from dailyIpTotals_69_55_232 where date >='2011-11-04'; delete from dailyIpTotals_69_55_233 where date >='2011-11-04'; delete from dailyIpTotals_69_55_234 where date >='2011-11-04'; delete from dailyIpTotals_69_55_235 where date >='2011-11-04'; delete from dailyIpTotals_69_55_236 where date >='2011-11-04'; delete from dailyIpTotals_69_55_237 where date >='2011-11-04'; delete from dailyIpTotals_69_55_238 where date >='2011-11-04'; delete from dailyIpTotals_69_55_239 where date >='2011-11-04'; delete from portTotals_69_55_224 where date >='2011-11-04'; delete from portTotals_69_55_225 where date >='2011-11-04'; delete from portTotals_69_55_226 where date >='2011-11-04'; delete from portTotals_69_55_227 where date >='2011-11-04'; delete from portTotals_69_55_228 where date >='2011-11-04'; delete from portTotals_69_55_230 where date >='2011-11-04'; delete from portTotals_69_55_232 where date >='2011-11-04'; delete from portTotals_69_55_233 where date >='2011-11-04'; delete from portTotals_69_55_234 where date >='2011-11-04'; delete from portTotals_69_55_235 where date >='2011-11-04'; delete from portTotals_69_55_236 where date >='2011-11-04'; delete from portTotals_69_55_237 where date >='2011-11-04'; delete from portTotals_69_55_238 where date >='2011-11-04'; delete from portTotals_69_55_239 where date >='2011-11-04'; delete from dailyPortTotals_69_55_224 where date >='2011-11-04'; delete from dailyPortTotals_69_55_225 where date >='2011-11-04'; delete from dailyPortTotals_69_55_226 where date >='2011-11-04'; delete from dailyPortTotals_69_55_227 where date >='2011-11-04'; delete from dailyPortTotals_69_55_228 where date >='2011-11-04'; delete from dailyPortTotals_69_55_230 where date >='2011-11-04'; delete from dailyPortTotals_69_55_232 where date >='2011-11-04'; delete from dailyPortTotals_69_55_233 where date >='2011-11-04'; delete from dailyPortTotals_69_55_234 where date >='2011-11-04'; delete from dailyPortTotals_69_55_235 where date >='2011-11-04'; delete from dailyPortTotals_69_55_236 where date >='2011-11-04'; delete from dailyPortTotals_69_55_237 where date >='2011-11-04'; delete from dailyPortTotals_69_55_238 where date >='2011-11-04'; delete from dailyPortTotals_69_55_239 where date >='2011-11-04'; </pre> Run it: <tt>mysql -p traffic < rmdata.sql</tt> on bwdb AND backup1 (this will take some time to complete) 3. replace all the flow files for re-processing <pre>cp /usr/home/archive/ft-v05.2012-11-04.* /usr/home/working/ cp /usr/home/archive/ft-v05.2012-11-05.* /usr/home/working/ cp /usr/home/archive/ft-v05.2012-11-06.* /usr/home/working/ </pre> Look for any temporary files at the time of the crash, move and rename: <pre> mv /usr/home/flows/2012-11/2012-11-04/tmp-v05.2012-11-04.200000-0800 /usr/home/archive/ft-v05.2012-11-04.200000-0800 </pre> 4. restart slaving On bwdb: <pre> mysql> show master status; +-----------------+----------+--------------+------------------+ | File | Position | Binlog_Do_DB | Binlog_Ignore_DB | +-----------------+----------+--------------+------------------+ | bwdb-bin.001557 | 5612 | | | +-----------------+----------+--------------+------------------+ 1 row in set (0.00 sec) </pre> On backup1: <pre> mysql> stop slave; Query OK, 0 rows affected, 1 warning (0.00 sec) mysql> CHANGE MASTER TO MASTER_HOST='10.1.4.203',MASTER_USER='repl',MASTER_PASSWORD='qERUG8wf',MASTER_LOG_FILE='bwdb-bin.001557',MASTER_LOG_POS=5612; Query OK, 0 rows affected (1.35 sec) mysql> start slave; Query OK, 0 rows affected (0.00 sec) mysql> show slave status\G; *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 10.1.4.203 Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: bwdb-bin.001557 Read_Master_Log_Pos: 5612 Relay_Log_File: mysqld-relay-bin.000002 Relay_Log_Pos: 140 Relay_Master_Log_File: bwdb-bin.001557 Slave_IO_Running: Yes Slave_SQL_Running: Yes Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: traffic.% Replicate_Wild_Ignore_Table: Last_Errno: 0 Last_Error: Skip_Counter: 0 Exec_Master_Log_Pos: 5612 Relay_Log_Space: 140 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 1 row in set (0.00 sec) </pre> 5. on bwdb re-process the flows: <tt>/usr/home/flowbin/processflows.pl</tt> Shortly thereafter you should see the <tt>Relay_Master_Log_File</tt> on backup1 increase as it follows bwdb's replication. You should also see the list of flow files in the queue start to shrink (at least the ones from days ago will start to disappear). 6. once <tt>processflows.pl</tt> is done, uncomment the cronjob to let it start running on its own
Summary:
Please note that all contributions to JCWiki may be edited, altered, or removed by other contributors. If you do not want your writing to be edited mercilessly, then do not submit it here.
You are also promising us that you wrote this yourself, or copied it from a public domain or similar free resource (see
JCWiki:Copyrights
for details).
Do not submit copyrighted work without permission!
Cancel
Editing help
(opens in new window)
Navigation menu
Personal tools
Not logged in
Talk
Contributions
Create account
Log in
Namespaces
Page
Discussion
English
Views
Read
Edit
View history
More
Search
Navigation
Main page
Recent changes
Random page
Help about MediaWiki
Tools
What links here
Related changes
Special pages
Page information