Intermittent emulator failures test_incoming_hold_resume.js, test_incoming_reject.js, test_multiple_hold.js | MarionetteException: Emulator callback still pending when finish() called and then lots of fallout

RESOLVED FIXED in Firefox 23

Status

()

defect
RESOLVED FIXED
7 years ago
6 years ago

People

(Reporter: philor, Assigned: rwood)

Tracking

({intermittent-failure})

Trunk
mozilla23
ARM
Gonk (Firefox OS)
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox23 fixed, b2g18 fixed)

Details

Attachments

(1 attachment, 1 obsolete attachment)

https://tbpl.mozilla.org/php/getParsedLog.php?id=16969568&tree=Mozilla-Inbound
b2g_ics_armv7a_gecko_emulator mozilla-inbound opt test marionette-webapi on 2012-11-12 16:03:29 PST for push 866e9c7d656d
(https://hg.mozilla.org/integration/mozilla-inbound/rev/866e9c7d656d seems unlikely to actually be the cause, but what do I know?)
slave: talos-r3-fed-050

16:08:45     INFO -  TEST-START test_incoming_hold_resume.js
16:08:58     INFO -  /home/cltbld/talos-slave/test/build/tests/marionette/tests/dom/telephony/test/marionette/test_incoming_hold_resume.js, runTest (marionette_test.MarionetteJSTestCase) ... /home/cltbld/talos-slave/test/build/tests/marionette/marionette/errors.py:9: DeprecationWarning: BaseException.message has been deprecated as of Python 2.6
16:08:58     INFO -    self.message = message
16:08:58     INFO -  /home/cltbld/talos-slave/test/build/tests/marionette/marionette/errors.py:18: DeprecationWarning: BaseException.message has been deprecated as of Python 2.6
16:08:58     INFO -    return str(self.message)
16:08:58     INFO -  ERROR
16:08:58     INFO -  ======================================================================
16:08:58     INFO -  ERROR: /home/cltbld/talos-slave/test/build/tests/marionette/tests/dom/telephony/test/marionette/test_incoming_hold_resume.js, runTest (marionette_test.MarionetteJSTestCase)
16:08:58     INFO -  ----------------------------------------------------------------------
16:08:58    ERROR -  Traceback (most recent call last):
16:08:58     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette_test.py", line 209, in runTest
16:08:58     INFO -      results = self.marionette.execute_js_script(js, args, special_powers=True)
16:08:58     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.py", line 411, in execute_js_script
16:08:58     INFO -      specialPowers=special_powers)
16:08:58     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.py", line 188, in _send_message
16:08:58     INFO -      self._handle_error(response)
16:08:58     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.py", line 245, in _handle_error
16:08:58     INFO -      raise MarionetteException(message=message, status=status, stacktrace=stacktrace)
16:08:58     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_hold_resume.js | MarionetteException: Emulator callback still pending when finish() called
16:08:58     INFO -  START LOG:
16:08:58     INFO -  INFO TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/dom/telephony/test/marionette/test_incoming_hold_resume.js Tue Nov 13 2012 00:08:34 GMT+0000 (GMT)
16:08:58     INFO -  INFO Verifying initial state. Tue Nov 13 2012 00:08:35 GMT+0000 (GMT)
16:08:58     INFO -  INFO Initial call list: OK Tue Nov 13 2012 00:08:35 GMT+0000 (GMT)
16:08:58     INFO -  INFO Simulating an incoming call. Tue Nov 13 2012 00:08:35 GMT+0000 (GMT)
16:08:58     INFO -  INFO Received 'incoming' call event. Tue Nov 13 2012 00:08:35 GMT+0000 (GMT)
16:08:58     INFO -  INFO Call list is now: inbound from 5555551234 : incoming,OK Tue Nov 13 2012 00:08:35 GMT+0000 (GMT)
16:08:58     INFO -  INFO Answering the incoming call. Tue Nov 13 2012 00:08:35 GMT+0000 (GMT)
16:08:58     INFO -  INFO Received 'connecting' call event. Tue Nov 13 2012 00:08:35 GMT+0000 (GMT)
16:08:58     INFO -  INFO Received 'connected' call event. Tue Nov 13 2012 00:08:36 GMT+0000 (GMT)
16:08:58     INFO -  END LOG:
16:08:58     INFO -  ----------------------------------------------------------------------
16:08:58     INFO -  Ran 1 test in 12.852s
16:08:58    ERROR -  FAILED (errors=1)
...
16:09:00    ERROR -  Traceback (most recent call last):
16:09:00     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_answer_remote_hangup.js | got inbound from 5555551234 : active, expected OK | got false, expected true
16:09:00     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_answer_remote_hangup.js | got 2, expected 1 | got false, expected true
16:09:00     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_answer_remote_hangup.js | got [object TelephonyCall], expected [object TelephonyCall] | got false, expected true
16:09:00     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_answer_remote_hangup.js | got inbound from 5555551234 : active, expected inbound from 5555551111 : incoming | got false, expected true
16:09:00     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_answer_remote_hangup.js | got inbound from 5555551111 : incoming, expected OK | got false, expected true
16:09:00     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_answer_remote_hangup.js | got inbound from 5555551234 : held, expected inbound from 5555551111 : active | got false, expected true
16:09:00     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_answer_remote_hangup.js | got inbound from 5555551111 : active, expected OK | got false, expected true
16:09:00     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_answer_remote_hangup.js | got 1, expected 0 | got false, expected true
16:09:00     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_answer_remote_hangup.js | got inbound from 5555551234 : held, expected OK | got false, expected true
16:09:02    ERROR -  Traceback (most recent call last):
16:09:02     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_connecting_hangup.js | got inbound from 5555551234 : held, expected OK | got false, expected true
16:09:02     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_connecting_hangup.js | got 2, expected 1 | got false, expected true
16:09:02     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_connecting_hangup.js | got [object TelephonyCall], expected [object TelephonyCall] | got false, expected true
16:09:02     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_connecting_hangup.js | got inbound from 5555551234 : held, expected inbound from 5555551111 : incoming | got false, expected true
16:09:02     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_connecting_hangup.js | got inbound from 5555551111 : incoming, expected OK | got false, expected true
16:09:02     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_connecting_hangup.js | got 1, expected 0 | got false, expected true
16:09:02     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_connecting_hangup.js | got inbound from 5555551234 : held, expected OK | got false, expected true
16:09:03    ERROR -  Traceback (most recent call last):
16:09:03     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_connecting_remote_hangup.js | got inbound from 5555551234 : held, expected OK | got false, expected true
16:09:03     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_connecting_remote_hangup.js | got 2, expected 1 | got false, expected true
16:09:03     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_connecting_remote_hangup.js | got [object TelephonyCall], expected [object TelephonyCall] | got false, expected true
16:09:03     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_connecting_remote_hangup.js | got inbound from 5555551234 : held, expected inbound from 5555551111 : incoming | got false, expected true
16:09:03     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_connecting_remote_hangup.js | got inbound from 5555551111 : incoming, expected OK | got false, expected true
16:09:03     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_connecting_remote_hangup.js | got 1, expected 0 | got false, expected true
16:09:03     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_connecting_remote_hangup.js | got inbound from 5555551234 : held, expected OK | got false, expected true
16:09:05    ERROR -  Traceback (most recent call last):
16:09:05     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_cancel.js | got inbound from 5555551234 : held, expected OK | got false, expected true
16:09:05     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_cancel.js | got 2, expected 1 | got false, expected true
16:09:05     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_cancel.js | got [object TelephonyCall], expected [object TelephonyCall] | got false, expected true
16:09:05     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_cancel.js | got inbound from 5555551234 : held, expected inbound from 5555551111 : incoming | got false, expected true
16:09:05     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_cancel.js | got inbound from 5555551111 : incoming, expected OK | got false, expected true
16:09:05     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_cancel.js | got 1, expected 0 | got false, expected true
16:09:05     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_cancel.js | got inbound from 5555551234 : held, expected OK | got false, expected true
16:09:07    ERROR -  Traceback (most recent call last):
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got inbound from 5555551234 : held, expected OK | got false, expected true
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got 2, expected 1 | got false, expected true
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got [object TelephonyCall], expected [object TelephonyCall] | got false, expected true
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got inbound from 5555551234 : held, expected inbound from 5555551111 : incoming | got false, expected true
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got inbound from 5555551111 : incoming, expected OK | got false, expected true
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got inbound from 5555551234 : held, expected inbound from 5555551111 : active | got false, expected true
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got inbound from 5555551111 : active, expected OK | got false, expected true
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got [object TelephonyCall], expected null | got false, expected true
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got 2, expected 1 | got false, expected true
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got [object TelephonyCall], expected [object TelephonyCall] | got false, expected true
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got inbound from 5555551234 : active, expected inbound from 5555551111 : held | got false, expected true
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got inbound from 5555551111 : held, expected OK | got false, expected true
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got [object TelephonyCall], expected null | got false, expected true
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got 1, expected 0 | got false, expected true
16:09:07     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_remote_hangup_held.js | got inbound from 5555551234 : active, expected OK | got false, expected true
16:09:09    ERROR -  Traceback (most recent call last):
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got inbound from 5555551234 : active, expected OK | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got 2, expected 1 | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got [object TelephonyCall], expected [object TelephonyCall] | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got inbound from 5555551234 : active, expected inbound from 5555551111 : incoming | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got inbound from 5555551111 : incoming, expected OK | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got 2, expected 1 | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got [object TelephonyCall], expected [object TelephonyCall] | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got inbound from 5555551234 : held, expected inbound from 5555551111 : active | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got inbound from 5555551111 : active, expected OK | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got [object TelephonyCall], expected null | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got 2, expected 1 | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got [object TelephonyCall], expected [object TelephonyCall] | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got inbound from 5555551234 : active, expected inbound from 5555551111 : held | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got inbound from 5555551111 : held, expected OK | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got 2, expected 1 | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got [object TelephonyCall], expected [object TelephonyCall] | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got inbound from 5555551234 : held, expected inbound from 5555551111 : active | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got inbound from 5555551111 : active, expected OK | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got 1, expected 0 | got false, expected true
16:09:09     INFO -  TEST-UNEXPECTED-FAIL | test_incoming_onstatechange.js | got inbound from 5555551234 : held, expected OK | got false, expected true
16:09:11    ERROR -  Traceback (most recent call last):
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got inbound from 5555551234 : held, expected OK | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got 2, expected 1 | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got [object TelephonyCall], expected [object TelephonyCall] | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got inbound from 5555551234 : held, expected outbound to  5555551111 : ringing | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got outbound to  5555551111 : ringing, expected OK | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got inbound from 5555551234 : held, expected outbound to  5555551111 : active | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got outbound to  5555551111 : active, expected OK | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got [object TelephonyCall], expected null | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got 2, expected 1 | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got [object TelephonyCall], expected [object TelephonyCall] | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got inbound from 5555551234 : active, expected outbound to  5555551111 : held | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got outbound to  5555551111 : held, expected OK | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got 2, expected 1 | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got [object TelephonyCall], expected [object TelephonyCall] | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got inbound from 5555551234 : held, expected outbound to  5555551111 : active | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got outbound to  5555551111 : active, expected OK | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got 1, expected 0 | got false, expected true
16:09:11     INFO -  TEST-UNEXPECTED-FAIL | test_outgoing_onstatechange.js | got inbound from 5555551234 : held, expected OK | got false, expected true
16:09:14    ERROR -  Traceback (most recent call last):
16:09:14     INFO -  TEST-UNEXPECTED-FAIL | test_redundant_operations.js | got inbound from 5555551234 : held, expected OK | got false, expected true
16:09:14     INFO -  TEST-UNEXPECTED-FAIL | test_redundant_operations.js | got 2, expected 1 | got false, expected true
16:09:14     INFO -  TEST-UNEXPECTED-FAIL | test_redundant_operations.js | got [object TelephonyCall], expected [object TelephonyCall] | got false, expected true
16:09:14     INFO -  TEST-UNEXPECTED-FAIL | test_redundant_operations.js | got inbound from 5555551234 : held, expected inbound from 5555551111 : incoming | got false, expected true
16:09:14     INFO -  TEST-UNEXPECTED-FAIL | test_redundant_operations.js | got inbound from 5555551111 : incoming, expected OK | got false, expected true
16:09:14     INFO -  TEST-UNEXPECTED-FAIL | test_redundant_operations.js | got inbound from 5555551234 : held, expected inbound from 5555551111 : active | got false, expected true

