Bug #30128 rpl_events.test fails - timing bug in recent test case
Submitted: 30 Jul 2007 20:29 Modified: 30 Jan 2009 16:50
Reporter: Timothy Smith Email Updates:
Status: Closed Impact on me:
None 
Category:Tests: Replication Severity:S3 (Non-critical)
Version:5.1, 6.0 OS:Any
Assigned to: Serge Kozlov CPU Architecture:Any
Tags: 51rpl, pushbuild, sporadic, test failures

[30 Jul 2007 20:29] Timothy Smith
Description:
The rpl_events test is failing periodically.  It looks like a recent test has added some indeterministic behavior.

rpl.rpl_events                 [ fail ]

Errors are (from /dev/shm/var-n_mix-100/log/mysqltest-time) :
mysqltest: Result length mismatch
(the last lines may be the most important ones)
Below are the diffs between actual and expected results:
-------------------------------------------------------
*** /data0/pushbuild/pb1/pb/mysql-5.1-arch/141/mysql-5.1.21-beta-pb141/mysql-test/suite/rpl/r/rpl_events.result	Wed Jul 25 21:04:36 2007
--- /data0/pushbuild/pb1/pb/mysql-5.1-arch/141/mysql-5.1.21-beta-pb141/mysql-test/suite/rpl/r/rpl_events.reject	Wed Jul 25 21:49:11 2007
***************
*** 122,134 ****
  id	c	ts
  1	manually	TIMESTAMP
  2	from justonce	TIMESTAMP
! affected rows: 2
  "Checking event data on the slave"
  SELECT * FROM t1 ORDER BY id;
  id	c	ts
  1	manually	TIMESTAMP
  2	from justonce	TIMESTAMP
! affected rows: 2
  "Checking event is inactive on slave"
  SELECT db, name, status, originator FROM mysql.event WHERE db = 'test' AND name = 'justonce';
  db	name	status	originator
--- 122,136 ----
  id	c	ts
  1	manually	TIMESTAMP
  2	from justonce	TIMESTAMP
! 4	from er	TIMESTAMP
! affected rows: 3
  "Checking event data on the slave"
  SELECT * FROM t1 ORDER BY id;
  id	c	ts
  1	manually	TIMESTAMP
  2	from justonce	TIMESTAMP
! 4	from er	TIMESTAMP
! affected rows: 3
  "Checking event is inactive on slave"
  SELECT db, name, status, originator FROM mysql.event WHERE db = 'test' AND name = 'justonce';
  db	name	status	originator
-------------------------------------------------------

How to repeat:
See pushbuild test results, for example on this push:

https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=mysql-5.1-arch&order=141

(debx86-b)
[9 Aug 2007 18:33] Lars Thalmann
I'm writing version 5.1 because I guess that is the right one...
[9 Aug 2007 21:21] Jonathan Miller
http://lists.mysql.com/commits/32333
[10 Aug 2007 22:11] Jonathan Miller
Patch pushed into mysql-5.1-new-rpl team tree
[18 Aug 2007 0:15] Bugs System
Pushed into 5.1.22-beta
[28 Sep 2007 16:29] Timothy Smith
This is failing still, in current 5.2 trees, and also in some 5.1 trees as late as 17 Sept.:

https://intranet.mysql.com/secure/pushbuild/xref.pl?startdate=&enddate=&dir=&plat=&testtyp...

rpl.rpl_events                 [ fail ]

--- /data0/pushbuild/pb1/pb/mysql-5.2-opt/78/mysql-5.2.6-alpha-pb78/mysql-test/suite/rpl/r/rpl_events.result	2007-09-28 13:30:05.000000000 +0300
+++ /dev/shm/var-ps_stm-101/log/rpl_events.reject	2007-09-28 14:26:53.796023328 +0300
@@ -122,13 +122,15 @@
 id	c	ts
 1	manually	TIMESTAMP
 2	from justonce	TIMESTAMP
-affected rows: 2
+4	from er	TIMESTAMP
+affected rows: 3
 "Checking event data on the slave"
 SELECT * FROM t1 ORDER BY id;
 id	c	ts
 1	manually	TIMESTAMP
 2	from justonce	TIMESTAMP
-affected rows: 2
+4	from er	TIMESTAMP
+affected rows: 3
 "Checking event is inactive on slave"
 SELECT db, name, status, originator FROM mysql.event WHERE db = 'test' AND name = 'justonce';
 db	name	status	originator

I'm reopening this.  Perhaps double-check that the fix is correct for 5.2, and that it was merged properly?
[18 Oct 2007 19:27] Paul Dubois
For 5.1.22: Test case change only. No changelog entry needed.

For 5.2.x: Not sure, but probably same.
[22 Feb 2008 15:03] Chuck Bell
I've encountered this bug in mysql-6.0-backup tree. I think I know what is the cause.

I have included the latest reject file from the test. The test fails with a result mismatch error.

Look at the row that is 'extra':

4	from er	TIMESTAMP

This is a row from the test.er event. However, if you look at the test again, you will see that this event is dropped before this mismatch occurs. Furthermore, the table is dropped after the event test.er is dropped. Additionally, the test checks both the slave and the master to make sure the event is no longer there. But it must still be executing somehow. There is (seemingly) no other way for that row to get inserted into the table unless the event test.er is not actually dropped when the DROP EVENT is issued. If this isn't the cause, it at least is a clue as to why the extra rows are appearing in the table.
[22 Feb 2008 15:05] Chuck Bell
Reject file from test run in mysql-6.0-backup

