WL#4033: Support for informational log events

Affects: Server-5.6   —   Status: Complete

RATIONALE
=========
* Allow future versions of the server to send such informational
  events which are ignored by default.


SUMMARY
=======
1. Adding a new ignorable log event, and its incremental sub-hierarchy,
   which have as default that if their type code are not recognized,
   these events are just ignored and replication keeps going as usual.

2. The architecture is open-ended for ignoring future informational events.
   After the solution is committed, an new version master with incremental
   sub-class of the the informational event will work fine with the version
   slave.

3. Record original SQL statement in RBR binlog by using ignorable log event.


LIMITATIONS
===========
-A master with the work log can not work fine with an low version slave
 due to the original architecture is not open-ended for ignoring event.


Cross-version replication impact
================================

  NM, NS - master or slave server patched with WL#4033
  OM, OS - master or slave server not patched with WL#4033

  1. NM -> OS

     - What breaks ?

       OS will not recognize eventual new ignorable events
       sent from NM. If OS gets an Ignorable event,
       replication will break with an error
       "Unknown event code: ......"

     - Limitations ?

       OS can not safely ignore ignorable events, which
       will cause replication break.

     - Workarounds ?

       If not enabling the option for logging ignorable
       events, then replication between NM and OS should
       proceed according to the same limitations as before
       patch for WL#4033 was introduced.

  2. OM -> NS

     - What breaks ?

       OM will not create ignorable events. So it will not
       cause replication break.
           
     - Limitations ?

       Nothing to report.

     - Workarounds

       Nothing to report.

  3. NM -> NS, should work just fine

  4. OM -> OS, nothing to report.


CONTEXT
=======
When a slave receives an event that it does not recognize, it stops by default
indicating an error.

In some situations, it is necessary to send over informational data to the
slave: data that a slave can handle in case there is code for handling it, but
which can be ignored if it is not recognized. Examples of such informational
events are checking the correctness of a table, optimizing a table, or other
such data that when ignored does not lead to a corrupt database.


BACKGROUND
==========
>> Instead, let us consider two simple cases that I think are
>> representative of what we want to use the informational event for:
>>
>> - Comment events that are used to add the executed query for row-based
>>   replication. The event contents shall be printable in the output of
>>   mysqlbinlog and also visible through the SHOW BINLOG EVENTS command,
>>   but nothing else is required.
>>
>> - Table hashes/checksums. The event contain a table checksum or hash
>>   that is computed on the master. When it reaches the slave, a hash
>>   shall be computed for the same table and if the hashes are
>>   different, replication shall stop with an error. Old slaves shall,
>>   of course, just ignore this event.
>>     
>
> I actually realized another usage that we are likely to implement in a
> not too far future: sending over lock information to allow parallel
> slave execution to sort transactions efficiently. This should be
> ignored by old slaves (that do not have parallel execution and does
> not need that information), but is going to be used whenever the slave
> has parallel execution and has it turned on.
>   
The kind of case can be easily handled by the current architecture.
The new slave will get the concrete class and handle it according
to its logic. The old slave will ignore it as an Ignorable_log_event. 

See also BUG#50935
See also WL#5404
Requirements
============


REPLICATION BINLOG CHANGED: create an ignorable log event and write it into binlog
---------------------------------------------------------------------------------

1. Using the flags attribute of Log_event class to set LOG_EVENT_IGNORABLE_F
   bit for ignorable event, which is constructed with the LOG_EVENT_IGNORABLE_F 
   bit is set. So that its every sub-class will be set ignorable by default and   
   the SLAVE SQL THREAD can ignore an unrecognized new one.

2. Every sub-class object of ignorable event is written into binlog and can be    
   displayed as a comment by MYSQLBINLOG DUMP and SHOW BINLOG EVENTS command if
   it is necessary.


IGNORED ON SLAVE: How to handle the ignorable event and its sub-classes on slave
-------------------------------------------------------------------------------

1. The SLAVE I/O THREAD will write ignorable event and its sub-classes to slave  
   relay log from master binlog as usual.

2. The SLAVE SQL THREAD will handle every recognized sub-class according to
   its logic.

3. The SLAVE SQL THREAD will treat unrecognized sub-class as its base class
   'ignorable_log_event' and ignore it after update the positions of the relay
   log.


USING IGNORABLE EVENT IN RBR: Rows_query_log_event
--------------------------------------------------------------------------------------
1. Create a Rows_query_log_event, which is a sub-class of Ignorable_log_event.
   And record query of rows event into the Rows_query_log_event.

2. Write the Rows_query_log_event into binlog with its row event.

3. The Rows_query_log_event will be displayed with its row event
   by MYSQLBINLOG DUMP and SHOW BINLOG EVENTS command.


SERVER OPTION: --binlog-rows-query-log-events
----------------------------------------------------------------------------
Tells the master to write Rows_query_log events to the binary log.

    * Variable Name: binlog_rows_query_log_events
    * Scope: Global & Session
    * Access Type: Dynamic
    * Data Type: bool
    * Default Value: OFF

