917252 - B2G mochitests should output a failure message when bug 906793 occurs

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Ed Morley [:emorley]]

In the case of bug 906793, the log output is:

https://tbpl.mozilla.org/php/getParsedLog.php?id=27960997&tree=Mozilla-Inbound

{
03:31:54     INFO -  12794 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementReplaceWithToHTMLMethod - 1 assertions, 0 failures, 0 errors
03:31:54     INFO -  12795 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementSelectorMethod - 6 assertions, 0 failures, 0 errors
03:31:54     INFO -  12796 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementAdjacent - 4 assertions, 0 failures, 0 errors
03:31:54     INFO -  12797 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementIdentify - 5 assertions, 0 failures, 0 errors
03:31:54     INFO -  12798 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementClassNameMethod - 4 assertions, 0 failures, 0 errors
03:37:26     INFO -  12799 INFO TEST-PASS | /tB2GRunner TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | application timed out after None seconds with no output
03:38:29     INFO -  Mochitest INFO | runtestsb2g.py | Running tests: end.
03:38:46     INFO -  ests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementAncestors - 3 assertions, 0 failures, 0 errors
03:38:46     INFO -  12800 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementDescendants - 3 assertions, 0 failures, 0 errors
03:38:46     INFO -  12801 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementFirstDescendant - 2 assertions, 0 failures, 0 errors
03:38:46     INFO -  12802 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementChildElements - 4 assertions, 0 failures, 0 errors
03:38:46     INFO -  12803 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementImmediateDescendants - 1 assertions, 0 failures, 0 errors
03:38:46     INFO -  12804 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementPreviousSiblings - 3 assertions, 0 failures, 0 errors
03:38:46     INFO -  12805 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementNextSiblings - 3 assertions, 0 failures, 0 errors
03:38:46     INFO -  12806 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementSiblings - 2 assertions, 0 failures, 0 errors
03:38:46     INFO -  12807 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementUp - 10 assertions, 0 failures, 0 errors
03:38:46     INFO -  12808 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementDown - 9 assertions, 0 failures, 0 errors
03:38:46     INFO -  12809 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementPrevious - 7 assertions, 0 failures, 0 errors
03:38:46     INFO -  12810 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementNext - 8 assertions, 0 failures, 0 errors
03:38:46     INFO -  12811 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementInspect - 3 assertions, 0 failures, 0 errors
03:38:46     INFO -  12812 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementMakeClipping - 15 assertions, 0 failures, 0 errors
03:38:46     INFO -  12813 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementExtend - 151 assertions, 0 failures, 0 errors
03:38:46     INFO -  12814 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementExtendReextendsDiscardedNodes - 2 assertions, 0 failures, 0 errors
03:38:46     INFO -  12815 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementCleanWhitespace - 9 assertions, 0 failures, 0 errors
03:38:46     INFO -  12816 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementEmpty - 3 assertions, 0 failures, 0 errors
03:38:46     INFO -  12817 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testDescendantOf - 22 assertions, 0 failures, 0 errors
03:38:46     INFO - Return code: 0
03:38:46     INFO - dumping logcat
03:38:46     INFO - Running command: ['cat', '/builds/slave/test/build/emulator-5554.log']
03:38:46     INFO - Copy/paste: cat /builds/slave/test/build/emulator-5554.log
03:38:46     INFO -  09-17 10:10:57.495    35    35 I qemu-props: connected to 'boot-properties' qemud service.
03:38:46     INFO -  09-17 10:10:57.495    35    35 I qemu-props: receiving..
...
<snip>
...
03:38:53     INFO -  09-17 10:31:56.035   687   687 I GeckoDump: 12816 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testElementEmpty - 3 assertions, 0 failures, 0 errors
03:38:53     INFO -  09-17 10:31:56.035   687   687 I GeckoDump:
03:38:53     INFO -  09-17 10:31:56.135   687   687 I GeckoDump: 12817 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testDescendantOf - 22 assertions, 0 failures, 0 errors
03:38:53     INFO -  09-17 10:31:56.135   687   687 I GeckoDump:
03:38:53     INFO -  09-17 10:37:26.345    33    33 I ServiceManager: service 'media.resource_manager' died
03:38:53     INFO - Return code: 0
03:38:53     INFO - TinderboxPrint: mochitest<br/><em class="testfail">T-FAIL</em>
03:38:53  WARNING - # TBPL WARNING #
}

Other than the logcat "ServiceManager: service 'media.resource_manager' died", there is no other parsable indication as to why the job failed.

We need to:
* Make runtestsb2g.py (or similar) output a sensible error message.
* Make runtestsb2g.py not return code 0 (see just before logcat dump starts)

