1046830 - Crashes of type "This test left crash dumps behind, but we weren't expecting it to!" incorrectly state "Shutdown" in the PROCESS-CRASH message

Status: RESOLVED INCOMPLETE

(Testing :: General, defect)

Description

[Ed Morley [:emorley]]

eg:
https://tbpl.mozilla.org/php/getParsedLog.php?id=44973855&tree=Mozilla-Inbound
Android 4.0 Panda mozilla-inbound debug test plain-reftest-8 on 2014-07-31 07:01:29 PDT for push 641d9afb5bd2

{
07:15:04     INFO -  REFTEST TEST-START | http://10.26.128.20:30123/tests/layout/reftests/table-background/border-collapse-opacity-table.html
07:15:04     INFO -  REFTEST TEST-LOAD | http://10.26.128.20:30123/tests/layout/reftests/table-background/border-collapse-opacity-table.html | 84 / 1340 (6%)
07:15:04     INFO -  REFTEST TEST-LOAD | http://10.26.128.20:30123/tests/layout/reftests/table-background/border-collapse-opacity-table-ref.html | 84 / 1340 (6%)
07:15:04     INFO -  REFTEST TEST-PASS | http://10.26.128.20:30123/tests/layout/reftests/table-background/border-collapse-opacity-table.html | image comparison (==)
07:15:04     INFO -  REFTEST TEST-UNEXPECTED-FAIL | http://10.26.128.20:30123/tests/layout/reftests/table-background/border-collapse-opacity-table-ref.html | This test left crash dumps behind, but we weren't expecting it to!
07:15:04     INFO -  REFTEST INFO | Found unexpected crash dump file /mnt/sdcard/tests/reftest/profile/minidumps/0708ff0b-3b0e-f4ef-4553dd67-0d5a4c5d.dmp.
07:15:04     INFO -  REFTEST INFO | Found unexpected crash dump file /mnt/sdcard/tests/reftest/profile/minidumps/0708ff0b-3b0e-f4ef-4553dd67-0d5a4c5d.extra.
07:15:04     INFO -  REFTEST INFO | Loading a blank page
07:15:04     INFO -  REFTEST TEST-END | http://10.26.128.20:30123/tests/layout/reftests/table-background/border-collapse-opacity-table.html
...
...
07:43:09  WARNING -  REFTEST INFO | Unexpected: 1 (1 unexpected fail, 0 unexpected pass, 0 unexpected asserts, 0 unexpected fixed asserts, 0 failed load, 0 exception)
07:43:09  WARNING -  One or more unittests failed.
07:43:09     INFO -  REFTEST INFO | Known problems: 95 (56 known fail, 0 known asserts, 26 random, 13 skipped, 0 slow)
07:43:09     INFO -  REFTEST INFO | Total canvas count = 2
07:43:09     INFO -  REFTEST TEST-START | Shutdown
07:43:09     INFO -  INFO | automation.py | Application ran for: 0:31:07.627685
07:43:09     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpavwtF_pidlog
07:43:09     INFO -  Contents of /data/anr/traces.txt:
07:43:10     INFO -  mozcrash INFO | Downloading symbols from: https://ftp-ssl.mozilla.org/pub/mozilla.org/mobile/tinderbox-builds/mozilla-inbound-android-debug/1406814365/fennec-34.0a1.en-US.android-arm.crashreporter-symbols.zip
07:43:12  WARNING -  PROCESS-CRASH | Shutdown | application crashed [Unknown top frame]
}
(in this example the stack wasn't valid, but it normally is, search for "test left crash dumps behind" and see the logs in recent bugs)

Given that the js harness noticed mid-way through the run ("Found unexpected crash dump file") we should handle this more intelligently.

Comment 1

[Ed Morley [:emorley]]

Sorry meant to add:
I'm presuming only a child process crashed (and thus the run was able to continue), we noticed the unexpected dump at that point, however since we don't call mozcrash until the end of the run, by that point testLastSeen is set to the last 'test' which is 'Shutdown'.

Comment 2

[Ed Morley [:emorley]]

Also in:
https://tbpl.mozilla.org/php/getParsedLog.php?id=45035819&tree=B2g-Inbound

We're blaming the crash on another (!Shutdown) test name:

{
01:33:45     INFO -  348 INFO TEST-START | /tests/content/media/webaudio/test/test_audioBufferSourceNodeEnded.html
01:33:45     INFO -  349 INFO TEST-UNEXPECTED-ERROR | /tests/content/media/webaudio/test/test_audioBufferSourceNodeEnded.html | This test left crash dumps behind, but we weren't expecting it to!
01:33:45     INFO -  TEST-INFO expected OK | took 1365ms
01:33:45     INFO -  350 INFO TEST-START | /tests/content/media/webaudio/test/test_audioBufferSourceNodeLazyLoopParam.html
...
...
01:40:48     INFO -  702 INFO TEST-START | /tests/docshell/test/navigation/test_bug430624.html
01:40:48     INFO -  703 INFO TEST-OK | /tests/docshell/test/navigation/test_bug430624.html | took 1503ms
01:41:08     INFO -  INFO | automation.py | Application ran for: 0:28:28.824458
01:41:08     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpKXLq3npidlog
01:41:08     INFO -  Contents of /data/anr/traces.txt:
01:41:10     INFO -  mozcrash INFO | Downloading symbols from: https://ftp-ssl.mozilla.org/pub/mozilla.org/mobile/tinderbox-builds/b2g-inbound-android-debug/1406876955/fennec-34.0a1.en-US.android-arm.crashreporter-symbols.zip
01:41:14  WARNING -  PROCESS-CRASH | /tests/docshell/test/navigation/test_bug430624.html | application crashed [@ libxul.so + 0x2e20b4]
}

Comment 3

[(not currently active) Ted Mielczarek]

(In reply to Ed Morley [:edmorley] from comment #0)
> Given that the js harness noticed mid-way through the run ("Found unexpected
> crash dump file") we should handle this more intelligently.

Right, it's just not communicating that to the Python harness. This is probably easier to do once we have structured logging hooked up everywhere.

(In reply to Ed Morley [:edmorley] from comment #2)
> Also in:
> https://tbpl.mozilla.org/php/getParsedLog.php?id=45035819&tree=B2g-Inbound
> 
> We're blaming the crash on another (!Shutdown) test name:

I assume this is just some Reftest vs. Mochitest harness difference.

Comment 4

[Ed Morley [:emorley]]

Mass-closing old bugs I filed that have not had recent activity/no longer affect me.