[MDEV-13248] binlog.binlog_parallel_replication_marks_row fails in buildbot - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.1(EOL)
Fix Version/s: 10.1.26, 10.2.7
Component/s: Tests
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

Attachments

Activity

Ascending order - Click to sort in descending order

Elena Stepanova added a comment - 2017-07-05 21:15

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.

Elena Stepanova added a comment - 2017-07-05 21:15 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.

Elena Stepanova added a comment - 2017-07-06 14:29

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.

Elena Stepanova added a comment - 2017-07-06 14:29 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.

People

Assignee:: Elena Stepanova

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 1 Start watching this issue

Dates

Created:: 2017-07-05 20:34

Updated:: 2017-07-06 14:29

Resolved:: 2017-07-06 14:29

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server