[MDEV-18055] rpl.rpl_trigger failed in buildbot with wrong result Created: 2018-12-21  Updated: 2023-11-29  Resolved: 2023-11-29

Status: Closed
Project: MariaDB Server
Component/s: Replication, Tests
Affects Version/s: 10.1
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Andrei Elkin
Resolution: Won't Fix Votes: 0
Labels: None

Attachments: Text File mysqld.1.err.3.txt     Text File mysqld.2.err.3.txt     Text File stdio.txt    

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-deb-stretch-ppc64le/builds/3120

rpl.rpl_trigger 'stmt,xtradb'            w1 [ fail ]
 
        Test ended at 2018-12-06 19:39:53
 
 
 
CURRENT_TEST: rpl.rpl_trigger
 
--- /usr/share/mysql/mysql-test/suite/rpl/r/rpl_trigger.result	2018-12-06 15:49:05.000000000 -0500
 
+++ /dev/shm/var/1/log/rpl_trigger.reject	2018-12-06 19:39:53.003032383 -0500
 
@@ -771,16 +771,13 @@
 
 f1
 
 5
 
 4
 
-3
 
-2
 
-1
 
+-3
 
+-2
 
+-1
 
 SELECT * from t32 /* must be f3 5 * 100 ...  100 */;
 
 f3
 
 500
 
 400
 
-300
 
-200
 
-100
 
 drop trigger trg12;
 
 drop table t22,t32;
 
 drop table t12;
 
@@ -797,11 +794,6 @@
 
 insert into t11 values (-1);
 
 select * from t11;
 
 f1
 
--5
 
--4
 
--3
 
--2
 
--1
 
 create trigger trg11 before update on t11 /* slave local */
 
 for each row
 
 begin
 
@@ -826,14 +818,8 @@
 
 UPDATE t11 SET f1=5 where f1=-5;
 
 SELECT * from t11 /* must be f1 5, 1 - 5 2 - 5 ... -1 */;
 
 f1
 
-5
 
--4
 
--3
 
--2
 
--1
 
 SELECT * from t31 /* must be f3 5*100 */;
 
 f3
 
-500
 
 UPDATE t11 SET f1=5 where f1=-5;
 
 UPDATE t11 SET f1=4 where f1=-4;
 
 UPDATE t11 SET f1=3 where f1=-3;
 
@@ -841,18 +827,8 @@
 
 UPDATE t11 SET f1=1 where f1=-1;
 
 SELECT * from t11 /* must be f1 5 ... 1 */;
 
 f1
 
-5
 
-4
 
-3
 
-2
 
-1
 
 SELECT * from t31 /* must be f3 5 * 100 ...  100 */;
 
 f3
 
-500
 
-400
 
-300
 
-200
 
-100
 
 drop trigger trg11;
 
 drop table t21,t31;
 
 drop table t11;
 
 
 
mysqltest: Result length mismatch



 Comments   
Comment by Elena Stepanova [ 2019-07-22 ]

Another occurrence:
http://buildbot.askmonty.org/buildbot/builders/kvm-deb-stretch-ppc64le/builds/3792/steps/mtr/logs/stdio

10.1-serg dec7f43425a02f2269b72e51d8789959

 
rpl.rpl_trigger 'innodb_plugin,stmt'     w3 [ fail ]
 
        Test ended at 2019-04-10 06:49:52
 
 
 
CURRENT_TEST: rpl.rpl_trigger
 
--- /usr/share/mysql/mysql-test/suite/rpl/r/rpl_trigger.result	2019-04-10 05:00:50.000000000 -0400
 
+++ /dev/shm/var/3/log/rpl_trigger.reject	2019-04-10 06:49:52.273854028 -0400
 
@@ -293,11 +293,6 @@
 
 insert into t18 values (-1);
 
 select * from t18;
 
 f1
 
--5
 
--4
 
--3
 
--2
 
--1
 
 create trigger trg18 before update on t18 /* slave local */
 
 for each row
 
 begin
 
@@ -322,14 +317,8 @@
 
 UPDATE t18 SET f1=5 where f1=-5;
 
 SELECT * from t18 /* must be f1 5, 1 - 5 2 - 5 ... -1 */;
 
 f1
 
-5
 
--4
 
--3
 
--2
 
--1
 
 SELECT * from t38 /* must be f3 5*100 */;
 
 f3
 
-500
 
 UPDATE t18 SET f1=5 where f1=-5;
 
 UPDATE t18 SET f1=4 where f1=-4;
 
 UPDATE t18 SET f1=3 where f1=-3;
 