etc. etc. ad not quite infinitum

https://tbpl.mozilla.org/php/getParsedLog.php?id=16971339&tree=Mozilla-Inbound
https://tbpl.mozilla.org/php/getParsedLog.php?id=16971527&tree=Mozilla-Inbound
https://tbpl.mozilla.org/php/getParsedLog.php?id=16973126&tree=Mozilla-Inbound
https://tbpl.mozilla.org/php/getParsedLog.php?id=16973215&tree=Mozilla-Inbound
Summary: Intermittent emulator failures test_incoming_hold_resume.js | MarionetteException: Emulator callback still pending when finish() called and then lots of fallout → Intermittent emulator failures test_incoming_hold_resume.js, test_incoming_reject.js | MarionetteException: Emulator callback still pending when finish() called and then lots of fallout
Those are telephony tests Rob Wood has written. Lets get him CC'ed.
Component: Marionette → DOM: Device Interfaces
Product: Testing → Core
They are timing out with absolutely zero output, which should be impossible for them, shouldn't it? And if you look at the logcat spew, once you manage to find them, they seem to be merrily passing, and just not being able to tell anyone that they are:

18:19:06     INFO - I/Gecko   (  307): MARIONETTE LOG: INFO: TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/dom/telephony/test/marionette/test_incoming_reject.js
18:19:06     INFO - I/Gecko   (  307): 1352772773551	Marionette	INFO	sendToClient: {"from":"conn2.marionette1","value":null}, undefined, null
18:19:06     INFO - E/GeckoConsole(  307): Content JS INFO at app://system.gaiamobile.org/js/window_manager.js:1000 in createFrame: %%%%% Launching Homescreen as remote (OOP)
18:19:06     INFO - E/GeckoConsole(  307): [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://10.12.49.147:35032/empty.html" line: 0}]
18:19:06     INFO - I/Gecko   (  307): 1352772776264	Marionette	INFO	sendToClient: {"from":"conn2.marionette1","ok":true}, undefined, null
18:19:06     INFO - I/Gecko   (  307): 1352772776332	Marionette	INFO	sendToClient: {"from":"conn2.marionette1","ok":true}, undefined, null
18:19:06     INFO - I/Gecko   (  307): [Parent 307] WARNING: pipe error (83): Connection reset by peer: file /builds/slave/m-in-ics-armv7a-gecko/build/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 421
18:19:06     INFO - I/Gecko   (  307): [Parent 307] WARNING: waitpid failed pid:341 errno:10: file /builds/slave/m-in-ics-armv7a-gecko/build/ipc/chromium/src/base/process_util_posix.cc, line 260
18:19:06     INFO - I/Gecko   (  307): MARIONETTE LOG: INFO: Verifying initial state.
18:19:06     INFO - I/Gecko   (  307): MARIONETTE TEST RESULT:TEST-PASS | test_incoming_reject.js | undefined - [object Telephony] was false, expected true
18:19:06     INFO - I/Gecko   (  307): MARIONETTE TEST RESULT:TEST-PASS | test_incoming_reject.js | undefined - null should equal null
18:19:06     INFO - I/Gecko   (  307): MARIONETTE TEST RESULT:TEST-PASS | test_incoming_reject.js | undefined -  was false, expected true
18:19:06     INFO - I/Gecko   (  307): MARIONETTE TEST RESULT:TEST-PASS | test_incoming_reject.js | undefined - 0 should equal 0
18:19:06     INFO - I/Gecko   (  307): 1352772776529	Marionette	INFO	sendToClient: {"emulator_cmd":"gsm list","id":0}, undefined, null
18:19:06     INFO - I/Gecko   (  307): MARIONETTE LOG: INFO: Initial call list: OK
18:19:06     INFO - I/Gecko   (  307): MARIONETTE TEST RESULT:TEST-PASS | test_incoming_reject.js | undefined - OK should equal OK
18:19:06     INFO - I/Gecko   (  307): MARIONETTE LOG: INFO: Simulating an incoming call.
18:19:06     INFO - I/Gecko   (  307): 1352772776606	Marionette	INFO	sendToClient: {"emulator_cmd":"gsm call 5555552368","id":1}, undefined, null
18:19:06     INFO - I/Gecko   (  307): [Parent 307] WARNING: waitpid failed pid:341 errno:10: file /builds/slave/m-in-ics-armv7a-gecko/build/ipc/chromium/src/base/process_util_posix.cc, line 260
18:19:06     INFO - I/Gecko   (  307): [Parent 307] WARNING: Failed to deliver SIGKILL to 341!(3).: file /builds/slave/m-in-ics-armv7a-gecko/build/ipc/chromium/src/chrome/common/process_watcher_posix_sigchld.cc, line 118
18:19:06     INFO - I/Gecko   (  307): 1352772786456	Marionette	INFO	sendToClient: {"from":"conn2.marionette1","error":{"message":"timed out","status":28,"stacktrace":null}}, undefined, null


And they seem to be the very first tests that run, so probably my feeling, gained from other suites that leave busted state around and cause later tests to fail, was wrong, and rather than "fallout" it's "including the very first test which runs, many tests fail, or rather pass but can't say that they passed."
Component: DOM: Device Interfaces → Marionette
Product: Core → Testing
Not sure if this really belongs to the Marionette component. But to be sure it needs to be investigated. Given that Rob is working on those tests he should be the best person to get those intermittent failures investigated.
Assignee: nobody → rwood
The most recent failures here were actually bustage caused by bug 809674, which has now been backed out.

https://tbpl.mozilla.org/?tree=Mozilla-Inbound&fromchange=26c2e6c1c22e&tochange=bcb591d32bd6&jobname=webapi
There was a single test failure with no fallout, not sure if it's the same problem:
https://tbpl.mozilla.org/php/getParsedLog.php?id=16991161&tree=Mozilla-Inbound
(In reply to Phil Ringnalda (:philor) from comment #4)
> They are timing out with absolutely zero output, which should be impossible
> for them, shouldn't it? And if you look at the logcat spew, once you manage
> to find them, they seem to be merrily passing, and just not being able to
> tell anyone that they are:

...snip... 

> 18:19:06     INFO - I/Gecko   (  307): 1352772786456	Marionette	INFO
> sendToClient: {"from":"conn2.marionette1","error":{"message":"timed
> out","status":28,"stacktrace":null}}, undefined, null
> 

The above line indicates the failure.  All the other TEST-PASS lines are not shown in the Marionette output, but only in logcat.  This is similar to a mochitest run in which a test has a bunch of TEST-PASS lines followed by "Test timed out".  If you think we should change the logging to make things more clear, please file a bug.

> 
> And they seem to be the very first tests that run, so probably my feeling,
> gained from other suites that leave busted state around and cause later
> tests to fail, was wrong, and rather than "fallout" it's "including the very
> first test which runs, many tests fail, or rather pass but can't say that
> they passed."

I think this is the case of bad state from the first failing test.  If a telephony test fails, it can leave the ril in a weird state, which would cause subsequent failure of telephony tests.  All the failures in these logs are telephony-related.
I have not been able to reproduce the initial test failures which caused the other test fallout. It looks like the emulator did not respond / did not execute the callback when commands were sent. Recent builds have been green. I will keep an eye out for this, but may eventually close as unreproducible.
If you really want to reproduce it, you probably need to do so with one of the affected builds: "the first instance was intermittent, on a jsengine push, then it was permaorange was on an xpconnect push a few pushes later, then it hasn't happened since the xpconnect push was backed out" is characteristic of something reading uninitialized memory, and the pushes that "caused" it just happening to put something surprising in that uninitialized memory.
Component: Marionette → DOM: Device Interfaces
Product: Testing → Core
Blocks: 812149
Unassigning myself (cc'd dev). The latest failure is an emulator crash - this *might* be the same problem as Bug 790463. The test causing the crash (test_incoming_reject.js) will be disabled on TBPL.
Assignee: rwood → nobody
With test_incoming_reject.js disabled, the crash just happens with the next telephony test in the list (test_outgoing_answer_hangup.js). Will disable the entire telephony test manifest until this issue is resolved.

https://tbpl.mozilla.org/php/getParsedLog.php?id=17092492&tree=Mozilla-Aurora#error0
I filed bug 813292 to get marionette to abort the test run if a crash has occurred.
Whiteboard: [orange]
https://tbpl.mozilla.org/php/getParsedLog.php?id=17347081&tree=Mozilla-Inbound#error0

{
11:17:25    ERROR -  Traceback (most recent call last):
11:17:25     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette_test.py", line 209, in runTest
11:17:25     INFO -      results = self.marionette.execute_js_script(js, args, special_powers=True)
11:17:25     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.py", line 434, in execute_js_script
11:17:25     INFO -      specialPowers=special_powers)
11:17:25     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.py", line 211, in _send_message
11:17:25     INFO -      self._handle_error(response)
11:17:25     INFO -    File "/home/cltbld/talos-slave/test/build/tests/marionette/marionette/marionette.py", line 268, in _handle_error
11:17:25     INFO -      raise MarionetteException(message=message, status=status, stacktrace=stacktrace)
11:17:25     INFO -  TEST-UNEXPECTED-FAIL | test_multiple_hold.js | MarionetteException: Emulator callback still pending when finish() called
11:17:25     INFO -  START LOG:
11:17:25     INFO -  INFO TEST-START: /home/cltbld/talos-slave/test/build/tests/marionette/tests/dom/telephony/test/marionette/test_multiple_hold.js Mon Nov 26 2012 19:16:58 GMT+0000 (GMT)
11:17:25     INFO -  INFO Verifying initial state. Mon Nov 26 2012 19:16:58 GMT+0000 (GMT)
11:17:25     INFO -  INFO Initial call list: OK Mon Nov 26 2012 19:16:58 GMT+0000 (GMT)
11:17:25     INFO -  INFO Simulating an incoming call. Mon Nov 26 2012 19:16:58 GMT+0000 (GMT)
11:17:25     INFO -  INFO Received 'incoming' call event. Mon Nov 26 2012 19:16:58 GMT+0000 (GMT)
11:17:25     INFO -  INFO Call list is now: inbound from 5555551111 : incoming,OK Mon Nov 26 2012 19:16:58 GMT+0000 (GMT)
11:17:25     INFO -  INFO Answering the incoming call. Mon Nov 26 2012 19:16:58 GMT+0000 (GMT)
11:17:25     INFO -  INFO Received 'connecting' call event for original (incoming) call. Mon Nov 26 2012 19:16:58 GMT+0000 (GMT)
11:17:25     INFO -  INFO Received 'connected' call event for original (incoming) call. Mon Nov 26 2012 19:16:59 GMT+0000 (GMT)
11:17:25     INFO -  INFO Call list is now: inbound from 5555551111 : active,OK Mon Nov 26 2012 19:16:59 GMT+0000 (GMT)
11:17:25     INFO -  INFO Putting the original (incoming) call on hold. Mon Nov 26 2012 19:16:59 GMT+0000 (GMT)
11:17:25     INFO -  INFO Received 'holding' call event Mon Nov 26 2012 19:16:59 GMT+0000 (GMT)
11:17:25     INFO -  INFO Received 'held' call event Mon Nov 26 2012 19:16:59 GMT+0000 (GMT)
11:17:25     INFO -  INFO Call list is now: inbound from 5555551111 : held,OK Mon Nov 26 2012 19:16:59 GMT+0000 (GMT)
11:17:25     INFO -  INFO Making an outgoing call (while have one call already held). Mon Nov 26 2012 19:16:59 GMT+0000 (GMT)
11:17:25     INFO -  INFO Received 'onalerting' call event. Mon Nov 26 2012 19:17:00 GMT+0000 (GMT)
11:17:25     INFO -  INFO Call list is now: inbound from 5555551111 : held,outbound to  5555552222 : ringing,OK Mon Nov 26 2012 19:17:00 GMT+0000 (GMT)
11:17:25     INFO -  INFO Answering the outgoing/2nd call Mon Nov 26 2012 19:17:00 GMT+0000 (GMT)
11:17:25     INFO -  INFO Received 'connected' call event for outgoing/2nd call. Mon Nov 26 2012 19:17:00 GMT+0000 (GMT)
11:17:25     INFO -  INFO Call list is now: inbound from 5555551111 : held,outbound to  5555552222 : active,OK Mon Nov 26 2012 19:17:01 GMT+0000 (GMT)
11:17:25     INFO -  INFO Putting the 2nd (outgoing) call on hold. Mon Nov 26 2012 19:17:01 GMT+0000 (GMT)
11:17:25     INFO -  INFO Received 'holding' call event for 2nd call. Mon Nov 26 2012 19:17:01 GMT+0000 (GMT)
11:17:25     INFO -  INFO Received 'connected' call event for original (incoming) call. Mon Nov 26 2012 19:17:01 GMT+0000 (GMT)
11:17:25     INFO -  INFO Received 'held' call event for 2nd call. Mon Nov 26 2012 19:17:01 GMT+0000 (GMT)
}
Summary: Intermittent emulator failures test_incoming_hold_resume.js, test_incoming_reject.js | MarionetteException: Emulator callback still pending when finish() called and then lots of fallout → Intermittent emulator failures test_incoming_hold_resume.js, test_incoming_reject.js, test_multiple_hold.js | MarionetteException: Emulator callback still pending when finish() called and then lots of fallout
Hi Jonathan,

Several of the telephony test failures are caused by a single (not always the same) telephony test timeout/crash, which leaves behind an active call on the emulator; which in turn causes all of the telephony tests after that to fail out because they expect zero existing calls in their initial test state.

Attached is an example patch of what I propose adding to all of the telephony tests. Instead of failing out the test immediately if an existing call exists at test startup, this will attempt to cancel any existing calls first, and then proceed with the test. If any existing calls are cancelled, the call list is checked again after that to verify the cancel(s) actually worked before proceeding.

This doesn't tackle the original intermittent test failure cause, however this should greatly reduce the number of subsequent failures that are caused from fallout.

I tested this code with zero exiting calls, one existing call, and three existing calls and it seemed to work well.

What do you think?

Thanks,

Rob
Attachment #741482 - Flags: review?(jgriffin)
Comment on attachment 741482 [details] [diff] [review]
Improve telephony test startup

Review of attachment 741482 [details] [diff] [review]:
-----------------------------------------------------------------

Cool, I noticed this problem as well.
Attachment #741482 - Flags: review?(jgriffin) → review+
Update the WebTelephony tests to cancel any existing emulator calls on startup. This will reduce fallout from other failed telephony tests.
Attachment #741482 - Attachment is obsolete: true
Attachment #742369 - Flags: review?(jgriffin)
Comment on attachment 742369 [details] [diff] [review]
Update all telephony tests

Review of attachment 742369 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good, thanks.
Attachment #742369 - Flags: review?(jgriffin) → review+
https://hg.mozilla.org/mozilla-central/rev/2b8ed660a51c
Assignee: nobody → rwood
Status: NEW → RESOLVED
Closed: 6 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → mozilla23
Duplicate of this bug: 842492
You need to log in before you can comment on or make changes to this bug.