Bug #40377 sporadic pushbuild failure in log_state: result mismatch
Submitted: 28 Oct 2008 20:24 Modified: 21 Jan 17:17
Reporter: Sven Sandberg
Status: Closed
Category:Tests: Server Severity:S2 (Serious)
Version:5.1, 6.0 OS:Any
Assigned to: Matthias Leich Target Version:5.1+
Tags: pushbuild, sporadic, test failure, log_state
Triage: Triaged: D3 (Medium)

[28 Oct 2008 20:24] Sven Sandberg 
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
[8 Jan 13:25] Matthias Leich 
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.
[9 Jan 19:50] Matthias Leich 
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".
[9 Jan 19: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/62884

2730 Matthias Leich	2009-01-09
      - Fix for Bug#40377 sporadic pushbuild failure in log_state: result mismatch
      - minor improvements
[13 Jan 13:54] Matthias Leich 
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.
[13 Jan 14:08] 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/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
[13 Jan 17:29] Matthias Leich 
Pushed to
6.0-bugteam
5.1-bugteam
[14 Jan 10:33] 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/63197

2748 He Zhenxing	2009-01-14 [merge]
      Auto merge
[15 Jan 7:37] Bugs System 
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)
[16 Jan 4:43] Paul DuBois 
Test case changes. No changelog entry needed.

Setting report to NDI pending push into 6.0.x.
[19 Jan 12: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-20090115073240-1wanl85vlvw2she1) (merge vers:
5.1.31-ndb-6.2.17) (pib:6)
[19 Jan 14: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 16:53] Jon Stephens 
Setting status back to NDI pending merge to 6.0 tree.
[19 Jan 17:11] 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)
[20 Jan 19:58] Bugs System 
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)
[21 Jan 17:17] Paul DuBois 
Test case changes. No changelog entry needed.