@@ -337,18 +326,8 @@
 
 UPDATE t18 SET f1=1 where f1=-1;
 
 SELECT * from t18 /* must be f1 5 ... 1 */;
 
 f1
 
-5
 
-4
 
-3
 
-2
 
-1
 
 SELECT * from t38 /* must be f3 5 * 100 ...  100 */;
 
 f3
 
-500
 
-400
 
-300
 
-200
 
-100
 
 drop trigger trg18;
 
 drop table t28,t38;
 
 drop table t18;
 
@@ -365,11 +344,6 @@
 
 insert into t17 values (-1);
 
 select * from t17;
 
 f1
 
--5
 
--4
 
--3
 
--2
 
--1
 
 create trigger trg17 before update on t17 /* slave local */
 
 for each row
 
 begin
 
@@ -394,14 +368,8 @@
 
 UPDATE t17 SET f1=5 where f1=-5;
 
 SELECT * from t17 /* must be f1 5, 1 - 5 2 - 5 ... -1 */;
 
 f1
 
-5
 
--4
 
--3
 
--2
 
--1
 
 SELECT * from t37 /* must be f3 5*100 */;
 
 f3
 
-500
 
 UPDATE t17 SET f1=5 where f1=-5;
 
 UPDATE t17 SET f1=4 where f1=-4;
 
 UPDATE t17 SET f1=3 where f1=-3;
 
@@ -409,18 +377,8 @@
 
 UPDATE t17 SET f1=1 where f1=-1;
 
 SELECT * from t17 /* must be f1 5 ... 1 */;
 
 f1
 
-5
 
-4
 
-3
 
-2
 
-1
 
 SELECT * from t37 /* must be f3 5 * 100 ...  100 */;
 
 f3
 
-500
 
-400
 
-300
 
-200
 
-100
 
 drop trigger trg17;
 
 drop table t27,t37;
 
 drop table t17;
 
@@ -437,11 +395,6 @@
 
 insert into t16 values (-1);
 
 select * from t16;
 
 f1
 
--5
 
--4
 
--3
 
--2
 
--1
 
 create trigger trg16 before update on t16 /* slave local */
 
 for each row
 
 begin
 
@@ -466,14 +419,8 @@
 
 UPDATE t16 SET f1=5 where f1=-5;
 
 SELECT * from t16 /* must be f1 5, 1 - 5 2 - 5 ... -1 */;
 
 f1
 
-5
 
--4
 
--3
 
--2
 
--1
 
 SELECT * from t36 /* must be f3 5*100 */;
 
 f3
 
-500
 
 UPDATE t16 SET f1=5 where f1=-5;
 
 UPDATE t16 SET f1=4 where f1=-4;
 
 UPDATE t16 SET f1=3 where f1=-3;
 
@@ -481,18 +428,8 @@
 
 UPDATE t16 SET f1=1 where f1=-1;
 
 SELECT * from t16 /* must be f1 5 ... 1 */;
 
 f1
 
-5
 
-4
 
-3
 
-2
 
-1
 
 SELECT * from t36 /* must be f3 5 * 100 ...  100 */;
 
 f3
 
-500
 
-400
 
-300
 
-200
 
-100
 
 drop trigger trg16;
 
 drop table t26,t36;
 
 drop table t16;
 
@@ -509,11 +446,6 @@
 
 insert into t15 values (-1);
 
 select * from t15;
 
 f1
 
--5
 
--4
 
--3
 
--2
 
--1
 
 create trigger trg15 before update on t15 /* slave local */
 
 for each row
 
 begin
 
@@ -538,14 +470,8 @@
 
 UPDATE t15 SET f1=5 where f1=-5;
 
 SELECT * from t15 /* must be f1 5, 1 - 5 2 - 5 ... -1 */;
 
 f1
 
-5
 
--4
 
--3
 
--2
 
--1
 
 SELECT * from t35 /* must be f3 5*100 */;
 
 f3
 
-500
 
 UPDATE t15 SET f1=5 where f1=-5;
 
 UPDATE t15 SET f1=4 where f1=-4;
 
 UPDATE t15 SET f1=3 where f1=-3;
 
@@ -553,18 +479,8 @@
 
 UPDATE t15 SET f1=1 where f1=-1;
 
 SELECT * from t15 /* must be f1 5 ... 1 */;
 
 f1
 
-5
 
-4
 
-3
 
-2
 
-1
 
 SELECT * from t35 /* must be f3 5 * 100 ...  100 */;
 
 f3
 
-500
 
-400
 
-300
 
-200
 
