Bug #57288 binlog_tmp_table fails sporadically: "Failed to write the DROP statement ..."
Submitted: 6 Oct 2010 15:05 Modified: 6 Jan 2011 4:20
Reporter: Luis Soares Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.5+ OS:Any
Assigned to: Luis Soares CPU Architecture:Any
Tags: Drop, regression, sporadic, temporary tables, WL#2687
Triage: Triaged: D2 (Serious)

[6 Oct 2010 15:05] Luis Soares
Description:
The test case binary_tmp_table fails randomly on PB2,
with the following symptom:

binlog.binlog_tmp_table                  [ fail ]  Found warnings/errors in server log file!
        Test ended at 2010-10-05 14:38:27
line
101005 15:38:27 [ERROR] Failed to write the DROP statement for temporary tables to binary log
^ Found warnings in /export/home/pb2/test/sb_1-2357452-1286279856.57/mysql-5.6.1-m4-freebsd7.0-i386-test/mysql-test/var-n_mix/log/mysqld.1.err
ok

NOTES: 

  N1. The failures have been observed mostly on freebsd7, but
      they also show up less frequently on sparc64.

  N2. According to xref, the first failure with the given symptom
      was observed on 2010-07-29 21:02:54.

How to repeat:
List of failures for binlog_tmp_table with the reported symptom:
- http://tinyurl.com/2ex26wp

Sample of a test failure in daily-next-mr-bugfixing:
- http://tinyurl.com/2725ngq

Suggested fix:
.
[12 Oct 2010 14:27] Luis Soares
I've hit this locally in Linux x86_64 as well.
[13 Oct 2010 14:18] 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/120692

3241 Luis Soares	2010-10-13 [merge]
      BUG#57288: binlog_tmp_table fails sporadically: "Failed to write
      the DROP statement ..."
      
      Problem: When using temporary tables and closing a session, an
      implicit DROP TEMPORARY TABLE IF EXISTS is written to the binary
      log (while cleaning up the context of the session THD - see:
      sql_class.cc:THD::cleanup which calls close_temporary_tables).
      
      close_temporary_tables, first checks if the binary log is opened
      and then proceeds to creating the DROP statements. Then, such
      statements, are written to the binary log through
      MYSQL_BIN_LOG::write(Log_event *). Inside, there is another check
      if the binary log is opened and if not an error is returned. This
      is where the faulty behavior is triggered. Given that the test
      case replays a binary log, with temp tables statements, and right
      after it issues RESET MASTER, there is a chance that is_open will
      report false (when the mysql session is closed and the temporary
      tables are written). 
      
      is_open may return false, because MYSQL_BIN_LOG::reset_logs is
      not setting the correct flag (LOG_CLOSE_TO_BE_OPENED), on the
      MYSQL_LOG_BIN::log_state (instead it sets just the
      LOG_CLOSE_INDEX flag, leaving the log_state to
      LOG_CLOSED). Thence, when writing the DROP statement as part of
      the THD::cleanup, the thread could get a return value of false
      for is_open - inside MYSQL_BIN_LOG::write, ultimately reporting
      that it can't write the event to the binary log.
      
      Fix: We fix this by adding the correct flag, missing in the
      second close. Additionally, we also make the assignment of
      log_file to be protected inside MYSQL_BIN_LOG::write, which could
      also lead to potential races.
[21 Oct 2010 14:06] 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/121546

