List:Commits« Previous MessageNext Message »
From:Luis Soares Date:July 22 2010 9:19am
Subject:bzr commit into mysql-trunk-bugfixing branch (luis.soares:3133)
Bug#55387
View as plain text  
#At file:///home/lsoares/Workspace/bzr/work/bugfixing/55387/mysql-trunk-bugfixing/ based on revid:jonathan.perkin@stripped

 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.

    modified:
      mysql-test/suite/binlog/r/binlog_tmp_table.result
      mysql-test/suite/binlog/t/binlog_tmp_table.test
      sql/log.cc
      sql/log_event.cc
      sql/sql_base.cc
      sql/sql_base.h
=== modified file 'mysql-test/suite/binlog/r/binlog_tmp_table.result'
--- a/mysql-test/suite/binlog/r/binlog_tmp_table.result	2010-04-27 11:25:55 +0000
+++ b/mysql-test/suite/binlog/r/binlog_tmp_table.result	2010-07-22 09:19:06 +0000
@@ -40,3 +40,10 @@ ERROR 42S01: Table 't1' already exists
 insert into t1 values(1);
 DROP DATABASE b51226;
 FLUSH LOGS;
+RESET MASTER;
+SET @old_debug= @global.debug;
+CREATE TEMPORARY TABLE t1 (a int);
+INSERT INTO t1 VALUES (1),(2);
+SET GLOBAL DEBUG= '+d,fault_injection_event_wite_error';
+SET GLOBAL DEBUG= @old_debug;
+RESET MASTER;

=== modified file 'mysql-test/suite/binlog/t/binlog_tmp_table.test'
--- a/mysql-test/suite/binlog/t/binlog_tmp_table.test	2010-04-28 12:47:49 +0000
+++ b/mysql-test/suite/binlog/t/binlog_tmp_table.test	2010-07-22 09:19:06 +0000
@@ -157,3 +157,34 @@ FLUSH LOGS;
 #            instead of failing with "Table 'XXX.YYY' doesn't exist"
 -- let $MYSQLD_DATADIR= `select @@datadir`
 -- exec $MYSQL_BINLOG $MYSQLD_DATADIR/master-bin.000001 | $MYSQL
+
+#
+# BUG#55387: binlog.binlog_tmp_table crashes the server sporadically
+#
+
+#
+# DESCRIPTION
+# ===========
+#
+# On con1 create a temporary table, insert some values
+# and disconnect. This shall log an implicit drop for the
+# temporary table. However, before droping we activate
+# fault injection so that when writing the implicit drop
+# event we get an error. This shall push an error into the
+# stmt_da, but after the fix, will not cause the ASSERTION.
+#
+
+RESET MASTER;
+SET @old_debug= @global.debug;
+connect (con1,localhost,root,,test,$MASTER_MYPORT,$MASTER_MYSOCK);
+connection con1;
+CREATE TEMPORARY TABLE t1 (a int);
+INSERT INTO t1 VALUES (1),(2);
+SET GLOBAL DEBUG= '+d,fault_injection_event_wite_error';
+disconnect con1;
+connection default;
+let $wait_binlog_event= DROP;
+--source include/wait_for_binlog_event.inc
+SET GLOBAL DEBUG= @old_debug;
+RESET MASTER;
+

=== modified file 'sql/log.cc'
--- a/sql/log.cc	2010-07-15 13:47:50 +0000
+++ b/sql/log.cc	2010-07-22 09:19:06 +0000
@@ -4804,7 +4804,7 @@ unlock:
       mysql_mutex_unlock(&LOCK_log);
     }
 