-100
 
 drop trigger trg15;
 
 drop table t25,t35;
 
 drop table t15;
 
@@ -581,11 +497,6 @@
 
 insert into t14 values (-1);
 
 select * from t14;
 
 f1
 
--5
 
--4
 
--3
 
--2
 
--1
 
 create trigger trg14 before update on t14 /* slave local */
 
 for each row
 
 begin
 
@@ -610,14 +521,8 @@
 
 UPDATE t14 SET f1=5 where f1=-5;
 
 SELECT * from t14 /* must be f1 5, 1 - 5 2 - 5 ... -1 */;
 
 f1
 
-5
 
--4
 
--3
 
--2
 
--1
 
 SELECT * from t34 /* must be f3 5*100 */;
 
 f3
 
-500
 
 UPDATE t14 SET f1=5 where f1=-5;
 
 UPDATE t14 SET f1=4 where f1=-4;
 
 UPDATE t14 SET f1=3 where f1=-3;
 
@@ -625,18 +530,8 @@
 
 UPDATE t14 SET f1=1 where f1=-1;
 
 SELECT * from t14 /* must be f1 5 ... 1 */;
 
 f1
 
-5
 
-4
 
-3
 
-2
 
-1
 
 SELECT * from t34 /* must be f3 5 * 100 ...  100 */;
 
 f3
 
-500
 
-400
 
-300
 
-200
 
-100
 
 drop trigger trg14;
 
 drop table t24,t34;
 
 drop table t14;
 
@@ -653,11 +548,6 @@
 
 insert into t13 values (-1);
 
 select * from t13;
 
 f1
 
--5
 
--4
 
--3
 
--2
 
--1
 
 create trigger trg13 before update on t13 /* slave local */
 
 for each row
 
 begin
 
@@ -682,14 +572,8 @@
 
 UPDATE t13 SET f1=5 where f1=-5;
 
 SELECT * from t13 /* must be f1 5, 1 - 5 2 - 5 ... -1 */;
 
 f1
 
-5
 
--4
 
--3
 
--2
 
--1
 
 SELECT * from t33 /* must be f3 5*100 */;
 
 f3
 
-500
 
 UPDATE t13 SET f1=5 where f1=-5;
 
 UPDATE t13 SET f1=4 where f1=-4;
 
 UPDATE t13 SET f1=3 where f1=-3;
 
@@ -697,18 +581,8 @@
 
 UPDATE t13 SET f1=1 where f1=-1;
 
 SELECT * from t13 /* must be f1 5 ... 1 */;
 
 f1
 
-5
 
-4
 
-3
 
-2
 
-1
 
 SELECT * from t33 /* must be f3 5 * 100 ...  100 */;
 
 f3
 
-500
 
-400
 
-300
 
-200
 
-100
 
 drop trigger trg13;
 
 drop table t23,t33;
 
 drop table t13;
 
@@ -725,11 +599,6 @@
 
 insert into t12 values (-1);
 
 select * from t12;
 
 f1
 
--5
 
--4
 
--3
 
--2
 
--1
 
 create trigger trg12 before update on t12 /* slave local */
 
 for each row
 
 begin
 
@@ -754,14 +623,8 @@
 
 UPDATE t12 SET f1=5 where f1=-5;
 
 SELECT * from t12 /* must be f1 5, 1 - 5 2 - 5 ... -1 */;
 
 f1
 
-5
 
--4
 
--3
 
--2
 
--1
 
 SELECT * from t32 /* must be f3 5*100 */;
 
 f3
 
-500
 
 UPDATE t12 SET f1=5 where f1=-5;
 
 UPDATE t12 SET f1=4 where f1=-4;
 
 UPDATE t12 SET f1=3 where f1=-3;
 
@@ -769,18 +632,8 @@
 
 UPDATE t12 SET f1=1 where f1=-1;
 
 SELECT * from t12 /* must be f1 5 ... 1 */;
 
 f1
 
-5
 
-4
 
-3
 
-2
 
-1
 
 SELECT * from t32 /* must be f3 5 * 100 ...  100 */;
 
 f3
 
-500
 
-400
 
-300
 
-200
 
-100
 
 drop trigger trg12;
 
 drop table t22,t32;
 
 drop table t12;
 
@@ -797,11 +650,6 @@
 
 insert into t11 values (-1);
 
 select * from t11;
 
 f1
 
--5
 
--4
 
--3
 
--2
 
--1
 
 create trigger trg11 before update on t11 /* slave local */
 
 for each row
 
 begin
 
