MySQL Bugs: #48277: binlog reports error on inserts

Bug #48277	binlog reports error on inserts
Submitted:	23 Oct 2009 23:41	Modified:	25 Oct 2009 1:25
Reporter:	Jean Mikoyan	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.1.39	OS:	Linux (fedora 11)
Assigned to:		CPU Architecture:	Any
Tags:	binlog

Description:
any insert statement creates this error below in the binlog.  I discovered it during setting up replication, but it happens no matter what with the master server.

mysqlbinlog mysql-bin.000028

/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#091023 14:34:54 server id 1  end_log_pos 106 	Start: binlog v 4, server v 5.1.39-log created 091023 14:34:54 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
fiHiSg8BAAAAZgAAAGoAAAABAAQANS4xLjM5LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAB+IeJKEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
'/*!*/;
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 108, event_type: 2
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

How to repeat:
make any insert or update statement

I would like to add, before anyone says I'm a crazy person, that I have uninstalled and re-installed mysql twice, tried it on two different machines and three different hard drives.  The binary log is always corrupted, though mysql seems to be working fine otherwise.

Thank you for the problem report. Please, upload the smallest of binary logs that demonstrates this problem. SHOW CREATE TABLE for the table you are inserting into and example of INSERT statement will be also useful.

binary log before corruption

Attachment: beforeCorruption.log (application/octet-stream, text), 106 bytes.

binary log after corruption

Attachment: afterCorruption.log (application/octet-stream, text), 213 bytes.

I ran flush logs to make a small binary log file, uploaded as beforeCorruption.log, which checks out fine with mysqlbinlog.  I then issue this command:
insert into feedGuids set guid='xxxxx0';

feedGuids is a simple table: +----------+--------------+------+-----+---------+-------+
| Field    | Type         | Null | Key | Default | Extra |
+----------+--------------+------+-----+---------+-------+
| user_id  | int(11)      | YES  | MUL | NULL    |       | 
| guid     | varchar(255) | YES  | MUL | NULL    |       | 
| imported | datetime     | YES  |     | NULL    |       | 
+----------+--------------+------+-----+---------+-------+
3 rows in set (0.14 sec)

The binary log is now corrupted.  The corrupted log is uploaded as afterCorruption.log.

I have upgraded to 5.1.40, and the problem persists.

I found a way to make the binary log work, but it isn't right.  If I create a file called 'sql' that contains:

insert into poop set idx=7;

and run

mysql -p test < sql

then the binary log becomes corrupt.  However, taking a cue from my successful import of an old database via mysqldump, I edited sql to contain

/*!40101 SET @OLD_CHARACTER_SET_CLIENT=@@CHARACTER_SET_CLIENT */;
/*!40101 SET @OLD_CHARACTER_SET_RESULTS=@@CHARACTER_SET_RESULTS */;
/*!40101 SET @OLD_COLLATION_CONNECTION=@@COLLATION_CONNECTION */;
/*!40101 SET NAMES utf8 */;
/*!40103 SET @OLD_TIME_ZONE=@@TIME_ZONE */;
/*!40103 SET TIME_ZONE='+00:00' */;
/*!40014 SET @OLD_UNIQUE_CHECKS=@@UNIQUE_CHECKS, UNIQUE_CHECKS=0 */;
/*!40014 SET @OLD_FOREIGN_KEY_CHECKS=@@FOREIGN_KEY_CHECKS, FOREIGN_KEY_CHECKS=0 */;
/*!40101 SET @OLD_SQL_MODE=@@SQL_MODE, SQL_MODE='NO_AUTO_VALUE_ON_ZERO' */;
/*!40111 SET @OLD_SQL_NOTES=@@SQL_NOTES, SQL_NOTES=0 */;

insert into poop set idx=7;

and it doesn't corrupt the binary log.

This must be related to OS and the mysql command line tool, but how?

solved.  This may not be a bug, but it's a huge, non-obvious gotcha.  If one installs fedora 11 and mysql, there is a mismatch in character sets.  Setting the default character set to utf8 will make the binary log start to behave again.  This is a really hard to pin down error.

Thank you for the feedback and closing according last comment.

IMHO the ability to cause this error message is a bug:

"ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log',
data_len: 108, event_type: 2"

Hello, 

i got the same error with Fedora 12 & mysql 5.0.87 and could fix it with "SET NAMES utf8" or configuring "--with-charset=utf8" as described. 

But we need it to work with latin1 encoding. After searching for replication errors in the mysql bug-database, i found a patch for "sql/log_event.cc" (http://lists.mysql.com/commits/89843). 

The patch ist not exactly for the mysql 5.0.87 Version (different lines) but i searched for the changes and saw, that the first line with 

	-static void write_str_with_code_and_len(char **dst, const char *src,
	-                                        int len, uint code)
	+static void write_str_with_code_and_len(uchar **dst, const char *src,
	+                                        uint len, uint code)

was different and the other two changes were OK in the 5.0.87 sources. So i changed only the first differences to "uchar" and "uint". After compiling with latin1 the mysql-binlogs seems not to be broken any more. 

But i'm unsure and want to ask the developers, if it's OK ?

I have fedora11 and I tested it with 5.0.85 and with 5.0.88. I have always corrupted binlogs even when the file is first created! Compiling with option --with-charset=utf8 didn't solve any thing. On the other hand I have rpm package MySQL version 5.0.37 installed on the same machine and it has not this problem.