MySQL Bugs: #20624: events_logs_tests.test fails randomly

Bug #20624	events_logs_tests.test fails randomly
Submitted:	22 Jun 2006 11:23	Modified:	19 Jul 2006 7:25
Reporter:	Ingo Strüwing	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Stored Routines	Severity:	S1 (Critical)
Version:	5.1.11bk	OS:	Linux (Linux kernel 2.6.16 PREEMPT)
Assigned to:	Andrey Hristov	CPU Architecture:	Any

Description:
events_logs_tests              [ fail ]

Errors are (from /mnt/hdb7/mytest/mysql-5.1-test/tmp/test1/mysql-test/var/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:
-------------------------------------------------------
*** r/events_logs_tests.result  2006-06-09 11:47:20.000000000 +0300
--- r/events_logs_tests.reject  2006-06-22 10:35:33.000000000 +0300
***************
*** 34,39 ****
--- 34,40 ----
  TRUNCATE mysql.slow_log;
  SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
  user_host     query_time      db      sql_text
+ USER_HOST     00:00:14        events_test     TRUNCATE mysql.slow_log
  "Set new values"
  SET GLOBAL long_query_time=4;
  SET SESSION long_query_time=1;
***************
*** 43,48 ****
--- 44,50 ----
  0
  SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
  user_host     query_time      db      sql_text
+ USER_HOST     SLEEPVAL        events_test     TRUNCATE mysql.slow_log
  USER_HOST     SLEEPVAL        events_test     SELECT SLEEP(2)
  TRUNCATE mysql.slow_log;
  CREATE TABLE slow_event_test (slo_val tinyint, val tinyint);
-------------------------------------------------------
Please follow the instructions outlined at
http://www.mysql.com/doc/en/Reporting_mysqltest_bugs.html
to find the reason to this problem and how to report this.

This happens in average every second time on my machine. I use to run two test suites in parallel. One runs in normal mode, the other one runs in --ps-protocol --mysqld=--binlog-format=row mode.

When the failure happens, then it is in normal mode. I didn't see it with --ps-protocol --mysqld=--binlog-format=row yet.

How to repeat:
BUILD/compile-pentium-debug-max
copy the tree
in one tree do cd mysql-test && MTR_BUILD_THREADS=1 ./mysql-test-run
in the other tree do cd mysql-test && MTR_BUILD_THREADS=2 ./mysql-test-run --ps-protocol --mysqld=--binlog-format=row

Repeat the tests until the failure happens.

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/8076

Fix is submitted and pushed. It's modification to the test file. I believe this should fix the problem but still leave the report open if Ingo continues to experience the problem.

It's pushed into 5.1-runtime and will be merged soon into 5.1

Bad news. It happened again. This time I got:

events_logs_tests              [ fail ]

Errors are (from /mnt/hdb7/mytest/mysql-5.1-test/tmp/test1/mysql-test/var/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:
-------------------------------------------------------
*** r/events_logs_tests.result  2006-06-27 05:10:16.000000000 +0300
--- r/events_logs_tests.reject  2006-06-29 13:30:50.000000000 +0300
***************
*** 67,72 ****
--- 67,73 ----
  "Check slow log. Should not see anything because 3 is under the threshold of 4 for GLOBAL, though over SESSION which is 2"
  SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
  user_host     query_time      db      sql_text
+ root[root] @ localhost []     00:00:05        events_test     CREATE TABLE slow_event_test (slo_val tinyint, val tinyint)
  "This should go to the slow log"
  DROP EVENT long_event;
  SET SESSION long_query_time=10;
***************
*** 81,86 ****
--- 82,88 ----
  "Check slow log. Should see 1 row because 4 is over the threshold of 3 for GLOBAL, though under SESSION which is 10"
  SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
  user_host     query_time      db      sql_text
+ USER_HOST     SLEEPVAL        events_test     CREATE TABLE slow_event_test (slo_val tinyint, val tinyint)
  USER_HOST     SLEEPVAL        events_test     INSERT INTO slow_event_test SELECT @@long_query_time, SLEEP(2)
  DROP EVENT long_event2;
  "Make it quite long"
-------------------------------------------------------
Please follow the instructions outlined at

Hi Ingo,
I have then to check the whole test for such possibitlies, again.
I thought I have fixed all problems. The actual problem is that 
the threshold for the queries to be logged is low but if you run parallel tests everything gets slow and non-wanted queries go to the slow log too.
In this particular case I thikn it's fixable.

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/8704

A new fix was pushed and merged into 5.1 . I am expecting feedback from Ingo whether this fix will lead to a cease of the failures of the test case. Expect some delay before being able to close it

Hi Andrey,

since this was pushed to the main tree on July 7, I had 10 tests in a row without this failure ever happen again. So I suggest to close this bug now.

Regards
Ingo

Thanks Ingo.

Closing this one. No need to document it in the ChangeLog as it was test failure.