Bug #43808 binlog error: sanity check failed
Submitted: 23 Mar 2009 19:01 Modified: 14 May 2009 17:13
Reporter: Adrian Rollett Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:5.1 OS:Linux
Assigned to: Luis Soares CPU Architecture:Any
Tags: binlog, mysqlbinlog, replication
Triage: Triaged: D2 (Serious)

[23 Mar 2009 19:01] Adrian Rollett
Description:
I am running mysql 5.1.32-1 (from the debian repositories) on debian lenny 64bit linux with a master and one slave (same version of everything) replicating. This morning, binlog on the master broke, mysqlbinlog gives this error:

mysql1:/var/log/mysql# mysqlbinlog -Hvv mysql-bin.000057 --start-position=16267379
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#090323 10:14:17 server id 1  end_log_pos 106 
# Position  Timestamp   Type   Master ID        Size      Master Pos    Flags 
#        4 49 a7 c7 49   0f   01 00 00 00   66 00 00 00   6a 00 00 00   00 00
#       17 04 00 35 2e 31 2e 33 32  2d 31 2d 6c 6f 67 00 00 |..5.1.32.1.log..|
#       27 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |................|
#       37 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |................|
#       47 00 00 00 00 00 00 00 00  13 38 0d 00 08 00 12 00 |.........8......|
#       57 04 04 04 04 12 00 00 53  00 04 1a 08 00 00 00 08 |.......S........|
#       67 08 08 02  |...|
#       Start: binlog v 4, server v 5.1.32-1-log created 090323 10:14:17
BINLOG '
SafHSQ8BAAAAZgAAAGoAAAAAAAQANS4xLjMyLTEtbG9nAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
'/*!*/;
# at 16267379
ERROR: Error in Log_event::read_log_event(): 'Sanity check failed', data_len: 939008, event_type: 73
ERROR: Could not read entry at offset 16268115: Error in log format or read error.
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

I will attache the full statement log from the same time.

I have done a pretty comprehensive search of the 'net and the mysql bugs DB without turning up anything specific to this error. I'm pasting the my.cnf below, please let me know if I can provide any more information to help run this down.

#
# The MySQL database server configuration file.
#
# You can copy this to one of:
# - "/etc/mysql/my.cnf" to set global options,
# - "/var/lib/mysql/my.cnf" to set server-specific options or
# - "~/.my.cnf" to set user-specific options.
# 
# One can use all long options that the program supports.
# Run program with --help to get a list of available options and with
# --print-defaults to see which it would actually understand and use.
#
# For explanations see
# http://dev.mysql.com/doc/mysql/en/server-system-variables.html

# This will be passed to all mysql clients
# It has been reported that passwords should be enclosed with ticks/quotes
# escpecially if they contain "#" chars...
# Remember to edit /etc/mysql/debian.cnf when changing the socket location.
[client]
port		= 3306
socket		= /var/run/mysqld/mysqld.sock

# Here is entries for some specific programs
# The following values assume you have at least 32M ram

# This was formally known as [safe_mysqld]. Both versions are currently parsed.
[mysqld_safe]
socket		= /var/run/mysqld/mysqld.sock
nice		= 0

[mysqld]
old_passwords = true # inserted by debconf
#
# * Basic Settings
#
user		= mysql
pid-file	= /var/run/mysqld/mysqld.pid
socket		= /var/run/mysqld/mysqld.sock
port		= 3306
basedir		= /usr
#datadir		= /var/lib/mysql
datadir		= /export/sandata/mysql
tmpdir		= /tmp
language	= /usr/share/mysql/english
skip-external-locking
#
# Instead of skip-networking the default is now to listen only on
# localhost which is more compatible and is not less secure.
#bind-address            = 127.0.0.1

#
# * Fine Tuning
#
# key_buffer		= 512
key_buffer_size		= 512M
max_allowed_packet	= 16M
thread_stack		= 128K
table_open_cache 	= 16384
sort_buffer_size = 10M
read_buffer_size = 128K
read_rnd_buffer_size = 4M
myisam_sort_buffer_size = 64M
thread_cache_size = 8

