MySQL Bugs: #51226: mysqlbinlog replay: ERROR 1146 when using temp tables + failing statements

Bug #51226	mysqlbinlog replay: ERROR 1146 when using temp tables + failing statements
Submitted:	16 Feb 2010 23:18	Modified:	21 Jun 2010 0:55
Reporter:	Victor Kirkebo	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	5.1.44, 6.0-backup	OS:	Any
Assigned to:	Luis Soares	CPU Architecture:	Any
Tags:	error 1146, mysqlbinlog, replay, table, temp, temporary

Description:
When using temporary tables the binary log needs to insert "@@session.pseudo_thread_id" for threads that are using temporary tables each time a switch happens between two threads that are both using temporary tables.
In the How-to-repeat section below is shown that if a thread issues a failing statement before exit then the binary log will be missing the "@@session.pseudo_thread_id" for that thread. This in turn can cause the binary log to be missing "@@session.pseudo_thread_id" for the next thread that tries to do something with a temporary table. A subsequent replay of the binary log will then fail with ERROR 1146 (42S02) at line nn: Table 'tttt' doesn't exist.

How to repeat:
client #1
---------
mysql> create database mydb;
Query OK, 1 row affected (0.00 sec)
mysql> use mydb;
Database changed
mysql> create temporary table tmp(i int);
Query OK, 0 rows affected (0.01 sec)

client #2: 
---------
mysql> use mydb;
Database changed
mysql> create temporary table tmp(i int);
Query OK, 0 rows affected (0.00 sec)

client #1
---------
Here we provoke an error on purpose before exiting. I don't think it matters what type of error we get here. I've tried lock wait timeout errors and even syntax errors. The result is that upon exit "@@session.pseudo_thread_id" will be missing in the binary log for the drop temporary table statement for client #1
---------
mysql> create temporary table tmp(i int);
ERROR 1050 (42S01): Table 'tmp' already exists
mysql> exit;
Bye

client #2
---------
The error that client #1 caused above has the effect that the binary log for the insert statement below will be missing "@@session.pseudo_thread_id" which in turn will make a mysqlbinlog replay fail with ERROR 1146 (42S02) at line nn: Table 'mydb.tmp' doesn't exist
---------
mysql> insert into tmp values(1);
Query OK, 1 row affected (0.00 sec)
mysql> exit
Bye

Replaying the binary log:
----------------------------
mysqlbinlog master-bin.000001 | mysql 
ERROR 1146 (42S02) at line 49: Table 'mydb.tmp' doesn't exist

Here's the binary log.
thread_id=25 is client #1 and thread_id=26 is client #2:
--------------------------------------------------------
#100216 22:58:11 server id 1  end_log_pos 12474137      Query   thread_id=25    exec_time=0     error_code=0
SET TIMESTAMP=1266357491/*!*/;
SET @@session.sql_mode=0/*!*/;
create database mydb
/*!*/;
# at 12474137
#100216 23:01:02 server id 1  end_log_pos 12474233      Query   thread_id=25    exec_time=0     error_code=0
use mydb/*!*/;
SET TIMESTAMP=1266357662/*!*/;
SET @@session.pseudo_thread_id=25/*!*/;
create temporary table tmp(i int)
/*!*/;
# at 12474233
#100216 23:01:31 server id 1  end_log_pos 12474329      Query   thread_id=26    exec_time=0     error_code=0
SET TIMESTAMP=1266357691/*!*/;
SET @@session.pseudo_thread_id=26/*!*/;
create temporary table tmp(i int)
/*!*/;
# at 12474329
#100216 23:02:43 server id 1  end_log_pos 12474440      Query   thread_id=25    exec_time=0     error_code=0
SET TIMESTAMP=1266357763/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `tmp`
/*!*/;
# at 12474440
#100216 23:02:52 server id 1  end_log_pos 12474528      Query   thread_id=26    exec_time=0     error_code=0
SET TIMESTAMP=1266357772/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
insert into tmp values(1)
/*!*/;
# at 12474528
#100216 23:02:54 server id 1  end_log_pos 12474639      Query   thread_id=26    exec_time=0     error_code=0
SET TIMESTAMP=1266357774/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `tmp`
/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;

Verified as described.

Related: BUG#35583.

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

