Bug #39863 events_bugs fails sporadically on pushbuild (extra processes in I_S.PROCESSLIST)
Submitted: 4 Oct 2008 14:56 Modified: 28 Nov 2008 18:20
Reporter: Sven Sandberg Email Updates:
Status: Closed Impact on me:
None 
Category:Tests: Server Severity:S7 (Test Cases)
Version:5.1, 6.0 OS:Any
Assigned to: Matthias Leich CPU Architecture:Any
Tags: disabled, events_bugs, pushbuild, sporadic, test failure

[4 Oct 2008 14:56] Sven Sandberg
Description:
Pushbuild failure:

main.events_bugs               [ fail ]

--- /export/home/pushbuild/pb/bzr_mysql-5.1-telco-6.3/112/mysql-5.1.28-ndb-6.3.18-pb112/mysql-test/r/events_bugs.result	Fri Oct  3 13:30:34 2008
+++ /export/home/pushbuild/pb/bzr_mysql-5.1-telco-6.3/112/mysql-5.1.28-ndb-6.3.18-pb112/mysql-test/r/events_bugs.reject	Fri Oct  3 14:25:13 2008
@@ -120,6 +120,7 @@
 root	localhost	events_test	select get_lock('ee_16407_2', 60)
 root	localhost	events_test	select get_lock('ee_16407_2', 60)
 root	localhost	events_test	select get_lock('ee_16407_2', 60)
+root	localhost	events_test	select get_lock('test_bug16407', 60)
 select release_lock('ee_16407_2');
 release_lock('ee_16407_2')
 1

mysqltest: Result content mismatch

Stopping All Servers
Restoring snapshot of databases

How to repeat:
https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-5.1-telco-6.3&order=... sol10-amd64-a/ps_row

Has failed 39 times according to xref: http://tinyurl.com/47bx7s

Suggested fix:
Fails in all trees, both 5.1 and 6.0, mostly on slow machines. Probably a race?
[9 Oct 2008 19:58] Matthias Leich
Different timing related effect which should be also fixed:  
Logging: ./mysql-test-run.pl --mem events_bugs events_bugs
events_bugs events_bugs events_bugs events_bugs events_bugs
events_bugs
....

Symlinking 'var' to '/dev/shm/var'
Installing Master Database
=======================================================

TEST                           RESULT         TIME (ms)
-------------------------------------------------------

main.events_bugs               [ pass ]          18749
main.events_bugs               [ fail ]

--- ... r/events_bugs.result
+++ ... r/events_bugs.reject
@@ -5,7 +5,7 @@
 use events_test;
 select * from information_schema.global_variables where variable_name like 'event_scheduler';
 VARIABLE_NAME  VARIABLE_VALUE
-EVENT_SCHEDULER        ON
+EVENT_SCHEDULER        OFF
 SET GLOBAL event_scheduler = 'OFF';
 CREATE EVENT lower_case ON SCHEDULE EVERY 1 MINUTE DO SELECT 1;
 CREATE EVENT Lower_case ON SCHEDULE EVERY 2 MINUTE DO SELECT 2;
[13 Oct 2008 15:24] Matthias Leich
Experimenting with the goal to reproduce the problem.
Till now no success, but several new bugs in events
tests found.
[15 Oct 2008 15:44] Matthias Leich
The last reported effect is now
Bug#39978 main.events_bugs does not clean up
[15 Oct 2008 16:34] Matthias Leich
The first reported effect (additional line in
PROCESSLIST with info = "select get_lock
('test_bug16407', 60)") seems be caused by:
===========================================

The subtest for Bug#16407 does the following
1. The default session creates the user lock
   "test_bug16407.
2. An event which tries to get the same user
   lock is created.
3. It is waited till within the PROCESSLIST a
   sessions exists which waits for getting
   this user lock
   = The execution of the event (2.) is running.
4. The default session releases the user lock.
5. It is expected that 4. causes that the event
   execution completes because the lock was released
   by the default session
   = the session which executes the event and hangs
     when requesting the user lock disappears from
     the PROCESSLIST

And exact this session did not end within the current
bug. The reason might be that the release of the
user lock had no effect.  See also
Bug#32782 User lock hash fails to find lock.

There is no obvious mistake within the event_bugs.test
code and logics which could cause the observed effect.
[16 Oct 2008 19:46] 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/56416

2672 Matthias Leich	2008-10-16
      - Fix for Bug #39848, #39863, #39978, #39569
        Bug#39848 events_bugs fails sporadically on pushbuild
                  (missing rows in table event_log)
           Details: Reimplement the subtest for BUG 28924
                    - check if the number of rows within the table
                      event_log changes but don't print rows
                      because the number varies depending on
                      load on testing box
                    - shift DROP USER befor DROP EVENT
                      = Subtest fits again to old bug
                    - remove no more needed comments + variables
        Bug#39863 events_bugs fails sporadically on pushbuild (extra processes
                  in I_S.PROCESSLIST)
           Details: Abort with appropriate message to the protocol if
                    release_lock() does not has the intended effect. 
                    This cannot prevent problems caused by the probably
                    buggy release_lock() but it reveals if we had a problem
                    in this area.
        Bug#39978 main.events_bugs does not clean up
           Detail: Restore global.event_scheduler = ON at end of test
        Bug#39569 events_bugs fails sporadically on pushbuild (should have
                  failed with errno 1539)
           Detail: Set $wait_timeout to 4 instead of 2
      - Minor improvements of formatting
           Details:
           - Add comments
           - Remove tabs and trailing blanks
           - Add line breaks for better readability
