MySQL Bugs: #51426: User var unsigned_flag value not preserved until binlog time

Bug #51426	User var unsigned_flag value not preserved until binlog time
Submitted:	23 Feb 2010 15:57	Modified:	4 Aug 2010 12:16
Reporter:	Matthias Leich	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	5.1.44,5.5.99-m3	OS:	Any
Assigned to:	Luis Soares	CPU Architecture:	Any
Tags:	auto_increment, mixed, statement

Description:
My script:
----------
--source include/master-slave.inc
--source include/have_binlog_format_mixed_or_statement.inc

--disable_abort_on_error

# A better SQL_MODE avoids the problem
# SET SESSION SQL_MODE='STRICT_ALL_TABLES';

CREATE TABLE t1 ( pk INT AUTO_INCREMENT, col1 BIGINT, PRIMARY KEY (pk));
CREATE TRIGGER tr1 AFTER INSERT ON t1 FOR EACH ROW SET @aux = 1 ;

SET @aux = 10294947273192243200;
INSERT INTO t1 ( pk , col1 ) VALUES ( @aux , 1 ) , ( 20030914140121 , 2 );

--connection master
--sync_slave_with_master

Result on 5.5.99-m3
mysql-next-mr revno: 3097 2010-02-22
------------------------------------
./mysql-test-run  --mem --mysqld=--binlog-format=mixed rpl_ml5
....
main.rpl_ml5                             [ fail ]
...
=== SHOW SLAVE STATUS ===
Last_Errno  0
Last_Error  Query caused different errors on master and slave.     Error on master: 'Duplicate entry '%-.192s' for key %d' (1062), Error on slave: 'no error' (0). Default database: 'test'. Query: 'INSERT INTO t1 ( pk , col1 ) VALUES ( @aux , 1 ) , ( 20
030914140121 , 2 )'
....

I get the same bug for
- statement based replication
- 5.1.44
  mysql-5.1 revno: 3315 2010-01-15

Strange observation:
--------------------
The content of @aux is after SET @aux = ...
10294947273192243200 .
The binary logs show a
   "@`aux`=-8151796800517308416" .
Of course 10294947273192243200 is outside of
the possible value rang of INT and in
SQL_MODE=='' happens finally a mangling of
the value so that it fits inside the range.
But why from a huge positive number to
a huge negative one and not to the maximum
positive number.

Workarounds:
------------
1. Use ROW based replication
or
2. SET SESSION SQL_MODE='STRICT_ALL_TABLES'; 

How to repeat:
See above

See also: BUG#49562.

My notes on this bug analysis:

In BUG#49562 we fixed the case where numeric user var events
would not serialize the flag stating whether the value was signed
or unsigned. This fixed the case that the slave would get an
overflow while treating the unsigned values as signed.

After BUG#49562 fix, a similar defective behavior is reported in
in this bug report. In the test case presented, I find that the
user variable @aux is set to 10294947273192243200 and then
inserted into an INT typed column, which causes overflow while
logging the user var log event, suggesting that the unsigned flag
is not being properly replicated. Given BUG 49562 fix, I would
not expect this to happen.

The problem reported stems from the fact that the value of @aux
is affected in a trigger declared on the table on which @aux is
inserted:

CREATE TRIGGER tr1 AFTER INSERT ON t1 FOR EACH ROW SET @aux = 1 ;

This makes the unsigned flag to change at the time the INSERT is
binlogged. Details follow.

Checking how user variables are stored and binlogged, I find
that:
 
  1. For runtime purposes, user variables are stored in
     THD::user_vars, which holds user_var_entry instances.

  2. For binlog purposes, user variables are tracked in
     THD::user_var_events, which holds BINLOG_USER_VAR_EVENT

  3. a BINLOG_USER_VAR_EVENT instance, copies part of a
     user_var_entry instance information (eg, the var value) and
     also keeps a pointer to the user_var_entry instance

  4. At binlogging time the User_var_log_event instantiated using
     contents from a BINLOG_USER_VAR_EVENT instance and the
     user_var_entry instance it references.

  5. One of the user_var_entry information that is taken is the
     unsigned_flag value.

