Closed Bug 1038510 Opened 11 years ago Closed 10 years ago

Intermittent test_wifi_tethering_wifi_disabled.js | ScriptTimeoutException: ScriptTimeoutException: timed out | test_wifi_tethering_wifi_inactive.js | MarionetteException: MarionetteException: Emulator callback still pending when finish() called

Categories

(Firefox OS Graveyard :: Wifi, defect)

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

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME

People

(Reporter: KWierso, Assigned: hchang)

Details

(Keywords: intermittent-failure)

https://tbpl.mozilla.org/php/getParsedLog.php?id=43777220&tree=Mozilla-Inbound b2g_emulator_vm mozilla-inbound opt test marionette-webapi on 2014-07-14 14:43:18 PDT for push 8bfe7afa1996 slave: tst-linux64-spot-464 15:28:42 INFO - INFO TEST-START: /builds/slave/test/build/tests/marionette/tests/dom/wifi/test/marionette/test_wifi_auto_connect.js Mon Jul 14 2014 18:28:30 GMT-0400 (EDT) 15:28:42 INFO - INFO Already enabled Mon Jul 14 2014 18:28:31 GMT-0400 (EDT) 15:28:42 INFO - INFO unknown ssid: goldfish Mon Jul 14 2014 18:28:32 GMT-0400 (EDT) 15:28:42 INFO - INFO event.status: connecting Mon Jul 14 2014 18:28:34 GMT-0400 (EDT) 15:28:42 INFO - INFO event.network.ssid: goldfish Mon Jul 14 2014 18:28:34 GMT-0400 (EDT) 15:28:42 INFO - INFO Not expected "connected" statuschange event. Wait again! Mon Jul 14 2014 18:28:34 GMT-0400 (EDT) 15:28:42 INFO - INFO event.status: associated Mon Jul 14 2014 18:28:34 GMT-0400 (EDT) 15:28:42 INFO - INFO event.network.ssid: goldfish Mon Jul 14 2014 18:28:34 GMT-0400 (EDT) 15:28:42 INFO - INFO Not expected "connected" statuschange event. Wait again! Mon Jul 14 2014 18:28:34 GMT-0400 (EDT) 15:28:42 INFO - INFO event.status: connected Mon Jul 14 2014 18:28:35 GMT-0400 (EDT) 15:28:42 INFO - INFO event.network.ssid: goldfish Mon Jul 14 2014 18:28:35 GMT-0400 (EDT) 15:28:42 INFO - INFO event.status: connecting Mon Jul 14 2014 18:28:39 GMT-0400 (EDT) 15:28:42 INFO - INFO event.network.ssid: goldfish Mon Jul 14 2014 18:28:39 GMT-0400 (EDT) 15:28:42 INFO - INFO Not expected "connected" statuschange event. Wait again! Mon Jul 14 2014 18:28:39 GMT-0400 (EDT) 15:28:42 INFO - INFO event.status: associated Mon Jul 14 2014 18:28:40 GMT-0400 (EDT) 15:28:42 INFO - INFO event.network.ssid: goldfish Mon Jul 14 2014 18:28:40 GMT-0400 (EDT) 15:28:42 INFO - INFO Not expected "connected" statuschange event. Wait again! Mon Jul 14 2014 18:28:40 GMT-0400 (EDT) 15:28:42 INFO - INFO event.status: connected Mon Jul 14 2014 18:28:40 GMT-0400 (EDT) 15:28:42 INFO - INFO event.network.ssid: goldfish Mon Jul 14 2014 18:28:40 GMT-0400 (EDT) 15:28:42 INFO - INFO Already enabled Mon Jul 14 2014 18:28:40 GMT-0400 (EDT) 15:28:42 INFO - INFO Already enabled Mon Jul 14 2014 18:28:41 GMT-0400 (EDT) 15:28:42 INFO - INFO TEST-END: /builds/slave/test/build/tests/marionette/tests/dom/wifi/test/marionette/test_wifi_auto_connect.js Mon Jul 14 2014 18:28:41 GMT-0400 (EDT) 15:28:42 INFO - END LOG: 15:28:42 INFO - TEST-START | test_wifi_tethering_wifi_disabled.js 15:29:44 ERROR - TEST-UNEXPECTED-ERROR | test_wifi_tethering_wifi_disabled.js | ScriptTimeoutException: ScriptTimeoutException: timed out 15:29:44 INFO - Traceback (most recent call last): 15:29:44 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 171, in run 15:29:44 INFO - testMethod() 15:29:44 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 505, in runTest 15:29:44 INFO - filename=os.path.basename(self.jsFile)) 15:29:44 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 1040, in execute_js_script 15:29:44 INFO - line=None) 15:29:44 INFO - File "/builds/slave/test/build/tests/marionette/marionette/decorators.py", line 35, in _ 15:29:44 INFO - return func(*args, **kwargs) 15:29:44 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 614, in _send_message 15:29:44 INFO - self._handle_error(response) 15:29:44 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 676, in _handle_error 15:29:44 INFO - raise errors.ScriptTimeoutException(message=message, status=status, stacktrace=stacktrace) 15:29:44 INFO - TEST-INFO expected PASS | took 61685ms 15:29:45 INFO - START LOG: 15:29:45 INFO - INFO TEST-START: /builds/slave/test/build/tests/marionette/tests/dom/wifi/test/marionette/test_wifi_tethering_wifi_disabled.js Mon Jul 14 2014 18:28:43 GMT-0400 (EDT) 15:29:45 INFO - INFO verifyTetheringRouting rejected due to MASQUERADE not found while tethering is enabled (20) Mon Jul 14 2014 18:28:45 GMT-0400 (EDT) 15:29:45 INFO - INFO verifyTetheringRouting rejected due to MASQUERADE not found while tethering is enabled (19) Mon Jul 14 2014 18:28:46 GMT-0400 (EDT) 15:29:45 INFO - INFO verifyTetheringRouting rejected due to MASQUERADE not found while tethering is enabled (18) Mon Jul 14 2014 18:28:48 GMT-0400 (EDT) 15:29:45 INFO - END LOG: 15:29:46 INFO - TEST-START | test_wifi_tethering_wifi_inactive.js 15:29:51 ERROR - TEST-UNEXPECTED-ERROR | test_wifi_tethering_wifi_inactive.js | MarionetteException: MarionetteException: Emulator callback still pending when finish() called 15:29:51 INFO - Traceback (most recent call last): 15:29:51 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 171, in run 15:29:51 INFO - testMethod() 15:29:51 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 505, in runTest 15:29:51 INFO - filename=os.path.basename(self.jsFile)) 15:29:51 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 1040, in execute_js_script 15:29:51 INFO - line=None) 15:29:51 INFO - File "/builds/slave/test/build/tests/marionette/marionette/decorators.py", line 35, in _ 15:29:51 INFO - return func(*args, **kwargs) 15:29:51 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 614, in _send_message 15:29:51 INFO - self._handle_error(response) 15:29:51 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 688, in _handle_error 15:29:51 INFO - raise errors.MarionetteException(message=message, status=status, stacktrace=stacktrace) 15:29:51 INFO - TEST-INFO expected PASS | took 5355ms 15:29:52 INFO - START LOG: 15:29:52 INFO - INFO {"wlan0":{"src":"192.168.1.1","default":false},"eth0":{"src":"10.0.2.15","default":true},"rmnet0":{"src":"10.0.2.100","default":true}} Mon Jul 14 2014 18:29:44 GMT-0400 (EDT) 15:29:52 INFO - INFO {"lo":{"ip":"127.0.0.1"},"eth0":{"ip":"10.0.2.15"},"eth1":{"ip":"0.0.0.0"},"rmnet1":{"ip":"10.0.2.101"},"rmnet2":{"ip":"10.0.2.102"},"rmnet3":{"ip":"10.0.2.103"},"wlan0":{"ip":"192.168.1.1"},"sit0":{"ip":"0.0.0.0"},"rmnet0":{"ip":"10.0.2.100"}} Mon Jul 14 2014 18:29:44 GMT-0400 (EDT) 15:29:52 INFO - INFO verifyTetheringRouting rejected due to MASQUERADE found while tethering is disabled (20) Mon Jul 14 2014 18:29:44 GMT-0400 (EDT) 15:29:52 INFO - INFO TEST-START: /builds/slave/test/build/tests/marionette/tests/dom/wifi/test/marionette/test_wifi_tethering_wifi_inactive.js Mon Jul 14 2014 18:29:46 GMT-0400 (EDT) 15:29:52 INFO - END LOG: 15:29:52 INFO - TEST-START | test_wifi_tethering_wifi_active.js 15:30:18 INFO - TEST-PASS | test_wifi_tethering_wifi_active.js | took 25616ms 15:30:18 INFO - START LOG:
Assignee: nobody → hchang
It seems more and more frequent now...
The recent failures are due to the "MozWifiManager.enabled" check. Wifi is turned on at the beginning of the marionette test. However, MozWifiManager.enabled returns |false| when running the first wifi test case so that all the subsequent operation will fail.
Inactive; closing (see bug 1180138).
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.