Bug #28086 SBR of USER() becomes corrupted on slave
Submitted: 25 Apr 2007 0:42 Modified: 28 Nov 2007 17:13
Reporter: Jonathan Miller Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.1-telco OS:Linux (32)
Assigned to: Mats Kindahl
Tags: bfsm_2007_10_18

[25 Apr 2007 0:42] Jonathan Miller
Description:
Hi,

I got around the table locking issues, but the diff of the dumps for master and slave causes the test to fail on:

'sapsrv1' Autopush
'sapsrv2' -max
'sol10-sparc-a' -max
'powermacg5' -max

I have also reproduced it locally by running.

./mysql-test-run.pl --do-test=rpl_ndb_stm --mysqld=--binlog-format=STATEMENT

The diff of the files show:

/data1/mysql-5.1-telco2/mysql-test> diff ./var/tmp/master_apply_status.sql ./var/tmp/slave_apply_status.sql
1111,1125c1111,1125
< INSERT INTO `history` VALUES (1,98,5,10,'1.00','2007-04-25 03:25:39','root@localhost','ad59b120-4413-102a-97ae-00e081203f51','completed trans');
< INSERT INTO `history` VALUES (2,1,30,10,'1.00','2007-04-25 03:25:39','root@localhost','ad5a7efc-4413-102a-97ae-00e081203f51','completed trans');
< INSERT INTO `history` VALUES (3,58,8,10,'1.00','2007-04-25 03:25:39','root@localhost','ad5b4102-4413-102a-97ae-00e081203f51','completed trans');
< INSERT INTO `history` VALUES (4,8,1,10,'1.00','2007-04-25 03:25:39','root@localhost','ad5bec1a-4413-102a-97ae-00e081203f51','completed trans');
< INSERT INTO `history` VALUES (5,3,63,10,'1.00','2007-04-25 03:25:39','root@localhost','ad5c95f2-4413-102a-97ae-00e081203f51','completed trans');
< INSERT INTO `history` VALUES (6,59,10,10,'1.00','2007-04-25 03:26:09','root@localhost','bf58eeb8-4413-102a-97ae-00e081203f51','completed trans');
< INSERT INTO `history` VALUES (7,3,1,10,'1.00','2007-04-25 03:26:09','root@localhost','bf5bffe0-4413-102a-97ae-00e081203f51','completed trans');
< INSERT INTO `history` VALUES (8,1,2,10,'1.00','2007-04-25 03:26:09','root@localhost','bf5cae0e-4413-102a-97ae-00e081203f51','completed trans');
< INSERT INTO `history` VALUES (9,10,20,10,'1.00','2007-04-25 03:26:09','root@localhost','bf5d64e8-4413-102a-97ae-00e081203f51','completed trans');
< INSERT INTO `history` VALUES (10,65,64,10,'1.00','2007-04-25 03:26:09','root@localhost','bf5e105a-4413-102a-97ae-00e081203f51','completed trans');
< INSERT INTO `history` VALUES (11,9,67,10,'1.00','2007-04-25 03:26:40','root@localhost','d1604c1e-4413-102a-97ae-00e081203f51','completed trans');
< INSERT INTO `history` VALUES (12,9,65,10,'1.00','2007-04-25 03:26:40','root@localhost','d16407d2-4413-102a-97ae-00e081203f51','completed trans');
< INSERT INTO `history` VALUES (13,9,9,10,'1.00','2007-04-25 03:26:40','root@localhost','d164b344-4413-102a-97ae-00e081203f51','completed trans');
< INSERT INTO `history` VALUES (14,8,2,10,'1.00','2007-04-25 03:26:40','root@localhost','d165563c-4413-102a-97ae-00e081203f51','completed trans');
< INSERT INTO `history` VALUES (15,64,1,10,'1.00','2007-04-25 03:26:40','root@localhost','d165f498-4413-102a-97ae-00e081203f51','completed trans');
---
> INSERT INTO `history` VALUES (1,98,5,10,'1.00','2007-04-25 03:25:39','X?<\0\0\0.??\0??6??\0?','ada85938-4413-102a-abe3-00e081203f51','completed trans');
> INSERT INTO `history` VALUES (2,1,30,10,'1.00','2007-04-25 03:25:39','X?<\0\0\0.??\0??6??\0?','ada960a8-4413-102a-abe3-00e081203f51','completed trans');
> INSERT INTO `history` VALUES (3,58,8,10,'1.00','2007-04-25 03:25:39','X?<\0\0\0.??\0??6??\0?','adaa5b7a-4413-102a-abe3-00e081203f51','completed trans');
> INSERT INTO `history` VALUES (4,8,1,10,'1.00','2007-04-25 03:25:39','X?<\0\0\0.??\0??6??\0?','adab4f62-4413-102a-abe3-00e081203f51','completed trans');
> INSERT INTO `history` VALUES (5,3,63,10,'1.00','2007-04-25 03:25:39','X?<\0\0\0.??\0??6??\0?','adac3df0-4413-102a-abe3-00e081203f51','completed trans');
> INSERT INTO `history` VALUES (6,59,10,10,'1.00','2007-04-25 03:26:09','X?<\0\0\0.??\0??6??\0?','bf67e184-4413-102a-abe3-00e081203f51','completed trans');
> INSERT INTO `history` VALUES (7,3,1,10,'1.00','2007-04-25 03:26:09','X?<\0\0\0.??\0??6??\0?','bf68d5b2-4413-102a-abe3-00e081203f51','completed trans');
> INSERT INTO `history` VALUES (8,1,2,10,'1.00','2007-04-25 03:26:09','X?<\0\0\0.??\0??6??\0?','bf69c8e6-4413-102a-abe3-00e081203f51','completed trans');
> INSERT INTO `history` VALUES (9,10,20,10,'1.00','2007-04-25 03:26:09','X?<\0\0\0.??\0??6??\0?','bf6abca6-4413-102a-abe3-00e081203f51','completed trans');
> INSERT INTO `history` VALUES (10,65,64,10,'1.00','2007-04-25 03:26:09','X?<\0\0\0.??\0??6??\0?','bf6bac88-4413-102a-abe3-00e081203f51','completed trans');
> INSERT INTO `history` VALUES (11,9,67,10,'1.00','2007-04-25 03:26:40','O?<\0\0\0.??\0??6??\0?','d16cce8a-4413-102a-abe3-00e081203f51','completed trans');
> INSERT INTO `history` VALUES (12,9,65,10,'1.00','2007-04-25 03:26:40','O?<\0\0\0.??\0??6??\0?','d16d8820-4413-102a-abe3-00e081203f51','completed trans');
> INSERT INTO `history` VALUES (13,9,9,10,'1.00','2007-04-25 03:26:40','O?<\0\0\0.??\0??6??\0?','d16e3d24-4413-102a-abe3-00e081203f51','completed trans');
> INSERT INTO `history` VALUES (14,8,2,10,'1.00','2007-04-25 03:26:40','P?<\0\0\0.??\0??6??\0?','d16ef89a-4413-102a-abe3-00e081203f51','completed trans');
> INSERT INTO `history` VALUES (15,64,1,10,'1.00','2007-04-25 03:26:40','P?<\0\0\0.??\0??6??\0?','d16fa9ac-4413-102a-abe3-00e081203f51','completed trans');

