MySQL:How to correct a corrupted MySQL binary log on Master server?

Question

We are using MySQL DB with one master and one slave. We are using this setup for months now. The slave sync stopped today and the error we got was:

Last_IO_Errno: 1236
            Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master'
           Last_SQL_Errno: 1594
           Last_SQL_Error: Relay log read failure: Could not parse relay log event entry. The possible reasons are: the master's binary log is corrupted (you can check this by running 'mysqlbinlog' on the binary log), the slave's relay log is corrupted (you can check this by running 'mysqlbinlog' on the relay log), a network problem, or a bug in the master's or slave's MySQL code. If you want to check the master's binary log or slave's relay log, you will be able to know their names by issuing 'SHOW SLAVE STATUS' on this slave.

We tried restarting slave's mysql service and start and stop the slave replication with no help. After further investigation we found that there was an issue with particularly big size of query. In the error log of the master server we got error log like below:

[ERROR] Error in Log_event::read_log_event(): 'Event too big', data_len: 1936941420, event_type: 109

We have identified the query that caused this issue. We can ignore the update from that query. This error is logged constantly in the mysql error log.

The issue is, the master is not able to read the from the relay log after that perticular log position. We just want to remove that particular relay log number from the binary log of the master server. How can we remove a particular relay log entry from the binary log file? And yes, we have a critical situation with the application due to this.:(

Answer 1

A possible solution that comes to mind is to set the master_log_position to the next one:

change master to master_log_position = <next_pos>;
start slave;

Or just use sql_slave_skip_counter = 1. If that doesn't work, you may try to parse the binlog (if mysqlbinlog is able to parse it ...):

mysqlbinlog filename > script.sql

Edit the script and remove the part up to and including the long statement. Run the modified script manually on the slave and set the master_logfile to the next binlog:

change master to master_log_file ...;
start slave;

You may also check, just in case, if both master and slave use the same *max_allowed_packet*.

Answer 2

Quite some time ago we had an corrupted binary log on the master due to some severe issues with the SAN, which did things that a SAN really really really should not do like writing blocks of zeros instead of the actual data, which we learned afterwards.

My solution was to skip the broken blocks / log entries by setting the master_log_position on the slaves to the next valid statement in the master bin log and hope that the skipped / missing statements did not do break anything on the logical level aka slave complaining about duplicate key and such things afterwards.

Problem is to find the next valid position within the binary log in this case.

So I took a look into the developer documentation of mysql to know the internal structure of the binary log and looked into my broken master binary log with a hex editor. The position of the last valid entry can be seen on the slave, start from there.

As the binary log contained the recorded sql statements in almost text form so I was able the identify the position of next INSERT / UPDATE / something statements. Subtract the size of the binary log header fields before the actual statement (see developer documentation), set the master_log_position to that value and the restart the slave. If you hit a valid position it will continue, if not it will complain. You can use mysqlbinlog to dump the statement at that position as well.

This is nothing for the faint of heart and I can not give you a more detailed step by step instruction.

If your binary log is really corrupted (and to me it looks like this, date_len is pulled from a field in the bin log and this is not a valid value, that's why the slave is complaining) the by the book solution is to rebuild the slave by restoring a fresh backup from the master into the slave (etc., like setting up a new slave) as you can not tell afterwards if the data is really in sync with your master anymore because you skipped some statements.

Answer 3

Yes, setting master_log_position to the next valid statement is the way to go.

A good way to find the correct log position is to use the --hexdump option in mysqlbinlog, like this:

[root@c2 mysql]# mysqlbinlog c2-bin.001316 --hexdump |tail -100
ERROR: Error in Log_event::read_log_event(): 'Event too big', data_len:  1919251301, event_type: 117
#  6201cf2 a8 e1 5f 18 00 00 00 00  02 00 00 22 00 00 00 40 |................|
...
# at 102768549
#150922 18:34:57 server id 62  end_log_pos 102768729 
# Position  Timestamp   Type   Master ID        Size      Master Pos    Flags 
#  6201fa5 31 83 01 56   02   3e 00 00 00   b4 00 00 00   59 20 20 06   00 00
#  6201fb8 97 18 00 00 00 00 00 00  08 00 00 1a 00 00 00 40 |................|
#  6201fc8 00 00 01 00 00 20 00 00  00 00 00 06 03 73 74 64 |.............std|
#  6201fd8 04 08 00 08 00 08 00 61  73 74 65 72 69 73 6b 00 |.......asterisk.|
#  6201fe8 75 70 64 61 74 65 20 63  75 72 72 65 6e 74 5f 63 |update.current.c|
#  6201ff8 61 6c 6c 73 20 73 65 74  31 83 01 56 02 3e 00 00 |alls.set1..V....|
#  6202008 00 7d 00 00 00 d6 20 20  06 00 00 37 b4 03 00 00 |...........7....|
#  6202018 00 00 00 08 00 00 1a 00  00 00 40 00 00 01 00 00 |................|
#  6202028 20 00 00 00 00 00 06 03  73 74 64 04 08 00 08 00 |........std.....|
#  6202038 08 00 61 73 74 65 72 69  73 6b 00 75 70 64 61 74 |..asterisk.updat|
#  6202048 65 20 64 69 61 6c 73 74  61 74 75 73 20 73 65 74 |e.dialstatus.set|
#  6202058 20  |.|
#       Query   thread_id=6295  exec_time=0     error_code=0
SET TIMESTAMP=1442939697/*!*/;
update current_calls set1V>}Ö  7@ asteriskupdate dialstatus set 
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

You can see that the statement gets corrupted halfway through the block, and the next record is starting at 0x6202000 (31830156 is the next timestamp in little endian format). 0x6202000 is 102768640 decimal.

So the fix is:

stop slave;
change master to master_log_pos = 102768640;
start slave;

Answer 4

This error is usually caused by a hardware glitch or a bug so vague that it hasn't been found in over a decade. The optimal solution that will definitely fix it without any risk of anomalies is to fully re-initialize the replication. You can do this without downtime or locking by using either xtrabackup or mysqldump --single-transaction.

First of all you need to see SHOW SLAVE STATUS\G output. There you can find your mysqlbinlog.

Replication can be expensive if you have terabytes of data, so there may be a way you can restore replication without rebuilding the slave completely. You can use mysqlbinlog on the master to identify where the transaction is begin and look for near position (your Exec_Master_Log_Pos). There is a very good chance that the position listed is actually has error and no transaction in the binlog starts at that position. You are also very likely to find that the coordinate distances between these transactions are nowhere near your max_allowed_packet value.

If that is the case, you can reset your replication coordinates on the slave to the last transaction mysqlbinlog lists that is before the position the slave thinks it is at. You can find more details on exactly what to do in this MariaDB and MySQL troubleshooting article.

In most cases, if there is a primary key and we are using binlog_format=ROW, replication will break on a missing row (on a delete) or a duplicate key (on an INSERT), and we can skip the transaction and resume.