[17 Oct 2008 12:55] 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/56471

2673 Matthias Leich	2008-10-17
      - Fix for Bug #39848, #39863, #39978, #39569
        Bug#39848 events_bugs fails sporadically on pushbuild
                  (missing rows in table event_log)
           Details: Reimplement the subtest for BUG 28924
                    - check if the number of rows within the table
                      event_log changes but don't print rows
                      because the number varies depending on
                      load on testing box
                    - shift DROP USER befor DROP EVENT
                      = Subtest fits again to old bug
                    - remove no more needed comments + variables
        Bug#39863 events_bugs fails sporadically on pushbuild (extra processes
                  in I_S.PROCESSLIST)
           Details: Abort with appropriate message to the protocol if
                    release_lock() does not has the intended effect.
                    This cannot prevent problems caused by the probably
                    buggy release_lock() but it reveals if we had a problem
                    in this area.
        Bug#39978 main.events_bugs does not clean up
           Detail: Restore global.event_scheduler = ON at end of test
        Bug#39569 events_bugs fails sporadically on pushbuild (should have
                  failed with errno 1539)
           Detail: Set $wait_timeout to 4 instead of 2
      - Fix two instabilities (result sets pulled from processlist in subtest
        for bug 16407) which were found during tests with high parallel
        I/O load
      
      - Minor improvements of formatting
        Details:
          - Add comments
          - Remove tabs and trailing blanks
          - Add line breaks for better readability
[17 Oct 2008 13:08] Matthias Leich
One note about the patch above:
If we have a non fixed bug within "release_lock" than
the patch above cannot avoid that we get sporadic
result differences when running "events_bugs".
But the patch causes an
- appropriate message to the protocol
- immediate abort of test
if release_lock() does not has the intended effect.
[27 Oct 2008 21:22] Patrick Crews
Ok to push.
[4 Nov 2008 11:27] 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/57771

2692 Matthias Leich	2008-11-04
      - Fix for Bug #39848, #39863, #39978, #39569
        Bug#39848 events_bugs fails sporadically on pushbuild
                  (missing rows in table event_log)
           Details: Reimplement the subtest for BUG 28924
                    - check if the number of rows within the table
                      event_log changes but don't print rows
                      because the number varies depending on
                      load on testing box
                    - shift DROP USER befor DROP EVENT
                      = Subtest fits again to old bug
                    - remove no more needed comments + variables
        Bug#39863 events_bugs fails sporadically on pushbuild 
                  (extra processes in I_S.PROCESSLIST)
           Details: Abort with appropriate message to the protocol if
                    release_lock() does not has the intended effect.
                    This cannot prevent problems caused by the probably
                    buggy release_lock() but it reveals if we had a
                    problem in this area.
        Bug#39978 main.events_bugs does not clean up
           Detail: Restore global.event_scheduler = ON at end of test
        Bug#39569 events_bugs fails sporadically on pushbuild
                  (should have failed with errno 1539)
           Detail: Set $wait_timeout to 4 instead of 2
      - Fix two instabilities (result sets pulled from processlist in
        subtest for bug 16407) which were found during tests with high
        parallel I/O load
      - Minor improvements of formatting
        Details:
        - Add comments
        - Remove tabs and trailing blanks
        - Add line breaks for better readability
[5 Nov 2008 12:27] Matthias Leich
Pushed to
5.1-bugteam
6.0-bugteam
[10 Nov 2008 10:53] Bugs System
Pushed into 6.0.8-alpha  (revid:matthias.leich@sun.com-20081104112721-bqfae4rvb8tatg2e) (version source revid:matthias.leich@sun.com-20081104183908-ux6g8n3yj43bd43l) (pib:5)
[10 Nov 2008 11:36] Bugs System
Pushed into 5.1.30  (revid:matthias.leich@sun.com-20081104112721-bqfae4rvb8tatg2e) (version source revid:matthias.leich@sun.com-20081104180256-w9rqsaozf7wby5ab) (pib:5)
[10 Nov 2008 17:43] Paul DuBois
Test case changes. No changelog entry needed.
[26 Nov 2008 17:06] Sven Sandberg
Re-opening bug. I got the following failure in a tree which has the above changeset:

--- /data0/pushbuild/pb2-2/pb/bzr_mysql-5.1-rpl/87/mysql-5.1.31-pb87/mysql-test/r/events_bugs.result	2008-11-21 11:24:25.000000000 +0300
+++ /data0/pushbuild/pb2-2/pb/bzr_mysql-5.1-rpl/87/mysql-5.1.31-pb87/mysql-test/r/events_bugs.reject	2008-11-21 12:28:44.000000000 +0300
@@ -170,6 +170,11 @@
 order by info;
 user	host	db	info
 event_scheduler	localhost	NULL	NULL