@@ -826,14 +674,8 @@
 
 UPDATE t11 SET f1=5 where f1=-5;
 
 SELECT * from t11 /* must be f1 5, 1 - 5 2 - 5 ... -1 */;
 
 f1
 
-5
 
--4
 
--3
 
--2
 
--1
 
 SELECT * from t31 /* must be f3 5*100 */;
 
 f3
 
-500
 
 UPDATE t11 SET f1=5 where f1=-5;
 
 UPDATE t11 SET f1=4 where f1=-4;
 
 UPDATE t11 SET f1=3 where f1=-3;
 
@@ -841,18 +683,8 @@
 
 UPDATE t11 SET f1=1 where f1=-1;
 
 SELECT * from t11 /* must be f1 5 ... 1 */;
 
 f1
 
-5
 
-4
 
-3
 
-2
 
-1
 
 SELECT * from t31 /* must be f3 5 * 100 ...  100 */;
 
 f3
 
-500
 
-400
 
-300
 
-200
 
-100
 
 drop trigger trg11;
 
 drop table t21,t31;
 
 drop table t11;
 
 
 
mysqltest: Result length mismatch

Portion of stdout prior to the failure:

worker[3] > Restart [mysqld.1 - pid: 6082, winpid: 6082] - running with different options '--ignore-builtin-innodb --plugin-load-add=ha_innodb.so --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-tables --innodb-metrics --binlog-format=statement --log-bin=master-bin --log-bin=master-bin' != '--ignore-builtin-innodb --plugin-load-add=ha_innodb.so --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-tables --innodb-metrics --log-bin=master-bin --binlog-format=statement --log-bin=master-bin'
 
worker[3] > Restart [mysqld.2 - pid: 6090, winpid: 6090] - running with different options '--ignore-builtin-innodb --plugin-load-add=ha_innodb.so --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-tables --innodb-metrics --binlog-format=statement --log-bin=slave-bin --log-bin=slave-bin' != '--ignore-builtin-innodb --plugin-load-add=ha_innodb.so --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-tables --innodb-metrics --log-bin=slave-bin --binlog-format=statement --log-bin=slave-bin'
 
rpl.rpl_sp_variables 'row'               w2 [ pass ]    163
 
rpl.rpl_set_null_myisam 'row'            w1 [ pass ]    558
 
rpl.rpl_stm_EE_err2 'row'                w1 [ skipped ]  Neither MIXED nor STATEMENT binlog format
 
rpl.rpl_stm_conflicts 'row'              w1 [ skipped ]  Neither MIXED nor STATEMENT binlog format
 
rpl.rpl_stm_flsh_tbls 'row'              w1 [ skipped ]  Neither MIXED nor STATEMENT binlog format
 
rpl.rpl_stm_maria 'row'                  w1 [ skipped ]  Neither MIXED nor STATEMENT binlog format
 
rpl.rpl_ssl 'row'                        w2 [ pass ]    300
 
rpl.rpl_stm_max_relay_size 'row'         w1 [ skipped ]  Neither MIXED nor STATEMENT binlog format
 
rpl.rpl_stm_mix_show_relaylog_events 'row' w1 [ skipped ]  Neither MIXED nor STATEMENT binlog format
 
rpl.rpl_stm_multi_query 'row'            w1 [ skipped ]  Neither MIXED nor STATEMENT binlog format
 
rpl.rpl_stm_no_op 'row'                  w1 [ skipped ]  Neither MIXED nor STATEMENT binlog format
 
rpl.rpl_stm_reset_slave 'row'            w1 [ skipped ]  Neither MIXED nor STATEMENT binlog format
 
rpl.rpl_stm_until 'row'                  w1 [ skipped ]  Neither MIXED nor STATEMENT binlog format
 
rpl.rpl_ssl1 'row'                       w2 [ pass ]    666
 
rpl.rpl_switch_stm_row_mixed 'row'       w1 [ pass ]    351
 
rpl.rpl_temp_table 'row'                 w1 [ skipped ]  Neither MIXED nor STATEMENT binlog format
 
rpl.rpl_strict_password_validation 'row' w2 [ pass ]    246
 
rpl.rpl_temporal_format_mariadb53_to_mysql56 'row' w1 [ skipped ]  Neither MIXED nor STATEMENT binlog format
 
worker[1] > Restart [mysqld.1 - pid: 6789, winpid: 6789] - running with different options '--log-bin=master-bin --binlog-format=row --log-bin=master-bin' != '--binlog-format=row --log-bin=master-bin --log-bin=master-bin'
 