Comment 1

[Ed Morley [:emorley]]

From runtestsb2g.py:
{
        try:
            runner_args = { 'profile': self.profile,
                            'devicemanager': self._dm,
                            'marionette': self.marionette,
                            'remote_test_root': self.remote_test_root,
                            'test_script': self.test_script,
                            'test_script_args': self.test_script_args }
            self.runner = B2GRunner(**runner_args)
            self.runner.start(outputTimeout=timeout)
            self.runner.wait()
        except KeyboardInterrupt:
            log.info("runtests.py | Received keyboard interrupt.\n");
            status = -1
        except:
            traceback.print_exc()
            log.error("Automation Error: Received unexpected exception while running application\n")
            status = 1

        self.stopWebServer(options)
        self.stopWebSocketServer(options)

        log.info("runtestsb2g.py | Running tests: end.")

        if manifest is not None:
            self.cleanup(manifest, options)
        return status
}

Unlike the other harnesses, we're relying on an exception to return anything other than zero (as opposed to returning the exit code directly). We need B2GRunner (mozrunner) to raise when we hit bug 906793 - and then either mozrunner or runtestsb2g.py to output a TBPL parsable error when this occurs.

jgriffin, could you find someone to own this? :-)

Comment 2

[Jonathan Griffin (:jgriffin)]

Andrew, would you mind looking at this?

Comment 3

[Andrew Halberstadt [:ahal]]

