[MDEV-10631] rpl.rpl_mdev6386 failed in buildbot Created: 2016-08-21  Updated: 2017-02-19  Resolved: 2017-02-19

Status: Closed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 10.0
Fix Version/s: 10.0.30, 10.1.22, 10.2.5

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Elena Stepanova
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Blocks
blocks MDEV-7069 Fix buildbot failures in main server ... Stalled
Sprint: 5.5.55

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-centos5-x86/builds/5070/steps/test/logs/stdio

rpl.rpl_mdev6386 'row,xtradb'            w2 [ fail ]
 
        Test ended at 2016-08-14 10:16:52
 
 
 
CURRENT_TEST: rpl.rpl_mdev6386
 
--- /usr/local/mariadb-10.0.27-linux-i686/mysql-test/suite/rpl/r/rpl_mdev6386.result	2016-08-14 09:31:19.000000000 +0200
 
+++ /usr/local/mariadb-10.0.27-linux-i686/mysql-test/suite/rpl/r/rpl_mdev6386.reject	2016-08-14 10:16:52.000000000 +0200
 
@@ -46,11 +46,6 @@
 
 Contents on slave after:
 
 SELECT * FROM t1 ORDER BY a;
 
 a	b
 
-1	1
 
-2	1
 
-3	1
 
-4	1
 
-5	1
 
 DROP TABLE t1;
 
 include/stop_slave.inc
 
 SET GLOBAL slave_parallel_threads= @old_parallel;
 
 
 
mysqltest: Result length mismatch



 Comments   
Comment by Elena Stepanova [ 2017-02-17 ]

Here is the occurrence where we still have logs present:
http://buildbot.askmonty.org/buildbot/builders/kvm-deb-jessie-amd64/builds/779/steps/test_4/logs/stdio

No dependency on previous tests, both master and slave were restarted before this test.

Nothing obvious in the slave error log that would show any difference comparing to a normal run. The fact that at the end it restarts from 0-1-4 in one run and from 0-1-5 in another shouldn't matter, it happens after the point where the failure occurs, because there is no synchronization after final DROP TABLE (event 0-1-5).

slave error log, failed run

 
CURRENT_TEST: rpl.rpl_mdev6386
 
160421  4:50:57 [Note] /usr/sbin/mysqld (mysqld 10.0.24-MariaDB-1~jessie) starting as process 32343 ...
 
160421  4:50:57 [Note] Plugin 'XTRADB_READ_VIEW' is disabled.
 
160421  4:50:57 [Note] Plugin 'XTRADB_INTERNAL_HASH_TABLES' is disabled.
 
160421  4:50:57 [Note] Plugin 'XTRADB_RSEG' is disabled.
 
160421  4:50:57 [Note] Plugin 'FEDERATED' is disabled.
 
160421  4:50:57 [Note] Plugin 'BLACKHOLE' is disabled.
 
160421  4:50:57 [Note] Plugin 'ARCHIVE' is disabled.
 
160421  4:50:57 [Note] Plugin 'FEEDBACK' is disabled.
 
160421  4:50:57 [Note] Plugin 'partition' is disabled.
 
160421  4:50:57 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
160421  4:50:57 [Note] InnoDB: The InnoDB memory heap is disabled
 
160421  4:50:57 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
160421  4:50:57 [Note] InnoDB: Memory barrier is not used
 
160421  4:50:57 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
160421  4:50:57 [Note] InnoDB: Using Linux native AIO
 
160421  4:50:57 [Note] InnoDB: Not using CPU crc32 instructions
 
160421  4:50:57 [Note] InnoDB: Initializing buffer pool, size = 8.0M
 
160421  4:50:57 [Note] InnoDB: Completed initialization of buffer pool
 
160421  4:50:57 [Note] InnoDB: Highest supported file format is Barracuda.
 
160421  4:50:57 [Note] InnoDB: 128 rollback segment(s) are active.
 
160421  4:50:57 [Note] InnoDB: Waiting for purge to start
 