Taking items #1..#5 into consideration, and looking at the test
case, we find that the INSERT will fire a trigger that changes
the value of @aux variable from 10294947273192243200 to 1. This
seems harmless, but in fact changes the unsigned_flag in @aux's
user_var_entry instance from "true" to "false". Now... Given that
the User_var_log_event is written to the binary log at the end of
the INSERT statement, it will be instantiated with the original
value: 10294947273192243200, but will take the value for the
unsigned_flag already set to "false" (because it picks it from
user_var_entry).

This is what is causing the failure.

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

2976 Luis Soares	2010-02-25
      BUG#51426: overflow for auto_increment column causes slave to stop
      
      In BUG#49562 we fixed the case where numeric user var events
      would not serialize the flag stating whether the value was signed
      or unsigned (unsigned_flag). This fixed the case that the slave
      would get an overflow while treating the unsigned values as
      signed.
      
      In this bug, we find that the unsigned_flag can sometimes change
      between the moment that the user value is recorded for binlogging
      purposes and the actual binlogging time. Since we take the
      unsigned_flag from the runtime variable data, at binlogging time,
      and the variable value is comes from the copy taken earlier in
      the execution, there may be inconsistency in the
      User_var_log_event between the variable value and its
      unsigned_flag.
      
      We fix this by also copying the unsigned_flag of the
      user_var_entry when its value is copied, for binlogging
      purposes. Later, at binlogging time, we use the copied
      unsigned_flag and not the one in the runtime user_var_entry
      instance.
     @ sql/item_func.cc
        Gets a copy of the unsigned_flag.
     @ sql/log.cc
        Sets the unsigned_flag from the copy instead of taking it
        from the user_var_entry instance.
     @ sql/sql_class.h
        Added unsigned_flag field to BINLOG_USER_VAR_EVENT.

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

2977 Luis Soares	2010-03-04
      BUG#51426
      
      Addressing review comments.
      Test case improvements.

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

2976 Luis Soares	2010-03-09
      BUG#51426: overflow for auto_increment column causes slave to stop
      
      In BUG#49562 we fixed the case where numeric user var events
      would not serialize the flag stating whether the value was signed
      or unsigned (unsigned_flag). This fixed the case that the slave
      would get an overflow while treating the unsigned values as
      signed.
      
      In this bug, we find that the unsigned_flag can sometimes change
      between the moment that the user value is recorded for binlogging
      purposes and the actual binlogging time. Since we take the
      unsigned_flag from the runtime variable data, at binlogging time,
      and the variable value is comes from the copy taken earlier in
      the execution, there may be inconsistency in the
      User_var_log_event between the variable value and its
      unsigned_flag.
      
      We fix this by also copying the unsigned_flag of the
      user_var_entry when its value is copied, for binlogging
      purposes. Later, at binlogging time, we use the copied
      unsigned_flag and not the one in the runtime user_var_entry
      instance.
      ******
      BUG#51426
      
      Addressing review comments.
      Test case improvements.
     @ sql/item_func.cc
        Gets a copy of the unsigned_flag.
     @ sql/log.cc
        Sets the unsigned_flag from the copy instead of taking it
        from the user_var_entry instance.
     @ sql/sql_class.h
        Added unsigned_flag field to BINLOG_USER_VAR_EVENT.

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

2998 Luis Soares	2010-03-17
      BUG#51426: overflow for auto_increment column causes slave to stop
      
      In BUG#49562 we fixed the case where numeric user var events
      would not serialize the flag stating whether the value was signed
      or unsigned (unsigned_flag). This fixed the case that the slave
      would get an overflow while treating the unsigned values as
      signed.
            
      In this bug, we find that the unsigned_flag can sometimes change
      between the moment that the user value is recorded for binlogging
      purposes and the actual binlogging time. Since we take the
      unsigned_flag from the runtime variable data, at binlogging time,
      and the variable value is comes from the copy taken earlier in
      the execution, there may be inconsistency in the
      User_var_log_event between the variable value and its
      unsigned_flag.
            
      We fix this by also copying the unsigned_flag of the
      user_var_entry when its value is copied, for binlogging
      purposes. Later, at binlogging time, we use the copied
      unsigned_flag and not the one in the runtime user_var_entry
      instance.
      ******
      Merge bundle from BUG 50442 bug report.

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