3341 Luis Soares	2010-02-22
      BUG#51226: mysqlbinlog replay: ERROR 1146 when using temp tables
                 + failing statements
      
      This is a small regression from BUG@35583 which happens in a very
      particular situation. Consider two connections con1 and con2,
      where their pseudo_thread_ids are 1 and 2 respectively. Both
      connections create a temporary table with the same name, say
      t1. On both connections several statements are executing
      concurrently, so their events (lets use E1 to identify an event
      from con1 and E2 for an event from con2) end up in the binary log
      inter-leaved. Now, picture the case that we have the following
      sequence: E1,E2,S*1; in which S*1 is a failing statement in
      con1. Furthermore, assume that after S*1, con1 disconnects and an
      implicit 'drop temp table t1' is written to the binary log,
      before any other event from con2 is logged. This causes the
      implicit drop event to be logged without the proper
      pseudo_thread_id=1, thence when replaying the binary log, the
      drop would be executed under the assumption that it had been
      originally processed under con2.
      
      This happens because right before starting execution of S*1 the
      thread context is reset, and consequently the
      thread_specific_used flag is unset (note: this is one of the
      flags that transitively controls logging and printing of
      pseudo_thread_id in the event header). Since S*1 fails and right
      after the connection is be dropped, the thread_specific_used flag
      would remain unset, the pseudo_thread_id would therefore not be
      logged.
      
      This scenario only happens for the case that we have: E1,E2,S*1
      followed by a disconnection. If we had a successful statement
      executed on con1 before S*1 (E1,E2,E1,S*1 followed by
      disconnection), there would not be a problem, as the correct
      pseudo_thread_id would have been logged before S*1.
      
      We fix this by setting thread_specific_used whenever we are
      binlogging a DROP in close_temporary_tables, and resetting it to
      its previous value afterward.

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

3341 Luis Soares	2010-03-03
      BUG#51226: mysqlbinlog replay: ERROR 1146 when using temp tables
                 + failing statements
      
      Implicit DROP event for temporary table is not getting
      LOG_EVENT_THREAD_SPECIFIC_F flag, because, in the previous
      executed statement in the same thread, which might even be a
      failed statement, the thread_specific_used flag is set to
      FALSE (in mysql_reset_thd_for_next_command) and not set to TRUE
      before connection is shutdown. This means that implicit DROP
      event will take the FALSE value from thread_specific_used and
      will not set LOG_EVENT_THREAD_SPECIFIC_F in the event header. As
      a consequence, mysqlbinlog will not print the pseudo_thread_id
      from the DROP event, because one of the requirements for the
      printout is that this flag is set to TRUE.
      
      We fix this by setting thread_specific_used whenever we are
      binlogging a DROP in close_temporary_tables, and resetting it to
      its previous value afterward.

Pushed into 5.5.4-m3 (revid:alik@sun.com-20100326080914-2pz8ns984e0spu03) (version source revid:alexey.kopytov@sun.com-20100312095153-t4rtoqc7p96lmxvh) (merge vers: 5.5.3-m2) (pib:16)

Pushed into mysql-next-mr (revid:alik@sun.com-20100326081116-m3v4l34yhr43mtsv) (version source revid:alik@sun.com-20100325072612-4sds00ix8ajo1e84) (pib:16)

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100326081944-qja07qklw1p2w7jb) (version source revid:alik@sun.com-20100325073410-4t4i9gu2u1pge7xb) (merge vers: 6.0.14-alpha) (pib:16)

DOcumented bugfix in the 5.5.4 and 6.0.14 changelogs as follows:

        When using temporary tables the binary log needs to insert a
        pseudo-thread ID for threads that are using temporary tables,
        each time a switch happens between two threads, both of which
        are using temporary tables. However, if a thread issued a
        failing statement before exit, its ID was not recorded in the
        binary log, and this in turn caused the ID for the next thread
        that tried to do something with a temporary table not to be
        logged as well. Subsequent replays of the binary log failed with
        the error Table ... doesn't exist.
      
Set NM status - waiting for 5.1.

5.5.4 changelog entry was moved to 5.5.5.

Pushed into 5.1.46 (revid:sergey.glukhov@sun.com-20100405111026-7kz1p8qlzglqgfmu) (version source revid:luis.soares@sun.com-20100308235726-6kptibjdohgj87dh) (merge vers: 5.1.45) (pib:16)

Also documented in the 5.1.46 changelog. Closed.

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)

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)

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)