MySQL Bugs: #54452: mysqlbinlog -vv crashed but the binlog can be applied properly

Bug #54452	mysqlbinlog -vv crashed but the binlog can be applied properly
Submitted:	12 Jun 2010 4:03	Modified:	16 Jul 2010 10:58
Reporter:	Yuan WANG	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: Row Based Replication ( RBR )	Severity:	S2 (Serious)
Version:	5.1.41, 5.1.49-bzr, 5.5.5-m3	OS:	Any (Linuux 2.6.18-6-amd64, Mac OS X)
Assigned to:	Luis Soares	CPU Architecture:	Any
Tags:	Contribution

Description:
We have developed a storage engine which use row-based replication. Recently in test we found that if we try to parse the content of the binlogs with -vv option (that is, print out the explanatory sql statement), it will crash. However, if -vv is not used, it will not crash. And we can apply this binlog to the database, and the end result is correct. So we think the content of the binlog should be corrent and there should be a bug in mysqlbinlog only when -vv option is given.

One of the problematic binlog file is given in the attachment. The schema of the target table is (NTSE is the name of our storage engine):

CREATE TABLE `Blog` (
  `ID` bigint(20) NOT NULL,
  `UserID` bigint(20) DEFAULT NULL,
  `Title` varchar(255) DEFAULT NULL,
  `Abstract` varchar(2000) DEFAULT NULL,
  `Content` mediumtext,
  `AllowView` smallint(6) DEFAULT NULL,
  `PublishTime` bigint(20) DEFAULT NULL,
  `AccessCount` int(11) DEFAULT NULL,
  `CommentCount` int(11) DEFAULT NULL,
  PRIMARY KEY (`ID`),
  KEY `IDX_BLOG_UID_PUBTIME` (`UserID`,`PublishTime`,`AllowView`)
) ENGINE=NTSE DEFAULT CHARSET=utf8

How to repeat:
Try to parse the attachment.

One of our problematic binlog file

Attachment: mysql-bin.000006 (, text), 363.65 KiB.

Another smaller problematic binlog file

Attachment: mysql-bin.000015 (, text), 19.88 KiB.

It seems that the problem is the follow code in Rows_log_event::print_verbose_one_row() get the wrong number of bytes of the null bitmap.
  value+= (m_width + 7) / 8;

The code above thinks that number of bytes of the null bitmap is (m_width + 7) / 8, however, it should be:
  size_t const master_null_byte_count= (bitmap_bits_set(cols) + 7) / 8;
which is used in pack_row() and unpack_row().

We change the code in Rows_log_event::print_verbose_one_row() to
  size_t const master_null_byte_count= (bitmap_bits_set(cols) + 7) / 8;
, then we can parse the binlogs without any problem.

Thank you for the bug report and suggested fix. Verified just as described with current 5.1.49 and mysql-trunk trees from bzr:

valeriy-kravchuks-macbook-pro:trunk openxs$ bin/mysqlbinlog -vv -uroot ~/Downloads/mysql-bin.000015 
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#100612  8:38:17 server id 1  end_log_pos 106 	Start: binlog v 4, server v 5.1.41-debug-log created 100612  8:38:17 at startup
ROLLBACK/*!*/;
BINLOG '
SR0TTA8BAAAAZgAAAGoAAAAAAAQANS4xLjQxLWRlYnVnLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAABJHRNMEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
'/*!*/;
# at 106
#100612  8:38:17 server id 1  end_log_pos 170 	Query	thread_id=0	exec_time=69	error_code=0
SET TIMESTAMP=1276321097/*!*/;
SET @@session.pseudo_thread_id=0/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=0/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 170
# at 227
Segmentation fault

NOTES
=====

  N1. I could not come up with a binary log that would cause the
      crash in mysqlbinlog for 5.1. 

  N2. I investigated the binary log provided and found out that the
      bitmaps for the update event (the first in the binary log) were
      not fully set for (at least) the before image (BI). In 5.1, the
      entire images (Before and After images - BI and AI) are always
      logged (consequently, their bitmaps are fully set).

  N3. In the obsolete mysql-6.0-codebase, there was an optimization to
      only log partial images, according to the fields needed - to
      find and to update/write the row at the slave. I tried to run a
      test case with a table with a similar structure to the one in
      the bug report [1]. Alghough I did not run into a crash, I did
      run into incoherent output from mysqlbinlog -vv.

  N4. Given that WL#5092 implements partial and full images logging -
      based on some 6.0 backports, I tried the same test case used in
      N3. It also failed to output the correct data.

  N5. Applying the proposed patch, fixes this.

QUESTIONS
=========

  Q1. Yuan, is it the case that your engine is tampering with the
      table->read/write_set? If not, can you provide a deterministic
      test case for 5.1?

REFERENCES
==========

[1] Sketch of the test case:

-- source include/have_binlog_format_row.inc

CREATE TABLE t1 (
  c1 bigint(20) NOT NULL,
  c2 bigint(20) DEFAULT NULL,
  c3 varchar(255) DEFAULT NULL,
  c4 varchar(2000) DEFAULT NULL,
  c5 mediumtext,
  c6 smallint(6) DEFAULT NULL,
  c7 bigint(20) DEFAULT NULL,
  c8 int(11) DEFAULT NULL,
  c9 int(11) DEFAULT NULL,
  PRIMARY KEY (c1),
) ENGINE=MyISAM DEFAULT CHARSET=utf8;

INSERT INTO t1 VALUES (1,2,'3','4','5',6,7,8,9);
INSERT INTO t1(c1,c4) VALUES (2,'aaaaaaaaaaaaa');
UPDATE t1 SET c9=1;
FLUSH LOGS;

--let $MYSQLD_DATADIR=`select @@datadir`
--exec $MYSQL_BINLOG -vv $MYSQLD_DATADIR/master-bin.000001
-- exit

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".