3545 Luis Soares	2010-10-21
      BUG#57288: binlog_tmp_table fails sporadically: "Failed to write
      the DROP statement ..."
            
      Problem: When using temporary tables and closing a session, an
      implicit DROP TEMPORARY TABLE IF EXISTS is written to the binary
      log (while cleaning up the context of the session THD - see:
      sql_class.cc:THD::cleanup which calls close_temporary_tables).
            
      close_temporary_tables, first checks if the binary log is opened
      and then proceeds to creating the DROP statements. Then, such
      statements, are written to the binary log through
      MYSQL_BIN_LOG::write(Log_event *). Inside, there is another check
      if the binary log is opened and if not an error is returned. This
      is where the faulty behavior is triggered. Given that the test
      case replays a binary log, with temp tables statements, and right
      after it issues RESET MASTER, there is a chance that is_open will
      report false (when the mysql session is closed and the temporary
      tables are written). 
            
      is_open may return false, because MYSQL_BIN_LOG::reset_logs is
      not setting the correct flag (LOG_CLOSE_TO_BE_OPENED), on the
      MYSQL_LOG_BIN::log_state (instead it sets just the
      LOG_CLOSE_INDEX flag, leaving the log_state to
      LOG_CLOSED). Thence, when writing the DROP statement as part of
      the THD::cleanup, the thread could get a return value of false
      for is_open - inside MYSQL_BIN_LOG::write, ultimately reporting
      that it can't write the event to the binary log.
            
      Fix: We fix this by adding the correct flag, missing in the
      second close. Additionally, we also make the assignment of
      log_file to be protected by lock_log. Finally, we remove the
      'if(is_open)' from MYSQL_BIN_LOG::write(event) and 
      MYSQL_BIN_LOG::write(cache), place a DBUG_ASSERT(is_open) in
      the former and keep the DBUG_ASSERT(is_open) in the latter.
[30 Nov 2010 16: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/125529

3528 Luis Soares	2010-11-30
      BUG#57288: binlog_tmp_table fails sporadically: "Failed to write
      the DROP statement ..."
            
      Problem: When using temporary tables and closing a session, an
      implicit DROP TEMPORARY TABLE IF EXISTS is written to the binary
      log (while cleaning up the context of the session THD - see:
      sql_class.cc:THD::cleanup which calls close_temporary_tables).
           
      close_temporary_tables, first checks if the binary log is opened
      and then proceeds to creating the DROP statements. Then, such
      statements, are written to the binary log through
      MYSQL_BIN_LOG::write(Log_event *). Inside, there is another check
      if the binary log is opened and if not an error is returned. This
      is where the faulty behavior is triggered. Given that the test
      case replays a binary log, with temp tables statements, and right
      after it issues RESET MASTER, there is a chance that is_open will
      report false (when the mysql session is closed and the temporary
      tables are written).
            
      is_open may return false, because MYSQL_BIN_LOG::reset_logs is
      not setting the correct flag (LOG_CLOSE_TO_BE_OPENED), on the
      MYSQL_LOG_BIN::log_state (instead it sets just the
      LOG_CLOSE_INDEX flag, leaving the log_state to
      LOG_CLOSED). Thence, when writing the DROP statement as part of
      the THD::cleanup, the thread could get a return value of false
      for is_open - inside MYSQL_BIN_LOG::write, ultimately reporting
      that it can't write the event to the binary log.
            
      Fix: We fix this by adding the correct flag, missing in the
      second close.
[30 Nov 2010 18:25] Luis Soares
Queued in mysql-5.1-bugteam, mysql-5.5-bugteam, mysql-trunk-bugfixing.
[5 Dec 2010 12:38] Bugs System
Pushed into mysql-trunk 5.6.1 (revid:alexander.nozdrin@oracle.com-20101205122447-6x94l4fmslpbttxj) (version source revid:alexander.nozdrin@oracle.com-20101205122447-6x94l4fmslpbttxj) (merge vers: 5.6.1) (pib:23)
[14 Dec 2010 6:43] Jon Stephens
Issue doesn't appear in any 5.6 release, so no changelog entry required there.

Waiting for pushes to 5.1 and 5.5 trees.
[17 Dec 2010 12:49] Bugs System
Pushed into mysql-5.1 5.1.55 (revid:georgi.kodinov@oracle.com-20101217124435-9imm43geck5u55qw) (version source revid:mats.kindahl@oracle.com-20101201193331-1c07sjno2g7m46ix) (merge vers: 5.1.55) (pib:24)
[17 Dec 2010 12:53] Bugs System
Pushed into mysql-5.5 5.5.9 (revid:georgi.kodinov@oracle.com-20101217124733-p1ivu6higouawv8l) (version source revid:luis.soares@oracle.com-20101130181706-mbuf93dt0v32j37s) (merge vers: 5.5.8) (pib:24)
[6 Jan 2011 4:20] Jon Stephens
Documented bugfix in the 5.1.55 and 5.5.9 changelogs as follows:

      When closing a session that used temporary tables, binary 
      logging could sometimes fail with a spurious -Failed to write 
      the DROP statement for temporary tables to binary log- error.

Closed.