Ok so if I understand correctly.. B2GRunner needs to raise an exception when any generic timeout happens (as it can't detect what the cause of the timeout is at the moment).. or else the mochitest runner can be modified to look at the return code and B2GRunner can return 1.

Then if you want a specific message to this bug, rather than a generic timeout one, it'll either have to live in mozharness, or we'll need to modify the test runner to parse logcat (not too crazy about this approach.. though I don't know that logcat parsing really belongs in mozharness either).

Comment 4

[Ed Morley [:emorley]]

Any exception will be better than what we have at present (which is a failed run, but with nothing parsable in stdout, which results in TBPL's "no summary found") :-)

Comment 5

[Jonathan Griffin (:jgriffin)]

It seems like the real problem here is that we're exiting with return code 0, which I don't understand.  It's not actually timing out:

03:38:46     INFO -  12817 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | testDescendantOf - 22 assertions, 0 failures, 0 errors
03:38:46     INFO - Return code: 0

But it's terminating before it finishes the tests.

Comment 6

[Ed Morley [:emorley]]

We do get:
03:38:29     INFO -  Mochitest INFO | runtestsb2g.py | Running tests: end.

It's just higher up the log... seems like another case of stdout being interleaved.

Comment 7

[Andrew Halberstadt [:ahal]]

(In reply to Ed Morley [:edmorley UTC+1] from comment #4)
> Any exception will be better than what we have at present (which is a failed
> run, but with nothing parsable in stdout, which results in TBPL's "no
> summary found") :-)

So currently there is an error being printed, search for "application timed out" in your log dump in comment 0. The problem is that it doesn't seem to wait for the process_handler to finish processing output from the test first. I'll take a look into this.

(In reply to Jonathan Griffin (:jgriffin) from comment #5)
> It seems like the real problem here is that we're exiting with return code
> 0, which I don't understand.  It's not actually timing out:
> 
> 03:38:46     INFO -  12817 INFO TEST-PASS |
> /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html |
> testDescendantOf - 22 assertions, 0 failures, 0 errors
> 03:38:46     INFO - Return code: 0
> 
> But it's terminating before it finishes the tests.

The return code 0 thing is a bug, if it times out then it should return 1. I think Mihnea actually fixed this already, but it hasn't been synced to m-c yet. If you look at bug 906793 though, you'll see a bunch of test runs where the timeout does happen in the middle of a run, e.g:
https://tbpl.mozilla.org/php/getParsedLog.php?id=26722508&tree=B2g-Inbound

Comment 8

[Ed Morley [:emorley]]

(In reply to Andrew Halberstadt [:ahal] from comment #7)
> So currently there is an error being printed, search for "application timed
> out" in your log dump in comment 0. The problem is that it doesn't seem to
> wait for the process_handler to finish processing output from the test
> first. I'll take a look into this.

Ah sorry missed that, the parser didn't highlight it, since it exempts any lines containing TEST-PASS...

03:37:26     INFO -  12799 INFO TEST-PASS | /tB2GRunner TEST-UNEXPECTED-FAIL | /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html | application timed out after None seconds with no output

Comment 9

[Andrew Halberstadt [:ahal]]

I don't understand why the "application timed out" message is being interleaved with the process output. Both the on_output and on_timeout methods are called from within the same thread, and on_timeout is only ever called after all the on_output processing has been finished..

on_output called here: https://github.com/mozilla/mozbase/blob/master/mozprocess/mozprocess/processhandler.py#L701
on_timeout called here: https://github.com/mozilla/mozbase/blob/master/mozprocess/mozprocess/processhandler.py#L708

There can only ever be one thread in that function. Furthermore, I tried creating an artificial timeout to reproduce locally, but no luck. The output is in sequential order as I'd expect it to be.

Jeff, I vaguely remember you working on (or talking about?) a similar issue back in the day. Do you understand how this behaviour might be possible? If not, don't worry about it, I'll keep digging.

Comment 10

[Andrew Halberstadt [:ahal]]

For context the specific on_output and on_timeout callbacks in this case are in mozrunner: https://github.com/mozilla/mozbase/blob/master/mozrunner/mozrunner/remote.py#L184

Comment 11

[Jeff Hammel]

There are several interleaving issues ticketed in the Testing::Mozbase component, but they're mostly windows so I believe they don't apply here (sorry, I can't dig through https://bugzilla.mozilla.org/buglist.cgi?resolution=---&component=Mozbase&product=Testing&list_id=7920704 right now). I'm not familiar enough end-to-end of how b2g testing is done to have a good guess, but there is to consider stdout/err flushing on the device and host OS, a missing '\n' ...somewhere in the chain, mozdevice, certainly mozprocess (the threading worries me, but I agree with Andrew and don't see anything obviously wrong) and maybe more I can't think of.

> 03:37:26 INFO - 12799 INFO TEST-PASS | /tB2GRunner TEST-UNEXPECTED-FAIL |
> /tests/dom/tests/mochitest/ajax/prototype/test_Prototype.html |
> application timed out after None seconds with no output

Timing out after None seconds confuses me....am I wrong to think that `None` means "never time out"?

Comment 12

[Andrew Halberstadt [:ahal]]

(In reply to Jeff Hammel [:jhammel] from comment #11)
> Timing out after None seconds confuses me....am I wrong to think that `None`
> means "never time out"?

That's another bug that I've fixed in my local patch, unrelated to the issue at hand.

I don't think I'm going to be able to fix the interleaving problem without figuring out how to reproduce it locally. My only theory is that it has something to do with running through mozharness or not (in the mozharness case we have a subprocess within a subprocess.. though don't ask me why that would cause problems).

In the meantime I can at least make the return code non-zero if there was a timeout, and fix the None in the timeout message.

Comment 13

[Andrew Halberstadt [:ahal]]

Attachment: Patch 1.0 - fix timeout error message

I still haven't been able to figure out the interleaving, but figured I might as well upload the fix to the timeout error message while I was thinking about it.

Comment 14

[Jeff Hammel]

Comment on attachment 809422 [details] [diff] [review]
Patch 1.0 - fix timeout error message

wfm

Comment 15

[Andrew Halberstadt [:ahal]]

Attachment: Patch 1.1 (m-c) - return status code from b2g mochitests

So like I said, I don't know what to do about the message interleaving, but I can at least fix the status code. This will give you the option of either looking for status code 124 or you could try searching the "application timed out" message (though it won't be at the start of the line).

I chose 124 because that is what the Unix 'timeout' command returns when a program times out. After quick googling, other programs seem to use 124 for timeouts as well.

Will this return value be sufficient to close out this bug? I'll file another one for the interleaving issue if that's the case.

Comment 16

[Andrew Halberstadt [:ahal]]

Note, the previous patch will depend on https://github.com/mozilla/mozbase/commit/968f70bf99f6a4a82630569cc4d9dab0f11d17db getting synced to m-c.

Comment 17

[Andrew Halberstadt [:ahal]]

https://github.com/mozilla/mozbase/commit/affd0e83f931d363631eb7d8321f36c85c4b0fc0

Comment 18

[Jeff Hammel]

(In reply to Andrew Halberstadt [:ahal] from comment #16)
> Note, the previous patch will depend on
> https://github.com/mozilla/mozbase/commit/
> 968f70bf99f6a4a82630569cc4d9dab0f11d17db getting synced to m-c.

I'm working on bug 917750 fwiw

Comment 19

[Andrew Halberstadt [:ahal]]

Excellent, thanks!

Comment 20

[Ed Morley [:emorley]]

Comment on attachment 809432 [details] [diff] [review]
Patch 1.1 (m-c) - return status code from b2g mochitests

Thank you :-)

Comment 21

[Andrew Halberstadt [:ahal]]

I just cherry picked the necessary changes into m-c in bug 921029 instead of waiting for the full sync.

https://hg.mozilla.org/integration/mozilla-inbound/rev/4e93e321909d

Comment 22

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/4e93e321909d