| Bug #70222 | ERROR: Could not read entry at offset n : Error in log format or read err | ||
|---|---|---|---|
| Submitted: | 3 Sep 2013 8:53 | Modified: | 29 Aug 2014 17:03 |
| Reporter: | Robert Tejada Petrovic | Email Updates: | |
| Status: | No Feedback | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S3 (Non-critical) |
| Version: | 5.6.12 | OS: | Solaris (11.1) |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | event datalen, mysqlbinlog, replication | ||
[3 Sep 2013 8:53]
Robert Tejada Petrovic
[7 Sep 2013 11:48]
Hartmut Holzgraefe
Doesn't look like a server bug, but like file system problem, e.g incomplete write due to full disk (as mentioned in the error message), or binlog event not written completely due to e.g. a power failure ...
[10 Sep 2013 16:11]
Robert Tejada Petrovic
Hi Hartmut, There wasn't any file system problem at the moment of write binlog, not even any power failure, the problem is reproduced almost once a day, and the binlog file not ends there, there are lot of events writes after this position. I cannot attach the binlogs due at his size. I'm trying to understand how the binlog is writen and why is truncated the data in the event, but I don't for the moment. I thing the problem can be related to the size of the events, but I see events with much large size before the truncated event. If you thing that I can do some kind of test to reproduce, plesase, let me know. we have this related configuration: max_allowed_packet 268435456 slave_max_allowed_packet 1073741824 read_buffer_size 131072 Regards,
[14 Oct 2013 22:41]
Ammon Sutherland
Had the same thing happen on 5.6.13 and the server did not crash, just decided to hate the binlog event (64 bit, RedHat 64 bit) showing the following in the error log:
[ERROR] Error in Log_event::read_log_event(): 'read error', data_len: 441605216, event_type: -75
And the following in the binlog:
mysql> show binlog events in 'mysql-bin.000006' from 36621628\G
*************************** 1. row ***************************
Log_name: mysql-bin.000006
Pos: 36621628
Event_type: Incident
Server_id: 24138
End_log_pos: 36621685
Info: #1 (LOST_EVENTS)
*************************** 2. row ***************************
Log_name: mysql-bin.000006
Pos: 36621685
Event_type: Rotate
Server_id: 24138
End_log_pos: 36621732
Info: mysql-bin.000007;pos=4
2 rows in set (0.01 sec)
or via mysqlbinlog -vv including event preceding:
#131011 14:55:08 server id 24138 end_log_pos 36621628 CRC32 0xe0d31eb5 Xid = 5869167
COMMIT/*!*/;
# at 36621628
#131014 16:20:29 server id 24138 end_log_pos 36621685 CRC32 0x2ffe553b
# Incident: LOST_EVENTS
RELOAD DATABASE; # Shall generate syntax error
# at 36621685
#131014 16:20:29 server id 24138 end_log_pos 36621732 CRC32 0x05753ed0 Rotate to mysql-bin.000007 pos: 4
DELIMITER ;
# End of log file
Which also caused replication to stop on slaves with the following message:
Last_Error: The incident LOST_EVENTS occured on the master. Message: error writing to the binary log
binlog related variables which are not defaults:
binlog_format = MIXED
log_slave_updates = 1
log-bin = /var/lib/mysql/mysql-bin
expire-logs-days = 14
sync-binlog = 1
transaction-isolation = READ-COMMITTED
innodb_locks_unsafe_for_binlog=1
[13 Dec 2013 9:31]
Juraj Blahunka
Having the same problem on Master server, error arises several times a day. Server produces around 1.6 GB of binlogs per day. 5.6.12-log MySQL Community Server (GPL) Debian 7.1 64bit Binlog related configuration: log-bin = mysql-bin gtid_mode = ON enforce-gtid-consistency binlog_format = mixed binlog-do-db = db_example log-slave-updates expire_logs_days = 10 max_binlog_size = 200M sync_binlog = 1 Error message when trying to read binlog: $ mysqlbinlog mysql-bin.000123 > /dev/null ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 134796079, event_type: 95
[13 Dec 2013 9:53]
Juraj Blahunka
Last binlog event, which can be read looks like this:
/*!*/;
# at 148057369
# at 148057401
#131213 9:58:42 server id 10 end_log_pos 148057401 CRC32 0x3afff93e Intvar
SET INSERT_ID=273510630/*!*/;
#131213 9:58:42 server id 10 end_log_pos 148057806 CRC32 0x0252aacc Query thread_id=144 exec_time=0 error_code=0
SET TIMESTAMP=1386925122/*!*/;
INSERT INTO some_table (day_id,date,other_id,other_id_2,val1,val2,val3,val4,val5,val6,val7,val8,val9,val10,val11,val12) VALUES (to_days('2013-12-13'),'2013-12-13 09:48:47',1887,12241,617.0,615.4,618.8,621.4,6p̪R!
^@^@^@0^@^@^@<C9>.<D3>^H^@^@^A:<AB><CF><DA>Y^]^Q<E3><87><F5>^@PV<9A>E<85><CD>R^\^@^@^@^@^@<9F><<A1>Wp
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
[17 Dec 2013 9:40]
MySQL Verification Team
Can you see if adding/changing the following options fixes the corruptions? [mysqld] binlog-rows-query-log-events=0 binlog-stmt-cache-size=1M
[18 Dec 2013 11:20]
Juraj Blahunka
I've added "binlog-stmt-cache-size=1M" to the configuration. The other setting "binlog-rows-query-log-events=0" was already setup.
The error however repeated itself after ~1GB of binlogs again:
$ mysqlbinlog mysql-bin.000160 > /dev/null
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 655954, event_type: -80
last event (which looks damaged, similar to previous one):
/*!*/;
# at 49571780
# at 49571812
#131218 11:39:09 server id 10 end_log_pos 49571812 CRC32 0x74df969c Intvar
SET INSERT_ID=1386599027/*!*/;
#131218 11:39:09 server id 10 end_log_pos 49572092 CRC32 0x00000027 Query thread_id=1300 exec_time=0 error_code=0
SET TIMESTAMP=1387363149/*!*/;
INSERT INTO some_table (some_id,some_date,some_id_2,some_id_3,val1,val2,val3) VALUES (to_days('2013-12-18'),'2013-12-1M{<B1>R!
^@^@^@0^@^@^@^Bi<F4>^B^@^@^A:<AB><CF><DA>Y^]^Q<E3><87><F5>^@PV<9A>E<85><E4>C
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
Most of the time, 4 threads are writing to Master, ~10-50 are reading, Master has enough free RAM and CPU averages at 10%
[1 Jan 2014 10:32]
MySQL Verification Team
We should wait until this internal bug has been fixed to check if this fixes it. Bug 17842137 - ASSERT IN ROW BASED REPLICATION WHEN TRANSACTION CACHE SIZE IS EXACTLY 32768
[11 Apr 2014 9:06]
Hartmut Holzgraefe
now that bug 17842137 is listed as fixed in the 5.6.16 changelog ... what about this bug? fixed by that or not?
[15 Apr 2014 11:56]
Sveta Smirnova
Robert, please upgrade to latest version and check if fix for bug #17842137 fixed your issue too. Hartmut, thank you for the reminder!
[16 May 2014 1:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
[27 Jul 2014 18:18]
Rohit Kalhans
We recently encountered a similar bug. the partition of temp directory got full and we it lead to the corruption of binary log. Noteworthy is the fact that the partition on which the binary-logs are present still had enough space left. We are using MySQL 5.5.38 Below is the output of mysqlbinlog on the corrupted binlog file. http://pastebin.com/tGLw9rAE The relevant entries from the errorlog are attached..
[27 Jul 2014 18:18]
Rohit Kalhans
retracted ErrorLog
Attachment: mysql-error_log_140727 copy.txt (text/plain), 4.75 KiB.
[29 Jul 2014 17:03]
Sveta Smirnova
Rohit, thank you for the feedback. We suspect that this is same issue as fixed in bug #17842137 in versions 5.6.16 and up. Please try your case with version 5.6.16+ and inform us if problem still exists.
[30 Aug 2014 1:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
