MySQL Bugs: #38181: Please print more debug info when tests fail

Bug #38181	Please print more debug info when tests fail
Submitted:	16 Jul 2008 17:24	Modified:	30 Jan 2009 17:18
Reporter:	Sven Sandberg	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Tests	Severity:	S7 (Test Cases)
Version:	5.1+	OS:	Any
Assigned to:	Magnus Blåudd	CPU Architecture:	Any
Tags:	51rpl, debug info, pushbuild, test, test failure, timeout

Description:
In order to analyze many pushbuild errors, more information is needed than is currently provided by mtr. There are a number of bugs that will be difficult to fix before this is done, including: Bug#38176, Bug#38172, Bug#37714.

Especially timeout errors are almost impossible to debug, since no debug information is given. Also timeout failures in sync_with_master or sync_slave_with_master would need some more information.

How to repeat:
See BUG#38176, BUG#38172, BUG#37712.

These bugs are set to "Need Feedback" status until the present bug has been fixed and more information is available in pushbuild.

Suggested fix:
Please augment mtr in the following ways:

On test case timeout, force a stop of the test case, and then output:
 - the time that mtr waited before timeout
 - a result diff
 - the result of "SHOW PROCESSLIST" on all running servers (that can indicate if the servers are overloaded).

When server goes away during query, show a result diff. If there is any other server still alive, output the result of "SHOW PROCESSLIST" on that server.

On sync_with_master timeout and sync_slave_with_master timeout, force a stop of the test case, and then output:
 - the time that mtr waited before timeout
 - a result diff
 - the result of "SHOW PROCESSLIST" on all running servers
 - the result of "SHOW BINLOG EVENTS" on master and slave, for the currently active binlogs.
See also mysql-test/include/wait_for_slave_param.inc in the current 5.1-rpl tree.

See also BUG#34896.

On failure to start mysqld, please save the core file, or try to generate a traceback.

See also BUG#38286.

BUG#38287 is also waiting for this one.

Note that debug info should be printed also when mtr's internal queries to the servers fail. E.g., during check-testcase, which is where the server crashed for rpl_row_sp002 on https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-6.0-rpl&order=27 'vm-win2003-64-b' Win64 VS2005 -max-n/ps_row

BUG#38288 is also awaiting this one.

BUG#38289 is also waiting for this one.

Preview of how it looks when mtr.pl runs "include/analyze-timeout.test" on all started MySQL Servers.

rpl_ndb.rpl_ndb_2ndb                     [ fail ]  timeout

Test case timeout after 1 minute(s)

 == /data/msvensson/mysql/5.1-rpl/mysql-test/var/2/tmp/analyze-timeout-mysqld.2.1.err ==
SHOW PROCESSLIST;
Id	User	Host	db	Command	Time	State	Info
1	system user			Daemon	0	Waiting for event from ndbcluster	NULL
4	root	localhost	NULL	Query	0	NULL	SHOW PROCESSLIST

 == /data/msvensson/mysql/5.1-rpl/mysql-test/var/2/tmp/analyze-timeout-mysqld.1.1.err ==
SHOW PROCESSLIST;
Id	User	Host	db	Command	Time	State	Info
1	system user			Daemon	0	Waiting for event from ndbcluster	NULL
10	root	localhost:53344	NULL	Binlog Dump	23	Has sent all binlog to slave; waiting for binlog to be updated	NULL
11	root	localhost	NULL	Query	0	NULL	SHOW PROCESSLIST

 == /data/msvensson/mysql/5.1-rpl/mysql-test/var/2/tmp/analyze-timeout-mysqld.1.slave.err ==
SHOW PROCESSLIST;
Id	User	Host	db	Command	Time	State	Info
1	system user			Daemon	0	Waiting for event from ndbcluster	NULL
3	root	localhost:53464	test	Query	3	end	ALTER TABLE t1 DROP COLUMN y
11	system user		NULL	Connect	24	Waiting for master to send event	NULL
12	system user		NULL	Connect	16	Has read all relay log; waiting for the slave I/O thread to update it	NULL
13	root	localhost	NULL	Query	0	NULL	SHOW PROCESSLIST

 - saving '/data/msvensson/mysql/5.1-rpl/mysql-test/var/2/log/rpl_ndb.rpl_ndb_2ndb/' to '/data/msvensson/mysql/5.1-rpl/mysql-test/var/log/rpl_ndb.rpl_ndb_2ndb/'

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

2639 Magnus Svensson	2008-08-04
      Bug #38181  Please print more debug info when tests fail

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

2639 Magnus Svensson	2008-08-04
      Bug #38181  Please print more debug info when tests fail

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

2639 Magnus Svensson	2008-08-04
      Bug #38181  Please print more debug info when tests fail

Pushed to 5.1-rpl and 6.0-rpl

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)

Pushed into 5.1.32 (revid:luis.soares@sun.com-20090129165946-d6jnnfqfokuzr09y) (version source revid:msvensson@mysql.com-20080804202545-afe6oop1ablo37i3) (merge vers: 5.1.28) (pib:6)

Test suite changes. No changelog entry needed.

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)

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)

Pushed into 5.1.32-ndb-6.2.17 (revid:tomas.ulin@sun.com-20090217134216-5699eq74ws4oxa0j) (version source revid:tomas.ulin@sun.com-20090201210519-vehobc4sy3g9s38e) (merge vers: 5.1.32-ndb-6.2.17) (pib:6)