2998 Luis Soares	2010-03-17
      BUG#51426: overflow for auto_increment column causes slave to stop
      
      In BUG#49562 we fixed the case where numeric user var events
      would not serialize the flag stating whether the value was signed
      or unsigned (unsigned_flag). This fixed the case that the slave
      would get an overflow while treating the unsigned values as
      signed.
            
      In this bug, we find that the unsigned_flag can sometimes change
      between the moment that the user value is recorded for binlogging
      purposes and the actual binlogging time. Since we take the
      unsigned_flag from the runtime variable data, at binlogging time,
      and the variable value is comes from the copy taken earlier in
      the execution, there may be inconsistency in the
      User_var_log_event between the variable value and its
      unsigned_flag.
            
      We fix this by also copying the unsigned_flag of the
      user_var_entry when its value is copied, for binlogging
      purposes. Later, at binlogging time, we use the copied
      unsigned_flag and not the one in the runtime user_var_entry
      instance.

The previous three commits are pretty much the same. They are just 
about fixing commit message.

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

3183 Luis Soares	2010-03-17
      Cherrypicked fix for BUG#51426 from mysql-trunk and merged it
      in mysql-5.1-rep+2.
      
      Details:
       - orig tree: mysql-trunk-bugfixing
       - orig rev : revid:luis.soares@sun.com-20100317110853-me506o821ajn7lyn
       - dest tree: mysql-5.1-rep+2
      
      Commit Message:
      
      BUG#51426: overflow for auto_increment column causes slave to stop
            
      In BUG#49562 we fixed the case where numeric user var events
      would not serialize the flag stating whether the value was signed
      or unsigned (unsigned_flag). This fixed the case that the slave
      would get an overflow while treating the unsigned values as
      signed.
                  
      In this bug, we find that the unsigned_flag can sometimes change
      between the moment that the user value is recorded for binlogging
      purposes and the actual binlogging time. Since we take the
      unsigned_flag from the runtime variable data, at binlogging time,
      and the variable value is comes from the copy taken earlier in
      the execution, there may be inconsistency in the
      User_var_log_event between the variable value and its
      unsigned_flag.
                  
      We fix this by also copying the unsigned_flag of the
      user_var_entry when its value is copied, for binlogging
      purposes. Later, at binlogging time, we use the copied
      unsigned_flag and not the one in the runtime user_var_entry
      instance.

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100324081249-yfwol7qtcek6dh7w) (version source revid:alik@sun.com-20100324081113-kc7x1iytnplww91u) (merge vers: 6.0.14-alpha) (pib:16)

Pushed into 5.5.4-m3 (revid:alik@sun.com-20100324081056-6bndv6f0nrvbblhp) (version source revid:alik@sun.com-20100324081056-6bndv6f0nrvbblhp) (merge vers: 5.5.4-m3) (pib:16)

Pushed into mysql-next-mr (revid:alik@sun.com-20100324081159-5b8juv8ldiqwce8v) (version source revid:alik@sun.com-20100324081105-y72rautcea375zxm) (pib:16)

Documented bugfix in the 5.5.4 and 6.0.14 changelogs as follows:

        The flag stating whether a user value was signed or unsigned
        (unsigned_flag) could sometimes change between the time that 
        the user value was recorded for logging purposes and the time 
        that the value was actually written to the binary log, which could 
        lead to inconsistency. Now unsigned_flag is copied when the user
        variable value is copied, and the copy of unsigned_flag is then used 
        for logging.

Set NM status - waiting for 5.1.

5.5.4 changelog entry was moved to 5.5.5.

Closing: No 5.1.x changelog entry needed.

Pushed into mysql-next-mr (revid:alik@sun.com-20100615080558-cw01bzdqr1bdmmec) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (pib:16)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804080001-bny5271e65xo34ig) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (merge vers: 5.1.47) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804081533-c1d3rbipo9e8rt1s) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (merge vers: 5.1.47) (pib:18)

Changelog entry added for 5.6.1. Closed.

5.6 version is 5.6.0 not 5.6.1 - fixed changelog entry.