160421  4:50:57 [Note] InnoDB: 5.6.29 started; log sequence number 1629415
 
160421  4:50:57 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
 
160421  4:50:57 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
 
160421  4:50:57 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
 
160421  4:50:57 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
 
160421  4:50:57 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-interval=60'
 
160421  4:50:57 [Warning] /usr/sbin/mysqld: unknown option '--loose-skip-plugin-innodb-changed-pages'
 
160421  4:50:57 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
 
160421  4:50:57 [Note] Server socket created on IP: '127.0.0.1'.
 
160421  4:50:57 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '10.0.24-MariaDB-1~jessie'  socket: '/dev/shm/var/tmp/4/mysqld.2.sock'  port: 16041  mariadb.org binary distribution
 
160421  4:50:58 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='127.0.0.1', master_port='16040', master_log_file='master-bin.000001', master_log_pos='4'.
 
160421  4:50:58 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 4, relay log './slave-relay-bin.000001' position: 4
 
160421  4:50:58 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16040',replication started in log 'master-bin.000001' at position 4
 
160421  4:50:58 [Note] Error reading relay log event: slave SQL thread was killed
 
160421  4:50:58 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
 
160421  4:50:58 [Note] Slave I/O thread exiting, read up to log 'master-bin.000002', position 524
 
160421  4:50:58 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16040', master_log_file='master-bin.000002', master_log_pos='524'. New state master_host='127.0.0.1', master_port='16040', master_log_file='master-bin.000002', master_log_pos='524'.
 
160421  4:50:58 [Note] Previous Using_Gtid=No. New Using_Gtid=Current_Pos
 
160421  4:50:58 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16040',replication starts at GTID position '0-1-2'
 
160421  4:50:58 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000002' at position 524, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-2'
 
160421  4:50:58 [ERROR] Slave SQL: Could not execute Write_rows_v1 event on table test.t1; Duplicate entry '1' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log master-bin.000002, end_log_pos 678, Gtid 0-1-3, Internal MariaDB error code: 1062
 
160421  4:50:58 [Warning] Slave: Duplicate entry '1' for key 'PRIMARY' Error_code: 1062
 
160421  4:50:58 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'master-bin.000002' position 524; GTID position '0-1-2'
 
160421  4:50:58 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000002' at position 524; GTID position '0-1-2'
 
160421  4:50:58 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
 
160421  4:50:58 [Note] Slave I/O thread exiting, read up to log 'master-bin.000002', position 874; GTID position 0-1-4
 
160421  4:50:58 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16040',replication starts at GTID position '0-1-2'
 
160421  4:50:58 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000002' at position 524, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-2'
 
160421  4:50:58 [Note] Error reading relay log event: slave SQL thread was killed
 
160421  4:50:58 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
 
160421  4:50:58 [Note] Slave I/O thread exiting, read up to log 'master-bin.000002', position 1016; GTID position 0-1-5
 
160421  4:50:58 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16040',replication starts at GTID position '0-1-4'
 
160421  4:50:58 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000002' at position 874, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-4'
 
160421  4:50:58 [Note] Error reading relay log event: slave SQL thread was killed
 
160421  4:50:58 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
 
160421  4:50:58 [Note] Slave I/O thread exiting, read up to log 'master-bin.000002', position 1016; GTID position 0-1-5
 
160421  4:50:58 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16040', master_log_file='master-bin.000002', master_log_pos='1016'. New state master_host='127.0.0.1', master_port='16040', master_log_file='', master_log_pos='1016'.
 
160421  4:50:58 [Note] Previous Using_Gtid=Current_Pos. New Using_Gtid=No

slave error log, normal run

 
CURRENT_TEST: rpl.rpl_mdev6386
 
160421  4:50:59 [Note] /usr/sbin/mysqld (mysqld 10.0.24-MariaDB-1~jessie) starting as process 32615 ...
 
160421  4:50:59 [Note] Plugin 'XTRADB_READ_VIEW' is disabled.
 