Looking at the binlog you can see the statement that were replicated.

master-bin.000001       3789    Xid     1       3816    COMMIT /* xid=5213 */
master-bin.000001       3816    Query   1       3884    use `test`; BEGIN
master-bin.000001       3884    Query   1       187     use `tpcb`; UPDATE tpcb.account SET balance =  NAME_CONST('bal',1.00), filler = 'account updated'
     WHERE id =  NAME_CONST('acct',64)
master-bin.000001       4071    Query   1       374     use `tpcb`; UPDATE tpcb.branch SET balance =  NAME_CONST('bbal',1.00), filler = 'branch updated'
     WHERE bid =  NAME_CONST('brch',10)
master-bin.000001       4258    Query   1       560     use `tpcb`; UPDATE tpcb.teller SET balance =  NAME_CONST('tbal',3.00), filler = 'teller updated'
     WHERE tid =  NAME_CONST('tell',1)
master-bin.000001       4444    Intvar  1       588     INSERT_ID=15
master-bin.000001       4472    Query   1       832     use `tpcb`; INSERT INTO tpcb.history VALUES(NULL, NAME_CONST('acct',64), NAME_CONST('tell',1), NAME_CONST('brch',10), NAME_CONST('amount',1.00), NOW(), USER(),
UUID(),'completed trans')
master-bin.000001       4716    Xid     1       4743    COMMIT /* xid=5260 */

How to repeat:
Use rpl_ndb_stm_innodb.test in the 5.1-telco clone and run using the following

./mysql-test-run.pl --do-test=rpl_ndb_stm --mysqld=--binlog-format=STATEMENT
[25 Apr 2007 0:46] Bugs System
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/25361

ChangeSet@1.2481, 2007-04-25 02:45:50+02:00, jmiller@mysql.com +1 -0
  disabled.def:
    Disabled test due to Bug #28086
[25 Apr 2007 14:25] Jonathan Miller
This happens if you use innodb -> myisam as well. Will attached test case in a few.
[25 Apr 2007 16:17] Jonathan Miller
innodb->myisam test

Attachment: rpl_stm_innodb.test (application/octet-stream, text), 6.50 KiB.

[25 Apr 2007 16:17] Jonathan Miller
option file

Attachment: rpl_stm_innodb-master.opt (application/octet-stream, text), 41 bytes.

[25 Apr 2007 16:17] Jonathan Miller
include file

Attachment: tpcb.inc (application/octet-stream, text), 4.32 KiB.

[31 Oct 2007 11:26] Bugs System
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/36743

ChangeSet@1.2605, 2007-10-31 12:25:38+01:00, mats@kindahl-laptop.dnsalias.net +3 -0
  BUG#28086 (SBR of USER() becomes corrupted on slave):
  
  Marking statements containing USER() as unsafe, causing them to switch to using
  row-based logging in MIXED mode and generate a warning in STATEMENT mode.
[31 Oct 2007 13:47] Tatiana Azundris Nuernberg
Patch looks good. Is CURRENT_USER() subject to this issue?
[31 Oct 2007 20:10] Bugs System
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/36796

ChangeSet@1.2605, 2007-10-31 21:09:52+01:00, mats@kindahl-laptop.dnsalias.net +3 -0
  BUG#28086 (SBR of USER() becomes corrupted on slave):
  
  Marking statements containing USER() or CURRENT_USER() as unsafe, causing
  them to switch to using row-based logging in MIXED mode and generate a
  warning in STATEMENT mode.
[27 Nov 2007 10:50] Bugs System
Pushed into 5.1.23-rc
[27 Nov 2007 10:52] Bugs System
Pushed into 6.0.4-alpha
[28 Nov 2007 17:13] Jon Stephens
Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.

If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html

Documented in 5.1.23 and 6.0.4 changelogs as follows:

        Replication of USER(), 
        CURRENT_USER(), and
        CURRENT_USER now switches to
        row-based logging in MIXED mode, and
        generates a warning in STATEMENT mode.

Also noted in http://dev.mysql.com/doc/refman/5.1/en/binary-log-mixed.html and http://dev.mysql.com/doc/refman/6.0/en/binary-log-mixed.html.