| 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: | |
| 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 | ||
[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.
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: .