Failed Android 4.0 debug mochitest jobs with no error summary & test results after "runtests.py | Running tests: end."

RESOLVED WONTFIX

Status

Testing
Mochitest
RESOLVED WONTFIX
3 years ago
2 years ago

People

(Reporter: emorley, Assigned: gbrown)

Tracking

(Blocks: 1 bug)

Trunk
ARM
Android
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

(Reporter)

Description

3 years ago
Android 4.0 Panda mozilla-inbound debug test mochitest-2 on 2014-08-12 05:47:22 PDT for push 59e5f46a92dc

slave: panda-0587

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

{
06:00:42     INFO -  70 INFO TEST-START | /tests/content/html/content/test/forms/test_input_list_attribute.html
06:00:42     INFO -  71 INFO TEST-OK | /tests/content/html/content/test/forms/test_input_list_attribute.html | took 1370ms
06:00:42     INFO -  72 INFO TEST-START | /tests/content/html/content/test/forms/test_input_number_key_events.html
06:00:42     INFO -  73 INFO TEST-OK | /tests/content/html/content/test/forms/test_input_number_key_events.html | took 1525ms
06:00:42     INFO -  74 INFO TEST-START | /tests/content/html/content/test/forms/test_input_radio_radiogroup.html
06:00:42     INFO -  75 INFO TEST-OK | /tests/content/html/content/test/forms/test_input_radio_radiogroup.html | took 1681ms
06:00:42     INFO -  76 INFO TEST-START | /tests/content/html/content/test/forms/test_input_range_attr_order.html
06:00:42     INFO -  77 INFO TEST-OK | /tests/content/html/content/test/forms/test_input_range_attr_order.html | took 431ms
06:00:42     INFO -  78 INFO TEST-START | /tests/content/html/content/test/forms/test_input_range_key_events.html
06:00:42     INFO -  INFO | automation.py | Application ran for: 0:05:05.523639
06:00:42     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpWcKHyWpidlog
06:00:42     INFO -  Contents of /data/anr/traces.txt:
06:00:43     INFO -  /data/tombstones does not exist; tombstone check skipped
06:00:43     INFO -  Stopping web server
06:00:43     INFO -  Stopping web socket server
06:00:43     INFO -  Stopping ssltunnel
06:00:43     INFO -  WARNING | leakcheck | refcount logging is off, so leaks can't be detected!
06:00:43     INFO -  runtests.py | Running tests: end.
06:00:45     INFO -  79 INFO must wait for load
06:00:45     INFO -  80 INFO TEST-PASS | /tests/content/html/content/test/forms/test_input_range_key_events.html | Test VK_LEFT for ltr range with value set to the midpoint (50)
06:00:45     INFO -  81 INFO TEST-PASS | /tests/content/html/content/test/forms/test_input_range_key_events.html | Test repeat of VK_LEFT for ltr range
06:00:45     INFO -  82 INFO TEST-PASS | /tests/content/html/content/test/forms/test_input_range_key_events.html | Test VK_LEFT for ltr range with value set to the maximum (100)
06:00:45     INFO -  83 INFO TEST-PASS | /tests/content/html/content/test/forms/test_input_range_key_events.html | Test repeat of VK_LEFT for ltr range
06:00:45     INFO -  84 INFO TEST-PASS | /tests/content/html/content/test/forms/test_input_range_key_events.html | Test VK_LEFT for ltr range with value set to the minimum (0)
06:00:45     INFO -  85 INFO TEST-PASS | /tests/content/html/content/test/forms/test_input_range_key_events.html | Test repeat of VK_LEFT for ltr range
06:00:45     INFO -  86 INFO TEST-PASS | /tests/content/html/content/test/forms/test_input_range_key_events.html | Test VK_LEFT for ltr range with a step that is greater than 10% of the range (step=20)
06:00:45     INFO -  87 INFO SUITE-END | took 311s
06:00:46     INFO -  88 INFO
06:00:46     INFO -  --------- beginning of /dev/log/main
}
(Reporter)

Comment 1

3 years ago
We recieved TEST-PASSes after the app had been reported to have stopped - and we didn't see a "TEST-START | Shutdown". Is this something that bug 886570 might have caused?
Blocks: 886570
(Reporter)

Comment 2

3 years ago
Same again with this one:

Android 4.0 Panda fx-team debug test mochitest-5 on 2014-08-12 04:06:26 PDT for push 4821747ca37d

slave: panda-0587

https://tbpl.mozilla.org/php/getParsedLog.php?id=45744314&full=1&branch=fx-team

