MySQL Lists are EOL. Please join:

List:Commits« Previous MessageNext Message »
From:Sven Sandberg Date:December 13 2007 4:54pm
Subject:Re: bk commit into 5.1 tree (sven:1.2651) BUG#32407
View as plain text  
Hi Mats!

Many thanks for a very thorough review! See my comments below.

/Sven


Mats Kindahl wrote:
[...]
>>   sql/slave.cc@stripped, 2007-12-10 10:42:42+01:00, sven@riska.(none)
>> +207 -111
>>      - Factored out part of exec_relay_log_event to the new function
>>        apply_event_and_update_pos, because that code is needed when
>> executing
>>        BINLOG statements. (this should be functionally equivalent to the
>>        previous code)
>>   
> 
> "should"?!
> 
> If you are unsure if you can make the refactored code behave
> identically, then refactoring is dangerous.

Sorry: it *is* functionally identical, except:
 - the return value, which is documented above, and
 - skipping is now optional (the parameter 'skip'). See further down,
and attached diff.

I'll be more clear in the re-commit.

[...]
>>      DBUG_PRINT("debug", ("event_type: %s", ev->get_type_str()));
>>  
>> @@ -565,7 +570,7 @@ int process_event(PRINT_EVENT_INFO *prin
>>      case QUERY_EVENT:
>>        if (check_database(((Query_log_event*)ev)->db))
>>   
> 
> That code is just awful. Not yours, I know, but nevertheless...

I know, and actually, I have a refactoring about 80% done. (The major
problem, though, is how LOAD DATA INFILE is handled. If we
unconditionally used row-based replication for that, we could drop sooo
much code (and code complexity) in mysqlbinlog. Except, of course, we
need to keep it for backward compatibility for a while.)

>> @@ -678,6 +683,38 @@ Create_file event for file_id: %u\n",exv
>>  Begin_load_query event for file_id: %u\n", exlq->file_id);
>>        break;
>>      }
>> +    case TABLE_MAP_EVENT:
>> +    case WRITE_ROWS_EVENT:
>> +    case DELETE_ROWS_EVENT:
>> +    case UPDATE_ROWS_EVENT:
>> +    case PRE_GA_WRITE_ROWS_EVENT:
>> +    case PRE_GA_DELETE_ROWS_EVENT:
>> +    case PRE_GA_UPDATE_ROWS_EVENT:
>> +      /*
>> +        These events must be printed in base64 format, if printed.
>> +        base64 format requires a FD event to be safe, so if no FD
>> +        event has been printed, we give an error.  Except if user
>> +        passed --short-form, because --short-form disables printing
>> +        row events.
>> +      */
>> +      if (!print_event_info->printed_fd_event && !short_form)
> 
> Instead of introducing a new variable, you could check the mode. In AUTO
> and ALWAYS mode, a FD event shall have been printed earlier, so by just
> checking the mode, you can decide if you should print an error or not.

This is technically possible; however, I think the flag is more readable
and avoids a dependency in the code. The flag is set in the place where
the event is printed, which is what we need to check. So verifying
correctness is trivial. The alternative you suggest depends on the logic
that decides when FD events are printed. This logic is complicated, and
if we ever change that, we would have to rewrite this part of the code.

