Bug #40406 Please make mtr print better messages when servers fail to start
Submitted: 29 Oct 2008 19:57 Modified: 14 Nov 2010 2:53
Reporter: Sven Sandberg Email Updates:
Status: Closed Impact on me:
None 
Category:Tools: MTR / mysql-test-run Severity:S7 (Test Cases)
Version:5.1 OS:Any
Assigned to: Bjørn Munch CPU Architecture:Any
Tags: mtr

[29 Oct 2008 19:57] Sven Sandberg
Description:
When mtr starts a mysqld server, it waits for the pid file to be created. This may end in three ways:

 (1) The pid file is found, success!

 (2) The mysqld process dies before the pid file is found.

 (3) The pid file is not found and the mysqld process is still alive after a timeout is reached.

(1) doesn't need any debug info, of course. The debug info for case (2) and (3) is too terse. It's not clear when reading the log what mtr was doing when the error happened. Also, there is no message saying that a timeout happened in case (2).

The present bug is only about the wording of error messages. Note that after BUG#40399 and BUG#38817 are fixed, there should also be stack traces available in case (2) and (3).

How to repeat:
An example of case (2) is in falcon.falcon_select_explain on https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-6.0-rpl&order=93 sapsrv2/falcon

An example of case (3) is in falcon.falcon_temporary_alter on https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-6.0-rpl&order=93 sapsrv2/falcon

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

Suggested fix:
In case (2), I think it should say something like:

The mysqld process [NAME OF PROCESS] died after mysql-test-run waited X seconds for it to create a pid file.

In case (3), I think it should say something like:

Timeout after mysql-test-run waited X seconds for the mysqld process [NAME OF PROCESS] to create a pid file.

Here's a proposed patch against 5.1-rpl:

=== modified file 'mysql-test/lib/mtr_process.pl'
--- mysql-test/lib/mtr_process.pl	2007-12-12 17:19:24 +0000
+++ mysql-test/lib/mtr_process.pl	2008-10-29 19:52:42 +0000
@@ -68,12 +68,11 @@ sub mtr_ping_port ($) {
 
 sub sleep_until_file_created ($$$) {
   my $pidfile= shift;
-  my $timeout= shift;
+  my $timeout= shift * 1000; # Milliseconds
   my $proc=     shift;
   my $sleeptime= 100; # Milliseconds
-  my $loops= ($timeout * 1000) / $sleeptime;
 
-  for ( my $loop= 1; $loop <= $loops; $loop++ )
+  for ( my $waited= 0; $waited < $timeout; $waited += $sleeptime )
   {
     if ( -r $pidfile )
     {
@@ -83,24 +82,26 @@ sub sleep_until_file_created ($$$) {
     # Check if it died after the fork() was successful
     if ( defined $proc and ! $proc->wait_one(0) )
     {
-      mtr_warning("Process $proc died");
+      mtr_warning("The mysqld process $proc died after mysql-test-run " .
+                  "waited $waited milliseconds for it to create a pid file.");
       return 0;
     }
 
     mtr_debug("Sleep $sleeptime milliseconds waiting for $pidfile");
 
     # Print extra message every 60 seconds
-    my $seconds= ($loop * $sleeptime) / 1000;
-    if ( $seconds > 1 and int($seconds * 10) % 600 == 0 )
+    if ( $waited > 0 and $waited % 60000 == 0 )
     {
-      my $left= $timeout - $seconds;
-      mtr_warning("Waited $seconds seconds for $pidfile to be created, " .
-                  "still waiting for $left seconds...");
+      my $left= $timeout - $waited;
+      mtr_warning("Waited $waited milliseconds for mysqld process $proc to " .
+                  "create $pidfile, still waiting for $left milliseconds...");
     }
 
     mtr_milli_sleep($sleeptime);
 
   }
+  mtr_warning("Timeout after mysql-test-run waited $timeout milliseconds " .
+              "for the mysqld process $proc to create a pid file.");
 
   return 0;
 }
[12 Oct 2010 9: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/120543

3098 Bjorn Munch	2010-10-12
      Bug #40406 Please make mtr print better messages when servers fail to start
      Added some more details to warning messages, this should be enough.
[12 Oct 2010 13:59] 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/120563

3098 Bjorn Munch	2010-10-12
      Bug #40406 Please make mtr print better messages when servers fail to start
      Added some more details to warning messages, this should be enough.
[19 Oct 2010 13:12] Bjørn Munch
Pushed to -mtr branches
[29 Oct 2010 15:36] Paul DuBois
Changes to test suite. No changelog entry needed.
[13 Nov 2010 16:27] Bugs System
Pushed into mysql-trunk 5.6.99-m5 (revid:alexander.nozdrin@oracle.com-20101113155825-czmva9kg4n31anmu) (version source revid:alexander.nozdrin@oracle.com-20101113152450-2zzcm50e7i4j35v7) (merge vers: 5.6.1-m4) (pib:21)
[13 Nov 2010 16:41] Bugs System
Pushed into mysql-next-mr (revid:alexander.nozdrin@oracle.com-20101113160336-atmtmfb3mzm4pz4i) (version source revid:vasil.dimov@oracle.com-20100629074804-359l9m9gniauxr94) (pib:21)
[16 Dec 2010 22:34] Bugs System
Pushed into mysql-5.5 5.5.9 (revid:jonathan.perkin@oracle.com-20101216101358-fyzr1epq95a3yett) (version source revid:jonathan.perkin@oracle.com-20101216101358-fyzr1epq95a3yett) (merge vers: 5.5.9) (pib:24)