worker[1] > Restart [mysqld.2 - pid: 6791, winpid: 6791] - running with different options '--log-bin=slave-bin --binlog-format=row --log-bin=slave-bin' != '--binlog-format=row --log-bin=slave-bin --log-bin=slave-bin'
 
rpl.rpl_table_options 'row'              w2 [ pass ]    233
 
rpl.rpl_temporal_format_default_to_default 'row' w2 [ pass ]    145
 
rpl.rpl_temporal_format_mariadb53_to_mariadb53 'row' w2 [ pass ]    225
 
rpl.rpl_temporal_format_mysql56_to_mariadb53 'row' w2 [ pass ]    131
 
rpl.rpl_temporal_format_mysql56_to_mysql56 'row' w2 [ pass ]    152
 
rpl.rpl_temporal_mysql56 'row'           w2 [ pass ]    111
 
rpl.rpl_temporal_mysql56_to_mariadb 'row' w2 [ pass ]    118
 
rpl.rpl_temporal_mysql56_to_mariadb53 'row' w2 [ pass ]    248
 
rpl.rpl_temporary 'row'                  w2 [ pass ]    285
 
rpl.rpl_temporal_format_mariadb53_to_mysql56_dst 'row' w1 [ pass ]    171
 
rpl.rpl_truncate_2myisam 'row'           w2 [ pass ]    302
 
rpl.rpl_tmp_table_and_DDL 'row'          w1 [ pass ]    271
 
worker[1] > Restart [mysqld.1 - pid: 7608, winpid: 7608] - running with different options '--binlog-format=row --log-bin=master-bin --log-bin=master-bin' != '--log-bin=master-bin --binlog-format=row --log-bin=master-bin'
 
worker[1] > Restart [mysqld.2 - pid: 7613, winpid: 7613] - running with different options '--binlog-format=row --log-bin=slave-bin --log-bin=slave-bin' != '--log-bin=slave-bin --binlog-format=row --log-bin=slave-bin'
 
rpl.rpl_udf 'row'                        w2 [ skipped ]  Need udf example
 
rpl.rpl_trunc_temp 'row'                 w1 [ skipped ]  Neither MIXED nor STATEMENT binlog format
 
rpl.rpl_variables 'row'                  w1 [ pass ]    334
 
rpl.rpl_variables_stm 'row'              w1 [ skipped ]  Neither MIXED nor STATEMENT binlog format
 
worker[1] > Restart [mysqld.1 - pid: 7872, winpid: 7872] - running with different options '--binlog-format=statement --ignore-builtin-innodb --plugin-load-add=ha_innodb.so --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-tables --innodb-metrics --plugin-load-add=semisync_master.so --plugin-load-add=semisync_slave.so --loose-rpl-semi-sync-master --loose-rpl-semi-sync-slave --log-bin=master-bin --max-connections=40 --max-connections=40' != '--binlog-format=row --log-bin=master-bin --log-bin=master-bin'
 
worker[1] > Restart [mysqld.2 - pid: 7874, winpid: 7874] - running with different options '--binlog-format=statement --ignore-builtin-innodb --plugin-load-add=ha_innodb.so --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-tables --innodb-metrics --plugin-load-add=semisync_master.so --plugin-load-add=semisync_slave.so --loose-rpl-semi-sync-master --loose-rpl-semi-sync-slave --log-bin=slave-bin' != '--binlog-format=row --log-bin=slave-bin --log-bin=slave-bin'
 
rpl.rpl_trigger 'innodb_plugin,stmt'     w3 [ fail ]

Logs: stdio.txt mysqld.1.err.3.txt mysqld.2.err.3.txt
Nothing significant in kernel.log or syslog.

Comment by Elena Stepanova [ 2019-07-22 ]

Some observations:

  • According to the cross-reference, there have been only 2 occurrences of the problem, both mentioned in this bug report, one is in December 2018 and another one in April 2019. So, it is extremely rare.
  • With such a low probability, it is impossible to say whether the problem has gone away since the last occurrence. More likely it hasn't.
  • Both occurrences happened on 10.1-based tree. Given that tests on higher versions run much more often, it seems significant.
  • Both occurrences happened on kvm-deb-stretch-ppc64le. Given that tests on other platforms run hundreds times more frequently, it seems very significant. However, it is unclear in what way it is platform-dependent.
  • At least the second occurrence happened right after both server were restarted, so there should be no dependency on previous tests.
  • I see no room whatsoever for a race condition on the test side around the place where the problem occurs. So, it's likely to be a genuine failure, and might be a very significant one, as it represents as lost data without any clear error on the slave side. I don't recommend discarding it due to low frequency.
Generated at Thu Feb 08 08:41:10 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.