MySQL Lists are EOL. Please join:

List:Commits« Previous MessageNext Message »
From:Andrei Elkin Date:September 21 2009 9:51pm
Subject:Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)
Bug#37148
View as plain text  
Zhen Xing, hello.

I have some concerns, questions, comments and remarks.
Besides, I believe this work rather big patch would have less chances
to break anything if we had a test. I suggest to add one an error
simulation inside MYSQL_BIN_LOG::write() and activate it in the test.

> Andrei Elkin wrote:
>> Zhen Xing, hello.
>> 
>> > #At file:///media/sdb2/hezx/work/mysql/bzrwork/b37148/5.1-bugteam/ based on
> revid:aelkin@stripped
>> >
>> >  2973 He Zhenxing	2009-08-20
>> >       BUG#37148 Most callers of mysql_bin_log.write ignore the return
> result
>> >       
>> >       The return value of mysql_bin_log.write was ignored by most callers,
>> >       which may lead to inconsistent on master and slave if the transaction
>> >       was committed while the binlog was not correctly written.
>> 
>> I think it's important either to provide a test case proving the
>> complaining lines are not longer valid after your patch, or to
>> describe specifically how incorectness can be gained.
>> 
>
> I think we already have decided on this in the conference meeting that a
> test case is not needed for this.
>
> Please check this:
>  
> https://intranet.mysql.com/~lthalmann/ltplan.pl?file=mom-rpl.org&section=MOM-RPL-090902
>

My question carried two alternatives. If one doesn't like the testing
idea he has to compensate that by description what is the bug, what
is fixed and what is not.
Previously I thought testing would be difficult while the problem does
not match to that. Now I am inclined to reconsider it.
Considering rather big volume of changes I think we need at least a simple error
simulation test that would verify affected code branches.

>> 
>> As it stands the whole idea of the bug complaint is to optimize the error
>> path in that to react on an error condition sooner and not to do some
>> extra work.
>
> Yes, I think it's good to react on the error sooner, for example if we
> are doing a LOAD DATA statement to load a big hunk of data and if
> binlogging fails at the beginning, it would be much better to check for
> this error and quit the statement early then wait until the end of the
> statement. And I also think it would make the code clearer and less
> error prone.
>

Your comments confirm the bug is rather about optimization.
The existing logics of examining thd->main_da->is_error() at the end
of query execution does not seem to be compromised.
Correct me if it is said wrong.

Considering the current patch, I have some concerns, comments and
idea, please read on.

CONCERNS:

I have noticed some dangerous places.
Your patch forces early return from some functions like

@@ -2029,8 +2030,9 @@ ndb_binlog_thread_handle_schema_event(TH
         case SOT_CLEAR_SLOCK:
           abort();
         }
-        if (log_query && ndb_binlog_running)
-          ndb_binlog_query(thd, schema);
+        if (log_query && ndb_binlog_running &&
+            ndb_binlog_query(thd, schema))
+          DBUG_RETURN(1);

but I wonder if the early return does not leave out
the functions' epilogs. The qouted
ndb_binlog_thread_handle_schema_event()

        if (log_query && ndb_binlog_running)
          ndb_binlog_query(thd, schema);

follows with
        
        if (bitmap_is_set(&slock, node_id))
        {
          if (post_epoch_unlock)
            post_epoch_unlock_list->push_back(schema, mem_root);
          else
            ndbcluster_update_slock(thd, schema->db, schema->name);
        }
      }
      DBUG_RETURN(0);


It's evident your patch eliminates the `if (bitmap_is_set...)'.
I would not do that unless ha_ndbcluster_binlog.cc maintainers are
okay.


Similarly here

@@ -2288,14 +2290,15 @@ ndb_binlog_thread_handle_schema_event_po
         share= 0;
       }
     }
-    if (ndb_binlog_running && log_query)
-      ndb_binlog_query(thd, schema);
+    if (ndb_binlog_running && log_query &&
+        ndb_binlog_query(thd, schema))
+      DBUG_RETURN(1);

Similarly here

