Closed
Bug 811167
Opened 12 years ago
Closed 12 years ago
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
Categories
(Core :: DOM: Device Interfaces, defect)
Tracking
()
RESOLVED
FIXED
mozilla23
People
(Reporter: philor, Assigned: rwood)
References
Details
(Keywords: intermittent-failure)
Attachments
(1 file, 1 obsolete file)
|
(deleted),
patch
|
jgriffin
:
review+
|
Details | Diff | Splinter Review |
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
|
Reporter | |
Comment 1•12 years ago
|
||
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
|
|
Reporter | |
Comment 2•12 years ago
|
||
|
||
Comment 3•12 years ago
|
||
Those are telephony tests Rob Wood has written. Lets get him CC'ed.
Component: Marionette → DOM: Device Interfaces
Product: Testing → Core
|
|
Reporter | |
Comment 4•12 years ago
|
||
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
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
|
|
||
Comment 13•12 years ago
|
||
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
|
||
Comment 14•12 years ago
|
||
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
|
||
Comment 15•12 years ago
|
||
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
|
||
Comment 16•12 years ago
|
||
(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.
| Comment hidden (Legacy TBPL/Treeherder Robot) |
|
Assignee | |
Comment 18•12 years ago
|
||
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.
|
|
Reporter | |
Comment 19•12 years ago
|
||
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.
|
|
Reporter | |
Updated•12 years ago
|
Component: Marionette → DOM: Device Interfaces
Product: Testing → Core
| Comment hidden (Legacy TBPL/Treeherder Robot) |
|
|
Assignee | |
Comment 21•12 years ago
|
||
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
|
|
Assignee | |
Comment 22•12 years ago
|
||
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
|
|
Reporter | |
Comment 23•12 years ago
|
||
|
|
||
Comment 24•12 years ago
|
||
I filed bug 813292 to get marionette to abort the test run if a crash has occurred.
|
||
Updated•12 years ago
|
Keywords: intermittent-failure
| Comment hidden (Legacy TBPL/Treeherder Robot) |
|
|
||
Updated•12 years ago
|
Whiteboard: [orange]
|
||
Comment 26•12 years ago
|
||
| Comment hidden (Legacy TBPL/Treeherder Robot) |
|
|
||
Comment 28•12 years ago
|
||
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
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
|
|
||
Comment 31•12 years ago
|
||
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
| Comment hidden (Legacy TBPL/Treeherder Robot) |
|
|
Assignee | |
Comment 54•12 years ago
|
||
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 55•12 years ago
|
||
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+
|
|
Assignee | |
Comment 56•12 years ago
|
||
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 57•12 years ago
|
||
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+
|
|
Assignee | |
Comment 58•12 years ago
|
||
Pushed to try: https://tbpl.mozilla.org/?tree=Try&rev=2c2454274fef
|
|
Assignee | |
Comment 59•12 years ago
|
||
Try run green, pushed to inbound: https://hg.mozilla.org/integration/mozilla-inbound/rev/2b8ed660a51c
|
|
||
Comment 60•12 years ago
|
||
Assignee: nobody → rwood
Status: NEW → RESOLVED
Closed: 12 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → mozilla23
|
|
Assignee | |
Comment 61•12 years ago
|
||
Thanks Ryan.
Landed on b2g18: https://hg.mozilla.org/releases/mozilla-b2g18/rev/7af642635ab2
|
|
||
Updated•12 years ago
|
status-b2g18:
--- → fixed
status-firefox23:
--- → fixed
| Comment hidden (Legacy TBPL/Treeherder Robot) |
You need to log in
before you can comment on or make changes to this bug.
Description
•