tmp_table_size = 64M
max_heap_table_size = 64M
max_connections = 1000

# Try number of CPU's*2 for thread_concurrency
thread_concurrency = 8

#
# * Query Cache Configuration
#
query_cache_limit	= 1048576
query_cache_size	= 4096M
query_cache_type        = 1
#
# * Logging and Replication
#
# Both location gets rotated by the cronjob.
# Be aware that this log type is a performance killer.
#log		= /var/log/mysql.log
log		= /var/log/mysql/mysql.log
#
# Error logging goes to syslog. This is a Debian improvement :)
#

# Here you can see queries with especially long duration
# log-slow-queries	= /var/log/mysql/slow_queries.log
# long_query_time = 2

#
# The following can be used as easy to replay backup logs or for replication.
server-id		= 1
log-bin			= /var/log/mysql/mysql-bin.log

# This setting helps reduce the chances of replication failing after a crash on the master
# ( see http://dev.mysql.com/doc/refman/5.0/en/replication-features-mastercrash.html )
sync_binlog=1

binlog_format=mixed

# See /etc/mysql/debian-log-rotate.conf for the number of files kept.
max_binlog_size		= 104857600

# keep a month's worth of logs for now
expire-logs-days	= 30

#binlog-do-db		= include_database_name
#binlog-ignore-db	= include_database_name
#

#
# InnoDB is enabled by default with a 10MB datafile in /var/lib/mysql/.
# Read the manual for more InnoDB related options. There are many!
#
# * Security Feature
#
# Read the manual, too, if you want chroot!
# chroot = /var/lib/mysql/
#
# If you want to enable SSL support (recommended) read the manual or my
# HOWTO in /usr/share/doc/mysql-server/SSL-MINI-HOWTO.txt.gz
# ssl-ca=/etc/mysql/cacert.pem
# ssl-cert=/etc/mysql/server-cert.pem
# ssl-key=/etc/mysql/server-key.pem

[mysqldump]
--snipped--

How to repeat:
Unfortunately, I don't know enough about the problem to be able to repeat it...
[23 Mar 2009 19:03] Adrian Rollett
mysql.log snippet

Attachment: trans_log.txt (text/plain), 5.43 KiB.

[23 Mar 2009 19:21] Sveta Smirnova
Thank you for the report.

Do you get same error if skip --start-position=16267379? Please also provide full error log file.
[23 Mar 2009 20:01] Adrian Rollett
Hi Sveta,

thanks very much for your response - skipping that position produces no discernible difference:

mysql1:/var/log/mysql# mysqlbinlog -Hvv --start-position=16267379 --offset=1 mysql-bin.000057
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#090323 10:14:17 server id 1  end_log_pos 106 
# Position  Timestamp   Type   Master ID        Size      Master Pos    Flags 
#        4 49 a7 c7 49   0f   01 00 00 00   66 00 00 00   6a 00 00 00   00 00
#       17 04 00 35 2e 31 2e 33 32  2d 31 2d 6c 6f 67 00 00 |..5.1.32.1.log..|
#       27 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |................|
#       37 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00 |................|
#       47 00 00 00 00 00 00 00 00  13 38 0d 00 08 00 12 00 |.........8......|
#       57 04 04 04 04 12 00 00 53  00 04 1a 08 00 00 00 08 |.......S........|
#       67 08 08 02  |...|
#       Start: binlog v 4, server v 5.1.32-1-log created 090323 10:14:17
BINLOG '
SafHSQ8BAAAAZgAAAGoAAAAAAAQANS4xLjMyLTEtbG9nAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
'/*!*/;
# at 16267379
ERROR: Error in Log_event::read_log_event(): 'Sanity check failed', data_len: 939008, event_type: 73
ERROR: Could not read entry at offset 16268115: Error in log format or read error.
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

