Frequent Marionette-webapi test_audiomanager_phonestate.js | ScriptTimeoutException: timed out

RESOLVED FIXED in Firefox 31

Status

defect
RESOLVED FIXED
5 years ago
4 years ago

People

(Reporter: RyanVM, Assigned: aknow)

Tracking

({intermittent-failure})

unspecified
2.0 S1 (9may)
ARM
Gonk (Firefox OS)
Dependency tree / graph

Firefox Tracking Flags

(firefox29 wontfix, firefox30 wontfix, firefox31 fixed, firefox32 fixed, firefox-esr24 unaffected, b2g-v1.2 unaffected, b2g-v1.3 wontfix, b2g-v1.3T wontfix, b2g-v1.4 fixed, b2g-v2.0 fixed)

Details

(Whiteboard: [p=1])

Attachments

(2 attachments)

Reporter

Description

5 years ago
Spun-off from bug 948895 where these failures have been occurring with high frequency for months now. Hopefully someone can look at it soon. Mnw is flirting with hidden status and the only other option is mass-disabling of timeout-prone tests.

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

b2g_emulator_vm b2g-inbound opt test marionette-webapi on 2014-04-30 13:17:34 PDT for push 24abc31223ae
slave: tst-linux64-spot-747

13:43:15     INFO -  INFO TEST-START: /builds/slave/test/build/tests/marionette/tests/dom/telephony/test/marionette/test_audiomanager_phonestate.js Wed Apr 30 2014 16:42:14 GMT-0400 (EDT)
13:43:15     INFO -  INFO == Test SetUp == Wed Apr 30 2014 16:42:14 GMT-0400 (EDT)
13:43:15     INFO -  INFO Clear existing calls. Wed Apr 30 2014 16:42:15 GMT-0400 (EDT)
13:43:15     INFO -  INFO Verify initial state. Wed Apr 30 2014 16:42:15 GMT-0400 (EDT)
13:43:15     INFO -  INFO == Test Start == Wed Apr 30 2014 16:42:15 GMT-0400 (EDT)
13:43:15     INFO -  INFO Simulating an incoming call. Wed Apr 30 2014 16:42:15 GMT-0400 (EDT)
13:43:15     INFO -  INFO Received 'incoming' call event. Wed Apr 30 2014 16:42:15 GMT-0400 (EDT)
13:43:15     INFO -  INFO Answering the incoming call. Wed Apr 30 2014 16:42:15 GMT-0400 (EDT)
13:43:15     INFO -  INFO Received 'connecting' call event for incoming call. Wed Apr 30 2014 16:42:15 GMT-0400 (EDT)
13:43:15     INFO -  INFO Received 'connected' call event for incoming call. Wed Apr 30 2014 16:42:16 GMT-0400 (EDT)
13:43:15     INFO -  INFO Remote hanging up the call. Wed Apr 30 2014 16:42:16 GMT-0400 (EDT)
13:43:15     INFO -  INFO Received 'disconnected' call event. Wed Apr 30 2014 16:42:16 GMT-0400 (EDT)
13:43:15     INFO -  INFO Make an outgoing call: 5555550101, serviceId: 0 Wed Apr 30 2014 16:42:16 GMT-0400 (EDT)
13:43:15     INFO -  INFO Received 'onalerting' call event. Wed Apr 30 2014 16:42:17 GMT-0400 (EDT)
13:43:15     INFO -  INFO Remote answering the call. Wed Apr 30 2014 16:42:17 GMT-0400 (EDT)
13:43:15     INFO -  INFO Received 'connected' call event. Wed Apr 30 2014 16:42:18 GMT-0400 (EDT)
13:43:15     INFO -  INFO Remote hanging up the call. Wed Apr 30 2014 16:42:18 GMT-0400 (EDT)
13:43:15     INFO -  INFO Received 'disconnected' call event. Wed Apr 30 2014 16:42:18 GMT-0400 (EDT)
13:43:15     INFO -  INFO Make an outgoing call: 5555550101, serviceId: 0 Wed Apr 30 2014 16:42:18 GMT-0400 (EDT)
13:43:15     INFO -  END LOG:
13:43:15     INFO -  ======================================================================
13:43:15     INFO -  ERROR: None
13:43:15     INFO -  ----------------------------------------------------------------------
13:43:15     INFO -  Traceback (most recent call last):
13:43:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 163, in run
13:43:15     INFO -      testMethod()
13:43:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 490, in runTest
13:43:15     INFO -      filename=os.path.basename(self.jsFile))
13:43:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 1050, in execute_js_script
13:43:15     INFO -      line=None)
13:43:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/decorators.py", line 35, in _
13:43:15     INFO -      return func(*args, **kwargs)
13:43:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 624, in _send_message
13:43:15     INFO -      self._handle_error(response)
13:43:15     INFO -    File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 683, in _handle_error
13:43:15    ERROR -      raise ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace)
13:43:15    ERROR -  ScriptTimeoutException: ScriptTimeoutException: timed out
13:43:15     INFO -  TEST-UNEXPECTED-FAIL | test_audiomanager_phonestate.js |
13:43:15     INFO -  ----------------------------------------------------------------------
13:43:15     INFO -  Ran 1 test in 61.689s
13:43:15  WARNING -  FAILED (errors=1)
Flags: needinfo?(vyang)
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)
Nothing special on my 4-cores i7 desktop as usual, but telephony test cases fails frequently on my MBP, which is a bit more slower.  I'm running some tests repeatedly and investigating what's wrong in telephony test cases.
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)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Line 25226, sends out yet another REQUEST_GET_CURRENT_CALLS request and its response returned in line 25253.  During the time the third group of tests [1] begins, and it sent a REQUEST_DIAL out.  Line 25254, as a result of ril_worker function _processCalls(), line 3868:

  if (pendingOutgoingCall) { // now it's true because we have a dialing call.
    if (!newCalls || Object.keys(newCalls).length === 0) {
      // |newCalls.length === 0| because this response was sent __before__
      // the dial request.
      this._removePendingOutgoingCall(GECKO_CALL_ERROR_UNSPECIFIED);

These lines are introduced in bug 990467.
[1]: http://mxr.mozilla.org/mozilla-central/source/dom/telephony/test/marionette/test_audiomanager_phonestate.js#84
Attachment #8416996 - Flags: feedback?(szchen)
Attachment #8416996 - Flags: feedback?(htsai)
Flags: needinfo?(vyang)
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)
Depends on: 1005816
(In reply to Vicamo Yang [:vicamo][:vyang] from comment #45)
> Created attachment 8416996 [details]
> failed__test_audiomanager_phonestate.zip
> 
> Line 25226, sends out yet another REQUEST_GET_CURRENT_CALLS request and its
> response returned in line 25253.  During the time the third group of tests
> [1] begins, and it sent a REQUEST_DIAL out.  Line 25254, as a result of
> ril_worker function _processCalls(), line 3868:
> 
>   if (pendingOutgoingCall) { // now it's true because we have a dialing call.
>     if (!newCalls || Object.keys(newCalls).length === 0) {
>       // |newCalls.length === 0| because this response was sent __before__
>       // the dial request.
>       this._removePendingOutgoingCall(GECKO_CALL_ERROR_UNSPECIFIED);
> 
> These lines are introduced in bug 990467.
> [1]:
> http://mxr.mozilla.org/mozilla-central/source/dom/telephony/test/marionette/
> test_audiomanager_phonestate.js#84

I already filed bug 1005816.
Attachment #8416996 - Flags: feedback?(htsai)
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)
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)
Attachment #8416996 - Flags: feedback?(szchen)
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

Updated

5 years ago
Assignee: nobody → szchen
The solution of the root cause will be land in bug 1005816. However, it's not a small change and need some effort. To avoid the test cases continually fails on try server before we finish that bug, we could have a workaround that adding a little delay prior to telephony.dial(). It could reduce the occurrence of racing condition.
Attachment #8418615 - Flags: review?(htsai)
Comment on attachment 8418615 [details] [diff] [review]
Delay telephony.dial for 1s in test cases

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

As Aknow's comment 104, we know it's a workaround. But let's stop the failure flooding first. Ship it.
Attachment #8418615 - Flags: review?(htsai) → review+
Comment hidden (Legacy TBPL/Treeherder Robot)
Assignee

Updated

5 years ago
Whiteboard: [p=1]
Target Milestone: --- → 2.0 S1 (9may)
Comment hidden (Legacy TBPL/Treeherder Robot)
Reporter

Updated

5 years ago
Keywords: checkin-needed
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)
https://hg.mozilla.org/mozilla-central/rev/ca470540691c
Status: NEW → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Comment hidden (Legacy TBPL/Treeherder Robot)
Reporter

Comment 119

5 years ago
Yeah, this didn't play nicely with the older B2G branches. Any chance I could get a patch for v1.3/v1.4? :)

https://tbpl.mozilla.org/php/getParsedLog.php?id=39295252&tree=Mozilla-B2g28-v1.3
Well... I forgot that we just change the interface, so the patch is incompatible with v1.3 and v1.4. However, right now, I can't think an easy way to have the same mechanism on those branches. Could I know the fail rate of this case on those branches? If it is not bad, maybe we don't need the patch.
Reporter

Comment 121

5 years ago
Seeing some failures on v1.4. I figured that v1.3 would probably come along for free if v1.4 was fixed.
ni myself to provide the patch
Flags: needinfo?(szchen)
Ryan,
After a quick check, I think the patch should be compatible with v1.4. Would you want to try it? Then I will try to provide the patch for 1.3 version later.
Reporter

Comment 124

5 years ago
Landed and stuck on 1.4 :)
https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/bfcacdadbef9

FWIW, I'm fine with just wontfixing this for 1.3. It's quickly on the way to becoming irrelevant anyway.
Reporter

Comment 125

5 years ago
And overall, Mnw is much greener since this patch landed. I guess that bolsters your theory about the underlying problem.
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)
You need to log in before you can comment on or make changes to this bug.