NOTE. Session values allows to comment only some selected statements:
    ...
    SET SESSION binlog_rows_query_log_events=ON;
    ... statements to be commented ...
    SET SESSION binlog_rows_query_log_events=OFF;
    ... statements not to be commented ...


MYSQLBINLOG OUTPUT
---------------------------------------------------------------------------
With double verbose '-vv', mysqlbinlog outputs Rows_query_log events
in a form like this:

BEGIN
/*!*/;
# at 1183
#100610 12:22:17 server id 1  end_log_pos 1236  Rows_query
# insert into t1(a,b) values(1,2)
# at 1236
# at 1279
#100610 12:22:17 server id 1  end_log_pos 1279  Table_map: `test`.`t1` mapped to
number 23
#100610 12:22:17 server id 1  end_log_pos 1321  Write_rows: table id 23 flags:
STMT_END_F

BINLOG '
eWgQTB0BAAAANQAAANQEAACAACEjIGluc2VydCBpbnRvIHQxKGEsYikgdmFsdWVzKDEsMik=
eWgQTBMBAAAAKwAAAP8EAAAAABcAAAAAAAEABHRlc3QAAnQxAAMDAwMABg==
eWgQTBcBAAAAKgAAACkFAAAQABcAAAAAAAEAA//4AwAAAAEAAAACAAAA
'/*!*/;
### INSERT INTO test.t1
### SET
###   @1=3 /* INT meta=0 nullable=0 is_null=0 */
###   @2=1 /* INT meta=0 nullable=1 is_null=0 */
###   @3=2 /* INT meta=0 nullable=1 is_null=0 */
# at 1321
#100610 12:22:17 server id 1  end_log_pos 1390  Query   thread_id=3    
exec_time=0     error_code=0
SET TIMESTAMP=1276143737/*!*/;
COMMIT


SHOW BINLOG EVENTS OUTPUT
----------------------------------------------------------------------------
master-bin.000001       #       Query   #       #       BEGIN
master-bin.000001       #       Rows_query      #       #       # insert into
t1(a,b) values(1,7)
master-bin.000001       #       Table_map       #       #       table_id: #
(test.t1)
master-bin.000001       #       Write_rows      #       #       table_id: #
flags: STMT_END_F
master-bin.000001       #       Query   #       #       COMMIT
master-bin.000001       #       Query   #       #       BEGIN
master-bin.000001       #       Rows_query      #       #       # insert into
t2(a,b) values(2,4)
master-bin.000001       #       Table_map       #       #       table_id: #
(test.t2)
master-bin.000001       #       Write_rows      #       #       table_id: #
flags: STMT_END_F
master-bin.000001       #       Rows_query      #       #       # insert into
t2(a,b) values(2,5)
master-bin.000001       #       Table_map       #       #       table_id: #
(test.t2)
master-bin.000001       #       Write_rows      #       #       table_id: #
flags: STMT_END_F
master-bin.000001       #       Xid     #       #       COMMIT /* XID */


NOTES: In RBR, binlog pattern changed for INSERT DELAYED statement
--------------------------------------------------------------------------
The original binlog pattern is that the rows of different
INSERT DELAYED statements possibly will be binlogged in one
rows event. So it cause that no approach to make Rows_query
log event comment the statement for all its rows by rule and
line.
After the patch, all the rows of the INSERT DELAYED statement
will be binlogged together as one single Table_map event and
one or more its Rows events as general INSERT statement does,
then Rows_query log event can comment the statement for all
its rows by rule and line.
The 'Support for informational log events' is designed by the following steps:


1. Create an ignorable log event class
+
+/**
+  @class Ignorable_log_event
+  Ignorable log event to send over ignorable data to the slave,
+  and its incremental sub-hierarchy, which have as default that if
+  their type code are not recognized, these events are just ignored
+  and replication keeps going as usual.
+**/
+class Ignorable_log_event : public Log_event {
+public:
+#ifndef MYSQL_CLIENT
+  Ignorable_log_event(THD *thd_arg) : Log_event(thd_arg, 0, FALSE)
+  {
+    DBUG_ENTER("Ignorable_log_event::Ignorable_log_event");
+    set_ignorable_event();
+    DBUG_VOID_RETURN;
+  }
+#endif
+
+  Ignorable_log_event(const char *buf,
+                      const Format_description_log_event *descr_event);
+
+  virtual ~Ignorable_log_event();
+
+#ifdef MYSQL_CLIENT
+  virtual void print(FILE *file, PRINT_EVENT_INFO *print_event_info) { return; }
+#endif
+
+  virtual Log_event_type get_type_code() { return IGNORABLE_LOG_EVENT; }
+
+  virtual bool is_valid() const { return 1; }
+
+  virtual int get_data_size() { return IGNORABLE_HEADER_LEN; }
+
+private:
+  void set_ignorable_event() { flags |= LOG_EVENT_IGNORABLE_F; }
+
+};
+


