List:Commits« Previous MessageNext Message »
From:Luis Soares Date:October 21 2010 2:06pm
Subject:bzr commit into mysql-5.1-bugteam branch (luis.soares:3545) Bug#57288
View as plain text  
#At file:///home/lsoares/Workspace/bzr/work/bugfixing/57288/mysql-5.1-bugteam/ based on revid:li-bing.song@stripped

 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.

    modified:
      sql/log.cc
=== modified file 'sql/log.cc'
--- a/sql/log.cc	2010-10-20 18:21:40 +0000
+++ b/sql/log.cc	2010-10-21 14:06:03 +0000
@@ -3037,7 +3037,7 @@ bool MYSQL_BIN_LOG::reset_logs(THD* thd)
   }
 
   /* Start logging with a new file */
-  close(LOG_CLOSE_INDEX);
+  close(LOG_CLOSE_INDEX | LOG_CLOSE_TO_BE_OPENED);
   if ((error= my_delete_allow_opened(index_file_name, MYF(0))))	// Reset (open will update)
   {
     if (my_errno == ENOENT) 
@@ -4273,6 +4273,7 @@ bool MYSQL_BIN_LOG::write(Log_event *eve
   THD *thd= event_info->thd;
   bool error= 1;
   DBUG_ENTER("MYSQL_BIN_LOG::write(Log_event *)");
+  DBUG_ASSERT(is_open());
 
   if (thd->binlog_evt_union.do_union)
   {
@@ -4302,160 +4303,152 @@ bool MYSQL_BIN_LOG::write(Log_event *eve
 
   pthread_mutex_lock(&LOCK_log);
 
+  IO_CACHE *file= &log_file;
+#ifdef HAVE_REPLICATION
   /*
-     In most cases this is only called if 'is_open()' is true; in fact this is
-     mostly called if is_open() *was* true a few instructions before, but it
-     could have changed since.
-  */
-  if (likely(is_open()))
+    In the future we need to add to the following if tests like
+    "do the involved tables match (to be implemented)
+    binlog_[wild_]{do|ignore}_table?" (WL#1049)"
+  */
+  const char *local_db= event_info->get_db();
+  if ((thd && !(thd->options & OPTION_BIN_LOG)) ||
+      (thd->lex->sql_command != SQLCOM_ROLLBACK_TO_SAVEPOINT &&
+       thd->lex->sql_command != SQLCOM_SAVEPOINT &&
+       !binlog_filter->db_ok(local_db)))
   {
-    IO_CACHE *file= &log_file;
-#ifdef HAVE_REPLICATION
-    /*
-      In the future we need to add to the following if tests like
-      "do the involved tables match (to be implemented)
-      binlog_[wild_]{do|ignore}_table?" (WL#1049)"
-    */
-    const char *local_db= event_info->get_db();
-    if ((thd && !(thd->options & OPTION_BIN_LOG)) ||
-	(thd->lex->sql_command != SQLCOM_ROLLBACK_TO_SAVEPOINT &&
-         thd->lex->sql_command != SQLCOM_SAVEPOINT &&
-         !binlog_filter->db_ok(local_db)))
-    {
-      VOID(pthread_mutex_unlock(&LOCK_log));
-      DBUG_RETURN(0);
-    }
+    VOID(pthread_mutex_unlock(&LOCK_log));
+    DBUG_RETURN(0);
+  }
 #endif /* HAVE_REPLICATION */
 
 #if defined(USING_TRANSACTIONS) 
-    /*
-      Should we write to the binlog cache or to the binlog on disk?
+  /*
+    Should we write to the binlog cache or to the binlog on disk?
 
-      Write to the binlog cache if:
-      1 - a transactional engine/table is updated (stmt_has_updated_trans_table == TRUE);
-      2 - or the event asks for it (cache_stmt == TRUE);
-      3 - or the cache is already not empty (meaning we're in a transaction;
-      note that the present event could be about a non-transactional table, but
-      still we need to write to the binlog cache in that case to handle updates
-      to mixed trans/non-trans table types).
-      
-      Write to the binlog on disk if only a non-transactional engine is
-      updated and:
-      1 - the binlog cache is empty or;
-      2 - --binlog-direct-non-transactional-updates is set and we are about to
-      use the statement format. When using the row format (cache_stmt == TRUE).
-    */
-    if (opt_using_transactions && thd)
-    {
-      if (thd->binlog_setup_trx_data())
-        goto err;
+    Write to the binlog cache if:
+    1 - a transactional engine/table is updated (stmt_has_updated_trans_table == TRUE);
+    2 - or the event asks for it (cache_stmt == TRUE);
+    3 - or the cache is already not empty (meaning we're in a transaction;
+    note that the present event could be about a non-transactional table, but
+    still we need to write to the binlog cache in that case to handle updates
+    to mixed trans/non-trans table types).
+    
+    Write to the binlog on disk if only a non-transactional engine is
+    updated and:
+    1 - the binlog cache is empty or;
+    2 - --binlog-direct-non-transactional-updates is set and we are about to
+    use the statement format. When using the row format (cache_stmt == TRUE).
+  */
+  if (opt_using_transactions && thd)
+  {
+    if (thd->binlog_setup_trx_data())
+      goto err;
 
-      binlog_trx_data *const trx_data=
-        (binlog_trx_data*) thd_get_ha_data(thd, binlog_hton);
-      IO_CACHE *trans_log= &trx_data->trans_log;
-      my_off_t trans_log_pos= my_b_tell(trans_log);
-      if (event_info->get_cache_stmt() || stmt_has_updated_trans_table(thd) ||
-          (!thd->variables.binlog_direct_non_trans_update &&
-            trans_log_pos != 0))
-      {
-        DBUG_PRINT("info", ("Using trans_log: cache: %d, trans_log_pos: %lu",
-                            event_info->get_cache_stmt(),
-                            (ulong) trans_log_pos));
-        thd->binlog_start_trans_and_stmt();
-        file= trans_log;
-      }
-      /*
-        TODO as Mats suggested, for all the cases above where we write to
-        trans_log, it sounds unnecessary to lock LOCK_log. We should rather
-        test first if we want to write to trans_log, and if not, lock
-        LOCK_log.
-      */
+    binlog_trx_data *const trx_data=
+      (binlog_trx_data*) thd_get_ha_data(thd, binlog_hton);
+    IO_CACHE *trans_log= &trx_data->trans_log;
+    my_off_t trans_log_pos= my_b_tell(trans_log);
+    if (event_info->get_cache_stmt() || stmt_has_updated_trans_table(thd) ||
+        (!thd->variables.binlog_direct_non_trans_update &&
+          trans_log_pos != 0))
+    {
+      DBUG_PRINT("info", ("Using trans_log: cache: %d, trans_log_pos: %lu",
+                          event_info->get_cache_stmt(),
+                          (ulong) trans_log_pos));
+      thd->binlog_start_trans_and_stmt();
+      file= trans_log;
     }
-#endif /* USING_TRANSACTIONS */
-    DBUG_PRINT("info",("event type: %d",event_info->get_type_code()));
-
     /*
-      No check for auto events flag here - this write method should
-      never be called if auto-events are enabled
+      TODO as Mats suggested, for all the cases above where we write to
+      trans_log, it sounds unnecessary to lock LOCK_log. We should rather
+      test first if we want to write to trans_log, and if not, lock
+      LOCK_log.
     */
+  }
+#endif /* USING_TRANSACTIONS */
+  DBUG_PRINT("info",("event type: %d",event_info->get_type_code()));
 
-    /*
-      1. Write first log events which describe the 'run environment'
-      of the SQL command
-    */
+  /*
+    No check for auto events flag here - this write method should
+    never be called if auto-events are enabled
+  */
 
-    /*
-      If row-based binlogging, Insert_id, Rand and other kind of "setting
-      context" events are not needed.
-    */
-    if (thd)
+  /*
+    1. Write first log events which describe the 'run environment'
+    of the SQL command
+  */
+
+  /*
+    If row-based binlogging, Insert_id, Rand and other kind of "setting
+    context" events are not needed.
+  */
+  if (thd)
+  {
+    if (!thd->current_stmt_binlog_row_based)
     {
-      if (!thd->current_stmt_binlog_row_based)
+      if (thd->stmt_depends_on_first_successful_insert_id_in_prev_stmt)
       {
-        if (thd->stmt_depends_on_first_successful_insert_id_in_prev_stmt)
-        {
-          Intvar_log_event e(thd,(uchar) LAST_INSERT_ID_EVENT,
-                             thd->first_successful_insert_id_in_prev_stmt_for_binlog);
-          if (e.write(file))
-            goto err;
-        }
-        if (thd->auto_inc_intervals_in_cur_stmt_for_binlog.nb_elements() > 0)
-        {
-          DBUG_PRINT("info",("number of auto_inc intervals: %u",
-                             thd->auto_inc_intervals_in_cur_stmt_for_binlog.
-                             nb_elements()));
-          Intvar_log_event e(thd, (uchar) INSERT_ID_EVENT,
-                             thd->auto_inc_intervals_in_cur_stmt_for_binlog.
-                             minimum());
-          if (e.write(file))
-            goto err;
-        }
-        if (thd->rand_used)
+        Intvar_log_event e(thd,(uchar) LAST_INSERT_ID_EVENT,
+                           thd->first_successful_insert_id_in_prev_stmt_for_binlog);
+        if (e.write(file))
+          goto err;
+      }
+      if (thd->auto_inc_intervals_in_cur_stmt_for_binlog.nb_elements() > 0)
+      {
+        DBUG_PRINT("info",("number of auto_inc intervals: %u",
+                           thd->auto_inc_intervals_in_cur_stmt_for_binlog.
+                           nb_elements()));
+        Intvar_log_event e(thd, (uchar) INSERT_ID_EVENT,
+                           thd->auto_inc_intervals_in_cur_stmt_for_binlog.
+                           minimum());
+        if (e.write(file))
+          goto err;
+      }
+      if (thd->rand_used)
+      {
+        Rand_log_event e(thd,thd->rand_saved_seed1,thd->rand_saved_seed2);
+        if (e.write(file))
+          goto err;
+      }
+      if (thd->user_var_events.elements)
+      {
+        for (uint i= 0; i < thd->user_var_events.elements; i++)
         {
-          Rand_log_event e(thd,thd->rand_saved_seed1,thd->rand_saved_seed2);
+          BINLOG_USER_VAR_EVENT *user_var_event;
+          get_dynamic(&thd->user_var_events,(uchar*) &user_var_event, i);
+          User_var_log_event e(thd, user_var_event->user_var_event->name.str,
+                               user_var_event->user_var_event->name.length,
+                               user_var_event->value,
+                               user_var_event->length,
+                               user_var_event->type,
+                               user_var_event->charset_number);
           if (e.write(file))
             goto err;
         }
-        if (thd->user_var_events.elements)
-        {
-          for (uint i= 0; i < thd->user_var_events.elements; i++)
-          {
-            BINLOG_USER_VAR_EVENT *user_var_event;
-            get_dynamic(&thd->user_var_events,(uchar*) &user_var_event, i);
-            User_var_log_event e(thd, user_var_event->user_var_event->name.str,
-                                 user_var_event->user_var_event->name.length,
-                                 user_var_event->value,
-                                 user_var_event->length,
-                                 user_var_event->type,
-                                 user_var_event->charset_number);
-            if (e.write(file))
-              goto err;
-          }
-        }
       }
     }
+  }
 
-    /*
-       Write the SQL command
-     */
+  /*
+     Write the SQL command
+   */
 
-    if (event_info->write(file) || 
-        DBUG_EVALUATE_IF("injecting_fault_writing", 1, 0))
-      goto err;
+  if (event_info->write(file) || 
+      DBUG_EVALUATE_IF("injecting_fault_writing", 1, 0))
+    goto err;
 
-    if (file == &log_file) // we are writing to the real log (disk)
-    {
-      if (flush_and_sync())
-	goto err;
-      signal_update();
-      rotate_and_purge(RP_LOCK_LOG_IS_ALREADY_LOCKED);
-    }
-    error=0;
+  if (file == &log_file) // we are writing to the real log (disk)
+  {
+    if (flush_and_sync())
+      goto err;
+    signal_update();
+    rotate_and_purge(RP_LOCK_LOG_IS_ALREADY_LOCKED);
+  }
+  error=0;
 
 err:
-    if (error)
-      set_write_error(thd);
-  }
+  if (error)
+    set_write_error(thd);
 
   pthread_mutex_unlock(&LOCK_log);
   DBUG_RETURN(error);
@@ -4799,80 +4792,79 @@ bool MYSQL_BIN_LOG::write(THD *thd, IO_C
   /* NULL would represent nothing to replicate after ROLLBACK */
   DBUG_ASSERT(commit_event != NULL);
 
+  /* assert that the binlog is opened */
   DBUG_ASSERT(is_open());
-  if (likely(is_open()))                       // Should always be true
+
+  /*
+    We only bother to write to the binary log if there is anything
+    to write.
+   */
+  if (my_b_tell(cache) > 0)
   {
     /*
-      We only bother to write to the binary log if there is anything
-      to write.
-     */
-    if (my_b_tell(cache) > 0)
-    {
-      /*
-        Log "BEGIN" at the beginning of every transaction.  Here, a
-        transaction is either a BEGIN..COMMIT block or a single
-        statement in autocommit mode.
-      */
-      Query_log_event qinfo(thd, STRING_WITH_LEN("BEGIN"), TRUE, TRUE, 0);
-
-      /*
-        Now this Query_log_event has artificial log_pos 0. It must be
-        adjusted to reflect the real position in the log. Not doing it
-        would confuse the slave: it would prevent this one from
-        knowing where he is in the master's binlog, which would result
-        in wrong positions being shown to the user, MASTER_POS_WAIT
-        undue waiting etc.
-      */
-      if (qinfo.write(&log_file))
-        goto err;
+      Log "BEGIN" at the beginning of every transaction.  Here, a
+      transaction is either a BEGIN..COMMIT block or a single
+      statement in autocommit mode.
+    */
+    Query_log_event qinfo(thd, STRING_WITH_LEN("BEGIN"), TRUE, TRUE, 0);
 
-      DBUG_EXECUTE_IF("crash_before_writing_xid",
-                      {
-                        if ((write_error= write_cache(cache, false, true)))
-                          DBUG_PRINT("info", ("error writing binlog cache: %d",
-                                               write_error));
-                        DBUG_PRINT("info", ("crashing before writing xid"));
-                        DBUG_SUICIDE();
-                      });
+    /*
+      Now this Query_log_event has artificial log_pos 0. It must be
+      adjusted to reflect the real position in the log. Not doing it
+      would confuse the slave: it would prevent this one from
+      knowing where he is in the master's binlog, which would result
+      in wrong positions being shown to the user, MASTER_POS_WAIT
+      undue waiting etc.
+    */
+    if (qinfo.write(&log_file))
+      goto err;
 
-      if ((write_error= write_cache(cache, false, false)))
-        goto err;
+    DBUG_EXECUTE_IF("crash_before_writing_xid",
+                    {
+                      if ((write_error= write_cache(cache, false, true)))
+                        DBUG_PRINT("info", ("error writing binlog cache: %d",
+                                             write_error));
+                      DBUG_PRINT("info", ("crashing before writing xid"));
+                      DBUG_SUICIDE();
+                    });
 
-      if (commit_event && commit_event->write(&log_file))
-        goto err;
+    if ((write_error= write_cache(cache, false, false)))
+      goto err;
 
-      if (incident && write_incident(thd, FALSE))
-        goto err;
+    if (commit_event && commit_event->write(&log_file))
+      goto err;
 
-      if (flush_and_sync())
-        goto err;
-      DBUG_EXECUTE_IF("half_binlogged_transaction", DBUG_SUICIDE(););
-      if (cache->error)				// Error on read
-      {
-        sql_print_error(ER(ER_ERROR_ON_READ), cache->file_name, errno);
-        write_error=1;				// Don't give more errors
-        goto err;
-      }
-      signal_update();
-    }
+    if (incident && write_incident(thd, FALSE))
+      goto err;
 
-    /*
-      if commit_event is Xid_log_event, increase the number of
-      prepared_xids (it's decreasd in ::unlog()). Binlog cannot be rotated
-      if there're prepared xids in it - see the comment in new_file() for
-      an explanation.
-      If the commit_event is not Xid_log_event (then it's a Query_log_event)
-      rotate binlog, if necessary.
-    */
-    if (commit_event && commit_event->get_type_code() == XID_EVENT)
+    if (flush_and_sync())
+      goto err;
+    DBUG_EXECUTE_IF("half_binlogged_transaction", DBUG_SUICIDE(););
+    if (cache->error)				// Error on read
     {
-      pthread_mutex_lock(&LOCK_prep_xids);
-      prepared_xids++;
-      pthread_mutex_unlock(&LOCK_prep_xids);
+      sql_print_error(ER(ER_ERROR_ON_READ), cache->file_name, errno);
+      write_error=1;				// Don't give more errors
+      goto err;
     }
-    else
-      rotate_and_purge(RP_LOCK_LOG_IS_ALREADY_LOCKED);
+    signal_update();
+  }
+
+  /*
+    if commit_event is Xid_log_event, increase the number of
+    prepared_xids (it's decreasd in ::unlog()). Binlog cannot be rotated
+    if there're prepared xids in it - see the comment in new_file() for
+    an explanation.
+    If the commit_event is not Xid_log_event (then it's a Query_log_event)
+    rotate binlog, if necessary.
+  */
+  if (commit_event && commit_event->get_type_code() == XID_EVENT)
+  {
+    pthread_mutex_lock(&LOCK_prep_xids);
+    prepared_xids++;
+    pthread_mutex_unlock(&LOCK_prep_xids);
   }
+  else
+    rotate_and_purge(RP_LOCK_LOG_IS_ALREADY_LOCKED);
   VOID(pthread_mutex_unlock(&LOCK_log));
 
   DBUG_RETURN(0);


Attachment: [text/bzr-bundle] bzr/luis.soares@oracle.com-20101021140603-ltqoxn9q755j3hzd.bundle
Thread
bzr commit into mysql-5.1-bugteam branch (luis.soares:3545) Bug#57288Luis Soares21 Oct