From: He Zhenxing
Date: September 22 2009 5:28am
Subject: Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973)
 Bug#37148
List-Archive: http://lists.mysql.com/commits/84024
Message-Id: <1253597327.4367.52.camel@hezx>
MIME-Version: 1.0
Content-Type: text/plain
Content-Transfer-Encoding: 7BIT

Andrei Elkin wrote:
> 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.
> 

As we have agree, we'll not add such a test in this patch because it
would be a very big test to cover all the cases, but will create a
WL/BUG to do that.

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

I don't agree it's only about optimization, fail to check the return
value early can result in problem. For example, if we got an error in
mysql_bin_log.write(), it will set thd->main_da->is_error(), and if we
continue the execution and then encounter another error and try to call
my_error() to report it, this will cause the assertion in
Diagnostics_area::set_error_status() to fail because the error status
has already been set. This problem can be avoided by checking the error
and quite early.

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

Yes, Jonas has already review the NDB part of the fix and he is OK with
that.

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

this cleanup is also done at the end of the function:

 err:
#ifndef DBUG_OFF
  max_rows= 0;                                  // For DBUG output
#endif
  /* Remove all not used rows */
  while ((row=rows.get()))
  {
    if (table->s->blob_fields)
    {
      memcpy(table->record[0],row->record,table->s->reclength);
      free_delayed_insert_blobs(table);
    }
    delete row;
    thread_safe_increment(delayed_insert_errors,&LOCK_delayed_status);
    stacked_inserts--;
#ifndef DBUG_OFF
    max_rows++;
#endif
  }


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

Agree :)

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

No, actually the old code will cause problem, because if there is
already error in write_bin_log, then try to report another error by
my_message will cause assertion failure.

>    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().
> 

I mean the code should check the error and return early.

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

This error is ignored deliberately, and is OK.

> @@ -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:
> 

here too.

> 
> === 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.
> 

Agree, and since close_temporary_tables() is called when closing the
current connection, so I think the warning is no necessary, will be
removed.

> ============================================================================
> 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?
> 

This change is not related to this bug, errmsg can be uninitialized when
the call to my_stat() fails.

> =========================================================================
> 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.
> 

if (!result) means there is no error, and main_da->is_error() must be
false in this case.

> 
> 
> cheers,
> 
> Andrei
>