2. Create a concrete sub-class 'Rows_query_log_event' 
+
+class Rows_query_log_event : public Ignorable_log_event {
+public:
+#ifndef MYSQL_CLIENT
+  Rows_query_log_event(THD *thd_arg, const char * query, ulong query_len)
+    : Ignorable_log_event(thd_arg)
+  { }
+#endif
+
+#ifndef MYSQL_CLIENT
+  void pack_info(Protocol*);
+#endif
+
+  Rows_query_log_event(const char *buf, uint event_len,
+                     const Format_description_log_event *descr_event);
+
+  virtual ~Rows_query_log_event();
+
+#ifdef MYSQL_CLIENT
+  virtual void print(FILE *file, PRINT_EVENT_INFO *print_event_info);
+#endif
+  virtual bool write_data_body(IO_CACHE *file);
+
+  virtual Log_event_type get_type_code() { return ROWS_QUERY_LOG_EVENT; }
+
+  virtual int get_data_size()
+  {
+    return IGNORABLE_HEADER_LEN + 1 + (uint) strlen(m_rows_query);
+  }
+
+private:
+
+  char * m_rows_query;
+};
+


3. The SLAVE SQL THREAD will treat every unrecognized sub-class as its base
class 'ignorable_log_event'

default:
+      /*
+        Create an object of Ignorable_log_event for unrecognized sub-class.
+        So that SLAVE SQL THREAD can ignore the unrecognized one.
+      */
+      if (uint2korr(buf + FLAGS_OFFSET) & LOG_EVENT_IGNORABLE_F)
+      {
+        ev= new Ignorable_log_event(buf, description_event);
+        DBUG_RETURN(ev);
+      }
       DBUG_PRINT("error",("Unknown event code: %d",
                           (int) buf[EVENT_TYPE_OFFSET]));
       ev= NULL;


4. Write the 'Rows_query_log_event' into binlog with its row event.
--- sql/log.cc  2010-03-17 11:31:50 +0000
+++ sql/log.cc  2010-05-28 08:53:53 +0000
@@ -4361,6 +4361,15 @@
   DBUG_ASSERT(is_current_stmt_binlog_format_row() && mysql_bin_log.is_open());
   DBUG_ASSERT(table->s->table_map_id != ULONG_MAX);

+  if (this->variables.binlog_rows_query_log_events &&
+      is_current_stmt_binlog_format_row() && this->query())
+  {
+    /* Write the Rows_query_log_event into binlog before the table map */
+    Rows_query_log_event* ev= new Rows_query_log_event(this, this->query(),
+                                                       this->query_length());
+    mysql_bin_log.write(ev);
+  }
+


5. The 'Rows_query_log_event' will be displayed with its row event by
MYSQLBINLOG DUMP with double verbose '-vv'

BEGIN
/*!*/;
# at 1183
#100610 12:22:17 server id 1  end_log_pos 1236  Rows_query
# insert into t1(a,b) values(1,2)
# at 1236
# at 1279
#100610 12:22:17 server id 1  end_log_pos 1279  Table_map: `test`.`t1` mapped to
number 23
#100610 12:22:17 server id 1  end_log_pos 1321  Write_rows: table id 23 flags:
STMT_END_F

BINLOG '
eWgQTB0BAAAANQAAANQEAACAACEjIGluc2VydCBpbnRvIHQxKGEsYikgdmFsdWVzKDEsMik=
eWgQTBMBAAAAKwAAAP8EAAAAABcAAAAAAAEABHRlc3QAAnQxAAMDAwMABg==
eWgQTBcBAAAAKgAAACkFAAAQABcAAAAAAAEAA//4AwAAAAEAAAACAAAA
'/*!*/;
### INSERT INTO test.t1
### SET
###   @1=3 /* INT meta=0 nullable=0 is_null=0 */
###   @2=1 /* INT meta=0 nullable=1 is_null=0 */
###   @3=2 /* INT meta=0 nullable=1 is_null=0 */
# at 1321
#100610 12:22:17 server id 1  end_log_pos 1390  Query   thread_id=3    
exec_time=0     error_code=0
SET TIMESTAMP=1276143737/*!*/;
COMMIT


6. The 'Rows_query_log_event' will be displayed with its row event by "SHOW
BINLOG EVENTS"

master-bin.000001       #       Query   #       #       BEGIN
master-bin.000001       #       Rows_query      #       #       # insert into
t1(a,b) values(1,7)
master-bin.000001       #       Table_map       #       #       table_id: #
(test.t1)
master-bin.000001       #       Write_rows      #       #       table_id: #
flags: STMT_END_F
master-bin.000001       #       Query   #       #       COMMIT
master-bin.000001       #       Query   #       #       BEGIN
master-bin.000001       #       Rows_query      #       #       # insert into
t2(a,b) values(2,4)
master-bin.000001       #       Table_map       #       #       table_id: #
(test.t2)
master-bin.000001       #       Write_rows      #       #       table_id: #
flags: STMT_END_F
master-bin.000001       #       Rows_query      #       #       # insert into
t2(a,b) values(2,5)
master-bin.000001       #       Table_map       #       #       table_id: #
(test.t2)
master-bin.000001       #       Write_rows      #       #       table_id: #
flags: STMT_END_F
master-bin.000001       #       Xid     #       #       COMMIT /* XID */