{
04:21:07     INFO -  329 INFO TEST-START | /tests/dom/imptests/html/dom/ranges/test_Range-intersectsNode.html
04:21:07     INFO -  330 INFO TEST-OK | /tests/dom/imptests/html/dom/ranges/test_Range-intersectsNode.html | took 8334ms
04:21:07     INFO -  331 INFO TEST-START | /tests/dom/imptests/html/dom/ranges/test_Range-isPointInRange.html
04:25:46     INFO -  332 INFO TEST-OK | /tests/dom/imptests/html/dom/ranges/test_Range-isPointInRange.html | took 17587ms
04:25:46     INFO -  333 INFO TEST-START | /tests/dom/imptests/html/dom/ranges/test_Range-mutations.html
04:25:46     INFO -  INFO | automation.py | Application ran for: 0:12:42.523174
04:25:46     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpDonUpBpidlog
04:25:46     INFO -  Contents of /data/anr/traces.txt:
04:25:47     INFO -  Stopping web server
04:25:47     INFO -  Stopping web socket server
04:25:47     INFO -  Stopping ssltunnel
04:25:47     INFO -  WARNING | leakcheck | refcount logging is off, so leaks can't be detected!
04:25:47     INFO -  runtests.py | Running tests: end.
04:25:50     INFO -  334 INFO TEST-PASS | /tests/dom/imptests/html/dom/ranges/test_Range-mutations.html | Range mutation tests - Range mutation tests: Elided 100 passes or known failures.
04:25:50     INFO -  335 INFO TEST-PASS | /tests/dom/imptests/html/dom/ranges/test_Range-mutations.html | paras[0].firstChild.splitText(1), with selected range collapsed at (paras[0], 0) - paras[0].firstChild.splitText(1), with selected range collapsed at (paras[0], 0)
04:25:50     INFO -  336 INFO TEST-PASS | /tests/dom/imptests/html/dom/ranges/test_Range-mutations.html | Range mutation tests - Range mutation tests: Elided 100 passes or known failures.
04:25:50     INFO -  337 INFO TEST-PASS | /tests/dom/imptests/html/dom/ranges/test_Range-mutations.html | foreignTextNode.insertData(3, ""), with selected range on foreignTextNode from 1 to 3 - foreignTextNode.insertData(3, ""), with selected range on foreignTextNode from 1 to 3
}
Flags: needinfo?(akachkach)
(Reporter)

Updated

3 years ago
Summary: Failed Android 4.0 debug mochitest-2 job with no error summary → Failed Android 4.0 debug mochitest jobs with no error summary & test results after "runtests.py | Running tests: end."
This looks like the test process is still running when we start finishing the test run (the TEST-PASS messages are shown because at the end of the test run, we dump everything received since the last test_end). This doesn't look like a logging problem to me, but maybe there's some log parsing somewhere that was broken?

NI? gbrown, hoping he knows more about the android harness!
Flags: needinfo?(akachkach) → needinfo?(gbrown)
Summary: Failed Android 4.0 debug mochitest jobs with no error summary & test results after "runtests.py | Running tests: end." → Failed Android 4.0 debug mochitest-2 job with no error summary
Sorry, didn't mean to cancel these changes.
Summary: Failed Android 4.0 debug mochitest-2 job with no error summary → Failed Android 4.0 debug mochitest jobs with no error summary & test results after "runtests.py | Running tests: end."
Interesting to note that both failures happened on the same slave, panda-0587. Bad Panda?
In both cases, the Panda rebooted while the test was in progress. I don't see any indication of why the Panda rebooted.

In terms of the logging, I suspect that the test harness was happily polling the log and dumping what was received when the Panda rebooted. The test harness noticed that the browser was no longer running, signalling the end of the test and triggering "automation.py | Application ran for: ... " etc. When the Panda completed its reboot, the test harness was able to reconnect and check the log again, at which time it found a little bit of unreported log data and dumped that.

I have seen occasional reboots before, but I don't recall seeing them logged this way. The difference might just be chance: If the Panda took longer to reboot, the test harness would probably give up on reconnecting and we'd see a timeout or failed connection attempt instead. Or maybe there has been some change in our logging that I am not aware of...I'm not sure.
Flags: needinfo?(gbrown)
ahal: I remember you've done some changes to the runners when I was working on bug 886570. Could this be related?
Flags: needinfo?(ahalberstadt)
You mean mozrunner? No, Android doesn't use mozrunner at all.
Flags: needinfo?(ahalberstadt)
(In reply to Geoff Brown [:gbrown] from comment #6)
> I have seen occasional reboots before, but I don't recall seeing them logged
> this way. The difference might just be chance: If the Panda took longer to
> reboot, the test harness would probably give up on reconnecting and we'd see
> a timeout or failed connection attempt instead. Or maybe there has been some
> change in our logging that I am not aware of...I'm not sure.

Yeah bug 886570 changed the logging pretty drastically. What is the harness supposed to do when the device reboots? Is the bug here just that the harness is prematurely printing the "shutdown" messages?
(Reporter)

Comment 10

3 years ago
(In reply to Andrew Halberstadt [:ahal] from comment #9)
> Yeah bug 886570 changed the logging pretty drastically. What is the harness
> supposed to do when the device reboots? Is the bug here just that the
> harness is prematurely printing the "shutdown" messages?

I think so
See Also: → bug 1050242
(Reporter)

Comment 11

3 years ago
https://tbpl.mozilla.org/php/getParsedLog.php?id=46174152&tree=Mozilla-Inbound
We don't run mochitests on Android 4.0 now, and this seems specific to pandaboards.
Assignee: nobody → gbrown
Status: NEW → RESOLVED
Last Resolved: 2 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.