BUG#11754117 incorrect logging of INSERT into auto-increment

BUG#11761686 insert_id event is not filtered.
  
Two issues are covered.
  
INSERT into autoincrement field which is not the first part in the composed primary key 
is unsafe by autoincrement logging design. The case is specific to MyISAM engine
because Innodb does not allow such table definition.
  
However no warnings and row-format logging in the MIXED mode was done, and
that is fixed.
  
Int-, Rand-, User-var log-events were not filtered along with their parent
query that made possible them to screw up execution context of the following
query.
  
Fixed with deferring their execution until the parent query.

******
Bug#11754117 

Post review fixes.

mysql-test/suite/rpl/r/rpl_auto_increment_bug45679.result:
  a new result file is added.
mysql-test/suite/rpl/r/rpl_filter_tables_not_exist.result:
  results updated.
mysql-test/suite/rpl/t/rpl_auto_increment_bug45679.test:
  regression test for BUG#11754117-45670 is added.
mysql-test/suite/rpl/t/rpl_filter_tables_not_exist.test:
  regression test for filtering issue of BUG#11754117 - 45670 is added.
sql/log_event.cc:
  Logics are added for deferring and executing events associated 
  with the Query event.
sql/log_event.h:
  Interface to deferred events batch execution is added.
sql/rpl_rli.cc:
  initialization for new RLI members is added.
sql/rpl_rli.h:
  New members to RLI are added to facilitate deferred events gathering
  and execution control;
  two general character RLI cleanup methods are constructed.
sql/rpl_utility.cc:
  Deferred_log_events methods are difined.
sql/rpl_utility.h:
  A new class Deferred_log_events is defined to implement
  IRU events gathering, execution and cleanup.