+root	localhost	events_test	CREATE PROCEDURE `ee_16407_2`() SQL SECURITY INVOKER begin
+select get_lock('ee_16407_2', 60) /*ee_16407_2*/;
+select release_lock('ee_16407_2');
+insert into events_test.events_smode_test values('ee_16407_2','1980-19-02');
+end
 root	localhost	events_test	select get_lock('ee_16407_5', 60)
 root	localhost	events_test	select get_lock('ee_16407_5', 60)
 select release_lock('ee_16407_5');

mysqltest: Result content mismatch

This is from https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-5.1-rpl&order=87 sles10-ia64-a-2/ps_row
[26 Nov 2008 17:08] Sven Sandberg
There are two other symptoms than the two mentioned above. Please ensure that all four get fixed.

==== Failure 3 ====

main.events_bugs                         [ fail ]

CURRENT_TEST: main.events_bugs
--- /data0/pushbuild/pb/bzr_mysql-6.0-rpl/87/mysql-6.0.8-alpha-pb87/mysql-test/r/events_bugs.result	2008-10-14 13:12:29.000000000 +0300
+++ /data0/pushbuild/pb/bzr_mysql-6.0-rpl/87/mysql-6.0.8-alpha-pb87/mysql-test/r/events_bugs.reject	2008-10-14 13:29:58.000000000 +0300
@@ -61,6 +61,7 @@
 "Now if everything is fine the event has compiled and is locked"
 select /*1*/ user, host, db, info from information_schema.processlist where command!='Daemon' and (info is null or info not like '%processlist%') order by info;
 user	host	db	info
+root	localhost	NULL	NULL
 root	localhost	events_test	select get_lock('test_bug16407', 60)
 select release_lock('test_bug16407');
 release_lock('test_bug16407')
@@ -117,6 +118,7 @@
 select /*2*/ user, host, db, info from information_schema.processlist where (command!='Daemon' || user='event_scheduler') and (info is null or info not like '%processlist%') order by info;
 user	host	db	info
 event_scheduler	localhost	NULL	NULL
+root	localhost	NULL	NULL
 root	localhost	events_test	select get_lock('ee_16407_2', 60)
 root	localhost	events_test	select get_lock('ee_16407_2', 60)
 root	localhost	events_test	select get_lock('ee_16407_2', 60)

mysqltest: Result content mismatch

From https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=mysql-5.1-opt&order=402 sol10-sparc-a/ps_row

==== Failure 4 ====

main.events_bugs               [ fail ]

--- /export/home/pushbuild/pb/mysql-5.1-marvel/95/mysql-5.1.24-rc-pb95/mysql-test/r/events_bugs.result	Wed Feb 27 23:39:48 2008
+++ /export/home/pushbuild/pb/mysql-5.1-marvel/95/mysql-5.1.24-rc-pb95/mysql-test/r/events_bugs.reject	Sun Mar  2 18:20:52 2008
@@ -117,6 +117,9 @@
 select /*2*/ user, host, db, info from information_schema.processlist where (command!='Daemon' || user='event_scheduler') and (info is null or info not like '%processlist%') order by info;
 user	host	db	info
 event_scheduler	localhost	NULL	NULL
+root	localhost	events_test	CREATE PROCEDURE `e_16407`() SQL SECURITY INVOKER begin
+select get_lock('test_bug16407', 60);
+end
 root	localhost	events_test	select get_lock('ee_16407_2', 60)
 root	localhost	events_test	select get_lock('ee_16407_2', 60)
 root	localhost	events_test	select get_lock('ee_16407_2', 60)

mysqltest: Result content mismatch

From https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=mysql-6.0-runtime&order=12 debx86-b/n_mix
[26 Nov 2008 17:10] Sven Sandberg
Here is an xref link that shows all the four symptoms above: http://tinyurl.com/6d347q
[28 Nov 2008 18:20] Matthias Leich
The failures added by Sven will be tracked in
Bug#41111 events_bugs fails sporadically on pushbuild
[19 Jan 2009 11:28] Bugs System
Pushed into 5.1.31-ndb-6.2.17 (revid:tomas.ulin@sun.com-20090119095303-uwwvxiibtr38djii) (version source revid:tomas.ulin@sun.com-20090108105244-8opp3i85jw0uj5ib) (merge vers: 5.1.31-ndb-6.2.17) (pib:6)
[19 Jan 2009 13:06] Bugs System
Pushed into 5.1.31-ndb-6.3.21 (revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (version source revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (merge vers: 5.1.31-ndb-6.3.21) (pib:6)
[19 Jan 2009 16:12] Bugs System
Pushed into 5.1.31-ndb-6.4.1 (revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (version source revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (merge vers: 5.1.31-ndb-6.4.1) (pib:6)