Bug #50407 mysqlbinlog --database=X produces bad output for SAVEPOINTs
Submitted: 18 Jan 2010 11:11 Modified: 21 Jun 2010 0:46
Reporter: Sven Sandberg Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.1+, 5.5.99 OS:Any
Assigned to: Libing Song CPU Architecture:Any
Tags: mysqlbinlog, savepoint

[18 Jan 2010 11:11] Sven Sandberg
Description:
When mysqlbinlog is given the --database=X flag, it only prints statements executed when the default database selected by USE was X. Other statements are suppressed.

One exception is BEGIN, COMMIT, ROLLBACK, and ROLLBACK TO savepoint: all these statements are printed even if the default database selected by USE was not X. Since ROLLBACK TO savepoint is printed but SAVEPOINT is not printed, the output from mysqlbinlog will be bad: when the ROLLBACK TO savepoint statement is executed, mysqld will issue error ER_SP_DOES_NOT_EXIST (1305) "SAVEPOINT s does not exist".

How to repeat:
--source include/have_binlog_format_statement.inc
--source include/have_innodb.inc

USE test;

CREATE TABLE t1 (a INT);
CREATE TABLE t2 (a INT) ENGINE = InnoDB;

BEGIN;
  INSERT INTO t1 VALUES (1);
  INSERT INTO t2 VALUES (1);
  SAVEPOINT s;
    INSERT INTO t1 VALUES (2);
    INSERT INTO t2 VALUES (2);
  ROLLBACK TO s;
COMMIT;

--let $MYSQLD_DATADIR= `SELECT @@datadir`
--exec $MYSQL_BINLOG --database=other --force-if-open $MYSQLD_DATADIR/master-bin.000001

