Last Comment Bug 768608 - test failure: dom/telephony/test/marionette/*.js | ScriptTimeoutException: timed out
: test failure: dom/telephony/test/marionette/*.js | ScriptTimeoutException: ti...
Status: RESOLVED FIXED
: intermittent-failure
Product: Core
Classification: Components
Component: DOM: Device Interfaces (show other bugs)
: Trunk
: ARM Linux
: -- normal (vote)
: mozilla17
Assigned To: Hsin-Yi Tsai [:hsinyi]
:
:
Mentors:
Depends on:
Blocks: 438871
  Show dependency treegraph
 
Reported: 2012-06-26 12:45 PDT by Malini Das [:mdas] - Away, not checking bugmail
Modified: 2012-11-25 19:31 PST (History)
7 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
Add AT+CEER in android_modem (1.33 KB, patch)
2012-07-12 02:55 PDT, Hsin-Yi Tsai [:hsinyi]
no flags Details | Diff | Splinter Review
Support RIL_REQUEST_LAST_CALL_FAIL_CAUSE in reference-ril.c (2.00 KB, patch)
2012-07-12 02:56 PDT, Hsin-Yi Tsai [:hsinyi]
no flags Details | Diff | Splinter Review
Part 1: Add AT+CEER in android_modem (v2) (1.34 KB, patch)
2012-07-12 03:30 PDT, Hsin-Yi Tsai [:hsinyi]
no flags Details | Diff | Splinter Review
Part 2: Support RIL_REQUEST_LAST_CALL_FAIL_CAUSE in reference-ril.c (v2) (2.05 KB, patch)
2012-07-12 03:32 PDT, Hsin-Yi Tsai [:hsinyi]
no flags Details | Diff | Splinter Review
Change call state into disconnected even no response of call failure cause (1010 bytes, patch)
2012-07-13 23:12 PDT, Hsin-Yi Tsai [:hsinyi]
philipp: review+
Details | Diff | Splinter Review

Description Malini Das [:mdas] - Away, not checking bugmail 2012-06-26 12:45:45 PDT
These are the webapi tests running on the ARM b2g emulator. They passed before June 14th, and started failing sometime between the 14th and the 24th. I appended the respective logs under each test

======================================================================
ERROR: /data/jenkins/jobs/webapi-marionette-test/workspace/dom/telephony/test/marionette/test_incoming_answer_hangup.js, runTest (marionette_test.MarionetteJSTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette_test.py", line 176, in runTest
    results = self.marionette.execute_js_script(js, args)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 334, in execute_js_script
    newSandbox=new_sandbox)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 150, in _send_message
    self._handle_error(response)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 199, in _handle_error
    raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
ScriptTimeoutException: timed out

----------------------------------------------------------------------
Ran 1 test in 27.063s

FAILED (errors=1)

START LOG:
INFO Verifying initial state. Tue Jun 26 2012 18:23:14 GMT+0000 (GMT)
INFO Initial call list: OK Tue Jun 26 2012 18:23:14 GMT+0000 (GMT)
INFO Simulating an incoming call. Tue Jun 26 2012 18:23:14 GMT+0000 (GMT)
INFO Received 'incoming' call event. Tue Jun 26 2012 18:23:14 GMT+0000 (GMT)
INFO Call list is now: inbound from 5555552368 : incoming,OK Tue Jun 26 2012 18:23:14 GMT+0000 (GMT)
INFO Answering the incoming call. Tue Jun 26 2012 18:23:15 GMT+0000 (GMT)
INFO Received 'connecting' call event. Tue Jun 26 2012 18:23:15 GMT+0000 (GMT)
INFO Received 'connected' call event. Tue Jun 26 2012 18:23:15 GMT+0000 (GMT)
INFO Call list is now: inbound from 5555552368 : active,OK Tue Jun 26 2012 18:23:15 GMT+0000 (GMT)
INFO Hanging up the incoming call. Tue Jun 26 2012 18:23:15 GMT+0000 (GMT)
INFO Received 'disconnecting' call event. Tue Jun 26 2012 18:23:15 GMT+0000 (GMT)
END LOG:

TEST-START test_incoming_reject.js
/data/jenkins/jobs/webapi-marionette-test/workspace/dom/telephony/test/marionette/test_incoming_reject.js, runTest (marionette_test.MarionetteJSTestCase) ... ERROR

======================================================================
ERROR: /data/jenkins/jobs/webapi-marionette-test/workspace/dom/telephony/test/marionette/test_incoming_reject.js, runTest (marionette_test.MarionetteJSTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette_test.py", line 176, in runTest
    results = self.marionette.execute_js_script(js, args)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 334, in execute_js_script
    newSandbox=new_sandbox)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 150, in _send_message
    self._handle_error(response)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 199, in _handle_error
    raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
ScriptTimeoutException: timed out

----------------------------------------------------------------------
Ran 1 test in 10.701s

FAILED (errors=1)
START LOG:
INFO Verifying initial state. Tue Jun 26 2012 18:23:24 GMT+0000 (GMT)
INFO Initial call list: OK Tue Jun 26 2012 18:23:24 GMT+0000 (GMT)
INFO Simulating an incoming call. Tue Jun 26 2012 18:23:24 GMT+0000 (GMT)
INFO Received 'incoming' call event. Tue Jun 26 2012 18:23:24 GMT+0000 (GMT)
INFO Call list is now: inbound from 5555552368 : incoming,OK Tue Jun 26 2012 18:23:24 GMT+0000 (GMT)
INFO Reject the incoming call. Tue Jun 26 2012 18:23:24 GMT+0000 (GMT)
INFO Received 'disconnecting' call event. Tue Jun 26 2012 18:23:25 GMT+0000 (GMT)
END LOG:

TEST-START test_outgoing_answer_hangup.js
/data/jenkins/jobs/webapi-marionette-test/workspace/dom/telephony/test/marionette/test_outgoing_answer_hangup.js, runTest (marionette_test.MarionetteJSTestCase) ... ERROR

======================================================================
ERROR: /data/jenkins/jobs/webapi-marionette-test/workspace/dom/telephony/test/marionette/test_outgoing_answer_hangup.js, runTest (marionette_test.MarionetteJSTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette_test.py", line 176, in runTest
    results = self.marionette.execute_js_script(js, args)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 334, in execute_js_script
    newSandbox=new_sandbox)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 150, in _send_message
    self._handle_error(response)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 199, in _handle_error
    raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
ScriptTimeoutException: timed out

----------------------------------------------------------------------
Ran 1 test in 10.680s

FAILED (errors=1)

START LOG:
INFO Verifying initial state. Tue Jun 26 2012 18:23:35 GMT+0000 (GMT)
INFO Initial call list: OK Tue Jun 26 2012 18:23:35 GMT+0000 (GMT)
INFO Make an outgoing call. Tue Jun 26 2012 18:23:35 GMT+0000 (GMT)
INFO Call list is now: OK Tue Jun 26 2012 18:23:35 GMT+0000 (GMT)
INFO Answering the outgoing call. Tue Jun 26 2012 18:23:35 GMT+0000 (GMT)
INFO Received 'connected' call event. Tue Jun 26 2012 18:23:35 GMT+0000 (GMT)
INFO Call list is now: outbound to  5555552368 : active,OK Tue Jun 26 2012 18:23:35 GMT+0000 (GMT)
INFO Hanging up the outgoing call. Tue Jun 26 2012 18:23:35 GMT+0000 (GMT)
END LOG:

TEST-START test_incoming_answer_hangup_oncallschanged.js
/data/jenkins/jobs/webapi-marionette-test/workspace/dom/telephony/test/marionette/test_incoming_answer_hangup_oncallschanged.js, runTest (marionette_test.MarionetteJSTestCase) ... ERROR

======================================================================
ERROR: /data/jenkins/jobs/webapi-marionette-test/workspace/dom/telephony/test/marionette/test_incoming_answer_hangup_oncallschanged.js, runTest (marionette_test.MarionetteJSTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette_test.py", line 176, in runTest
    results = self.marionette.execute_js_script(js, args)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 334, in execute_js_script
    newSandbox=new_sandbox)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 150, in _send_message
    self._handle_error(response)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 199, in _handle_error
    raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
ScriptTimeoutException: timed out

----------------------------------------------------------------------
Ran 1 test in 10.705s

FAILED (errors=1)

START LOG:
INFO Verifying initial state. Tue Jun 26 2012 18:23:46 GMT+0000 (GMT)
INFO Initial call list: OK Tue Jun 26 2012 18:23:46 GMT+0000 (GMT)
INFO Simulating an incoming call. Tue Jun 26 2012 18:23:46 GMT+0000 (GMT)
INFO Received 'callschanged' event. Tue Jun 26 2012 18:23:46 GMT+0000 (GMT)
INFO Received 'callschanged' event for an incoming call. Tue Jun 26 2012 18:23:46 GMT+0000 (GMT)
INFO Call list is now: inbound from 5555552368 : incoming,OK Tue Jun 26 2012 18:23:46 GMT+0000 (GMT)
INFO Answering the incoming call. Tue Jun 26 2012 18:23:46 GMT+0000 (GMT)
INFO Received 'connecting' call event. Tue Jun 26 2012 18:23:46 GMT+0000 (GMT)
INFO Received 'connected' call event. Tue Jun 26 2012 18:23:46 GMT+0000 (GMT)
INFO Call list is now: inbound from 5555552368 : active,OK Tue Jun 26 2012 18:23:46 GMT+0000 (GMT)
INFO Hanging up the incoming call. Tue Jun 26 2012 18:23:46 GMT+0000 (GMT)
INFO Received 'disconnecting' call event. Tue Jun 26 2012 18:23:46 GMT+0000 (GMT)
END LOG:

TEST-START test_outgoing_answer_hangup_oncallschanged.js
/data/jenkins/jobs/webapi-marionette-test/workspace/dom/telephony/test/marionette/test_outgoing_answer_hangup_oncallschanged.js, runTest (marionette_test.MarionetteJSTestCase) ... ERROR

======================================================================
ERROR: /data/jenkins/jobs/webapi-marionette-test/workspace/dom/telephony/test/marionette/test_outgoing_answer_hangup_oncallschanged.js, runTest (marionette_test.MarionetteJSTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette_test.py", line 176, in runTest
    results = self.marionette.execute_js_script(js, args)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 334, in execute_js_script
    newSandbox=new_sandbox)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 150, in _send_message
    self._handle_error(response)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 199, in _handle_error
    raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
ScriptTimeoutException: timed out

----------------------------------------------------------------------
Ran 1 test in 10.677s

FAILED (errors=1)


START LOG:
INFO Verifying initial state. Tue Jun 26 2012 18:23:56 GMT+0000 (GMT)
INFO Initial call list: OK Tue Jun 26 2012 18:23:56 GMT+0000 (GMT)
INFO Make an outgoing call. Tue Jun 26 2012 18:23:56 GMT+0000 (GMT)
INFO Received 'callschanged' call event. Tue Jun 26 2012 18:23:56 GMT+0000 (GMT)
INFO Call list is now: outbound to  5555552368 : unknown,OK Tue Jun 26 2012 18:23:56 GMT+0000 (GMT)
INFO Answering the outgoing call. Tue Jun 26 2012 18:23:56 GMT+0000 (GMT)
INFO Received 'connected' call event. Tue Jun 26 2012 18:23:57 GMT+0000 (GMT)
INFO Call list is now: outbound to  5555552368 : active,OK Tue Jun 26 2012 18:23:57 GMT+0000 (GMT)
INFO Hanging up the outgoing call. Tue Jun 26 2012 18:23:57 GMT+0000 (GMT)
END LOG:

TEST-START test_outgoing_reject.js
/data/jenkins/jobs/webapi-marionette-test/workspace/dom/telephony/test/marionette/test_outgoing_reject.js, runTest (marionette_test.MarionetteJSTestCase) ... ERROR

======================================================================
ERROR: /data/jenkins/jobs/webapi-marionette-test/workspace/dom/telephony/test/marionette/test_outgoing_reject.js, runTest (marionette_test.MarionetteJSTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette_test.py", line 176, in runTest
    results = self.marionette.execute_js_script(js, args)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 334, in execute_js_script
    newSandbox=new_sandbox)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 150, in _send_message
    self._handle_error(response)
  File "/data/jenkins/jobs/webapi-marionette-test/workspace/testing/marionette/client/marionette/marionette.py", line 199, in _handle_error
    raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
ScriptTimeoutException: timed out
18:24----------------------------------------------------------------------
Ran 1 test in 10.703s 

START LOG:
INFO Verifying initial state. Tue Jun 26 2012 18:24:07 GMT+0000 (GMT)
INFO Initial call list: OK Tue Jun 26 2012 18:24:07 GMT+0000 (GMT)
INFO Make an outgoing call. Tue Jun 26 2012 18:24:07 GMT+0000 (GMT)
INFO Call list is now: outbound to  5555552368 : unknown,OK Tue Jun 26 2012
Comment 1 Hsin-Yi Tsai [:hsinyi] 2012-07-03 00:30:40 PDT
I am thinking these failures result from 'REQUEST_LAST_CALL_FAIL_CAUSE' in 'ril_worker.js' which we use to change call state into 'disconnected'

Please see my previous explanation here:
https://bugzilla.mozilla.org/show_bug.cgi?id=761533#c5
Comment 2 Philipp von Weitershausen [:philikon] 2012-07-06 16:56:57 PDT
Regression from bug 761533. Hsinyi knows what to do, I'm sure. :)
Comment 3 Hsin-Yi Tsai [:hsinyi] 2012-07-12 02:55:01 PDT
Created attachment 641405 [details] [diff] [review]
Add AT+CEER in android_modem
Comment 4 Hsin-Yi Tsai [:hsinyi] 2012-07-12 02:56:09 PDT
Created attachment 641407 [details] [diff] [review]
Support RIL_REQUEST_LAST_CALL_FAIL_CAUSE in reference-ril.c
Comment 5 Hsin-Yi Tsai [:hsinyi] 2012-07-12 03:30:44 PDT
Created attachment 641418 [details] [diff] [review]
Part 1: Add AT+CEER in android_modem (v2)

Addressed coding-style nit.
Comment 6 Hsin-Yi Tsai [:hsinyi] 2012-07-12 03:32:00 PDT
Created attachment 641419 [details] [diff] [review]
Part 2: Support RIL_REQUEST_LAST_CALL_FAIL_CAUSE in reference-ril.c (v2)

Addressed coding-style nit.
Comment 7 Michael Wu [:mwu] 2012-07-12 15:10:30 PDT
Comment on attachment 641419 [details] [diff] [review]
Part 2: Support RIL_REQUEST_LAST_CALL_FAIL_CAUSE in reference-ril.c (v2)

Please make this a pull request against https://github.com/mozilla-b2g/platform_hardware_ril
Comment 8 Michael Wu [:mwu] 2012-07-12 15:12:39 PDT
(In reply to Hsin-Yi Tsai [:hsinyi] from comment #5)
> Created attachment 641418 [details] [diff] [review]
> Part 1: Add AT+CEER in android_modem (v2)
> 
> Addressed coding-style nit.

Where is this file? I can't find android_modem.c
Comment 9 Hsin-Yi Tsai [:hsinyi] 2012-07-12 19:01:16 PDT
(In reply to Michael Wu [:mwu] from comment #8)
> (In reply to Hsin-Yi Tsai [:hsinyi] from comment #5)
> > Created attachment 641418 [details] [diff] [review]
> > Part 1: Add AT+CEER in android_modem (v2)
> > 
> > Addressed coding-style nit.
> 
> Where is this file? I can't find android_modem.c

it's under B2G/external/qemu/telephony
Comment 10 Michael Wu [:mwu] 2012-07-12 19:22:28 PDT
Comment on attachment 641418 [details] [diff] [review]
Part 1: Add AT+CEER in android_modem (v2)

Please submit a pull request to https://github.com/mozilla-b2g/platform_external_qemu
Comment 11 Hsin-Yi Tsai [:hsinyi] 2012-07-12 19:36:33 PDT
(In reply to Michael Wu [:mwu] from comment #10)
> Comment on attachment 641418 [details] [diff] [review]
> Part 1: Add AT+CEER in android_modem (v2)
> 
> Please submit a pull request to
> https://github.com/mozilla-b2g/platform_external_qemu
Got it. Thanks.
Comment 12 Philipp von Weitershausen [:philikon] 2012-07-13 15:12:45 PDT
FWIW, fixing the emulated modem to support the necessary requests is agreat. Thank you, Hsinyi! However, I think we should still make Gecko resilient against these failures. If for whatever reason RIL_REQUEST_LAST_CALL_FAIL_CAUSE fails when a phone call ends, we should still make sure we dispatch the "disconnected" event always.
Comment 13 Hsin-Yi Tsai [:hsinyi] 2012-07-13 23:12:06 PDT
Created attachment 642179 [details] [diff] [review]
Change call state into disconnected even no response of call failure cause
Comment 14 Hsin-Yi Tsai [:hsinyi] 2012-07-13 23:14:17 PDT
Hi Philip, thanks for the comment and I addressed that in attachment 642179 [details] [diff] [review] in addition to the improvement I did in qemu.
Comment 16 Ed Morley [:emorley] 2012-07-18 05:52:48 PDT
https://hg.mozilla.org/mozilla-central/rev/df99b539896a

Note You need to log in before you can comment on or make changes to this bug.