MySQL Bugs: #58186: binlogs are broken

Bug #58186	binlogs are broken
Submitted:	14 Nov 2010 19:20	Modified:	15 Nov 2010 20:54
Reporter:	Kiryl Hakhovich	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: General	Severity:	S2 (Serious)
Version:	5.1.32	OS:	Linux (Fedora Core 13 x86_64)
Assigned to:		CPU Architecture:	Any
Tags:	binlog, mysqlbinlog, replication

Description:
we have this odd problems, slave was unable to read relay logs from master.
we started looking at master, turned out master can't parse bin logs either.

mysql was compiled from source with:
./configure --with-plugins=innobase prefix=/usr --with-ssl --with-big-tables --with-pthread --enable-profiling --enable-assembler

filesystem: ext4

[root@master works]# mysqlbinlog -vv mysql-bin-102.000001 -H
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#101113  7:45:21 server id 101  end_log_pos 106 
# Position  Timestamp   Type   Master ID        Size      Master Pos    Flags 
#        4 61 88 de 4c   0f   65 00 00 00   66 00 00 00   6a 00 00 00   00 00
#       17 04 00 35 2e 31 2e 33 32  2d 6c 6f 67 00 00 00 00 |..5.1.32.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 61 88 de 4c  13 38 0d 00 08 00 12 00 |....a..L.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-log created 101113  7:45:21 at startup
ROLLBACK/*!*/;
BINLOG '
YYjeTA9lAAAAZgAAAGoAAAAAAAQANS4xLjMyLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAABhiN5MEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
'/*!*/;
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 534, event_type: 2
ERROR: Could not read entry at offset 106: Error in log format or read error.
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

here is my.cnf config

[root@master works]# cat /etc/my.cnf 
[mysqld]
datadir=/data/mysql/db/data
socket=/data/mysql/mysql.sock
user=mysql
max_connections=300 #lowered from 400
# Default to using old password format for compatibility with mysql 3.x
# clients (those using the mysqlclient10 compatibility package).
old_passwords=1
server-id=101
#### report-host=server6.expotv.local
max_allowed_packet=16M
ft_min_word_len=2
#slave_skip_errors=1452
query_cache_limit=5M
query_cache_size=4M
query_cache_type=1
key_buffer_size=64M #may need to increase to 200M, then check tune script to see mem allocation
sort_buffer_size=2M #lowered from 8, check show global status for sort_merge_passes, if not increases then leave this number small
read_rnd_buffer_size=5M #lowered from 10
read_buffer_size=2M #Lowererd from 8
table_cache=8192
join_buffer_size=3M
tmp_table_size=8M #Lowered from 16
max_heap_table_size=8M
innodb_buffer_pool_size = 5G
thread_cache_size=150
thread_concurrency=16
slow_query_log=1
slow_query_log_file=/var/log/mysql/mysql_slow_q.log
long_query_time=1
log-queries-not-using-indexes
log-warnings
query_cache_min_res_unit=1024
wait_timeout=600
innodb_force_recovery = 0
innodb_log_group_home_dir = /data/mysql/logs
innodb_file_per_table
innodb_log_file_size=250M
innodb_log_buffer_size=8M
#slave-skip-errors=1062
innodb_flush_log_at_trx_commit=1
innodb_lock_wait_timeout=50
log-bin=/data/mysql/works/mysql-bin-102
expire_logs_days=5
#with-charset=utf8

#a few new vars...
low_priority_updates=1
concurrent_insert=2

ssl-ca=/etc/mysql/ssl/ca-cert.pem
ssl-cert=/etc/mysql/ssl/server-cert.pem
ssl-key=/etc/mysql/ssl/server-key.pem

[mysqld_safe]
log-error=/var/log/mysql/mysqld.log
pid-file=/data/mysql/mysqld.pid

[client]
socket=/data/mysql/mysql.sock

How to repeat:
minimal FC13 installation, on DELL PowerEdge R710

mysql 5.1.32

./configure --with-plugins=innobase prefix=/usr --with-ssl --with-big-tables --with-pthread --enable-profiling --enable-assembler

Suggested fix:
n/a

zipped small bin log file that can't be parsed by mysqlbinlog tool on the box

Attachment: mysql-bin-102.000001.gz (application/x-gzip, text), 49.72 KiB.

Hi Kiryl,

5.1.32 is ancient.  There are numerous binlog corruption bugs fixed since then.

You should consider testing a modern version, such as 5.1.52.
Also, check master mysql error logs to be sure mysqld isn't crashing, thereby causing a corrupted binlog.

thanks for response. mysql does not crash according to mysqld.log.

when upgrading to this minor revision, should i also do table_upgrade step or can that be omitted in this case?

thanks.

okay. i have compiled 5.1.52 on this box, running the mtr --suite=binlog fail with following:

binlog.binlog_auto_increment_bug33029 'row' [ fail ]
        Test ended at 2010-11-15 11:28:52

CURRENT_TEST: binlog.binlog_auto_increment_bug33029
mysqltest: At line 26: command "copy_file" failed with error 1

The result from queries just before the failure was:
SET @old_relay_log_purge= @@global.relay_log_purge;

 - saving '/opt/mysql/mysql-test/var/log/binlog.binlog_auto_increment_bug33029-row/' to '/opt/mysql/mysql-test/var/log/binlog.binlog_auto_increment_bug33029-row/'

Only  72  of 122 completed.
mysql-test-run: *** ERROR: Not all tests completed

(previos version 5.1.32 was failing at a different test of mtr)

please advice.

thank you

to confirm:

for version 5.1.52 compile with following options solves the issue

CC='gcc'  CFLAGS=' -g -O2   -DUNIV_LINUX -DUNIV_LINUX'  CXX='g++'  CXXFLAGS='-O3    -fno-implicit-templates -fno-exceptions -fno-rtti'  LDFLAGS=' -rdynamic '  ASFLAGS='' ./configure  '--with-plugins=innobase' 'prefix=/usr' '--with-ssl' '--with-big-tables' '--with-pthread' '--enable-profiling' '--enable-assembler'

same options compile for 5.1.32 still breaks in mtr test for binlogsuite.

hope this help to anyone.

Hi I use the later version than 5.1.52.

But why is that I'm getting the same error when I use RBL on Linux version too?
+-------------------------+------------------------------+
| Variable_name           | Value                        |
+-------------------------+------------------------------+
| protocol_version        | 10                           |
| version                 | 5.1.61-log                   |
| version_comment         | MySQL Community Server (GPL) |
| version_compile_machine | i686                         |
| version_compile_os      | pc-linux-gnu                 |
+-------------------------+------------------------------+

Below is the err msg.

-bash-3.2$ mysqlbinlog /usr/local/mysql1_base/snapshot/mysql1_masterbin.000001 > rast.sql
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 80, event_type: 19
Could not read entry at offset 1133:Error in log format or read error

Regards,
Mannoj

Ignore the above one. I kinda fixed it. Forgotten that it was fixed.., and posted the same.. sorry for the trouble !!