Suggested fix:
=== modified file 'client/mysqlbinlog.cc'
--- client/mysqlbinlog.cc	2009-11-03 00:52:57 +0000
+++ client/mysqlbinlog.cc	2010-01-18 11:09:49 +0000
@@ -731,6 +731,7 @@ Exit_status process_event(PRINT_EVENT_IN
     case QUERY_EVENT:
       if (strncmp(((Query_log_event*)ev)->query, "BEGIN", 5) && 
           strncmp(((Query_log_event*)ev)->query, "COMMIT", 6) && 
+          strncmp(((Query_log_event*)ev)->query, "SAVEPOINT", 9) &&
           strncmp(((Query_log_event*)ev)->query, "ROLLBACK", 8) &&  
           shall_skip_database(((Query_log_event*)ev)->db))
         goto end;
[18 Jan 2010 19:17] Sveta Smirnova
Thank you for the report.

Verified as described.
[5 Feb 2010 4:16] 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/99365

3346 Li-Bing.Song@sun.com	2010-02-05
      Bug #50407  mysqlbinlog --database=X produces bad output for SAVEPOINTs
      
      When mysqlbinlog is given the --database=X flag, it always printed 'ROLLBACK TO',
      but the corresponding 'SAVEPOINT' statement was not printed.
      
      After this patch, 'SAVEPOINT' statement is always printed.
[10 Feb 2010 3:05] 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/99772

3346 Li-Bing.Song@sun.com	2010-02-10
      Bug #50407  mysqlbinlog --database=X produces bad output for SAVEPOINTs
      
      When mysqlbinlog was given the --database=X flag, it always printed 'ROLLBACK TO',
      but the corresponding 'SAVEPOINT' statement was not printed.
      
      After this patch, 'SAVEPOINT' statement is always printed.
[20 Feb 2010 9:27] Libing Song
The new patch with another solution has committed, please review it again.
[20 Feb 2010 9:27] 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/100954

3347 Li-Bing.Song@sun.com	2010-02-20
      Bug #50407  mysqlbinlog --database=X produces bad output for SAVEPOINTs
            
      When mysqlbinlog was given the --database=X flag, it always printed 'ROLLBACK TO',
      but the corresponding 'SAVEPOINT' statement was not printed.
      The replicated filter(--replicated-do-db) has the same problem. It is solved 
      in this patch together.
      
      A new flag LOG_EVENT_IGNORE_FILTER_F is added into log events. It indicates 
      the log event should be executed by slave or printed by mysqlbinlog even though
      it fails to meet the filter conditions.
      To compatible backward, we still check the query literal if the flag is
      not set.
[23 Feb 2010 9:23] 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/101160

3346 Li-Bing.Song@sun.com	2010-02-23
      Bug #50407  mysqlbinlog --database=X produces bad output for SAVEPOINTs
      
      When mysqlbinlog was given the --database=X flag, it always printed 'ROLLBACK TO',
      but the corresponding 'SAVEPOINT' statement was not printed.
      
      After this patch, 'SAVEPOINT' statement is always printed.
[24 Feb 2010 3:35] 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/101282

3346 Li-Bing.Song@sun.com	2010-02-24
      Bug #50407  mysqlbinlog --database=X produces bad output for SAVEPOINTs
      
      When mysqlbinlog was given the --database=X flag, it always printed 'ROLLBACK TO',
      but the corresponding 'SAVEPOINT' statement was not printed.
      The replicated filter(--replicated-do-db) has the same problem. It is solved 
      in this patch together.
      
      
      After this patch, We always check whether the query is 'SAVEPOINT' statement or not.
      Becaust this is a literal check, 'SAVEPOINT' and 'ROLLBACK TO' statements are also
      binlogged in uppercase with no any comments.
[1 Mar 2010 12:08] 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/101841

3366 Li-Bing.Song@sun.com	2010-03-01
      Bug #50407  mysqlbinlog --database=X produces bad output for SAVEPOINTs
      
      When mysqlbinlog was given the --database=X flag, it always printed 'ROLLBACK TO',
      but the corresponding 'SAVEPOINT' statement was not printed.
      The replicated filter(--replicated-do-db) and binlog filter(binlog-do-db)
      has the same problem. They are solved in this patch together.
      
      
      After this patch, We always check whether the query is 'SAVEPOINT' statement or not.
      Becaust this is a literal check, 'SAVEPOINT' and 'ROLLBACK TO' statements are also
      binlogged in uppercase with no any comments.
[4 Mar 2010 10:01] 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/102262

3369 Li-Bing.Song@sun.com	2010-03-04
      Bug #50407  mysqlbinlog --database=X produces bad output for SAVEPOINTs
      
      When mysqlbinlog was given the --database=X flag, it always printed
      'ROLLBACK TO', but the corresponding 'SAVEPOINT' statement was not
      printed. The replicated filter(replicated-do/ignore-db) and binlog
      filter (binlog-do/ignore-db) has the same problem. They are solved
      in this patch together.
      
      After this patch, We always check whether the query is 'SAVEPOINT'
      statement or not. Because this is a literal check, 'SAVEPOINT' and
      'ROLLBACK TO' statements are also binlogged in uppercase with no
      any comments.
      
      The binlog before this patch can be handled correctly except one case
      that any comments are in front of the keywords. for example:
       /* bla bla */ SAVEPOINT a;
       /* bla bla */ ROLLBACK TO a;
[8 Mar 2010 9:39] Libing Song
Luis,
Please review it again, Added more code into the patch
[22 Mar 2010 3:11] 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/103920

3412 Li-Bing.Song@sun.com	2010-03-22
      Bug #50407  mysqlbinlog --database=X produces bad output for SAVEPOINTs
      
      When mysqlbinlog was given the --database=X flag, it always printed
      'ROLLBACK TO', but the corresponding 'SAVEPOINT' statement was not
      printed. The replicated filter(replicated-do/ignore-db) and binlog
      filter (binlog-do/ignore-db) has the same problem. They are solved
      in this patch together.
      
      After this patch, We always check whether the query is 'SAVEPOINT'
      statement or not. Because this is a literal check, 'SAVEPOINT' and
      'ROLLBACK TO' statements are also binlogged in uppercase with no
      any comments.
      
      The binlog before this patch can be handled correctly except one case
      that any comments are in front of the keywords. for example:
       /* bla bla */ SAVEPOINT a;
       /* bla bla */ ROLLBACK TO a;
[28 Mar 2010 11:55] 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/104520

3430 Li-Bing.Song@sun.com	2010-03-28
      Bug #50407  mysqlbinlog --database=X produces bad output for SAVEPOINTs
      
      When mysqlbinlog was given the --database=X flag, it always printed
      'ROLLBACK TO', but the corresponding 'SAVEPOINT' statement was not
      printed. The replicated filter(replicated-do/ignore-db) and binlog
      filter (binlog-do/ignore-db) has the same problem. They are solved
      in this patch together.
      
      After this patch, We always check whether the query is 'SAVEPOINT'
      statement or not. Because this is a literal check, 'SAVEPOINT' and
      'ROLLBACK TO' statements are also binlogged in uppercase with no
      any comments.
      
      The binlog before this patch can be handled correctly except one case
      that any comments are in front of the keywords. for example:
       /* bla bla */ SAVEPOINT a;
       /* bla bla */ ROLLBACK TO a;
[29 Mar 2010 7:45] Libing Song
Pushed into mysql-5.1-bugteam and merged into mysql-pe
[6 Apr 2010 7:57] Bugs System
Pushed into 5.1.46 (revid:sergey.glukhov@sun.com-20100405111026-7kz1p8qlzglqgfmu) (version source revid:li-bing.song@sun.com-20100328115733-4lpsnybf8hftnpug) (merge vers: 5.1.46) (pib:16)
[6 Apr 2010 10:58] Jon Stephens
Documented bugfix in the 5.1.46 changelog as follows:

        When run with the --database option, mysqlbinlog printed
        ROLLBACK statements but did not print any corresponding
        SAVEPOINT statements.

Set NM status, waiting for merges to 5.5+.
[28 May 2010 5:53] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100524190136-egaq7e8zgkwb9aqi) (version source revid:alik@sun.com-20100422150750-vp0n37kp9ywq5ghf) (pib:16)
[28 May 2010 6:23] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100524190941-nuudpx60if25wsvx) (version source revid:alik@sun.com-20100422150658-fkhgnwwkyugtxrmu) (merge vers: 6.0.14-alpha) (pib:16)
[28 May 2010 6:50] Bugs System
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100524185725-c8k5q7v60i5nix3t) (version source revid:alexey.kopytov@sun.com-20100403173551-52r97erqowlqwkon) (merge vers: 5.5.4-m3) (pib:16)
[3 Jun 2010 11:10] Jon Stephens
Also documented fix in the 5.5.5 and 6.0.14 changelogs.

Closed.
[17 Jun 2010 11:54] Bugs System
Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 12:32] Bugs System
Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:martin.skold@mysql.com-20100609211156-tsac5qhw951miwtt) (merge vers: 5.1.46-ndb-6.2.19) (pib:16)
[17 Jun 2010 13:20] Bugs System
Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)