856865 - b2g mochitests can't agree between log and logcat about how they timed out

Status: RESOLVED WONTFIX

(Testing :: Mochitest, defect)

Description

[Phil Ringnalda (:philor)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=21320422&tree=Firefox is not even slightly unusual for b2g mochitests. In the regular log, it claims

13:19:12     INFO -  22974 INFO TEST-PASS | /tests/layout/style/test/test_initial_storage.html | value of 'background-position' before we do anything
13:19:12  WARNING -  TEST-UNEXPECTED-FAIL | /tests/layout/style/test/test_initial_storage.html | application timed out after 330 seconds with no output
13:19:12     INFO -  INFO | automation.py | Application ran for: 0:57:06.979858
13:19:12     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpyB6E2zpidlog
13:20:16     INFO -  checking for crashes in '/data/local/tests/profile/minidumps'
13:20:16     INFO -  WARNING | leakcheck | refcount logging is off, so leaks can't be detected!
13:20:16     INFO -  INFO | runtests.py | Running tests: end.
13:20:53    ERROR - Return code: 1

which is one thing, hanging after that particular subtest and then producing no output for 330 seconds (though in normal methods of counting time, 330 seconds with no output would not have a timestamp for the same second as the last bit of output), while the logcat dump says

13:21:10     INFO -  I/GeckoDump(  791): 25079 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/style/test/test_initial_storage.html | Test timed out.
13:21:10     INFO -  I/GeckoDump(  791): 25080 INFO TEST-END | /tests/layout/style/test/test_initial_storage.html | finished in 349422ms
13:21:10     INFO -  I/GeckoDump(  791): 25081 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/style/test/test_initial_storage.html | [SimpleTest.finish()] this test already called finish!
13:21:10     INFO -  I/GeckoDump(  791): 25082 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/style/test/test_initial_storage.html | called finish() multiple times
13:21:10     INFO -  I/GeckoDump(  791): 25083 INFO Error: Unable to restore focus, expect failures and timeouts.
13:21:10     INFO -  I/GeckoDump(  791): 25084 INFO TEST-START | /tests/layout/style/test/test_keyframes_rules.html

followed by several more tests running before a sudden stop.

If (yeah, I know, it's a strech) someone were to try to debug this test failure, those are two very very different things: "test timed out" means that they either need to make the test run faster or split up the test or increase the timeout because it just takes longer than the amount of time the harness gives it, "with no output" means the test hung. Claiming both for the same failure just means that if someone looked at it, they would say "broken harness, someone who is not me should fix that, my test is just fine."