There are no entries in the error log. (mysql.err is empty, daemon.log contains no entries for today)

again, let me know if there's anything more I can provide.

thanks!

Adrian
[25 Mar 2009 21:20] Adrian Rollett
OK, it's happened again - binlog snippet:

mysql1:/var/log/mysql# mysqlbinlog mysql-bin.000076|tail -25
ERROR: Error in Log_event::read_log_event(): 'Sanity check failed', data_len: 1770752, event_type: 73
ERROR: Could not read entry at offset 57240386: Error in log format or read error.
INSERT INTO accesslog (title, path, url, hostname, uid, sid, timer, timestamp) values('Office Communicator Client Download', 'node/400', 'http://messaging.unt.edu/node/400', '172.20.1.205', 4, 'd27faa99e1e628ddbbb54169929d014f', 383, 1237993415)
/*!*/;
# at 57239210
#090325 10:03:35 server id 1  end_log_pos 57239442  Query thread_id=367028 exec_time=0 error_code=0
SET TIMESTAMP=1237993415/*!*/;
UPDATE sessions SET uid = 4, cache = 0, hostname = '172.20.1.205', session = '', timestamp = 1237993415 WHERE sid = 'd27faa99e1e628ddbbb54169929d014f'
/*!*/;
# at 57239442
#090325 10:03:35 server id 1  end_log_pos 57239574  Query thread_id=367028 exec_time=0 error_code=0
SET TIMESTAMP=1237993415/*!*/;UPDATE users SET access = 1237993415 WHERE uid = 4
/*!*/;
# at 57239574
#090325 10:03:35 server id 1  end_log_pos 57239650  Query thread_id=367030 exec_time=0 error_code=0
use iase_unt_edu/*!*/;
SET TIMESTAMP=1237993415/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=192,@@session.collation_server=8/*!*/;
BEGIN
/*!*/;
# at 57239650
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

I will attach the mysql query log for thread id 367030 separately - I find it very interesting that the same DB was being accessed when this happened again. Could it have anything to do with these lines being issued when the table collations are set to latin1_swedish_ci?

                367030 Query    SET NAMES utf8
                367030 Query    SET collation_connection = 'utf8_unicode_ci'
[25 Mar 2009 21:22] Adrian Rollett
367030.log

Attachment: 367030.log (application/octet-stream, text), 2.44 KiB.

[26 Mar 2009 14:25] Adrian Rollett
Another tidbit: Binlogging broke again this morning, again after these statements:

                91972 Connect   xxxxxxx@mysql1.cws.private.unt.edu on 
                91972 Query     SELECT VERSION()
                91972 Query     SET NAMES utf8
                91972 Query     SET collation_connection = 'utf8_unicode_ci'
                91972 Query     SET NAMES utf8
                91972 Query     SET collation_connection = 'utf8_unicode_ci'

When I tried to change the 'proposal' table in the offending database to utf8_unicode_ci collation with the following query:

ALTER TABLE proposals CONVERT TO CHARACTER SET 'utf8' COLLATE 'utf8_unicode_ci'

I get this error message:

#1118 - Row size too large. The maximum row size for the used table type, not counting BLOBs, is 65535. You have to change some columns to TEXT or BLOBs 

Could it be that when the user sets the text collation to utf8_unicode_ci in their session, binlogging is breaking because the row size returned is larger than expected? (perhaps causing a buffer overflow?)

I will attach the referenced table's structure.
[26 Mar 2009 14:27] Adrian Rollett
proposals table structure

Attachment: proposals_structure.txt (text/plain), 12.51 KiB.

[27 Mar 2009 9:58] Sveta Smirnova
Thank you fro the feedback.

I can not repeat described behavior. Please try MySQL 5.1.32 binaries available at http://dev.mysql.com/downloads and inform us if problem still exists.