-    if (error)
+    if (error || DBUG_EVALUATE_IF("fault_injection_event_write_error", 1, 0))
     {
       set_write_error(thd);
       if (check_write_error(thd) && cache_data &&

=== modified file 'sql/log_event.cc'
--- a/sql/log_event.cc	2010-07-15 13:47:50 +0000
+++ b/sql/log_event.cc	2010-07-22 09:19:06 +0000
@@ -3719,6 +3719,7 @@ bool Start_log_event_v3::write(IO_CACHE*
 int Start_log_event_v3::do_apply_event(Relay_log_info const *rli)
 {
   DBUG_ENTER("Start_log_event_v3::do_apply_event");
+  int error= 0;
   switch (binlog_version)
   {
   case 3:
@@ -3731,7 +3732,7 @@ int Start_log_event_v3::do_apply_event(R
     */
     if (created)
     {
-      close_temporary_tables(thd);
+      error= close_temporary_tables(thd);
       cleanup_load_tmpdir();
     }
     else
@@ -3759,7 +3760,7 @@ int Start_log_event_v3::do_apply_event(R
         Can distinguish, based on the value of 'created': this event was
         generated at master startup.
       */
-      close_temporary_tables(thd);
+      error= close_temporary_tables(thd);
     }
     /*
       Otherwise, can't distinguish a Start_log_event generated at
@@ -3771,7 +3772,7 @@ int Start_log_event_v3::do_apply_event(R
     /* this case is impossible */
     DBUG_RETURN(1);
   }
-  DBUG_RETURN(0);
+  DBUG_RETURN(error);
 }
 #endif /* defined(HAVE_REPLICATION) && !defined(MYSQL_CLIENT) */
 

=== modified file 'sql/sql_base.cc'
--- a/sql/sql_base.cc	2010-07-15 13:47:50 +0000
+++ b/sql/sql_base.cc	2010-07-22 09:19:06 +0000
@@ -1634,7 +1634,7 @@ static inline uint  tmpkeyval(THD *thd, 
   creates one DROP TEMPORARY TABLE binlog event for each pseudo-thread 
 */
 
-void close_temporary_tables(THD *thd)
+int close_temporary_tables(THD *thd)
 {
   DBUG_ENTER("close_temporary_tables");
   TABLE *table;
@@ -1642,9 +1642,10 @@ void close_temporary_tables(THD *thd)
   TABLE *prev_table;
   /* Assume thd->variables.option_bits has OPTION_QUOTE_SHOW_CREATE */
   bool was_quote_show= TRUE;
+  int error= 0;
 
   if (!thd->temporary_tables)
-    DBUG_VOID_RETURN;
+    DBUG_RETURN(error);
 
   if (!mysql_bin_log.is_open())
   {
@@ -1655,7 +1656,7 @@ void close_temporary_tables(THD *thd)
       close_temporary(table, 1, 1);
     }
     thd->temporary_tables= 0;
-    DBUG_VOID_RETURN;
+    DBUG_RETURN(error);
   }
 
   /* Better add "if exists", in case a RESET MASTER has been done */
@@ -1754,11 +1755,27 @@ void close_temporary_tables(THD *thd)
       qinfo.db= db.ptr();
       qinfo.db_len= db.length();
       thd->variables.character_set_client= cs_save;
-      if (mysql_bin_log.write(&qinfo))
+
+      thd->stmt_da->can_overwrite_status= TRUE;
+      if ((error= error | mysql_bin_log.write(&qinfo)))
       {
-        push_warning(thd, MYSQL_ERROR::WARN_LEVEL_ERROR, MYF(0),
-                     "Failed to write the DROP statement for temporary tables to binary log");
+        /*
+          If we're here following THD::cleanup, thence the connection
+          has been closed already. So lets print a message to the
+          error log instead of pushing yet another error into the
+          stmt_da.
+
+          Also, we keep the error flag so that we porpagate the error
+          up in the stack. This way, if we're the SQL thread we notice
+          that close_temporary_tables failed. (Actually, the SQL
+          thread only calls close_temporary_tables while applying old
+          Start_log_event_v3 events.)
+        */
+        sql_print_error("Failed to write the DROP statement for "
+                        "temporary tables to binary log");
       }
+      thd->stmt_da->can_overwrite_status= FALSE;
+
       thd->variables.pseudo_thread_id= save_pseudo_thread_id;
       thd->thread_specific_used= save_thread_specific_used;
     }
@@ -1771,7 +1788,7 @@ void close_temporary_tables(THD *thd)
   if (!was_quote_show)
     thd->variables.option_bits&= ~OPTION_QUOTE_SHOW_CREATE; /* restore option */
   thd->temporary_tables=0;
-  DBUG_VOID_RETURN;
+  DBUG_RETURN(error);
 }
 
 /*

=== modified file 'sql/sql_base.h'
--- a/sql/sql_base.h	2010-06-11 15:28:18 +0000
+++ b/sql/sql_base.h	2010-07-22 09:19:06 +0000
@@ -222,7 +222,7 @@ int decide_logging_format(THD *thd, TABL
 void free_io_cache(TABLE *entry);
 void intern_close_table(TABLE *entry);
 bool close_thread_table(THD *thd, TABLE **table_ptr);
-void close_temporary_tables(THD *thd);
+int close_temporary_tables(THD *thd);
 TABLE_LIST *unique_table(THD *thd, TABLE_LIST *table, TABLE_LIST *table_list,
                          bool check_alias);
 int drop_temporary_table(THD *thd, TABLE_LIST *table_list);


Attachment: [text/bzr-bundle] bzr/luis.soares@sun.com-20100722091906-v23orepleyobbanq.bundle
Thread
bzr commit into mysql-trunk-bugfixing branch (luis.soares:3133)Bug#55387Luis Soares22 Jul
  • Re: bzr commit into mysql-trunk-bugfixing branch (luis.soares:3133)Bug#55387Davi Arnaut22 Jul
    • Re: bzr commit into mysql-trunk-bugfixing branch (luis.soares:3133)Bug#55387Luís Soares22 Jul
      • Re: bzr commit into mysql-trunk-bugfixing branch (luis.soares:3133)Bug#55387Davi Arnaut22 Jul
        • Re: bzr commit into mysql-trunk-bugfixing branch (luis.soares:3133)Bug#55387Luís Soares22 Jul
    • Re: bzr commit into mysql-trunk-bugfixing branch (luis.soares:3133)Bug#55387Konstantin Osipov22 Jul