| Bug #55387 | binlog.binlog_tmp_table crashes the server sporadically | ||
|---|---|---|---|
| Submitted: | 20 Jul 2010 6:44 | Modified: | 4 Aug 2010 16:42 |
| Reporter: | Alexander Nozdrin | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Replication | Severity: | S1 (Critical) |
| Version: | M3 (Celosia), M4 (Dahlia) | OS: | Any |
| Assigned to: | Luis Soares | CPU Architecture: | Any |
| Tags: | pb2, test failure | ||
[20 Jul 2010 15:21]
Alexander Nozdrin
It turned out that the crash is not new in trunk-bugfixing. Although the failure is reproduced now on FreeBSD only, it may affect any platform, since that code is not platform-specific.
[22 Jul 2010 9:19]
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/114121 3133 Luis Soares 2010-07-22 BUG#55387: binlog.binlog_tmp_table crashes the server sporadically There are two problems: 1. When closing temporary tables, during the THD clean up - and after the session connection was already closed, there is a chance we can push an error into the THD diagnostics area, if the writing of the implicit DROP event to the binary log fails for some reason. As a consequence an assertion can be triggered, because at that point the diagnostics area is already set. 2. Using push_warning with MYSQL_ERROR::WARN_LEVEL_ERROR is not a recomended practice, and should not be used. Given that close_temporary_tables is mostly called from THD::cleanup - ie, with the session already closed, we fix problem #1 by allowing the diagnostics area to be overwritten. There is one other place in the code that calls close_temporary_tables - while applying Start_log_event_v3. To cover that case, we make close_temporary_tables to return the error, thus, propagating upwards in the stack. To fix problem #2, we replace push_warning with sql_print_error. @ mysql-test/suite/binlog/t/binlog_tmp_table.test Test case. @ sql/log.cc Added fault injection point while writing an event. @ sql/log_event.cc Added handling of error returned by close_temporary_tables to Start_log_event_v3::do_apply_event. @ sql/sql_base.cc Three changes to close_temporary_tables: 1. it returns an integer now (instead of void) 2. it uses sql_print_error instead of push_warning when writing to binary log fails 3. we set can_overwrite_status before writing to the binary log, thence not risking triggering an assertion by any other push into diagnostics area happening inside mysql_bin_log.write. @ sql/sql_base.h Changed the interface of close_temporary_tables so that it returns int instead of void.
[22 Jul 2010 15:26]
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/114159 3133 Luis Soares 2010-07-22 BUG#55387: binlog.binlog_tmp_table crashes the server sporadically There are two problems: 1. When closing temporary tables, during the THD clean up - and after the session connection was already closed, there is a chance we can push an error into the THD diagnostics area, if the writing of the implicit DROP event to the binary log fails for some reason. As a consequence an assertion can be triggered, because at that point the diagnostics area is already set. 2. Using push_warning with MYSQL_ERROR::WARN_LEVEL_ERROR is a bug. Given that close_temporary_tables is mostly called from THD::cleanup - ie, with the session already closed, we fix problem #1 by allowing the diagnostics area to be overwritten. There is one other place in the code that calls close_temporary_tables - while applying Start_log_event_v3. To cover that case, we make close_temporary_tables to return the error, thus, propagating upwards in the stack. To fix problem #2, we replace push_warning with sql_print_error. @ sql/log_event.cc Added handling of error returned by close_temporary_tables to Start_log_event_v3::do_apply_event. @ sql/sql_base.cc Three changes to close_temporary_tables: 1. it returns a boolean now (instead of void) 2. it uses sql_print_error instead of push_warning when writing to binary log fails 3. we set can_overwrite_status before writing to the binary log, thence not risking triggering an assertion by any other push into diagnostics area happening inside mysql_bin_log.write. @ sql/sql_base.h Changed the interface of close_temporary_tables so that it returns bool instead of void.
[22 Jul 2010 15:57]
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/114162 3133 Luis Soares 2010-07-22 BUG#55387: binlog.binlog_tmp_table crashes the server sporadically There are two problems: 1. When closing temporary tables, during the THD clean up - and after the session connection was already closed, there is a chance we can push an error into the THD diagnostics area, if the writing of the implicit DROP event to the binary log fails for some reason. As a consequence an assertion can be triggered, because at that point the diagnostics area is already set. 2. Using push_warning with MYSQL_ERROR::WARN_LEVEL_ERROR is a bug. Given that close_temporary_tables is mostly called from THD::cleanup - ie, with the session already closed, we fix problem #1 by allowing the diagnostics area to be overwritten. There is one other place in the code that calls close_temporary_tables - while applying Start_log_event_v3. To cover that case, we make close_temporary_tables to return the error, thus, propagating upwards in the stack. To fix problem #2, we replace push_warning with sql_print_error. @ sql/log_event.cc Added handling of error returned by close_temporary_tables to Start_log_event_v3::do_apply_event. @ sql/sql_base.cc Three changes to close_temporary_tables: 1. it returns a boolean now (instead of void) 2. it uses sql_print_error instead of push_warning when writing to binary log fails 3. we set can_overwrite_status before writing to the binary log, thence not risking triggering an assertion by any other push into diagnostics area happening inside mysql_bin_log.write. @ sql/sql_base.h Changed the interface of close_temporary_tables so that it returns bool instead of void.
[28 Jul 2010 11:24]
Luis Soares
Queued in mysql-trunk-bugfixing and merged to mysql-next-mr-bugfixing: - http://pb2.norway.sun.com/web.py?template=push_details&push=1444835 - http://pb2.norway.sun.com/web.py?template=push_details&push=1444831
[4 Aug 2010 7:53]
Bugs System
Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100731131027-1n61gseejyxsqk5d) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)
[4 Aug 2010 8:08]
Bugs System
Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804080001-bny5271e65xo34ig) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)
[4 Aug 2010 8:24]
Bugs System
Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804081533-c1d3rbipo9e8rt1s) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)
[4 Aug 2010 9:04]
Bugs System
Pushed into mysql-next-mr (revid:alik@ibmvm-20100804081630-ntapn8bf9pko9vj3) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (pib:20)
[4 Aug 2010 16:42]
Jon Stephens
Documented bugfix in the 5.5.6 changelog as follows:
When closing temporary tables, after the session connection was
already closed, if the writing of the implicit DROP TABLE
statement into the binary log failed, it was possible for the
resulting error to be mishandled, triggering an assertion.
No further changelog entries required; closed.
Description: binlog.binlog_tmp_table started to crash the server on FreeBSD in trunk-bugfixing. First failure noticed in daily-trunk-bugfixing on 2010-07-16. It seems, that the reason might be in the following pushes: - marc.alff@oracle 2010-07-16 02:30:31 (http://tinyurl.com/2wors7q) - davi.arnaut@sun 2010-07-15 13:46:21 (http://tinyurl.com/2utk8qv) Symptoms: --------------------------------------------------- binlog.binlog_tmp_table [ fail ] Test ended at 2010-07-18 13:29:52 CURRENT_TEST: binlog.binlog_tmp_table mysqltest: At line 99: query 'RESET MASTER' failed: 2013: Lost connection to MySQL server during query The result from queries just before the failure was: < snip > insert into foo select * from tmp1_foo; insert into foo select * from tmp2_foo; truncate table tmp1_foo; truncate table tmp2_foo; flush logs; select * from foo; a 5 7 6 8 drop table foo; create table foo (a int); select * from foo; a 5 7 6 8 drop table foo; More results from queries before failure can be found in /export/home/pb2/test/sb_1-2055889-1279450178.59/mysql-5.5.6-m3-freebsd7.0-i386-test/mysql-test/var-n_mix/log/binlog_tmp_table.log Server [mysqld.1 - pid: 44776, winpid: 44776, exit: 256] failed during test run Server log from this test: Assertion failed: ((level != MYSQL_ERROR::WARN_LEVEL_ERROR) || (code == 1005) || (code == 1478)), function push_warning, file /export/home/pb2/build/sb_0-2054566-1279442848.06/mysql-5.5.6-m3/sql/sql_error.cc, line 600. 100718 14:29:49 - mysqld got signal 6 ; This could be because you hit a bug. It is also possible that this binary or one of the libraries it was linked against is corrupt, improperly built, or misconfigured. This error can also be caused by malfunctioning hardware. We will try our best to scrape up some info that will hopefully help diagnose the problem, but since we have already crashed, something is definitely wrong and this may fail. key_buffer_size=1048576 read_buffer_size=131072 max_used_connections=4 max_threads=151 thread_count=4 connection_count=4 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 60059 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Writing a core file --------------------------------------------------- How to repeat: Check out PB.