Re: bzr commit into mysql-5.1-bugteam branch (zhenxing.he:2973) Bug#37148

[He Zhenxing]

Alfranio Correia wrote:
> Let's have a call today and discuss this.
> Or we can wait for the meeting tomorrow.
> 

OK, let's have a call today.

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