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: | |
Category: | MySQL Server: Replication | Severity: | S1 (Critical) |
Version: | 5.1 | OS: | Linux |
Assigned to: | Luis Soares | CPU Architecture: | Any |
Tags: | binlog, mysqlbinlog, replication |
[23 Mar 2009 19:01]
Adrian Rollett
[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.