570730 - automation.py should indicate which test crashed (or timed out)

Status: RESOLVED FIXED

(Testing :: General, enhancement)

Description

[Jesse Ruderman]

Current:
PROCESS-CRASH | automation.py | application crashed (minidump found)

Desired:
PROCESS-CRASH | browser_bug511456.js | application crashed (minidump found)

Should be pretty easy.  
* Make waitForFinish check each line of output for a "TEST-START" and keep track of the last one seen.
* Pass this to checkForCrashes as the testName keyword argument.
* Change mochitest and reftest to output "TEST-START" lines instead of ad-hoc "loading" lines.

Comment 1

[Jesse Ruderman]

Attachment: patch

Comment 2

[cmtalbert]

Comment on attachment 450034 [details] [diff] [review]
patch

This looks great for mochitest and reftest.  Do you also have a plan to address XPCShell as well? If not, I think this is a big enough win to move forward with mochitest and reftest now and circle back to xpcshell. So...
* If you don't have a patch in the works to bring this support to xpcshell then file a follow-on bug for that.
* Please also file a follow on bug for topfails to start using this information. (Testing::General)
Thanks!

Don't forget to run it on try server. Automation.py is used in lots of very strange ways, and it's easy to break things when changing it.

Comment 3

[(not currently active) Ted Mielczarek]

This is going to have odd effects with plugin process crashes. You should probably detect if the process exits normally and unset the last seen test.

Comment 4

[Jesse Ruderman]

XPCShell runs each test file in a separate process.  If one crashes or times out, it displays the test file name.  So it's already good.
http://mxr.mozilla.org/mozilla-central/source/testing/xpcshell/runxpcshelltests.py

If one of the *python scripts* times out and *buildbot* has to kill it, buildbot won't show the test name.  I guess we could teach buildbot to look for TEST-START as well.  But bugs where buildbot kills things usually aren't test-specific, and should be fixed in the python script.

Topfails should be covered by bug 558045.  I don't think it will require changes to take advantage of this change.

I submitted this patch to Try server last week along with a patch to make Crashtest crash, and I remember it going well.  But I can't refer to the results now because the Try repository was reset this morning.

Comment 5

[Jesse Ruderman]

Plugin process crashes are tricky.  If there are minidumps for both Firefox and a plugin, we want the Firefox crash to be shown with the name of the last test, but the plugin crash to be shown without it.  I'll file a new bug for sorting that out.

Comment 6

[Jesse Ruderman]

To make plugin crashes less confusing in the case where the main process didn't crash, I added
    1.33 +    if status == 0:
    1.34 +      self.lastTestSeen = "Main app process exited normally"

Pushed:
http://hg.mozilla.org/mozilla-central/rev/71446dba02c8

Comment 7

[(no longer active)]

Hmm, this doesn't look right:

s: talos-r3-fed64-024
PROCESS-CRASH | Main app process exited normally | application crashed (minidump found)
PROCESS-CRASH | Main app process exited normally | application crashed (minidump found)
TEST-UNEXPECTED-FAIL | Main app process exited normally | application timed out after 330 seconds with no output
PROCESS-CRASH | Main app process exited normally | application crashed (minidump found)

From: http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1276223099.1276224232.8090.gz

Comment 8

[Jesse Ruderman]

The first two lines in that log were actually plugin crashes.  I filed bug 571436 for making those clearer.

The last two lines were due to a pair of bugs in my patch, which I fixed with followups:
http://hg.mozilla.org/mozilla-central/rev/fa6a8601ab7f
http://hg.mozilla.org/mozilla-central/rev/4089e93b323b

Thanks, Ehsan :)

Comment 9

[Joel Maher ( :jmaher ) (UTC -8)]

this is causing a javascript error in MozillaFileLogger.


Here is the code in TestRunner.js (added code is second block):
        if (TestRunner.logEnabled) {
            TestRunner.logger.log("Passed: " + $("pass-count").innerHTML);
            TestRunner.logger.log("Failed: " + $("fail-count").innerHTML);
            TestRunner.logger.log("Todo:   " + $("todo-count").innerHTML);
            TestRunner.logger.log("SimpleTest FINISHED");
        }

        if (TestRunner.onComplete) {
            TestRunner.logger.log("TEST-START | Shutdown");
            TestRunner.onComplete();
        }


Here is the code from MozillaFileLogger.js:
MozillaFileLogger.getLogCallback = function() {
  return function (msg) {
    netscape.security.PrivilegeManager.enablePrivilege("UniversalXPConnect");
    var data = msg.num + " " + msg.level + " " + msg.info.join(' ') + "\n";
    MozillaFileLogger._foStream.write(data, data.length);
    if (data.indexOf("SimpleTest FINISH") >= 0) {
      MozillaFileLogger.close();
    }
  }
}


We close the _foStream when we see 'SimpleTest FINISH', but now we are writing to the log and get this error:
JavaScript error: http://mochi.test:8888/tests/SimpleTest/MozillaFileLogger.js, line 58: MozillaFileLogger._foStream is null


A couple options to fix this:
1) change MozillaFileLogger to look for Shutdown
2) move the 'TEST-START | Shutdown' message above the 'SIMPLETEST finished' message
3) do an explicit MozillaFileLogger.close() in onComplete()

Also if you are doing this logging, please check if we have logging available 'if (TestRunner.logEnabled) {' before writing to the log.

To be fair, I probably wouldn't have found this in review of the code, although I wonder why this passes on try server?  Maybe when we adjust this we could put a comment in TestRunner so we know that a hard coded dependency exists.

Comment 10

[Ginn Chen]

I ran into the same problem as comment #9.
Firefox won't quit after mochitest-a11y or mochitest-plain.

I guess we can just remove the line
TestRunner.logger.log("TEST-START | Shutdown");
or change it to dump.

Is it used anywhere?

Comment 11

[Joel Maher ( :jmaher ) (UTC -8)]

I have a hack fix for this log file closing issue in my patch for bug 567417.

Comment 12

[Jesse Ruderman]

http://hg.mozilla.org/mozilla-central/rev/5c678ed34f3f should fix the log file closing issue.  Dunno if it's more or less of a hack than what Joel is considering.