MySQL Bugs: #65724: Mysqlbinlog coredumps when reading a binlog.

Bug #65724	Mysqlbinlog coredumps when reading a binlog.
Submitted:	25 Jun 2012 8:24	Modified:	5 Apr 2013 16:16
Reporter:	Andrea Brancatelli	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S1 (Critical)
Version:	5.5.24, 5.6.6, 5.5.27, 5.1.65, 5.0.97	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	coredump, extracting binary, mysqlbinlog

Description:
I'm currently trying to convert a binary log generated with Mysql 5.5.24 into an SQL file.

Midway during the process mysqlbinlog crashes with a segmentation fault (#11). The generated SQL is obviously incomplete.

I suppose the problem is related to the the DB containing many inserts into a longblog.

I was not able to find any workaround, I even tried to copy the binary log to another machine (also running 5.5.24) but the same problem happens.

I can share the binary log if needed, but it's 256MB big.

 Any help is appreciated.

Thank you.

[root@sac-v /repository/MySQL_Datas]# uname -a
FreeBSD sac-v.roma.schema31.it 9.0-RELEASE FreeBSD 9.0-RELEASE #0: Tue Jan  3 07:46:30 UTC 2012     root@farrell.cse.buffalo.edu:/usr/obj/usr/src/sys/GENERIC  amd64

[root@sac-v /repository/MySQL_Datas]# mysqlbinlog --version
mysqlbinlog Ver 3.3 for FreeBSD9.0 at amd64

[root@sac-v /repository/MySQL_Datas]# mysql --version
mysql  Ver 14.14 Distrib 5.5.24, for FreeBSD9.0 (amd64) using  5.2

How to repeat:

[root@sac-v /repository/MySQL_Datas]# mysqlbinlog mysql-bin.001012 > 1012.sql
Segmentation fault: 11 (core dumped)

Same thing happens coping the binary log to a Linux machine.

[root@curaro abrancatelli]# uname -a
Linux curaro.lavoripubblicilazio.it 2.6.43.2-6.fc15.x86_64 #1 SMP Sat Apr 21 12:53:32 UTC 2012 x86_64 x86_64 x86_64 GNU/Linux

[root@curaro abrancatelli]# mysql --version
mysql  Ver 14.14 Distrib 5.5.22, for Linux (x86_64) using readline 5.1

[root@curaro abrancatelli]# mysqlbinlog mysql-bin.001012 > 1012.sql
Errore di segmentazione

I have uploaded the binary log zipped in the FTP server.

Thank you for the report.

What is the name of file you uploaded?

Thank you for the feedback.

Verified as described.

Backtrace (version 5.5.27):

(gdb) bt
#0  0x000000000041d8c5 in User_var_log_event::print (this=0x97d410, file=0x31d778b780, print_event_info=0x7fffffffd800)
    at /home/sveta/src/mysql-5.5/sql/log_event.cc:5964
#1  0x000000000040b124 in process_event (print_event_info=0x7fffffffd800, ev=0x97d410, pos=185825266, logname=0x7fffffffe432 "mysql-bin.001012")
    at /home/sveta/src/mysql-5.5/client/mysqlbinlog.cc:1001
#2  0x000000000040cea8 in dump_local_log_entries (print_event_info=0x7fffffffd800, logname=0x7fffffffe432 "mysql-bin.001012")
    at /home/sveta/src/mysql-5.5/client/mysqlbinlog.cc:2023
#3  0x000000000040bc13 in dump_log_entries (logname=0x7fffffffe432 "mysql-bin.001012") at /home/sveta/src/mysql-5.5/client/mysqlbinlog.cc:1470
#4  0x000000000040d1da in main (argc=0, argv=0x97dcf0) at /home/sveta/src/mysql-5.5/client/mysqlbinlog.cc:2126

What's the uploaded file ID?

The problem is happening constantly on more than one server... Can I do anything to help speeding up the fix? Maybe you need any other binary log?

Andrea,

thank you for the feedback.

Since I could repeat the problem no new binary log file is needed.

We have many bug reports and have to prioritize work. This is why some bugs are fixed earlier and some are later.

Please be patient, or, if you have a MySQL subscription, please open a service request to help prioritize this based on your business needs.

Hello Sveta.

I have a good and a bad news for you :)

The good news is that I could track down without any doubt the origin of the problem.

Briefly: we load some binary files in our DB. We planned the system with MySQL 5.0 and Row Based Replication wasn't available yet and the LOAD_FILE() option wasn't Replication-Safe.

Our solution was to perform something like this:

SET @variable = LOAD_FILE('/tmp/something');
INSERT INTO table SET field = @variable;

This worked smoothly on 5.0.x for years.

Now we switched to 5.5.x and have been forced to increase the size limit for files we're saving in the DB. Actually our upload file limit has been pushed to 64MB.

The problem rises when the @variable gets filled with very long datas. To have all the problem disappear we took two different routes:

1) we switched to MIXED - but it didn't work out, because the LOAD_FILE wasn't triggering the ROW-repl, not being in the INSERT.
2) we changed our code removing the workaround and we just read the file in memory in our code and push the binary directly in the query. In PHP I'm talking about something like:

<?php
mysql_query("INSERT INTO table SET field = '".addslashes(readfile('/tmp/something'))."'");
?>

Obviously this allocates a bunch of memory in the server but we wanted to get rid of the problem.

And we got.

It's been 2 weeks and ALL our binlogs can be mysql-dumped without any problem. None of our binlog could be dumped before this fix.

That's the good news.

Now the bad one :-)

The bad one is that we could verify that the SAME problem happens with MySQL itself. It definitely has a lower impact (maybe there's something different in the way MySQL and MySQL Dump allocates memory) but we in the past we spuriously had our MySQL Slave crash with Segmentation Fault #11. It happened every couple of days on a different one... But since we changed that code it never happened any more even on MySQL Slave.

I understand that loading 64MB binary datas is a pretty uncommon pattern, but technically there's nothing preventing it...

A couple suggestion too:
1) We use UTF8
2) We have our BINLOG size set to 256MB
3) It doesn't seems to happen everytime. So don't expect you just bang in 64MB and it explodes.

I _suppose_ it could be related to the variable spanning across two different files? Sorry I could not dig it digger, but, hey, I'm not working for Oracle :-)

Warning:
There seems to be corruption even of OTHER variables in MySQL Slave when the previous problem arises. I mean, in the same code we used something like this on the MASTER

SET @variable = LAST_INSERT_ID();
INSERT INTO table SET parent_id = @variable;

It occasionally generated strange results (more often @variable being empty on the slave). Removing the "big" variable also fixed _THIS_ issue. I think there's some kind of memory corruption going on there.

Sorry for the long post :)

Hope this helps you.

Have a nice day.

Pushed into:
* mysql-5.1 (5.1.67)
* mysql-5.5 (5.5.29)
* mysql-5.6 (5.6.9)

In which version of MySQL NDB Cluster is that fixed ?