MySQL Bugs: #40377: sporadic pushbuild failure in log

Bug #40377	sporadic pushbuild failure in log_state: result mismatch
Submitted:	28 Oct 2008 19:24	Modified:	21 Jan 2009 16:17
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:	log_state, pushbuild, sporadic, test failure

Description:
log_state fails sporadically in pushbuild with result mismatch. There are two symptoms:

==== FAILURE 1 ====
main.log_state                 [ fail ]

--- C:/cygwin/home/pushbuild/pb1/pb/mysql-5.1-runtime/483/mysql-5.1.23-beta-pb483/mysql-test/r/log_state.result	2007-09-29 22:21:14.000000000 +0300
+++ e:\var-n_mix-100\log\log_state.reject	2007-09-30 09:39:12.265625000 +0300
@@ -46,6 +46,7 @@
 0
 select * from mysql.slow_log where sql_text NOT LIKE '%slow_log%';
 start_time	user_host	query_time	lock_time	rows_sent	rows_examined	db	last_insert_id	insert_id	server_id	sql_text
+TIMESTAMP	USER_HOST	QUERY_TIME	00:00:00	0	0	test	0	0	1	set session long_query_time=1
 TIMESTAMP	USER_HOST	QUERY_TIME	00:00:00	1	0	test	0	0	1	select sleep(2)
 show global variables
 where Variable_name = 'log' or Variable_name = 'log_slow_queries' or

mysqltest: Result content mismatch

Stopping All Servers
==== END FAILURE 1 ====

==== FAILURE 2 ====
main.log_state                           [ fail ]

CURRENT_TEST: main.log_state
--- /data0/pushbuild/pb/bzr_mysql-6.0-rpl/73/mysql-6.0.8-alpha-pb73/mysql-test/r/log_state.result	2008-09-15 19:19:56.000000000 +0300
+++ /data0/pushbuild/pb/bzr_mysql-6.0-rpl/73/mysql-6.0.8-alpha-pb73/mysql-test/r/log_state.reject	2008-09-15 19:58:36.000000000 +0300
@@ -25,6 +25,7 @@
 event_time	user_host	thread_id	server_id	command_type	argument
 TIMESTAMP	USER_HOST	#	1	Query	create table t1(f1 int)
 TIMESTAMP	USER_HOST	#	1	Query	select * from mysql.general_log
+TIMESTAMP	USER_HOST	#	1	Quit	
 TIMESTAMP	USER_HOST	#	1	Query	set global general_log= OFF
 set global general_log= ON;
 flush logs;

mysqltest: Result content mismatch

 - saving '/dev/shm/var-ps_row-131/2/log/main.log_state/' to '/dev/shm/var-ps_row-131/log/main.log_state/'

Retrying test, attempt(2/3)...

==== END FAILURE 2 ====

How to repeat:
Failure 1: https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-5.1-bugteam&order=80 vm-win2003-32-a/n_mix
Failure 1 has only happened on windows.

Failure 2: https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-6.0-rpl&order=73 sapsrv2/ps_row

xref: http://tinyurl.com/5eer5s

Failure 1:
The assumption that "set session long_query_time=1;"
needs less than one second (current value for session
long_query_time) seems to be too optimistic for a
testing box with heavy parallel load.
Minor issues:
1. There values <m> and <n> in
      set session long_query_time=<m>;
      select sleep(<n>);
   - should be configurable so that we can easy adjust
     it when needed like in the current situation
   - must follow the rule <m> < <n>
     This could be ensured by appropriate scripting.
2. This test uses several connections. It should be printed
   into the protocol whenever the session is changed.
3. Replace error numbers with error names if possible

Failure 2:
It looks like that we see the disconnect of an old
session within the log.
This old session can only belong to one of the preceding
(execution history and NOT names of tests in alphabetical
order) testcases which probably do not clean up perfect
(close all sessions).
Failure 2 was observed in RPL trees only. There we have
an improved mysql-test-run.pl which reorders the tests to
be executed. So it is difficult to guess which other test
is guilty.

Failure 2 will be not fixed here.
1. It occured only two times and only in RPL trees
2. log_state.test is not "guilty".
3. Some extra check at the beginning of log_state.test
   ensuring that no unexpected parallel sessions exist
   is IMHO no good solution because this wastes runtime
   in case the preceding test is good enough.
Bug#42003 tests missing the disconnect of connections <> default
takes care of at least most tests with missing "disconnect".

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

2730 Matthias Leich	2009-01-09
      - Fix for Bug#40377 sporadic pushbuild failure in log_state: result mismatch
      - minor improvements

Hi Patrick,

thank you for detecting the "--check-testcases" problem.
The test "log_state" is victim of
  Bug#38124 "general_log_file" variable silently unset
            when using expression
I will add a workaround.

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

2733 Matthias Leich	2009-01-13
      Fix for Bug#40377 sporadic pushbuild failure in log_state: result mismatch
      + add workaround for bug 38124
      + messages into the protocol when sessions are switched
      + replace error numbers by error names
      + reset of system variables to initial values per subtest
      + remove a file created by this test
      + minor improvements in structure and formatting

Pushed to
6.0-bugteam
5.1-bugteam

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

2748 He Zhenxing	2009-01-14 [merge]
      Auto merge

Pushed into 5.1.31 (revid:joro@sun.com-20090115053147-tx1oapthnzgvs1ro) (version source revid:chad@mysql.com-20090114155637-vi1ld8rpsfh465go) (merge vers: 5.1.31) (pib:6)

Test case changes. No changelog entry needed.

Setting report to NDI pending push into 6.0.x.

Pushed into 5.1.31-ndb-6.2.17 (revid:tomas.ulin@sun.com-20090119095303-uwwvxiibtr38djii) (version source revid:tomas.ulin@sun.com-20090115073240-1wanl85vlvw2she1) (merge vers: 5.1.31-ndb-6.2.17) (pib:6)

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)

Setting status back to NDI pending merge to 6.0 tree.

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)

Pushed into 6.0.10-alpha (revid:joro@sun.com-20090119171328-2hemf2ndc1dxl0et) (version source revid:timothy.smith@sun.com-20090114143745-x2dvnmix6gjlt6z6) (merge vers: 6.0.10-alpha) (pib:6)

Test case changes. No changelog entry needed.