160421  4:50:59 [Note] Plugin 'XTRADB_INTERNAL_HASH_TABLES' is disabled.
 
160421  4:50:59 [Note] Plugin 'XTRADB_RSEG' is disabled.
 
160421  4:50:59 [Note] Plugin 'FEDERATED' is disabled.
 
160421  4:50:59 [Note] Plugin 'BLACKHOLE' is disabled.
 
160421  4:50:59 [Note] Plugin 'ARCHIVE' is disabled.
 
160421  4:50:59 [Note] Plugin 'FEEDBACK' is disabled.
 
160421  4:50:59 [Note] Plugin 'partition' is disabled.
 
160421  4:50:59 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
160421  4:50:59 [Note] InnoDB: The InnoDB memory heap is disabled
 
160421  4:50:59 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
160421  4:50:59 [Note] InnoDB: Memory barrier is not used
 
160421  4:50:59 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
160421  4:50:59 [Note] InnoDB: Using Linux native AIO
 
160421  4:50:59 [Note] InnoDB: Not using CPU crc32 instructions
 
160421  4:50:59 [Note] InnoDB: Initializing buffer pool, size = 8.0M
 
160421  4:50:59 [Note] InnoDB: Completed initialization of buffer pool
 
160421  4:50:59 [Note] InnoDB: Highest supported file format is Barracuda.
 
160421  4:50:59 [Note] InnoDB: 128 rollback segment(s) are active.
 
160421  4:50:59 [Note] InnoDB: Waiting for purge to start
 
160421  4:50:59 [Note] InnoDB: 5.6.29 started; log sequence number 1629415
 
160421  4:50:59 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
 
160421  4:50:59 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
 
160421  4:50:59 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
 
160421  4:50:59 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
 
160421  4:50:59 [Warning] /usr/sbin/mysqld: unknown variable 'loose-feedback-debug-interval=60'
 
160421  4:50:59 [Warning] /usr/sbin/mysqld: unknown option '--loose-skip-plugin-innodb-changed-pages'
 
160421  4:50:59 [Warning] /usr/sbin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
 
160421  4:50:59 [Note] Server socket created on IP: '127.0.0.1'.
 
160421  4:50:59 [Note] /usr/sbin/mysqld: ready for connections.
 
Version: '10.0.24-MariaDB-1~jessie'  socket: '/dev/shm/var/tmp/4/mysqld.2.sock'  port: 16041  mariadb.org binary distribution
 
160421  4:51:00 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='127.0.0.1', master_port='16040', master_log_file='master-bin.000001', master_log_pos='4'.
 
160421  4:51:00 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 4, relay log './slave-relay-bin.000001' position: 4
 
160421  4:51:00 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16040',replication started in log 'master-bin.000001' at position 4
 
160421  4:51:00 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000002' at position 484
 
160421  4:51:00 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
 
160421  4:51:00 [Note] Slave I/O thread exiting, read up to log 'master-bin.000002', position 524
 
160421  4:51:00 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16040', master_log_file='master-bin.000002', master_log_pos='524'. New state master_host='127.0.0.1', master_port='16040', master_log_file='master-bin.000002', master_log_pos='484'.
 
160421  4:51:00 [Note] Previous Using_Gtid=No. New Using_Gtid=Current_Pos
 
160421  4:51:00 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000002' at position 484, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-2'
 
160421  4:51:00 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16040',replication starts at GTID position '0-1-2'
 
160421  4:51:00 [ERROR] Slave SQL: Could not execute Write_rows_v1 event on table test.t1; Duplicate entry '1' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log master-bin.000002, end_log_pos 678, Gtid 0-1-3, Internal MariaDB error code: 1062
 
160421  4:51:00 [Warning] Slave: Duplicate entry '1' for key 'PRIMARY' Error_code: 1062
 
160421  4:51:00 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'master-bin.000002' position 524; GTID position '0-1-2'
 
160421  4:51:00 [Note] Error reading relay log event: slave SQL thread was killed
 
160421  4:51:00 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
 
