[MDEV-13248] binlog.binlog_parallel_replication_marks_row fails in buildbot Created: 2017-07-05  Updated: 2017-07-06  Resolved: 2017-07-06

Status: Closed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 10.1
Fix Version/s: 10.1.26, 10.2.7

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


 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-deb-wheezy-amd64/builds/9437/steps/mtr/logs/stdio

binlog.binlog_parallel_replication_marks_row 'innodb_plugin,row' w4 [ fail ]
 
        Test ended at 2017-07-05 10:28:16
 
 
 
CURRENT_TEST: binlog.binlog_parallel_replication_marks_row
 
--- /usr/share/mysql/mysql-test/suite/binlog/r/binlog_parallel_replication_marks_row.result	2017-07-05 08:03:10.000000000 -0400
 
+++ /run/shm/var/4/log/binlog_parallel_replication_marks_row.reject	2017-07-05 10:28:15.992373389 -0400
 
@@ -37,61 +37,61 @@
 
 /* GTID */ INSERT INTO t1 VALUES (11, 7, 0);
 
 /* GTID */ COMMIT;
 
 FLUSH LOGS;
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
-# server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
-# server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
+#200121  8:32:22 server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
+#200121  8:32:22 server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
-# server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
-# server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
+#200121  8:32:22 server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
+#200121  8:32:22 server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# ddl
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# ddl
 
 /* GTID */ ALTER TABLE t1 ADD c INT
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
-# server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
-# server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
+#200121  8:32:22 server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
+#200121  8:32:22 server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
-# server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
-# server id 1  end_log_pos # 	Update_rows: table id # flags: STMT_END_F
 
-# server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
-# server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
-# server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
-# server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
+#200121  8:32:22 server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
+#200121  8:32:22 server id 1  end_log_pos # 	Update_rows: table id # flags: STMT_END_F
 
+#200121  8:32:22 server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
+#200121  8:32:22 server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
+#200121  8:32:22 server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
+#200121  8:32:22 server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
-# server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
-# server id 1  end_log_pos # 	Delete_rows: table id # flags: STMT_END_F
 
-# server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
-# server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
-# server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
-# server id 1  end_log_pos # 	Update_rows: table id # flags: STMT_END_F
 
+#200121  8:32:22 server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
+#200121  8:32:22 server id 1  end_log_pos # 	Delete_rows: table id # flags: STMT_END_F
 
+#200121  8:32:22 server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
+#200121  8:32:22 server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
+#200121  8:32:22 server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
+#200121  8:32:22 server id 1  end_log_pos # 	Update_rows: table id # flags: STMT_END_F
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
-# server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
-# server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
+#200121  8:32:22 server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
+#200121  8:32:22 server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
-# server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
-# server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
+#200121  8:32:22 server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
+#200121  8:32:22 server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
-# server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
-# server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
+#200121  8:32:22 server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
+#200121  8:32:22 server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
-# server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
-# server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
+#200121  8:32:22 server id 1  end_log_pos # 	Table_map: `test`.`t1` mapped to number #
 
+#200121  8:32:22 server id 1  end_log_pos # 	Write_rows: table id # flags: STMT_END_F
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# ddl
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# ddl
 
 DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `t5`
 
 DROP TABLE t1;
 
 
 
mysqltest: Result length mismatch


binlog.binlog_parallel_replication_marks_stm_mix 'mix,xtradb' w2 [ fail ]
 
        Test ended at 2017-07-05 10:27:28
 
 
 
CURRENT_TEST: binlog.binlog_parallel_replication_marks_stm_mix
 
--- /usr/share/mysql/mysql-test/suite/binlog/r/binlog_parallel_replication_marks_stm_mix.result	2017-07-05 08:03:10.000000000 -0400
 
+++ /run/shm/var/2/log/binlog_parallel_replication_marks_stm_mix.reject	2017-07-05 10:27:27.876371850 -0400
 