> There are no entries in the error log. (mysql.err is empty

Please add option log-error to your configuration file, then restart the server, so we can see what happened when same error occurs next time.

> #1118 - Row size too large. 

This error is irrelevant. Please consult MySQL user manual for reason why you get it.
[27 Mar 2009 14:24] Adrian Rollett
Ok, I've managed to reproduce the problem with the official binaries:

Steps to reproduce:

Using the official mysql-5.1.32 binaries with my.cnf:

---
[mysqld]
log_bin                 = /var/log/mysql/mysql-bin.log
max_binlog_size         = 100M
binlog_format           = mixed
---

webmail:/usr/local/mysql# ./bin/mysql -e 'CREATE DATABASE binlogging_test'
webmail:/usr/local/mysql# ./bin/mysql binlogging_test < proposals.sql
webmail:/usr/local/mysql# ./bin/mysql
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 6
Server version: 5.1.32-log MySQL Community Server (GPL)

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> use binlogging_test;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> SET names utf8;
Query OK, 0 rows affected (0.00 sec)

mysql> SET collation_connection = 'utf8_unicode_ci';
Query OK, 0 rows affected (0.00 sec)

mysql> update proposals SET `Title` = 'Cancel', `Abstract` = '', `Session` = '', `ProgramDescription` = '', `SurName1` = '', `FirstName1` = '', `LastName1` = '', `Position1` = '', `EmployAgency1` = '', `StreetAddress1` = '', `City1` = '', `State1` = '', `Country1` = '', `ZipCode1` = '', `PhoneNumber1` = '', `EmailWork1` = '', `SummerEmail1` = '', `SummerPhone1` = '', `SessionType` = '0', `SessionDate` = '0', `SessionTime` = '1000' WHERE `proposals`.`Index` = 74 LIMIT 1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> Bye

After the last query, the binlog is broken and no further statements can be read:

webmail:/var/log/mysql# /usr/local/mysql/bin/mysqlbinlog mysql-bin.000005 |tail
ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 162816, event_type: 73
SET @@session.sql_mode=0/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=192,@@session.collation_server=8/*!*/;
BEGIN
/*!*/;
# at 17436
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

It appears to keep logging, as the binlog file grows in size, but obviously it's useless for replication...
I will attach proposals.sql and mysql-bin.000005 separately.
[27 Mar 2009 14:26] Adrian Rollett
proposals.sql

Attachment: proposals.sql (application/octet-stream, text), 16.94 KiB.

[27 Mar 2009 14:27] Adrian Rollett
mysql-bin.000005

Attachment: mysql-bin.000005 (application/octet-stream, text), 18.61 KiB.

[31 Mar 2009 11:34] Susanne Ebrecht
I could reproduce it. In any case this problem only occurs because you have too many columns per table and too long queries.

Please read:
http://dev.mysql.com/doc/refman/5.1/en/column-count-limit.html

A workaround would be to normalise your database.

In any case bin-log/slave should not crash because of too long queries or too much columns whithout master throwing errors or warnings.

Verified like descibed by using actual bzr tree of MySQL 5.1 (5.1.35)

How to repeat:

Open the proposal.sql file given above in an editor.

Copy the create table statement into CLI.

Copy the insert statement into CLI.

After that slave crashes here.
[31 Mar 2009 13:49] Adrian Rollett
Hi Susanne,

thanks very much for taking a look - I'm aware of the row width limitations, but we run a shared hosting environment at our University with thousands of customers, and we don't have any control over their DB design choices. (or no more than MySQL itself enforces) I'm going to try and meet with the owner of this table and modify their table, but for all I know, there are 10 or 20 more tables like it out there...

Is there any ETA for a fix at this time?

viel danken,

Adrian
[21 Apr 2009 13:49] Adrian Rollett
Hi folks, 

any word on a fix? It's been several weeks, and we're still experiencing the problem, even after modifying the table in question and changing the largest columns to the TEXT type...

thanks!
[14 May 2009 17:03] Luis Soares
See also BUG#42749. This one seems duplicate.