[...]
>> @@ -707,12 +744,17 @@ static struct my_option my_long_options[
>>    {"autoclose", OPT_AUTO_CLOSE, "Auto close the screen on exit for
>> Netware.",
>>     0, 0, 0, GET_NO_ARG, NO_ARG, 0, 0, 0, 0, 0, 0},
>>  #endif
>> -  {"base64-output", OPT_BASE64_OUTPUT,
>> -   "Print all binlog entries using base64 encoding. "
>> -   "This is for debugging only. Logs produced using this option "
>> -   "should not be applied on production systems.",
>> -   (uchar**) &opt_base64_output, (uchar**) &opt_base64_output, 0,
>> GET_BOOL,
>> -   NO_ARG, 0, 0, 0, 0, 0, 0},
>> +  {"base64-output", OPT_BASE64_OUTPUT_MODE,
>> +   "Determine when the output statements should be base64-encoded
>> BINLOG "
>> +   "statements: 'never' disables it and works only for binlogs without "
>> +   "row-based events; 'auto' is the default and prints base64 only
>> when "
>> +   "necessary (i.e., for row-based events and format description
>> events); "
>> +   "'always' prints base64 whenever possible (it is currently not
>> always "
>> +   "possible). 'always' is for debugging only and should not be used
>> in a "
>> +   "production system. The default is 'auto'."
> 
> Remove the "(it is ...)",

I agree, done.

> and don't give advice on how the option should
> be used in the description of the option, since this makes it difficult
> to maintain. The documentation is for giving suggestions on how and when
> to use options, not the code. IMHO, the option description should
> contain what the option does, and nothing else.

The warning is not mine, it was there before the patch. I also think
unsafe options should contain a warning. That said, the
--base64-output=always should be safe now that we have a FD event, so
I'll remove the warning here.

>> +   ,(uchar**) &opt_base64_output_mode_str,
>> +   (uchar**) &opt_base64_output_mode_str,
>> +   0, GET_STR, OPT_ARG, 0, 0, 0, 0, 0, 0},
>>    /*
>>      mysqlbinlog needs charsets knowledge, to be able to convert a
>> charset
>>      number found in binlog to a charset name (to be able to print things
>> @@ -788,7 +830,10 @@ static struct my_option my_long_options[
>>    {"set-charset", OPT_SET_CHARSET,
>>     "Add 'SET NAMES character_set' to the output.", (uchar**) &charset,
>>     (uchar**) &charset, 0, GET_STR, REQUIRED_ARG, 0, 0, 0, 0, 0, 0},
>> -  {"short-form", 's', "Just show the queries, no extra info.",
>> +  {"short-form", 's', "Just show regular queries: no extra info and no "
>> +   "row-based events. This is for testing only, and should not be
>> used in "
>> +   "production systems. If you want to suppress base64-output,
>> consider "
>> +   "using --base64-output=never instead.",
> 
> See above.

This is a very dangerous option - see also BUG#18337. I'd suggest we
keep the warning. This flag is useful only in our tests (we use it
because it removes all traces of timestamps, so when the output of
mysqlbinlog ends up in a result file, the result file is deterministic).
Users really should not use this flag. Possible user scenario:

 - User writes script that pipes output of mysqlbinlog to client
 - User wants to optimize their script by removing unnecessary output.
 - User sees "--short-form" flag which removes comments. User tries it
on a binlog with no row events, and it seems to do this.
 - Later, user switches to row-based replication, and the script breaks.

At some point, I think we should deprecate the short-form flag and
introduce two safer flags like this:
 --no-comments                Do not print comments.
 --deterministic-output flag  Print all events as if they happened
                              at time 0.

[...]
>> @@ -1305,8 +1359,21 @@ err:
>>  }
>>  
>>  
>> +/**
>> +  Reads the Format_description_log_event from the beginning of the
>> +  input file.
>> +
>> +  The Format_description_log_event is only read if it is outside the
>> +  range specified with --start-position; otherwise, it will be seen
>> +  later.  If this is an old binlog, a fake Format_description_event is
>> +  created.  This also prints a Format_description_log_event to the
>> +  output, unless we reach the --start-position range. In this case, it
>> +  is assumed that a Format_description_log_event will be found when
>> +  reading events the usual way.
>>   
> 
> Please add parameters to the Doxygen comment.

Right, will do!

>> +*/
>>  static void check_header(IO_CACHE* file, -                       
>> Format_description_log_event **description_event)
>> +                         Format_description_log_event
>> **description_event,
>> +                         PRINT_EVENT_INFO *print_event_info)
>>  {
>>    uchar header[BIN_LOG_HEADER_SIZE];
>>    uchar buf[PROBE_HEADER_LEN];
>> @@ -1369,10 +1436,11 @@ Could not read entry at offset %lu : Err
>>      }
>>      else
>>      {
>> -      DBUG_PRINT("info",("buf[4]=%d", buf[4]));
>> +      DBUG_PRINT("info",("buf[EVENT_TYPE_OFFSET]=%d",
>> buf[EVENT_TYPE_OFFSET]));
> 
> It is more useful to have the actual value of the event type offset in
> the debug output.

I got the opposite comment in another review, and care very little
myself, so to please everyone I will do

DBUG_PRINT("info",("buf[EVENT_TYPE_OFFSET=%d]=%d",
                   EVENT_TYPE_OFFSET, buf[EVENT_TYPE_OFFSET]));

>>        /* always test for a Start_v3, even if no --start-position */
>> -      if (buf[4] == START_EVENT_V3)       /* This is 3.23 or 4.x */
>> +      if (buf[EVENT_TYPE_OFFSET] == START_EVENT_V3)
>>        {
>> +        /* This is 3.23 or 4.x */
>>          if (uint4korr(buf + EVENT_LEN_OFFSET) <             
>> (LOG_EVENT_MINIMAL_HEADER_LEN + START_V3_HEADER_LEN))
>>          {
>> @@ -1384,8 +1452,9 @@ Could not read entry at offset %lu : Err
>>        }
>>        else if (tmp_pos >= start_position)
>>          break;
>> -      else if (buf[4] == FORMAT_DESCRIPTION_EVENT) /* This is 5.0 */
>> +      else if (buf[EVENT_TYPE_OFFSET] == FORMAT_DESCRIPTION_EVENT)
>>        {
>> +        /* This is 5.0 */
>>          Format_description_log_event *new_description_event;
>>          my_b_seek(file, tmp_pos); /* seek back to event's start */
>>          if (!(new_description_event= (Format_description_log_event*)
>> @@ -1397,11 +1466,22 @@ Could not read entry at offset %lu : Err
>>  at offset %lu ; this could be a log format error or read error",
>>                tmp_pos);          }
>> -        delete *description_event;
>> -        *description_event= new_description_event;
>> +        if (opt_base64_output_mode == BASE64_OUTPUT_AUTO
>> +            || opt_base64_output_mode == BASE64_OUTPUT_ALWAYS)
>> +          /*
>> +            process_event will delete *description_event and set it to
>> +            the new one, so we should not do it ourselves in this
>> +            case.
>> +          */
>>   
> 
> If feels kind of strange to have one branch of the if-statement turning
> over the responsibility of deleting the event to another function and
> the other one not. Makes maintenance harder.
>
>> +          process_event(print_event_info, new_description_event,
>> tmp_pos);
>> +        else
>> +        {
>> +          delete *description_event;
>> +          *description_event= new_description_event;
>> +        }
> 
> Don't you need the FD event event even for NEVER mode? Don't if work if
> the FD event is always available? If you always set the FD event, it
> makes this code easier and more generic and also gives the possibility
> of using the FD event for checking versions even in NEVER mode.

Logically, it's not about deleting but about switching. There is always
a "current" FD event. The responsibility for creating it is at the top
of check_header() / check_master_version() (depending on if we are
printing a local or remote binlog). The responsibility for deleting it
is... uhm... er... *should be* somewhere near the shutdown (currently
it's not always done, that's a bug, but it's not my patch's fault).
Between creation and deletion, the FD event may be switched any number
of times. This is safe to do in a totally irresponsible way. Here,
process_event will switch, but since we don't call process_event in
NEVER mode, we have to switch manually.

To summarize: there is one create and one delete in this function, and
the new object replaces the old, so the sum is +-0.

> Also, it seems that you are using the existence of the FD event as an
> indicator for whether to print an error or not, and this logic will
> break down if the FD event for some reason is needed in the future; for
> example, if there is a need to do version checking even in NEVER mode.
>
> I would suggest to always set the FD event and look at the mode instead
> to decide when an error should be printed. This makes the code simpler,
> more generic, and less prone to introducing bugs with future changes.
> This also rhymes well with the fact that preconditions should be as weak
> as possible, but not weaker.

What part of the code are you referring to here? I see no error checking
here, and there is no place that tests the existence of FD events to
check errors. Possibly a misunderstanding? Does the above paragraph make
things more clear?

[...]
>> diff -Nrup a/mysql-test/suite/binlog/t/binlog_base64_flag.test
>> b/mysql-test/suite/binlog/t/binlog_base64_flag.test
>> --- /dev/null    Wed Dec 31 16:00:00 196900
>> +++ b/mysql-test/suite/binlog/t/binlog_base64_flag.test    2007-12-10
>> 10:42:43 +01:00
>> @@ -0,0 +1,107 @@
>> +# This test case verifies that the mysqlbinlog --base64-output=X flags
>> +# work as expected, and that BINLOG statements with row events fail if
>> +# they are not preceded by BINLOG statements with Format description
>> +# events.
>> +#
>> +# See also BUG#32407.
>> +#
>> +# Created by Sven.
> 
> You can remove your names from the test cases, which reminds me that you
> should add your name to the AUTHORS output.
> 
> I know some add themselves as creator in the test case file, but over
> time this file will not be anything like the original, and I really do
> not think you should take responsibility for what happens with this file
> in the future. If anybody really want to know who created it, there is a
> revision history maintained by BitKeeper for this purpose.

OK, will do.

[...]
>> +--error ER_NO_FORMAT_DESCRIPTION_EVENT_BEFORE_BINLOG_STATEMENT
> 
> Use non -- form of the test statement: that means that you will see any
> errors in the command. (I usually only use -- for echo since the ; last
> makes one believe that the ; will be written as well.)

OK, will do.

>> +BINLOG '
>> +SVtYRxMBAAAAKQAAADQBAAAAABAAAAAAAAAABHRlc3QAAnQxAAEDAAE=
>> +SVtYRxcBAAAAIgAAAFYBAAAQABAAAAAAAAEAAf/+AgAAAA==
>> +';
>> +# The above line should fail and 2 should not be in the table
>> +select * from t1;
>> +
>> +
>> +# Test that it works to read a Format_description_log_event with a
>> +# BINLOG statement, followed by a row-event in base64 from the same
>> +# version.
>> +--echo ==== Test BINLOG statement with FD event ====
>> +
>> +# This is a binlog statement containing a Format_description_log_event
>> +# from the same version as the Table_map and Write_rows_log_event.
>> +BINLOG '
>> +ODdYRw8BAAAAZgAAAGoAAAABAAQANS4xLjIzLXJjLWRlYnVnLWxvZwAAAAAAAAAAAAAAAAAAAAAA
>>
>> +AAAAAAAAAAAAAAAAAAA4N1hHEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
>> +';
>> +
>> +# This is a Table_map_log_event+Write_rows_log_event corresponding to:
>> +# INSERT INTO TABLE test.t1 VALUES (3)
>> +BINLOG '
>> +TFtYRxMBAAAAKQAAAH8BAAAAABAAAAAAAAAABHRlc3QAAnQxAAEDAAE=
>> +TFtYRxcBAAAAIgAAAKEBAAAQABAAAAAAAAEAAf/+AwAAAA==
>> +';
>> +# The above line should succeed and 3 should be in the table
>> +select * from t1;
>> +
>> +
>> +# Test that mysqlbinlog stops with an error message when the
>> +# --base64-output=never flag is used on a binlog with base64 events.
>> +#
>> +# This test is currently commented out, because mysqlbinlog is not
>> +# able to clean up after itself when stopped, so in debug mode it
>> +# produces lots of messages about memory leaks.
>> +--echo ==== Test --base64-output=never on a binlog with row events ====
>> +#
>> +# mysqlbinlog should fail
>> +#--replace_regex /exec of
>> .*suite/binlog/std_data/binlog-bug32407.000001/#/
>> +#--exec $MYSQL_BINLOG --base64-output=never
>> suite/binlog/std_data/binlog-bug32407.000001
>> +# the above line should output the query log event and then stop
> 
> Please enable the test. If mysqlbinlog contain a bug, we should report
> it and fix it. If there is no bug reported for this, please create one.

Basically, the bug is that we don't use exceptions ;-) More seriously,
when the program dies abruptly is IMHO one of few times that it is
usually better to *not* clean up - making sure that everything is freed
is a significant amount of work, and the OS does it for us anyway.

Should I uncomment the test even if it fails? Doesn't it have to be
disabled in the suite then?

[...]
>> diff -Nrup a/sql/log_event.cc b/sql/log_event.cc
>> --- a/sql/log_event.cc    2007-11-28 12:11:13 +01:00
>> +++ b/sql/log_event.cc    2007-12-10 10:42:42 +01:00
[...]
>> +  Log_event_type event_type= (Log_event_type)buf[EVENT_TYPE_OFFSET];
>> +  if (event_type < 0 ||
>> +      (event_type > description_event->number_of_event_types &&
>> +       event_type != FORMAT_DESCRIPTION_EVENT))
>>   
> 
> Since you are treating the event_type as an integer, I suggest you use
> an int instead of Log_event_type. The implicit cast of
> FORMAT_DESCRIPTION_EVENT does not produce an error (AIUI), so that is
> safe, and the other comparisons will do an implicit cast of the variable
> to an int anyway. The explicit cast might potentially hide errors, and
> using Log_event_type does not provide any safety anyway, so there is no
> value in using Log_event_type.

OK, will do.

>> diff -Nrup a/sql/log_event.h b/sql/log_event.h
>> --- a/sql/log_event.h    2007-10-30 09:51:08 +01:00
>> +++ b/sql/log_event.h    2007-12-10 10:42:42 +01:00
>> @@ -567,6 +567,15 @@ class Format_description_log_event;
>>  class Relay_log_info;
>>  
>>  #ifdef MYSQL_CLIENT
>> +enum enum_base64_output_mode {
>> +  BASE64_OUTPUT_NEVER= 0,
>> +  BASE64_OUTPUT_AUTO= 1,
>> +  BASE64_OUTPUT_ALWAYS= 2,
>> +  BASE64_OUTPUT_UNSPEC= 3,
>> +  /* insert new output modes here */
>> +  BASE64_OUTPUT_LAST_TYPE
>> +};
>>   
> 
> Since variables declared with this enum defaults to 0 (unless auto, of
> course), I would suggest to place the "UNSPEC" as 0, because that allows
> you to get a sensible and detectable value if you forget to assign a
> value to a variable of this type.
> 
> Then, since the enumeration only needs a sequence of number, and it does
> not matter which ones, I would say that you can remove the explicit 
> values for the enumeration constants.

These numbers are used as array indices in mysqlbinlog.cc, function
get_one_option, case OPT_BASE64_OUTPUT_MODE, in the call to
find_type_or_exit(). I know, it's horrible, but it's how the
--binlog-format flag is handled for mysqld and I see no way to get rid
of it using our current command line parsing library.

> Also, LAST_TYPE is not the last type, it is *one more* than the value of
> the last *enumeration constant*, and the closest description to what it
> is would be a count of the number of enumeration constants. (Assuming
> that you don't have holes in the sequence above.)
> 
> I suggest to use the name BASE64_OUTPUT_MODE_COUNT instead. (I have the
> convention for enums that I add the constant <enum-name>_COUNT last.)

OK, will do. Though I don't think the choice of name is as important as
being consistent throughout the code, but I suppose that will never
happen...

>> diff -Nrup a/sql/slave.cc b/sql/slave.cc
>> --- a/sql/slave.cc    2007-11-21 21:09:23 +01:00
>> +++ b/sql/slave.cc    2007-12-10 10:42:42 +01:00
[...]
>> @@ -1757,6 +1765,181 @@ static int has_temporary_error(THD *thd)
>>    DBUG_RETURN(0);
>>  }
>>  
>> +
>> +/**
>> +  Applies the given event and advances the relay log position.
>> +
>> +  In essence, this function does:
>> +
>> +  <pre>
>> +    ev->apply_event(rli);
>> +    ev->update_pos(rli);
>> +  </pre>
> 
> You have @code and @endcode for this purpose.

OK, will do!

>> +
>> +  But it also does some maintainance, such as skipping events if
>> +  needed and reporting errors.
>> +
>> +  If the @c skip flag is set, then it is tested whether the event
>> +  should be skipped, by looking at the slave_skip_counter and the
>> +  server id.  The skip flag should be set when calling this from a
>> +  replication thread but not set when executing an explicit BINLOG
>> +  statement.
>> +
>> +  @retval 0 OK.
>> +
>> +  @retval 1 Error calling ev->apply_event().
>> +
>> +  @retval 2 No error calling ev->apply_event(), but error calling
>> +  ev->update_pos().
> 
> Skip the periods last in the sentences, they are not needed.

I don't want to argue too much about this kind of things, but our
internal coding guidelines explicitly state that there should be a
period: see
http://forge.mysql.com/wiki/MySQL_Internals_Coding_Guidelines#Commenting_Code

[...]
>> +/**
>> +  Top-level function for executing the next event from the relay log.
>> +
>> +  This function reads the event from the relay log, executes it, and
>> +  advances the relay log position.  It also handles errors, etc.
>> +
>> +  @retval 0 OK.
>> +
>> +  @retval nonzero The event was not applied, for one of the following
>> +  reasons:
>> +
>> +  <ul>
>> +
>> +  <li>The position specfied by the UNTIL condition of the START SLAVE
>> +  command is reached.</li>
>> +
>> +  <li>It was not possible to read the event from the log.</li>
>> +
>> +  <li>The slave is killed.</li>
>> +
>> +  <li>An error occurred when applying the event, and the event has
>> +  been tried slave_trans_retries times.  If the event has been retried
>> +  fewer times, 0 is returned.</li>
>> +
>> +  <li>init_master_info or init_relay_log_pos failed. (These are called
>> +  if a failure occurs when applying the event.)</li>
>> +
>> +  <li>An error occurred when updating the binlog position.</li>
>> +
>> +  </ul>
> 
> The text associated with a return value should be brief. This text is
> better to put in the body of the description.

Sure, can do.

> Also, Doxygen handles normal lists well, so there is no need to use HTML
> here. You can type:
> 
>    If the return value is non-zero, the event was not applied for one
>    of the following reasons:
> 
>    - The position specfied by the UNTIL condition of the START SLAVE
>      command is reached
> 
>    - It was not possible to read the event from the log
> 
>    - The slave is killed

I had no idea it's that simple, cooool... Thanks for pointing that out!

>> +
>> +  The exact value returned is not meaningful; check the errors in the
>> +  thd and rli objects for details.
>> +*/
>>   
> 
> I assume this is just a cut and paste of the code removed below. If that
> is not the case, please tell me and I will take a more thorough look.

It is a cut and paste with small modifications. See the attached patch:
it is a 'diff -b' between the old fraction of exec_relay_log_event and
the new apply_event_and_update_pos.

>>  static int exec_relay_log_event(THD* thd, Relay_log_info* rli)
>>  {
>>    DBUG_ENTER("exec_relay_log_event");
>> @@ -1787,7 +1970,7 @@ static int exec_relay_log_event(THD* thd
>>      */
>>      rli->abort_slave= 1;
>>      pthread_mutex_unlock(&rli->data_lock);
>> -    DBUG_RETURN(1);
>> +    DBUG_RETURN(-1);
>>   
> 
> Please add this return value (-1) to the @retval list in the function
> comment.

OK, will do.

[...]
>>  }
> 
> If you add a prototype (declaration) for a new function early in the
> file, and add the new function definition *last* in the file, you will
> have significantly smaller and more readable diffs.

I think patch readability is a matter of giving the right arguments to
diff (use diff -c -b). Optimizing the code for patch readability should
have low priority. IMHO, it is more important to have the functions
organized in a logical manner in the file.

[...]

-- 
Sven Sandberg, Software Engineer
MySQL AB, www.mysql.com

Attachment: [text/x-patch] apply.diff
Thread
bk commit into 5.1 tree (sven:1.2651) BUG#32407Sven Sandberg10 Dec
  • Re: bk commit into 5.1 tree (sven:1.2651) BUG#32407Mats Kindahl13 Dec
    • Re: bk commit into 5.1 tree (sven:1.2651) BUG#32407Sven Sandberg13 Dec
      • Re: bk commit into 5.1 tree (sven:1.2651) BUG#32407Mats Kindahl13 Dec