MySQL Bugs: #25628: mysqlbinlog crashes while processing binary logs

Bug #25628	mysqlbinlog crashes while processing binary logs
Submitted:	15 Jan 2007 14:47	Modified:	9 Mar 2007 14:23
Reporter:	Hartmut Holzgraefe	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.1.14-ndb-6.1.0-telco, 5.1bk, 5.1.12	OS:	Linux (linux)
Assigned to:	Guilhem Bichot	CPU Architecture:	Any
Tags:	bfsm_2007_01_18

Description:
trying to dump the contents of a customer provided binary log i had the mysqlbinlog binary die with a segmentation fault

the crash backtrace looks like this:

#0  0x400aa81b in strnmov (dst=0xbfc39a06 "\003@�-@\001", src=0x81b4 <Address 0x81b4 out of bounds>, n=22) at strnmov.c:20
#1  0x40095f61 in create_temp_file (to=0xbfc39a90 "2VkR��@�034>@iSeRQAAATZ", dir=0x408593 <Address 0x408593 out of bounds>, 
    prefix=0x81b4 <Address 0x81b4 out of bounds>, mode=514, MyFlags=16) at mf_tempfile.c:82
#2  0x400a66c1 in real_open_cached_file (cache=0xbfc3b288) at mf_cache.c:77
#3  0x400a495d in my_b_flush_io_cache (info=0xbfc3b288, need_append_buffer_lock=0) at mf_iocache.c:1668
#4  0x400a437b in _my_b_write (info=0xbfc3b288, 
    Buffer=0x809bf08 "MzljODlkYTUtMzI2MC00M2YyLTg1MDktYjEy\nMWJiMzEwMTM3BABJTVBJFQBTTTFzdWIyXzEwQG5vcnRlbC5jb20=", Count=89) at mf_iocache.c:1464
#5  0x400a5968 in my_b_vprintf (info=0xbfc3b288, fmt=0x8064fcf "s\n", args=0xbfc39e2c "\020") at mf_iocache2.c:366
#6  0x400a56a8 in my_b_printf (info=0xbfc3b288, fmt=0x8064fce "%s\n") at mf_iocache2.c:284
#7  0x080574fa in Log_event::print_base64 (this=0x809bdf0, file=0xbfc3b288, print_event_info=0xbfc3af90, more=true) at log_event.cc:1172
#8  0x0805d882 in Rows_log_event::print_helper (this=0x809bdf0, file=0x80694a8, print_event_info=0xbfc3af90, name=0x80642e2 "Write_rows")
    at log_event.cc:5985
#9  0x0805fb30 in Write_rows_log_event::print (this=0x809bdf0, file=0x80694a8, print_event_info=0xbfc3af90) at log_event.cc:6723
#10 0x0805b42d in process_event (print_event_info=0xbfc3af90, ev=0x809bdf0, pos=59761) at mysqlbinlog.cc:667
#11 0x0805ecf2 in dump_local_log_entries (logname=0xbfc3d1a2 "/home/hartmut/new/site1_dbrepl2_binlog.000001") at mysqlbinlog.cc:1424
#12 0x0805f2cf in dump_log_entries (logname=0xbfc3d1a2 "/home/hartmut/new/site1_dbrepl2_binlog.000001") at mysqlbinlog.cc:996
#13 0x0805f50b in main (argc=0, argv=0x8069670) at mysqlbinlog.cc:1507

the actual reason for the crash seems to be real_open_cache_file() trying to access IO_CACHE dir and prefix elements which are only initialized by open_cached_file() which is never called by mysqlbinlog though (or at least a breakpoint set on it is never triggered ...)

How to repeat:
get the attached binlog file and try

mysqlbinlog site1_dbrepl2_binlog.000001

indeed I observed that this IO_CACHE has a problem, and I have asked Mats to tell me if we could get rid of it.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/19565

ChangeSet@1.2372, 2007-02-08 16:24:52+01:00, guilhem@gbichot3.local +6 -0
  Fix for BUG#25628: "mysqlbinlog crashes while processing binary logs".
  mysqlbinlog prints all row-based events of a single statement as a
  single "BINLOG" statement containing the concatenation of those events.
  Big (i.e. >64k) concatenations of row-based events
  (e.g. Write_rows_log_event) caused mysqlbinlog's IO_CACHE to overflow
  to a temporary file but the IO_CACHE had not been inited with
  open_cached_file(), so it tried to create a temporary file in
  an uninitialized directory (thus failing to create, then to write;
  some OS errors were printed, and it finally segfaulted).
  After fixing this, it appeared that mysqlbinlog was printing only
  a piece of big concatenations of row-based events (it printed
  at most the size of the IO_CACHE's buffer i.e. 64k); that caused data
  loss at restore. We fix and test that.
  Last, mysqlbinlog's printouts looked a bit strange with the informative
  header (#-prefixed) of groupped Rows_log_event all on one line,
  so we insert \n. After that, a small bug in the --hexdump code appeared
  (only if the string to hex-print had its length a multiple of 16),
  we fix it.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/20506

ChangeSet@1.2413, 2007-02-23 22:23:54+01:00, gbichot@dl145h.mysql.com +6 -0
  Fix for BUG#25628: "mysqlbinlog crashes while processing binary logs".
  mysqlbinlog prints all row-based events of a single statement as a
  single "BINLOG" statement containing the concatenation of those events.
  Big (i.e. >64k) concatenations of row-based events
  (e.g. Write_rows_log_event) caused mysqlbinlog's IO_CACHE to overflow
  to a temporary file but the IO_CACHE had not been inited with
  open_cached_file(), so it tried to create a temporary file in
  an uninitialized directory (thus failing to create, then to write;
  some OS errors were printed, and it finally segfaulted).
  After fixing this, it appeared that mysqlbinlog was printing only
  a piece of big concatenations of row-based events (it printed
  at most the size of the IO_CACHE's buffer i.e. 64k); that caused data
  loss at restore. We fix and test that.
  Last, mysqlbinlog's printouts looked a bit strange with the informative
  header (#-prefixed) of groupped Rows_log_event all on one line,
  so we insert \n. After that, a small bug in the --hexdump code appeared
  (only if the string to hex-print had its length a multiple of 16),
  we fix it.

pushed into the replication team tree mysql-5.1-rpl.
There were two bugs when a statement inserted/updated/deleted a lot of data in row-based binary logging:
- not all changes were recorded into the binlog (=> data loss on the slave or on restore from mysqlbinlog)
- mysqlbinlog would show OS errors or even crash, if run on the binlog.
"A lot of data" means ~ tens of kilobytes or more.

pushed to 5.1.17-beta

A note has been added to the 5.1.17 changelog.