160421  4:51:00 [Note] Slave I/O thread exiting, read up to log 'master-bin.000002', position 874; GTID position 0-1-4
 
160421  4:51:00 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000002' at position 524, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-2'
 
160421  4:51:00 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16040',replication starts at GTID position '0-1-2'
 
160421  4:51:00 [Note] Error reading relay log event: slave SQL thread was killed
 
160421  4:51:00 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
 
160421  4:51:00 [Note] Slave I/O thread exiting, read up to log 'master-bin.000002', position 1016; GTID position 0-1-5
 
160421  4:51:00 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000002' at position 1016, relay log './slave-relay-bin.000001' position: 4; GTID position '0-1-5'
 
160421  4:51:00 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16040',replication starts at GTID position '0-1-5'
 
160421  4:51:01 [Note] Error reading relay log event: slave SQL thread was killed
 
160421  4:51:01 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
 
160421  4:51:01 [Note] Slave I/O thread exiting, read up to log 'master-bin.000002', position 1016; GTID position 0-1-5
 
160421  4:51:01 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16040', master_log_file='master-bin.000002', master_log_pos='1016'. New state master_host='127.0.0.1', master_port='16040', master_log_file='', master_log_pos='1016'.
 
160421  4:51:01 [Note] Previous Using_Gtid=Current_Pos. New Using_Gtid=No

Comment by Elena Stepanova [ 2017-02-18 ]

There was a previous attempt to fix this test, but obviously it did not work: MDEV-7353.

The problem is reproducible reliably with this addition (on top of current 10.0 tree 01d5d6db4):

diff --git a/sql/log_event.cc b/sql/log_event.cc
 
index 14f6bb2..a8b4478 100644
 
--- a/sql/log_event.cc
 
+++ b/sql/log_event.cc
 
@@ -7430,6 +7430,7 @@ int Xid_log_event::do_apply_event(rpl_group_info *rgi)
 
   general_log_print(thd, COM_QUERY,
 
                     "COMMIT /* implicit, from Xid_log_event */");
 
   thd->variables.option_bits&= ~OPTION_GTID_BEGIN;
 
+  my_sleep(1000000);
 
   res= trans_commit(thd); /* Automatically rolls back on error. */
 
   thd->mdl_context.release_transactional_locks();

This is obviously an injection for RBR variation of the test.

$ perl ./mtr rpl.rpl_mdev6386,xtradb,row
 
...
 
rpl.rpl_mdev6386 'row,xtradb'            [ fail ]
 
        Test ended at 2017-02-18 03:00:17
 
 
 
CURRENT_TEST: rpl.rpl_mdev6386
 
--- /data/src/10.0-bug/mysql-test/suite/rpl/r/rpl_mdev6386.result	2017-01-29 18:09:46.011120981 +0200
 
+++ /data/src/10.0-bug/mysql-test/suite/rpl/r/rpl_mdev6386.reject	2017-02-18 03:00:16.792839152 +0200
 
@@ -46,11 +46,6 @@
 
 Contents on slave after:
 
 SELECT * FROM t1 ORDER BY a;
 
 a	b
 
-1	1
 
-2	1
 
-3	1
 
-4	1
 
-5	1
 
 DROP TABLE t1;
 
 include/stop_slave.inc
 
 SET GLOBAL slave_parallel_threads= @old_parallel;

So, even though the event 0-1-3 hasn't been committed yet, the GTID 0-1-4 is already visible.

knielsen,
Could you please take a look?
I could probably tweak the test so that it does not fail in such situation, but I'm not sure I should do so until it's confirmed to be the expected behavior.

Comment by Kristian Nielsen [ 2017-02-18 ]

I think it is a bug that the DROP TEMPORARY TABLE IF EXISTS is binlogged (in
row-based mode). In row-based, temporary table operations are not binlogged,
instead the actual rows are sent in row events.

