Closed Bug 1023210 Opened 10 years ago Closed 10 years ago

Intermittent test_dsds_default_service_id.js | TimeoutException: TimeoutException: Connection 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

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: emorley, Unassigned)

References

Details

(Keywords: intermittent-failure)

Broken out from bug 974580: b2g_emulator_vm mozilla-central opt test marionette-webapi on 2014-06-10 04:51:25 PDT for push 9dc0ffca10f4 slave: tst-linux64-spot-850 https://tbpl.mozilla.org/php/getParsedLog.php?id=41438652&tree=Mozilla-Central { 05:20:38 INFO - TEST-START test_dsds_default_service_id.js 05:26:43 INFO - /builds/slave/test/build/tests/marionette/tests/dom/voicemail/test/marionette/test_dsds_default_service_id.js, runTest (marionette_test.MarionetteJSTestCase) ... ERROR 05:26:43 INFO - ====================================================================== 05:26:43 INFO - ERROR: None 05:26:43 INFO - ---------------------------------------------------------------------- 05:26:43 INFO - Traceback (most recent call last): 05:26:43 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 170, in run 05:26:43 INFO - testMethod() 05:26:43 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 486, in runTest 05:26:43 INFO - self.marionette.set_script_timeout(timeout) 05:26:43 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 800, in set_script_timeout 05:26:43 INFO - response = self._send_message('setScriptTimeout', 'ok', ms=timeout) 05:26:43 INFO - File "/builds/slave/test/build/tests/marionette/marionette/decorators.py", line 35, in _ 05:26:43 INFO - return func(*args, **kwargs) 05:26:43 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 627, in _send_message 05:26:43 INFO - "Connection timed out", status=ErrorCodes.TIMEOUT) 05:26:43 INFO - TimeoutException: TimeoutException: Connection timed out 05:26:43 INFO - Most recent errors/exceptions are: 05:26:43 INFO - 06-10 08:20:29.701 I/Gecko ( 44): TelephonyService: handleCallDisconnected: {"state":0,"callIndex":2,"toa":129,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"0912345002","numberPresentation":0,"name":null,"namePresentation":0,"uusInfo":null,"isOutgoing":true,"isEmergency":false,"isConference":false,"started":1402402829155,"failCause":"NormalCallClearingError"} 05:26:43 INFO - 06-10 08:20:32.712 I/Gecko ( 44): 1402402832716 Marionette INFO failed loading frame script due toTypeError: this is undefined 05:26:43 INFO - 06-10 08:20:37.172 I/Gecko ( 44): 1402402837179 Marionette INFO failed loading frame script due toTypeError: this is undefined 05:26:43 INFO - 06-10 08:20:37.542 E/GeckoConsole( 44): [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: "data:text/html,<html>test%20page</html>" line: 0}] 05:26:43 INFO - 06-10 08:20:40.702 I/Gecko ( 44): 1402402840706 Marionette INFO failed loading frame script due toTypeError: this is undefined 05:26:43 ERROR - TEST-UNEXPECTED-FAIL | test_dsds_default_service_id.js | TimeoutException: TimeoutException: Connection timed out }
Flags: needinfo?(htsai)
I've put this in my queue. Will keep you posted!
The root cause seems different from bug 974580. Per log, 7 checks in test_dsds_default_service_id.js are all passed before time out. ===== 05:45:18 INFO - 06-10 08:18:37.572 44 44 I Gecko : MARIONETTE LOG: INFO: TEST-START: /builds/slave/test/build/tests/marionette/tests/dom/telephony/test/marionette/test_dsds_default_service_id.js 05:45:18 INFO - 06-10 08:18:38.092 44 44 I Gecko : MARIONETTE LOG: INFO: TEST-END: /builds/slave/test/build/tests/marionette/tests/dom/telephony/test/marionette/test_dsds_default_service_id.js ===== The duration b/w test-start and test-end is less than 60s. However, I have no idea now how if something goes run in marionette client that spends much more time in the finish process. In the end, the test was reported running 363.284s. ===== 05:26:43 ERROR - TEST-UNEXPECTED-FAIL | test_dsds_default_service_id.js | TimeoutException: TimeoutException: Connection timed out 05:26:43 INFO - ---------------------------------------------------------------------- 05:26:43 INFO - Ran 1 test in 363.284s =====
Flags: needinfo?(htsai)
(In reply to Hsin-Yi Tsai [:hsinyi] from comment #2) > ===== > The duration b/w test-start and test-end is less than 60s. > > However, I have no idea now how if something > goes run in marionette client ^^^^ typo: goes wrong > that spends much more time in the finish process. In the end, the test was > reported running 363.284s. > ===== > 05:26:43 ERROR - TEST-UNEXPECTED-FAIL | test_dsds_default_service_id.js > | TimeoutException: TimeoutException: Connection timed out > 05:26:43 INFO - > ---------------------------------------------------------------------- > 05:26:43 INFO - Ran 1 test in 363.284s > =====
Hsinyi, The failed test case is in voicemail (dom/voicemail/test/marionette/test_dsds_default_service_id.js), not the one in telephony. We have the same test name in telephony, voicemail, mobilemessage, ...
(In reply to Szu-Yu Chen [:aknow] from comment #4) > Hsinyi, > > The failed test case is in voicemail > (dom/voicemail/test/marionette/test_dsds_default_service_id.js), > not the one in telephony. We have the same test name in telephony, > voicemail, mobilemessage, ... Oops... ... embarrassed... let me check it again, thank you XD
Just like what the error message says -- connection time out error. Seems marionette-server takes more than 5 min to accept the client connection. 05:45:22 INFO - 06-10 08:20:40.832 44 44 I Gecko : 1402402840837 Marionette DEBUG Got request: setTestName, data: {"to":"0","sessionId":{"rotatable":true,"browserVersion":"33.0a1","takesScreenshot":true,"appBuildId":"20140610040208","XULappId":"{3c2e2abc-06d4-11e1-ac3b-374f68613e61}","secureSsl":false,"platform":"ANDROID","browserName":"B2G","version":"33.0a1","device":"qemu","b2g":true,"nativeEvents":false,"platformVersion":"33.0a1","takesElementScreenshot":true,"platformName":"ANDROID","handlesAlerts":false},"name":"setTestName","parameters":{"value":"test_dsds_default_service_id.js"}}, id: {c96a5a8b-921b-4778-ac56-16a95d3cb7a2} 05:45:22 INFO - 06-10 08:26:45.612 44 44 I Gecko : 1402403205613 Marionette DEBUG accepted connection on 127.0.0.1:36540
Hi Jonathan, I tried to analyze the failure logs, and found that it took too long to have a socket connection being accepted on marionette-servcer. It doesn't look like to me a problem of a specific test case, but more then emulator networking issue. You might refer to comment 6 for log snippet. Do you have any idea? Thanks!
Flags: needinfo?(jgriffin)
Yes, I agree, this looks like a networking problem with the emulator. We're trying a few things to see if we can find workarounds, like bug 1023595.
Flags: needinfo?(jgriffin)
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.