=== modified file 'sql/sql_insert.cc'
--- a/sql/sql_insert.cc	2009-06-22 14:01:42 +0000
+++ b/sql/sql_insert.cc	2009-08-20 09:53:53 +0000
@@ -2683,10 +2683,11 @@ bool Delayed_insert::handle_inserts(void
         will be binlogged together as one single Table_map event and one
         single Rows event.
       */
-      thd.binlog_query(THD::ROW_QUERY_TYPE,
-                       row->query.str, row->query.length,
-                       FALSE, FALSE, errcode);
-
+      if (thd.binlog_query(THD::ROW_QUERY_TYPE,
+                           row->query.str, row->query.length,
+                           FALSE, FALSE, errcode))
+        goto err;
+      

where `goto err' bypasses

    if (table->s->blob_fields)
      free_delayed_insert_blobs(table);

that could be a part of a cleanup, as I read it.

You took care of a cleanup, good, 

   table->file->ha_release_auto_increment();

in the following hunk

@@ -3207,16 +3209,21 @@ bool select_insert::send_eof()
     events are in the transaction cache and will be written when
     ha_autocommit_or_rollback() is issued below.
   */
-  if (mysql_bin_log.is_open())
+  if (mysql_bin_log.is_open() &&
+      (!error || thd->transaction.stmt.modified_non_trans_table))
   {
     int errcode= 0;
     if (!error)
       thd->clear_error();
     else
       errcode= query_error_code(thd, killed_status == THD::NOT_KILLED);
-    thd->binlog_query(THD::ROW_QUERY_TYPE,
-                      thd->query, thd->query_length,
-                      trans_table, FALSE, errcode);
+    if (thd->binlog_query(THD::ROW_QUERY_TYPE,
+                          thd->query, thd->query_length,
+                          trans_table, FALSE, errcode))
+    {
+      table->file->ha_release_auto_increment();
+      DBUG_RETURN(1);
+    }

But the resulting new code does not look pretty:

if (thd->binlog_query(..)
{
     table->file->ha_release_auto_increment();
     DBUG_RETURN(1);
}
table->file->ha_release_auto_increment();


Some more findings.

   @@ -6004,15 +6005,17 @@ bool mysql_revoke_all(THD *thd,  List <L

   VOID(pthread_mutex_unlock(&acl_cache->lock));

   -  write_bin_log(thd, FALSE, thd->query, thd->query_length);
   +  int binlog_error=
   +    write_bin_log(thd, FALSE, thd->query, thd->query_length);

   rw_unlock(&LOCK_grant);
   close_thread_tables(thd);

   -  if (result)
   +  /* error for writing binary log has already been reported */
   +  if (result && !binlog_error)
   my_message(ER_REVOKE_GRANTS, ER(ER_REVOKE_GRANTS), MYF(0));

   -  DBUG_RETURN(result);
   +  DBUG_RETURN(result || binlog_error);
   }
 

Obviously, the old code is okay:

   if (result)
      my_message()

because the returned combined result
   +  DBUG_RETURN(result || binlog_error);
is not yet merged at that point.


=== modified file 'sql/sql_base.cc'
--- a/sql/sql_base.cc	2009-06-19 08:24:43 +0000
+++ b/sql/sql_base.cc	2009-08-20 09:53:53 +0000
@@ -1333,7 +1333,8 @@ void close_thread_tables(THD *thd)
       handled either before writing a query log event (inside
       binlog_query()) or when preparing a pending event.
      */
-    thd->binlog_flush_pending_rows_event(TRUE);
+    /* TODO: I (hezx) think the error here should not be ignored */
+    (void)thd->binlog_flush_pending_rows_event(TRUE);
     mysql_unlock_tables(thd, thd->lock);
     thd->lock=0;
   }

I don't think you need such TODO here. The error is not ignored but
rather its check-out delayed till net_end_statement().

Similar hunk follows:

=== modified file 'sql/sql_delete.cc'
--- a/sql/sql_delete.cc	2009-06-19 08:24:43 +0000
+++ b/sql/sql_delete.cc	2009-08-20 09:53:53 +0000
@@ -841,9 +841,10 @@ void multi_delete::abort()
     if (mysql_bin_log.is_open())
     {
       int errcode= query_error_code(thd, thd->killed == THD::NOT_KILLED);
-      thd->binlog_query(THD::ROW_QUERY_TYPE,
-                        thd->query, thd->query_length,
-                        transactional_tables, FALSE, errcode);
+      /* possible error of writing binary log is ignored deliberately */
+      (void) thd->binlog_query(THD::ROW_QUERY_TYPE,
+                               thd->query, thd->query_length,
+                               transactional_tables, FALSE, errcode);

Yet another with the same comment:

@@ -3784,7 +3794,8 @@ void select_create::abort()
   select_insert::abort();
   thd->transaction.stmt.modified_non_trans_table= FALSE;
   reenable_binlog(thd);
-  thd->binlog_flush_pending_rows_event(TRUE);
+  /* possible error of writing binary log is ignored deliberately */
+  (void)thd->binlog_flush_pending_rows_event(TRUE);

And this one:


=== modified file 'sql/sql_update.cc'
--- a/sql/sql_update.cc	2009-06-18 14:16:14 +0000
+++ b/sql/sql_update.cc	2009-08-20 09:53:53 +0000
@@ -1851,9 +1851,10 @@ void multi_update::abort()
         into repl event.
       */
       int errcode= query_error_code(thd, thd->killed == THD::NOT_KILLED);
-      thd->binlog_query(THD::ROW_QUERY_TYPE,
-                        thd->query, thd->query_length,
-                        transactional_tables, FALSE, errcode);
+      /* the error of binary logging is ignored */
+      (void)thd->binlog_query(THD::ROW_QUERY_TYPE,


===============================================================================
COMMENTS:

This hunk seems to be okay

@@ -1543,7 +1544,11 @@ void close_temporary_tables(THD *thd)
                             s_query.length() - 1 /* to remove trailing ',' */,
                             0, FALSE, 0);
       thd->variables.character_set_client= cs_save;
-      mysql_bin_log.write(&qinfo);
+      if (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");
+      }
       thd->variables.pseudo_thread_id= save_pseudo_thread_id;
     }
     else

though my_error() must have been done inside mysql_bin_log.write().
I wonder if the warning is really necessary.

============================================================================
QUESTIONS:

=== modified file 'sql/sql_repl.cc'
--- a/sql/sql_repl.cc	2009-05-15 12:57:51 +0000
+++ b/sql/sql_repl.cc	2009-08-20 09:53:53 +0000
@@ -1007,8 +1007,8 @@ int reset_slave(THD *thd, Master_info* m
   MY_STAT stat_area;
   char fname[FN_REFLEN];
   int thread_mask= 0, error= 0;
-  uint sql_errno=0;
-  const char* errmsg=0;
+  uint sql_errno=ER_UNKNOWN_ERROR;
+  const char* errmsg= "Unknown error occured while reseting slave";
   DBUG_ENTER("reset_slave");

why these changes?

=========================================================================
REMARKS

The base code mysql_grant() calls

  if (!result)
  {
    write_bin_log(thd, TRUE, thd->query, thd->query_length);
  }

  rw_unlock(&LOCK_grant);
  close_thread_tables(thd);

  if (!result)
    my_ok(thd);

my_ok() not after examining main_da->is_error(). Sounds like an issue.

Similarly in mysql_create_db() and some more places.



cheers,

Andrei
Thread
bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973) Bug#37148He Zhenxing20 Aug
  • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)Bug#37148Andrei Elkin17 Sep
    • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)Bug#37148He Zhenxing19 Sep
      • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)Bug#37148Alfranio Correia20 Sep
        • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)Bug#37148He Zhenxing21 Sep
      • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)Bug#37148Andrei Elkin21 Sep
        • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)Bug#37148He Zhenxing22 Sep
          • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)Bug#37148Andrei Elkin22 Sep
            • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)Bug#37148He Zhenxing23 Sep
              • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)Bug#37148Andrei Elkin23 Sep
                • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)Bug#37148Andrei Elkin23 Sep
                  • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)Bug#37148He Zhenxing24 Sep
        • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)Bug#37148Alfranio Correia22 Sep
          • Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)Bug#37148He Zhenxing22 Sep