IIRC, this is something Monty introduced, I believe I have remarked upon it
before. It seems quite bad to inject extra errorneous DDL into the binlog
stream. It should also be extremely bad for optimistic parallel replication
in 10.1, where every DDL blocks things from running in parallel.

The DROP TEMPORARY TABLE does not do anything and there is nothing to block
it from completing before the prior transaction (when slave binlogging is
disabled as in the test). Hence the sync_with_master_gtid is ineffective and
we get the sporadic failures.

If you just want to hide the problem, an extra transaction to sync on after
the DROP table should work, I think:

diff --git a/mysql-test/suite/rpl/r/rpl_mdev6386.result b/mysql-test/suite/rpl/r/rpl_mdev6386.result
 
index fa49d9a..be9d208 100644
 
--- a/mysql-test/suite/rpl/r/rpl_mdev6386.result
 
+++ b/mysql-test/suite/rpl/r/rpl_mdev6386.result
 
@@ -22,6 +22,7 @@ INSERT INTO t2 VALUE (4, 1);
 
 INSERT INTO t2 VALUE (5, 1);
 
 INSERT INTO t1 SELECT * FROM t2;
 
 DROP TEMPORARY TABLE t2;
 
+INSERT INTO t1 VALUES (6, 3);
 
 include/save_master_gtid.inc
 
 Contents on master:
 
 SELECT * FROM t1 ORDER BY a;
 
@@ -31,6 +32,7 @@ a	b
 
 3	1
 
 4	1
 
 5	1
 
+6	3
 
 START SLAVE;
 
 include/wait_for_slave_sql_error.inc [errno=1062]
 
 STOP SLAVE IO_THREAD;
 
@@ -51,6 +53,7 @@ a	b
 
 3	1
 
 4	1
 
 5	1
 
+6	3
 
 DROP TABLE t1;
 
 include/stop_slave.inc
 
 SET GLOBAL slave_parallel_threads= @old_parallel;
 
diff --git a/mysql-test/suite/rpl/t/rpl_mdev6386.test b/mysql-test/suite/rpl/t/rpl_mdev6386.test
 
index 3e4e79e..1f6c708 100644
 
--- a/mysql-test/suite/rpl/t/rpl_mdev6386.test
 
+++ b/mysql-test/suite/rpl/t/rpl_mdev6386.test
 
@@ -31,6 +31,7 @@ INSERT INTO t2 VALUE (4, 1);
 
 INSERT INTO t2 VALUE (5, 1);
 
 INSERT INTO t1 SELECT * FROM t2;
 
 DROP TEMPORARY TABLE t2;
 
+INSERT INTO t1 VALUES (6, 3);
 
 --source include/save_master_gtid.inc
 
 --echo Contents on master:
 
 SELECT * FROM t1 ORDER BY a;

Comment by Elena Stepanova [ 2017-02-18 ]

knielsen,

Thanks, I'll use this or a similar approach. As I understand, you don't consider this particular effect to be overly dangerous (while I understand your concerns about the extra DDL in general).

FWIW, I don't think this extra DROP itself is something Monty introduced, at least not in MariaDB (maybe you meant that he did it back at MySQL, although I doubt it was him). MySQL also does it, and I remember the struggle with temporary tables at MySQL back when RBR was young. I think the reason back then was that because the log format could have changed to ROW after the temporary table was created, it wasn't known for sure whether its creation was logged or not, and if DROP wasn't logged, bad things would happen – both logical problems, since the slave would consider the table still existing, and resource problems, because the open temporary tables were leaking on slave. However, I see in the code Monty's later additions for remembering whether a table creation was logged or not, so maybe the code is actually ready to get rid of this extra event now, just nobody got to it.

Comment by Elena Stepanova [ 2017-02-18 ]

https://github.com/MariaDB/server/commit/f647852f9800e6c2eaccfa14277fa00c45998265

Comment by Elena Stepanova [ 2017-02-19 ]

https://github.com/MariaDB/server/commit/343ba58562ace1edd2bb24aeb31aabffcae5fec2

Generated at Thu Feb 08 07:43:43 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.