Attachment: rpl_events.reject (text/plain), 9.05 KiB.

[22 Feb 2008 15:06] Chuck Bell
Result file from test run in mysql-6.0-backup

Attachment: rpl_events.result (application/octet-stream, text), 8.81 KiB.

[1 Apr 2008 20:07] Serge Kozlov
I think that the possible reason of bug described on CREATE EVENT description:
http://dev.mysql.com/doc/refman/5.1/en/create-event.html

An EVERY clause may also contain an optional STARTS clause. STARTS is followed by a timestamp value which indicates when the action should begin repeating, and may also use + INTERVAL interval in order to specify an amount of time “from now” ... skipped ... Not specifying STARTS is the same as using STARTS CURRENT_TIMESTAMP — that is, the action specified for the event begins repeating immediately upon creation of the event.

I suggest to add STARTS + INTERVAL clause and define start time for events which shouldn't really executed but it doesn't prevent to replicate them to slave.
[1 Apr 2008 20:45] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/44758

ChangeSet@1.2552, 2008-04-02 00:44:36+04:00, skozlov@mysql.com +2 -0
  Bug#30128
[2 Apr 2008 15:43] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/44796

ChangeSet@1.2552, 2008-04-02 19:41:49+04:00, skozlov@mysql.com +2 -0
  Bug#30128, The reason that sometimes events were executed because without STARTS clause server fires immediately after creating event and
  time between create and delete event sometimes is enough for firing. So adding STARTS clause moves first execution in future after drop of event.
[2 Apr 2008 20:17] Jonathan Miller
Serge,

Good find and solution!

/Jeb
[21 Jan 2009 12:26] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/63704

2749 Serge Kozlov	2009-01-21
      Bug#30128: The reason that sometimes events were executed because without STARTS clause server fires immediately after creating event and time between create and delete event sometimes is enough for firing. So adding STARTS clause moves first execution in future after drop of event
      1. Added STARTS clause for CREATE EVENT.
      2. Updated result file.
[21 Jan 2009 12:32] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/63705

2971 Serge Kozlov	2009-01-21 [merge]
      Bug#30128, merge with 5.1.
      The reason that sometimes events were executed because without STARTS
      clause server fires immediately after creating event and time between create and delete
      event sometimes is enough for firing. So adding STARTS clause moves first execution in
      future after drop of event
      1. Added STARTS clause for CREATE EVENT.
      2. Updated result file.
[21 Jan 2009 15:48] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/63739

2749 Serge Kozlov	2009-01-21
      Bug#30128: The reason that sometimes events were executed because without STARTS
      clause server fires immediately after creating event and time between create and delete
      event sometimes is enough for firing. So adding STARTS clause moves first execution in
      future after drop of event
      1. Added STARTS clause for CREATE EVENT.
      2. Updated result file.
[21 Jan 2009 15:51] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/63740

2972 Serge Kozlov	2009-01-21 [merge]
      Bug#30128, merge with 5.1
[30 Jan 2009 13:32] Bugs System
Pushed into 6.0.10-alpha (revid:luis.soares@sun.com-20090129165607-wiskabxm948yx463) (version source revid:luis.soares@sun.com-20090129163120-e2ntks4wgpqde6zt) (merge vers: 6.0.10-alpha) (pib:6)
[30 Jan 2009 15:11] Bugs System
Pushed into 5.1.32 (revid:luis.soares@sun.com-20090129165946-d6jnnfqfokuzr09y) (version source revid:sp1r-msvensson@pilot.mysql.com-20080403195126-53515) (merge vers: 5.1.25-rc) (pib:6)
[30 Jan 2009 16:48] Paul Dubois
Test case changes. No changelog entry needed.
[3 Feb 2009 9:41] Bugs System
Pushed into 5.1.32 (revid:joro@sun.com-20090203090549-gos3v4320vimrzg6) (version source revid:horst@mysql.com-20090123182108-2efo5zwexcrf0h3o) (merge vers: 5.1.32) (pib:6)
[4 Feb 2009 11:16] Bugs System
Pushed into 6.0.10-alpha (revid:kostja@sun.com-20090204104420-mw1i2u9lum4bxjo6) (version source revid:serge.kozlov@sun.com-20090121155026-iwu94p9k3enxm5u1) (merge vers: 6.0.10-alpha) (pib:6)
[17 Feb 2009 15:01] Bugs System
Pushed into 5.1.32-ndb-6.3.23 (revid:tomas.ulin@sun.com-20090217131017-6u8qz1edkjfiobef) (version source revid:tomas.ulin@sun.com-20090203133556-9rclp06ol19bmzs4) (merge vers: 5.1.32-ndb-6.3.22) (pib:6)
[17 Feb 2009 16:49] Bugs System
Pushed into 5.1.32-ndb-6.4.3 (revid:tomas.ulin@sun.com-20090217134419-5ha6xg4dpedrbmau) (version source revid:tomas.ulin@sun.com-20090203133556-9rclp06ol19bmzs4) (merge vers: 5.1.32-ndb-6.3.22) (pib:6)
[17 Feb 2009 18:25] Bugs System
Pushed into 5.1.32-ndb-6.2.17 (revid:tomas.ulin@sun.com-20090217134216-5699eq74ws4oxa0j) (version source revid:tomas.ulin@sun.com-20090202111723-1zzwax187rtls913) (merge vers: 5.1.32-ndb-6.2.17) (pib:6)