MySQL Bugs: #29734: thread_id=0 in binary log which leads to temporary table conflicts

Bug #29734	thread_id=0 in binary log which leads to temporary table conflicts
Submitted:	11 Jul 2007 19:03	Modified:	23 Oct 2007 11:06
Reporter:	Harrison Fisk	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.0.38, 5.0.46BK	OS:	Linux
Assigned to:	Sergey Vojtovich	CPU Architecture:	Any
Tags:	bfsm_2007_10_18, mysql_change_user, replication, thread_id

Description:
In some cases, the binary log generated on the master can have a thread_id=0, possibly for multiple threads.  Normally this does not matter, however in the case where you have two threads using the same temporary table, the pseudo_thread_id is set to the same 0 value, and hence will cause conflicts and stop replication and point-in-time recovery.

I believe that thread_id should never be logged as 0, since MySQL never uses that as a thread_id (it starts at 1).

I have seen a few cases where this has occured:

1. http://bugs.mysql.com/bug.php?id=8436  Notice the thread_id=0 section.
2. http://forums.mysql.com/read.php?26,117716,117716  Notice thread_id=0 output.
3. The associated CSC issue with attached binary logs in that issue.

How to repeat:
No sure yet.

Suggested fix:
Do not ever log the invalid thread_id=0 to the binary log.

Test case to cause the replication failure

Attachment: bug_29734.c (text/x-csrc), 572 bytes.

I have managed to track this down to the COM_CHANGE_USER call.  This call occurs when you do mysql_change_user() in the C API or in Java/.NET when you are using connection pooling.  It appears you need to do something on the connection prior to using mysql_change_user() to make this occur.

When you do a mysql_change_user() call, then the thread_id for subsequent binary log entries gets set to 0.

I have uploaded a test case which uses mysql_change_user to cause this.  Once you have it compiled, just run it twice at the same time (I put a sleep() in to make this easy) and you will break replication.

The binary log output looks like:

hfisk@corona:/usr/local/mysqldata$ sudo ../mysql/bin/mysqlbinlog corona-bin.000449
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#070711 18:00:50 server id 1  end_log_pos 98    Start: binlog v 4, server v 5.0.44-enterprise-gpl-log created 070711 18:00:50
# Warning: this binlog was not closed properly. Most probably mysqld crashed writing it.
# at 98
#070711 18:01:07 server id 1  end_log_pos 196   Query   thread_id=26    exec_time=0     error_code=0
use test/*!*/;
SET TIMESTAMP=1184191267/*!*/;
SET @@session.pseudo_thread_id=26/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1/*!*/;
SET @@session.sql_mode=0/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
CREATE TEMPORARY TABLE bar (id int)/*!*/;
# at 196
#070711 18:01:07 server id 1  end_log_pos 314   Query   thread_id=26    exec_time=0     error_code=0
SET TIMESTAMP=1184191267/*!*/;
SET @@session.pseudo_thread_id=26/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `test`.`bar`/*!*/;
# at 314
#070711 18:01:07 server id 1  end_log_pos 412   Query   thread_id=0     exec_time=0     error_code=0
SET TIMESTAMP=1184191267/*!*/;
SET @@session.pseudo_thread_id=0/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
CREATE TEMPORARY TABLE foo (id int)/*!*/;
# at 412
#070711 18:01:07 server id 1  end_log_pos 501   Query   thread_id=0     exec_time=0     error_code=0
SET TIMESTAMP=1184191267/*!*/;
SET @@session.pseudo_thread_id=0/*!*/;
INSERT INTO foo VALUES (5)/*!*/;
# at 501
#070711 18:01:12 server id 1  end_log_pos 599   Query   thread_id=27    exec_time=0     error_code=0
SET TIMESTAMP=1184191272/*!*/;
SET @@session.pseudo_thread_id=27/*!*/;
CREATE TEMPORARY TABLE bar (id int)/*!*/;
# at 599
#070711 18:01:12 server id 1  end_log_pos 717   Query   thread_id=27    exec_time=0     error_code=0
SET TIMESTAMP=1184191272/*!*/;
SET @@session.pseudo_thread_id=27/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `test`.`bar`/*!*/;
# at 717
#070711 18:01:12 server id 1  end_log_pos 815   Query   thread_id=0     exec_time=0     error_code=0
SET TIMESTAMP=1184191272/*!*/;
SET @@session.pseudo_thread_id=0/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
CREATE TEMPORARY TABLE foo (id int)/*!*/;
# at 815
#070711 18:01:12 server id 1  end_log_pos 904   Query   thread_id=0     exec_time=0     error_code=0
SET TIMESTAMP=1184191272/*!*/;
SET @@session.pseudo_thread_id=0/*!*/;
INSERT INTO foo VALUES (5)/*!*/;
# at 904
#070711 18:01:07 server id 1  end_log_pos 1022  Query   thread_id=0     exec_time=27    error_code=0
SET TIMESTAMP=1184191267/*!*/;
SET @@session.pseudo_thread_id=0/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `test`.`foo`/*!*/;
# at 1022
#070711 18:01:12 server id 1  end_log_pos 1140  Query   thread_id=0     exec_time=23    error_code=0
SET TIMESTAMP=1184191272/*!*/;
SET @@session.pseudo_thread_id=0/*!*/;
DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `test`.`foo`/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;

The error you will get on the slave is:

Error 'Table 'foo' already exists' on query.  Default database: 'test'. Query: 'CREATE TEMPORARY TABLE foo (ID INT)'

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

ChangeSet@1.2526, 2007-07-13 18:55:36+05:00, svoj@mysql.com +1 -0
  BUG#29734 - thread_id=0 in binary log which leads to temporary table conflicts
  
  thread_id was not reset properly after mysql_change_user() command, which
  may cause replication failure when replicating temporary tables.
  
  Fixed by resetting thread_id to proper value after mysql_change_user().

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

ChangeSet@1.2526, 2007-07-13 22:09:50+05:00, svoj@mysql.com +1 -0
  BUG#29734 - thread_id=0 in binary log which leads to temporary table conflicts
  
  pseudo_thread_id was not reset properly after mysql_change_user() command,
  which may cause replication failure when replicating temporary tables.
  
  Fixed by correcting pseudo_thread_id value after mysql_change_user().

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

ChangeSet@1.2526, 2007-07-14 17:58:39+05:00, svoj@mysql.com +1 -0
  BUG#29734 - thread_id=0 in binary log which leads to temporary table conflicts
  
  pseudo_thread_id was reset to zero via mysql_change_user() handling
  whereas there is no reason to do that.  Moreover, having two
  concurrent threads that change user and create a namesake temp tables
  leads to recording the dup pair of queries:
  
     set @@session.pseudo_thread_id = 0;
     CREATE temporary table `the namesake`;
  
  which will stall the slave as the second instance can not be created.
  And that is the bug case.
  
  Fixed by correcting pseudo_thread_id value after mysql_change_user().

Pushed into 5.0.48

Pushed into 5.1.21-beta

Noted in 5.0.48, 5.1.21 changelogs.

The thread ID was not reset properly after execution of
mysql_change_user(), which could cause replication failure when
replicating temporary tables.

Closing this bug as original (pure replication) problem is solved. Reported BUG#31781 to track temp-pool related issue.