sql/slave.cc:
  Necessary changes to initialize `rli->deferred_events' and prevent
  deferred event deletion in the main read-exec branch.
sql/sql_base.cc:
  A new safe-check function for multi-part pk with auto-increment is defined
  and deployed in lock_tables().
sql/sql_class.cc:
  Initialization for a new member and replication cleanups are added
  to THD class.
sql/sql_class.h:
  THD class receives a new member to hold a specific execution
  context for slave applier.
sql/sql_parse.cc:
  Execution of the deferred event in started prior to its parent query.

mysql-test/suite/rpl/r/rpl_auto_increment_bug45679.result

+include/master-slave.inc
+[connection master]
+call mtr.add_suppression('Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT.');
+create table tm (b int auto_increment, a int, primary key (a,b)) engine= myisam;
+create table ti (b int auto_increment, a int, primary key (a,b)) engine= innodb;
+ERROR 42000: Incorrect table definition; there can be only one auto column and it must be defined as a key
+create table ti (b int auto_increment, a int, primary key (b,a)) engine= innodb;
+set @@binlog_format=statement;
+*** autoincrement field is not the first in PK warning must be there: ***
+insert into tm set b=null, a=1;
+Warnings:
+Note	1592	Statement may not be safe to log in statement format.
+show warnings;
+Level	Code	Message
+Note	1592	Statement may not be safe to log in statement format.
+*** no warning when autoincrement is the first in PK
+insert into ti set b=null, a=1;
+show warnings;
+Level	Code	Message
+create function multi_part_pk_with_autoinc (arg int)
+returns int
+begin
+insert into tm set b=null, a=arg;
+return arg;
+end//
+select multi_part_pk_with_autoinc (3);
+multi_part_pk_with_autoinc (3)
+3
+*** autoincrement field is not the first in PK warning must be there: ***
+show warnings;
+Level	Code	Message
+set @@binlog_format=mixed;
+insert into tm set b=null, a=2;
+drop table tm, ti;
+drop function multi_part_pk_with_autoinc;
+include/rpl_end.inc

mysql-test/suite/rpl/r/rpl_filter_tables_not_exist.result

@@ -114,4 +114,25 @@ id	c
 3	3
 [on master]
 drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
+CREATE TABLE test.t5 (a INT AUTO_INCREMENT PRIMARY KEY, b INT, c INT);
+CREATE TABLE test.t1 (a INT);
+INSERT INTO test.t1 VALUES(1);
+call mtr.add_suppression("Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT");
+CREATE TABLE test.t_slave (a INT AUTO_INCREMENT PRIMARY KEY, b INT, c INT);
+CREATE TRIGGER t1_update AFTER UPDATE ON test.t1 FOR EACH ROW
+INSERT INTO test.t_slave VALUES(NULL, ROUND(RAND() * 1000), @c);
+SET INSERT_ID=2;
+SET @c=2;
+SET @@rand_seed1=10000000, @@rand_seed2=1000000;
+INSERT INTO t5 VALUES (NULL, ROUND(RAND() * 1000), @c);
+Warnings:
+Note	1592	Statement may not be safe to log in statement format.
+SELECT b into @b FROM test.t5;
+UPDATE test.t1 SET a=2;
+SELECT a AS 'ONE' into @a FROM test.t_slave;
+SELECT c AS 'NULL' into @c FROM test.t_slave;
+SELECT b into @b FROM test.t_slave;
+drop table test.t5;
+drop table test.t1;
+drop table test.t_slave;
 include/rpl_end.inc

mysql-test/suite/rpl/t/rpl_auto_increment_bug45679.test

+# Test of auto-increment.
+#
+# BUG#11754117-45670 
+# Multipart primary key with the autoincrement part not first in it
+# is replication unsafe.
+#
+
+source include/master-slave.inc;
+source include/have_binlog_format_mixed.inc;
+source include/have_innodb.inc;
+
+call mtr.add_suppression('Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT.');
+
+--connection master
+create table tm (b int auto_increment, a int, primary key (a,b)) engine= myisam;
+--error ER_WRONG_AUTO_KEY
+create table ti (b int auto_increment, a int, primary key (a,b)) engine= innodb;
+create table ti (b int auto_increment, a int, primary key (b,a)) engine= innodb;
+
+set @@binlog_format=statement;
+--echo *** autoincrement field is not the first in PK warning must be there: ***
+insert into tm set b=null, a=1;
+show warnings;
+--echo *** no warning when autoincrement is the first in PK
+insert into ti set b=null, a=1;
+show warnings;
+
+delimiter //;
+create function multi_part_pk_with_autoinc (arg int)
+returns int
+begin
+  insert into tm set b=null, a=arg;
+  return arg;
+end//
+delimiter ;//
+
+select multi_part_pk_with_autoinc (3);
+--echo *** autoincrement field is not the first in PK warning must be there: ***
+show warnings;
+
+set @@binlog_format=mixed;
+insert into tm set b=null, a=2;
+
+sync_slave_with_master;
+
+if (`select count(*) <> 3 from tm`)
+{
+  --echo Wrong result from SELECT on the slave side.
+  select * from tm;
+  --die
+}
+
+# cleanup
+
+--connection master
+
+drop table tm, ti;
+drop function multi_part_pk_with_autoinc;
+
+sync_slave_with_master;
+
+--source include/rpl_end.inc

mysql-test/suite/rpl/t/rpl_filter_tables_not_exist.test

@@ -206,4 +206,64 @@ SELECT * FROM t3;
 connection master;
 echo [on master];
 drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
+
+--sync_slave_with_master
+
+#
+# BUG#11754117 - 45670: INTVAR_EVENTS FOR FILTERED-OUT QUERY_LOG_EVENTS ARE EXECUTED
+# Int-, Rand- and User- var events accompaning a filtered out Query-log-event should
+# be filtered as well.
+#
+connection master;
+CREATE TABLE test.t5 (a INT AUTO_INCREMENT PRIMARY KEY, b INT, c INT); # ignored on slave
+CREATE TABLE test.t1 (a INT); # accepted on slave
+INSERT INTO test.t1 VALUES(1);
+
+--sync_slave_with_master
+call mtr.add_suppression("Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT");
+CREATE TABLE test.t_slave (a INT AUTO_INCREMENT PRIMARY KEY, b INT, c INT);
+CREATE TRIGGER t1_update AFTER UPDATE ON test.t1 FOR EACH ROW
+                               INSERT INTO test.t_slave VALUES(NULL, ROUND(RAND() * 1000), @c);
+
+connection master;
+SET INSERT_ID=2;
+SET @c=2;
+SET @@rand_seed1=10000000, @@rand_seed2=1000000;
+INSERT INTO t5 VALUES (NULL, ROUND(RAND() * 1000), @c); # to be ignored
+SELECT b into @b FROM test.t5;
+--let $b_master=`select @b`
+UPDATE test.t1 SET a=2; # to run trigger on slave
+
+--sync_slave_with_master
+
+# The proof:
+SELECT a AS 'ONE' into @a FROM test.t_slave;
+SELECT c AS 'NULL' into @c FROM test.t_slave;
+
+let $count= 1;
+let $table= test.t_slave;
+source include/wait_until_rows_count.inc;
+
+if (`SELECT @a != 2 and @c != NULL`)
+{
+    SELECT * FROM test.t_slave;
+    --die Intvar or user var from replication events unexpetedly escaped out to screw a following query applying context.
+}
+
+SELECT b into @b FROM test.t_slave;
+--let $b_slave=`select @b`
+
+if (`SELECT $b_slave = $b_master`)
+{
+    --echo Might be pure coincidence of two randoms from master and slave table. Don not panic yet.
+}
+
+# cleanup BUG#11754117
+connection master;
+drop table test.t5;
+drop table test.t1;
+
+--sync_slave_with_master
+drop table test.t_slave;
+
 --source include/rpl_end.inc

sql/log_event.cc

@@ -5257,11 +5257,12 @@ void Intvar_log_event::print(FILE* file, PRINT_EVENT_INFO* print_event_info)
 #endif
 
 
+#if defined(HAVE_REPLICATION)&& !defined(MYSQL_CLIENT)
+
 /*
   Intvar_log_event::do_apply_event()
 */
 
-#if defined(HAVE_REPLICATION)&& !defined(MYSQL_CLIENT)
 int Intvar_log_event::do_apply_event(Relay_log_info const *rli)
 {
   /*
@@ -5270,6 +5271,9 @@ int Intvar_log_event::do_apply_event(Relay_log_info const *rli)
    */
   const_cast<Relay_log_info*>(rli)->set_flag(Relay_log_info::IN_STMT);
 
+  if (rli->deferred_events_collecting)
+    return rli->deferred_events->add(this);
+
   switch (type) {
   case LAST_INSERT_ID_EVENT:
     thd->stmt_depends_on_first_successful_insert_id_in_prev_stmt= 1;
@@ -5375,6 +5379,9 @@ int Rand_log_event::do_apply_event(Relay_log_info const *rli)
    */
   const_cast<Relay_log_info*>(rli)->set_flag(Relay_log_info::IN_STMT);
 
+  if (rli->deferred_events_collecting)
+    return rli->deferred_events->add(this);
+
   thd->rand.seed1= (ulong) seed1;
   thd->rand.seed2= (ulong) seed2;
   return 0;
@@ -5401,6 +5408,29 @@ Rand_log_event::do_shall_skip(Relay_log_info *rli)
   return continue_group(rli);
 }
 
+/**
+   Exec deferred Int-, Rand- and User- var events prefixing
+   a Query-log-event event.
+
+   @param thd THD handle
+
+   @return false on success, true if a failure in an event applying occurred.
+*/
+bool slave_execute_deferred_events(THD *thd)
+{
+  bool res= false;
+  Relay_log_info *rli= thd->rli_slave;
+
+  DBUG_ASSERT(rli && (!rli->deferred_events_collecting || rli->deferred_events));
+
+  if (!rli->deferred_events_collecting || rli->deferred_events->is_empty())
+    return res;
+
+  res= rli->deferred_events->execute(rli);
+
+  return res;
+}
+
 #endif /* !MYSQL_CLIENT */
 
 
@@ -5785,6 +5815,10 @@ int User_var_log_event::do_apply_event(Relay_log_info const *rli)
 {
   Item *it= 0;
   CHARSET_INFO *charset;
+
+  if (rli->deferred_events_collecting)
+    return rli->deferred_events->add(this);
+
   if (!(charset= get_charset(charset_number, MYF(MY_WME))))
     return 1;
   LEX_STRING user_var_name;

sql/log_event.h

@@ -3961,6 +3961,16 @@ static inline bool copy_event_cache_to_file_and_reinit(IO_CACHE *cache,
     reinit_io_cache(cache, WRITE_CACHE, 0, FALSE, TRUE);
 }
 
+#ifndef MYSQL_CLIENT
+/**
+   The function is called by slave applier in case there are
+   active table filtering rules to force gathering events associated
+   with Query-log-event into an array to execute
+   them once the fate of the Query is determined for execution.
+*/
+bool slave_execute_deferred_events(THD *thd);
+#endif
+
 /**
   @} (end of group Replication)
 */

sql/rpl_rli.cc

@@ -45,7 +45,9 @@ Relay_log_info::Relay_log_info()
    inited(0), abort_slave(0), slave_running(0), until_condition(UNTIL_NONE),
    until_log_pos(0), retried_trans(0),
    tables_to_lock(0), tables_to_lock_count(0),
-   last_event_start_time(0), m_flags(0)
+   last_event_start_time(0),
+   deferred_events(NULL),
+   m_flags(0)
 {
   DBUG_ENTER("Relay_log_info::Relay_log_info");
 

sql/rpl_rli.h

@@ -369,6 +369,41 @@ class Relay_log_info : public Slave_reporting_capability
    */
   time_t last_event_start_time;
 
+  /*
+    A container to hold on Intvar-, Rand-, Uservar- log-events in case
+    the slave is configured with table filtering rules.
+    The withhold events are executed when their parent Query destiny is
+    determined for execution as well.
+  */
+  Deferred_log_events *deferred_events;
+
+  /*
+    State of the container: true stands for IRU events gathering, 
+    false does for execution, either deferred or direct.
+  */
+  bool deferred_events_collecting;
+
+  /* 
+     Returns true if the argument event resides in the containter;
+     more specifically, the checking is done against the last added event.
+  */
+  bool is_deferred_event(Log_event * ev)
+  {
+    return deferred_events_collecting ? deferred_events->is_last(ev) : false;
+  };
+  /* The general cleanup that slave applier may need at the end of query. */
+  inline void cleanup_after_query()
+  {
+    if (deferred_events)
+      deferred_events->rewind();
+  };
+  /* The general cleanup that slave applier may need at the end of session. */
+  void cleanup_after_session()
+  {
+    if (deferred_events)
+      delete deferred_events;
+  };
+   
   /**
     Helper function to do after statement completion.
 

sql/rpl_utility.cc

@@ -226,3 +226,64 @@ table_def::compatible_with(Relay_log_info const *rli_arg, TABLE *table)
 
   return error;
 }
+
+#ifndef MYSQL_CLIENT
+Deferred_log_events::Deferred_log_events(Relay_log_info *rli) : last_added(NULL)
+{
+  my_init_dynamic_array(&array, sizeof(Log_event *), 32, 16);
+}
+
+Deferred_log_events::~Deferred_log_events() 
+{
+  delete_dynamic(&array);
+}
+
+int Deferred_log_events::add(Log_event *ev)
+{
+  last_added= ev;
+  insert_dynamic(&array, (uchar*) &ev);
+  return 0;
+}
+
+bool Deferred_log_events::is_empty()
+{  
+  return array.elements == 0;
+}
+
+bool Deferred_log_events::execute(Relay_log_info *rli)
+{
+  bool res= false;
+
+  DBUG_ASSERT(rli->deferred_events_collecting);
+
+  rli->deferred_events_collecting= false;
+  for (uint i=  0; !res && i < array.elements; i++)
+  {
+    Log_event *ev= (* (Log_event **)
+                    dynamic_array_ptr(&array, i));
+    res= ev->apply_event(rli);
+  }
+  rli->deferred_events_collecting= true;
+  return res;
+}
+
+void Deferred_log_events::rewind()
+{
+  /*
+    Reset preceeding Query log event events which execution was
+    deferred because of slave side filtering.
+  */
+  if (!is_empty())
+  {
+    for (uint i=  0; i < array.elements; i++)
+    {
+      Log_event *ev= *(Log_event **) dynamic_array_ptr(&array, i);
+      delete ev;
+    }
+    if (array.elements > array.max_element)
+      freeze_size(&array);
+    reset_dynamic(&array);
+  }
+}
+
+#endif

sql/rpl_utility.h

@@ -290,6 +290,24 @@ namespace {
   };
 
 }
+
+class Deferred_log_events
+{
+private:
+  DYNAMIC_ARRAY array;
+  Log_event *last_added;
+
+public:
+  Deferred_log_events(Relay_log_info *rli);
+  ~Deferred_log_events();
+  /* queue for exection at Query-log-event time prior the Query */;
+  int add(Log_event *ev);
+  bool is_empty();
+  bool execute(Relay_log_info *rli);
+  void rewind();
+  bool is_last(Log_event *ev) { return ev == last_added; };
+};
+
 #endif
 
 // NB. number of printed bit values is limited to sizeof(buf) - 1

sql/slave.cc

@@ -2360,7 +2360,8 @@ static int exec_relay_log_event(THD* thd, Relay_log_info* rli)
       used to read info about the relay log's format; it will be deleted when
       the SQL thread does not need it, i.e. when this thread terminates.
     */
-    if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT)
+    if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT &&
+        !rli->is_deferred_event(ev))
     {
       DBUG_PRINT("info", ("Deleting the event after it has been executed"));
       delete ev;
@@ -2990,6 +2991,12 @@ pthread_handler_t handle_slave_sql(void *arg)
     goto err;
   }
   thd->init_for_queries();
+  thd->rli_slave= rli;
+  if ((rli->deferred_events_collecting= rpl_filter->is_on()))
+  {
+    rli->deferred_events= new Deferred_log_events(rli);
+  }
+
   thd->temporary_tables = rli->save_temporary_tables; // restore temp tables
   set_thd_in_use_temporary_tables(rli);   // (re)set sql_thd in use for saved temp tables
   pthread_mutex_lock(&LOCK_thread_count);

sql/sql_base.cc

@@ -116,6 +116,8 @@ static void close_old_data_files(THD *thd, TABLE *table, bool morph_locks,
                                  bool send_refresh);
 static bool
 has_write_table_with_auto_increment(TABLE_LIST *tables);
+static bool
+has_write_table_auto_increment_not_first_in_pk(TABLE_LIST *tables);
 
 
 extern "C" uchar *table_cache_key(const uchar *record, size_t *length,
@@ -5471,6 +5473,12 @@ int lock_tables(THD *thd, TABLE_LIST *tables, uint count, bool *need_reopen)
 	*(ptr++)= table->table;
     }
 
+    if (thd->variables.binlog_format != BINLOG_FORMAT_ROW && tables)
+    {
+      if (has_write_table_auto_increment_not_first_in_pk(tables))
+        thd->lex->set_stmt_unsafe();
+    }
+
     /* We have to emulate LOCK TABLES if we are statement needs prelocking. */
     if (thd->lex->requires_prelocking())
     {
@@ -9065,6 +9073,32 @@ has_write_table_with_auto_increment(TABLE_LIST *tables)
   return 0;
 }
 
+/*
+  Tells if there is a table whose auto_increment column is a part
+  of a compound primary key while is not the first column in
+  the table definition.
+
+  @param tables Table list
+
+  @return true if the table exists, fais if does not.
+*/
+
+static bool
+has_write_table_auto_increment_not_first_in_pk(TABLE_LIST *tables)
+{
+  for (TABLE_LIST *table= tables; table; table= table->next_global)
+  {
+    /* we must do preliminary checks as table->table may be NULL */
+    if (!table->placeholder() &&
+        table->table->found_next_number_field &&
+        (table->lock_type >= TL_WRITE_ALLOW_WRITE)
+        && table->table->s->next_number_keypart != 0)
+      return 1;
+  }
+
+  return 0;
+}
+
 
 /*
   Open and lock system tables for read.

sql/sql_class.cc

@@ -601,7 +601,7 @@ Diagnostics_area::disable_status()
 THD::THD()
    :Statement(&main_lex, &main_mem_root, CONVENTIONAL_EXECUTION,
               /* statement id */ 0),
-   Open_tables_state(refresh_version), rli_fake(0),
+   Open_tables_state(refresh_version), rli_fake(NULL), rli_slave(NULL),
    lock_id(&main_lock_id),
    user_time(0), in_sub_stmt(0),
    sql_log_bin_toplevel(false),
@@ -1035,6 +1035,8 @@ THD::~THD()
     delete rli_fake;
     rli_fake= NULL;
   }
+  if (rli_slave)
+    rli_slave->cleanup_after_session();
 #endif
 
   free_root(&main_mem_root, MYF(0));
@@ -1267,6 +1269,10 @@ void THD::cleanup_after_query()
   /* reset table map for multi-table update */
   table_map_for_update= 0;
   m_binlog_invoker= FALSE;
+#ifndef EMBEDDED_LIBRARY
+  if (rli_slave)
+    rli_slave->cleanup_after_query();
+#endif
 }
 
 

sql/sql_class.h

@@ -1291,6 +1291,8 @@ class THD :public Statement,
 public:
   /* Used to execute base64 coded binlog events in MySQL server */
   Relay_log_info* rli_fake;
+  /* Slave applier execution context */
+  Relay_log_info* rli_slave;
 
   /*
     Constant for THD::where initialization in the beginning of every query.

sql/sql_parse.cc

@@ -2248,6 +2248,11 @@ mysql_execute_command(THD *thd)
       }
       DBUG_RETURN(0);
     }
+    /* 
+       Execute deferred events first
+    */
+    if (slave_execute_deferred_events(thd))
+      DBUG_RETURN(-1);
   }
   else
   {