@@ -37,21 +37,21 @@
 
 /* GTID */ INSERT INTO t1 VALUES (11, 7, 0);
 
 /* GTID */ COMMIT;
 
 FLUSH LOGS;
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
 /* GTID */ INSERT INTO t1 VALUES (1,0)
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
 /* GTID */ INSERT INTO t1 VALUES (2,0)
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# ddl
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# ddl
 
 /* GTID */ ALTER TABLE t1 ADD c INT
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
 /* GTID */ INSERT INTO t1 VALUES (3,0,0)
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# ddl
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# ddl
 
 BEGIN
 
 /* GTID */ UPDATE t1 SET b=1, c=1 WHERE a=2
 
 /* GTID */ CREATE TEMPORARY TABLE t2 (a INT PRIMARY KEY, b INT) ENGINE=InnoDB
 
@@ -60,9 +60,9 @@
 
 DROP TEMPORARY TABLE `t2` /* generated by server */
 
 /* GTID */ INSERT INTO t1 VALUES (6, 3, 0)
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# ddl
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# ddl
 
 /* GTID */ CREATE TEMPORARY TABLE t3 (a INT PRIMARY KEY) ENGINE=InnoDB
 
-# server id 1  end_log_pos # 	GTID #-#-# ddl
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# ddl
 
 BEGIN
 
 /* GTID */ DELETE FROM t1 WHERE a=5
 
 /* GTID */ INSERT INTO t3 VALUES (7)
 
@@ -70,27 +70,27 @@
 
 /* GTID */ UPDATE t1 SET c=1 WHERE a=7
 
 DROP TEMPORARY TABLE `t3` /* generated by server */
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# ddl
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# ddl
 
 /* GTID */ CREATE TEMPORARY TABLE t4 (a INT PRIMARY KEY) ENGINE=InnoDB
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
 /* GTID */ INSERT INTO t1 VALUES (8, 5, 0)
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# ddl
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# ddl
 
 /* GTID */ ALTER TABLE t4 ADD b INT
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
 /* GTID */ INSERT INTO t1 VALUES (9, 5, 1)
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# trans
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# trans
 
 BEGIN
 
 /* GTID */ INSERT INTO t1 VALUES (10, 6, 0)
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# ddl
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# ddl
 
 BEGIN
 
 /* GTID */ CREATE TEMPORARY TABLE t5 (a INT PRIMARY KEY) ENGINE=InnoDB
 
 /* GTID */ INSERT INTO t1 VALUES (11, 7, 0)
 
 COMMIT/*!*/;
 
-# server id 1  end_log_pos # 	GTID #-#-# ddl
 
+#200121  8:32:22 server id 1  end_log_pos # 	GTID #-#-# ddl
 
 DROP /*!40005 TEMPORARY */ TABLE IF EXISTS `t5`
 
 DROP TABLE t1;
 
 
 
mysqltest: Result length mismatch



 Comments   
Comment by Elena Stepanova [ 2017-07-05 ]

The immediate reason of the test failure is that the substitution fails for timestamps in the binary log:

  s/^#\d+ \d+:\d+:\d+ /# /;

The substitution fails because it expects exactly one blank space between date and time, while in the failing test we have two (because the hour part only has one digit).
The reason why it expects exactly one space is that at the beginning the test sets the timestamp and time zone to hardcoded values:

set time_zone="+02:00";
 
--let $stable_stamp= `SELECT UNIX_TIMESTAMP("2020-01-21 15:32:22")`
 
eval set timestamp=$stable_stamp;

The timestamp works; however, the local time zone does not anyhow affect the way mysqlbinlog interprets the timestamps in the binary log, so in fact they are converted into the system timezone.
The test was passing locally for all developers involved, because they operate in the '+02:00' timezone or close to it – as long as the system timzone falls within the range of -03:00 - +10:00 or so, the hour part still has 2 digits, and substitution works. However, some of buildbot builders operate in different timezones, hence the error.

The fix should be simple – in fact, since the test removes all timestamps anyway, it shouldn't care which particular time the binlog contains, so we can remove the timezone and timestamp values and make the substitution works for both one and two digits.

Comment by Elena Stepanova [ 2017-07-06 ]

I'm setting 10.2.7 as a fix version assuming there will be another merge before 10.2.7 release. Otherwise, it's failing in the current tree.

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