Closed Bug 1004152 Opened 11 years ago Closed 11 years ago

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

Categories

(Firefox OS Graveyard :: RIL, defect)

Product:
Firefox OS Graveyard
Component:
RIL
Platform:
ARM
Gonk (Firefox OS)
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(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)

Status:
RESOLVED FIXED
Milestone:
2.0 S1 (9may)
Tracking Flags:
Tracking Status
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

People

(Reporter: RyanVM, Assigned: aknow)

References

Details

(Keywords: intermittent-failure, Whiteboard: [p=1])

Attachments

(2 files)

failed__test_audiomanager_phonestate.zip
153.37 KB, application/zip
Details
Delay telephony.dial for 1s in test cases
2.10 KB, patch
hsinyi
: review+
Details | Diff | Splinter Review
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)
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.
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)
(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)
Attachment #8416996 - Flags: feedback?(szchen)
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+
Whiteboard: [p=1]
Target Milestone: --- → 2.0 S1 (9may)
Keywords: checkin-needed
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
status-b2g-v1.3: fixed → affected
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.
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.
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.
status-b2g-v1.3: affected → wontfix
status-b2g-v1.3T: --- → wontfix
status-b2g-v1.4: affected → fixed
Flags: needinfo?(szchen)
And overall, Mnw is much greener since this patch landed. I guess that bolsters your theory about the underlying problem.
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: