MySQL Bugs: #53643: assert in Field_new_decimal::store

Bug #53643	assert in Field_new_decimal::store_value on slave server
Submitted:	14 May 2010 10:43	Modified:	15 Nov 2010 13:08
Reporter:	Matthias Leich	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Row Based Replication ( RBR )	Severity:	S3 (Non-critical)
Version:	mysql-5.1-rpl-wl5092	OS:	Any
Assigned to:	Luis Soares	CPU Architecture:	Any
Tags:	assert, decimal

Description:
The assert happens in sql/field.cc line 2624
bool Field_new_decimal::store_value(const my_decimal *decimal_value)
{
  ASSERT_COLUMN_MARKED_FOR_WRITE; <--------------
  int error= 0;
  DBUG_ENTER("Field_new_decimal::store_value");
  ...

This bug is not relevant for users of official MySQL trees.
It requires a "SET SESSION BINLOG_ROW_IMAGE = minimal;"
which is part of WL#5092. And this WL is not pushed yet.

My script:
----------
--source include/master-slave.inc
--source include/have_innodb.inc
--disable_abort_on_error

# The assert disappears in case                        or
# - t0 uses MyISAM instead of InnoDB                   or
# - PRIMARY KEY (col1) from t1 is removed              or
# - col3 CHAR(35) instead of col3 DECIMAL(35,0) for t1 or
# - SET SESSION BINLOG_ROW_IMAGE = minimal; is removed

CREATE TABLE t0 ( col1 INT NOT NULL, col2 INT ) ENGINE=InnoDB;
INSERT INTO t0 (col1,col2) VALUES (4,7),(4,8);

CREATE TABLE t1 (
  col3 DECIMAL(35,0) DEFAULT NULL,
  col1 INT NOT NULL,
  col2 INT NOT NULL DEFAULT '0',
  PRIMARY KEY (col1)
) ENGINE=MyISAM DEFAULT CHARSET=latin1 ;

SET SESSION BINLOG_ROW_IMAGE = minimal;

# This statement leads to an assert on slave.
REPLACE INTO t1 ( col1,col2) SELECT col1,col2 FROM t0;

Result on mysql-5.1-rpl-wl5092:
-------------------------------
...
main.rpl_ml1                             [ fail ]
...
100514 13:03:25 [Note] next log './slave-relay-bin.000003' is currently active
mysqld: field.cc:2624: bool Field_new_decimal::store_value(const my_decimal*): Assertion `!table || (!table->write_set || bitmap_is_set(table->write_set, field_index))' failed.
100514 13:03:25 - mysqld got signal 6 ;
...
Thread 1 (process 5011):
#0  0x00007ffab187cce6 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000b2973f in my_write_core (sig=6) at stacktrace.c:329
#2  0x00000000006c01c1 in handle_segfault (sig=6) at mysqld.cc:2580
#3  <signal handler called>
#4  0x00007ffab0a855c5 in raise () from /lib64/libc.so.6
#5  0x00007ffab0a86bb3 in abort () from /lib64/libc.so.6
#6  0x00007ffab0a7e1e9 in __assert_fail () from /lib64/libc.so.6
#7  0x000000000069670b in Field_new_decimal::store_value (this=0x198f210, decimal_value=0x11795a0) at field.cc:2624
#8  0x0000000000697174 in Field_new_decimal::reset (this=0x198f210) at field.cc:2579
#9  0x00000000007d86a1 in unpack_row (rli=0x19428e0, table=0x1972d18, colcnt=3, row_data=0x18fa5bd "ù\004", cols=0x19544a0, row_end=0x1954510, master_reclength=0x19544c0, abort_on_warning=false, first_row=false) at rpl_record.cc:298
#10 0x00000000007d7697 in Rows_log_event::unpack_current_row (this=0x1954418, rli=0x19428e0, cols=0x19544a0, abort_on_warning=false) at log_event.h:3634
#11 0x00000000007c06c9 in Update_rows_log_event::do_exec_row (this=0x1954418, rli=0x19428e0) at log_event.cc:9698
#12 0x00000000007cac49 in Rows_log_event::do_apply_event (this=0x1954418, rli=0x19428e0) at log_event.cc:7646
#13 0x00000000008807f8 in Log_event::apply_event (this=0x1954418, rli=0x19428e0) at log_event.h:1125
#14 0x0000000000878115 in apply_event_and_update_pos (ev=0x1954418, thd=0x196dcf8, rli=0x19428e0) at slave.cc:2256
#15 0x000000000087998d in exec_relay_log_event (thd=0x196dcf8, rli=0x19428e0) at slave.cc:2416
#16 0x000000000087a721 in handle_slave_sql (arg=0x19414f0) at slave.cc:3196
#17 0x00007ffab1878040 in start_thread () from /lib64/libpthread.so.0
#18 0x00007ffab0b2608d in clone () from /lib64/libc.so.6
#19 0x0000000000000000 in ?? ()

How to repeat:
Please compile MySQL with debug, store the test from above
as t/rpl_ml1.test and run
./mysql-test-run --mysqld=--log_bin=on --mysqld=--binlog-format=mixed \
--skip-ndbcluster --mem rpl_ml1

Analysis
========

  Symptom
  ~~~~~~~

  While unpacking a row, the server calls f->reset() for nullable
  fields, ie, for fields that are later set to
  null (f->set_null()). This means that for the test case
  depicted, and for decimal types an assertion is faced because
  the table->write_set was not properly initialised before the
  procedure to unpack the row takes place.

  Calling Field_decimal::reset would ultimately make
  Field_decimal::store_value be called, which in its turn would
  check if the column being (re)set was marked in the
  table->write_set (this is the actual assertion).

  Given that the table->write_set was not conveniently
  initialised before unpacking, the bit for the given decimal
  column would not be set. As a consequence, the assertion would
  be triggered.

  Reason
  ~~~~~~

  The table->write_set was not properly initialised because it
  was being calculated from the event's read_set bitmap instead
  of the write_set bitmap in some cases. Initialisation takes
  place before the rows execution loop:
 
     log_event.cc:Rows_log_event::do_apply_event

  and at that point, write_set was being set from m_cols instead
  of m_cols_ai. This would work for Write_rows_event or
  Delete_event (the former just has one image, after image, and
  the m_cols is actually the write_set, while the latter also
  just has one image, before image, and m_cols is the read_set -
  for deletes the write_set is useless). The problem surfaces in
  the Update_rows_event, which uses both m_cols and m_cols_ai
  which can be different (as this case proves it), and therefore,
  table->read/write_set must be initialised according to the
  proper bitmap.

  Notes
  ~~~~~

  N1. Some fields types would not trigger this assertion because
      their reset method does not call store_value. Instead a
      simple assignment or memory cleanup is done. For example,
      for TINYINT:

        int reset(void) { ptr[0]=0; return 0; }

  N2. I don't think this is dependant of the engine for the
      reasons stated above. I have triggered the assertion even
      when using MyISAM in t0.

  N3. col3 CHAR(35) instead of col3 DECIMAL(35,0) for t1 does not
      trigger this assertion because the Field_string::reset does
      not resort to store_value for resetting the field.

  N4. If removing the PRIMARY KEY the REPLACE behaves as an
      INSERT and Write_rows_event(s) are used instead of Updates,
      thence the correct bitmap would be used (as inserts were
      not vulnerable).

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/108452

3187 Luis Soares	2010-05-17 [merge]
      BUG#53643: assert in Field_new_decimal::store_value on slave server
        
      The table->write_set at the slave was improperly set before
      processing a row event. For update events, it was being
      calculated from the event's read set instead of the event's 
      write_set.
        
      In some cases, this would lead to an assertion while unpacking
      and resetting decimal fields because the corresponding bit in
      the slave's table->write_set was incorrectly set.
        
      We fix this by properly initializing the read_set and write_set 
      before unpacking takes place.

Pushed into mysql-next-mr (revid:alexander.nozdrin@oracle.com-20101008132832-pbzewvmi9f365ak4) (version source revid:alexander.nozdrin@oracle.com-20101008132832-pbzewvmi9f365ak4) (pib:21)

Pushed into mysql-trunk 5.6.99-m5 (revid:alexander.nozdrin@oracle.com-20101113155825-czmva9kg4n31anmu) (version source revid:vasil.dimov@oracle.com-20100629074804-359l9m9gniauxr94) (merge vers: 5.6.99-m4) (pib:21)

Per MLeich's comments in Description, bug does not appear in any release versions. No changelog entry required. Closed.