Closed Bug 1124966 Opened 11 years ago Closed 10 years ago

Intermittent Mn-e10s test_window_management.py TestSwitchWindow.testShouldLoadAWindowAndThenCloseIt | TimeoutException: TimeoutException: Connection timed out and a lot more after it

Categories

(Testing :: Marionette Client and Harness, defect)

Product:
Testing
Component:
Marionette Client and Harness
Platform:
All
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(e10s+)

Status:
RESOLVED WORKSFORME
Tracking Flags:
Tracking Status
e10s + ---

People

(Reporter: RyanVM, Unassigned)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, pi-marionette-intermittent)

14:02:59 INFO - TEST-START | test_window_management.py TestSwitchWindow.testShouldCauseAWindowToLoadAndCheckItIsOpenThenCloseIt 14:03:00 INFO - TEST-PASS | test_window_management.py TestSwitchWindow.testShouldCauseAWindowToLoadAndCheckItIsOpenThenCloseIt | took 1548ms 14:03:00 INFO - TEST-START | test_window_management.py TestSwitchWindow.testShouldLoadAWindowAndThenCloseIt 14:09:01 ERROR - TEST-UNEXPECTED-ERROR | test_window_management.py TestSwitchWindow.testShouldLoadAWindowAndThenCloseIt | TimeoutException: TimeoutException: Connection timed out 14:09:01 INFO - Traceback (most recent call last): 14:09:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 283, in run 14:09:01 INFO - testMethod() 14:09:01 INFO - File "/builds/slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_window_management.py", line 66, in testShouldLoadAWindowAndThenCloseIt 14:09:01 INFO - window_handles = self.marionette.window_handles 14:09:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 956, in window_handles 14:09:01 INFO - response = self._send_message("getWindowHandles", "value") 14:09:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/decorators.py", line 36, in _ 14:09:01 INFO - return func(*args, **kwargs) 14:09:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 615, in _send_message 14:09:01 INFO - "Connection timed out", status=errors.ErrorCodes.TIMEOUT) 14:09:01 INFO - TEST-INFO took 360870ms 14:09:01 INFO - test_end for test_window_management.py TestSwitchWindow.testShouldLoadAWindowAndThenCloseIt logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_window_management.TestSwitchWindow", "method_name": "testShouldLoadAWindowAndThenCloseIt"}, "expected": "PASS", "test": "test_window_management.py TestSwitchWindow.testShouldLoadAWindowAndThenCloseIt", "message": "MarionetteException: MarionetteException: this.curBrowser is null\nstacktrace:\n\tMDA_applyArgumentsToSandbox@chrome://marionette/content/marionette-server.js:808:7\n\tMDA_execute@chrome://marionette/content/marionette-server.js:935:1\n\tMSC_onPacket@chrome://marionette/content/marionette-server.js:209:9\n\tDebuggerTransport.prototype._onJSONObjectReady/<@resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/transport/transport.js:461:9\n\tmakeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:82:14\n\tmakeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:82:14", "stack": "Traceback (most recent call last):\n File \"/builds/slave/test/build/tests/marionette/marionette/marionette_test.py\", line 311, in run\n self.tearDown()\n File \"/builds/slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_window_management.py\", line 106, in tearDown\n self.close_new_window()\n File \"/builds/slave/test/build/tests/marionette/tests/testing/marionette/client/marionette/tests/unit/test_window_management.py\", line 31, in close_new_window\n \"\"\")\n File \"/builds/slave/test/build/tests/marionette/marionette/marionette.py\", line 1293, in execute_script\n filename=os.path.basename(frame[0]))\n File \"/builds/slave/test/build/tests/marionette/marionette/decorators.py\", line 36, in _\n return func(*args, **kwargs)\n File \"/builds/slave/test/build/tests/marionette/marionette/marionette.py\", line 634, in _send_message\n self._handle_error(response)\n File \"/builds/slave/test/build/tests/marionette/marionette/marionette.py\", line 717, in _handle_error\n raise errors.MarionetteException(message=message, status=status, stacktrace=stacktrace)\n"} 14:09:01 INFO - TEST-START | test_window_management.py TestSwitchWindow.test_windows 14:09:01 ERROR - TEST-UNEXPECTED-ERROR | test_window_management.py TestSwitchWindow.test_windows | MarionetteException: MarionetteException: Malformed packet, expected key 'error' to be a dict: {u'message': u'this.curBrowser is null', u'error': u"error occurred while processing 'executeScript"} 14:09:01 INFO - Traceback (most recent call last): 14:09:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 265, in run 14:09:01 INFO - self.setUp() 14:09:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 522, in setUp 14:09:01 INFO - CommonTestCase.setUp(self) 14:09:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette_test.py", line 394, in setUp 14:09:01 INFO - self.marionette.start_session() 14:09:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 824, in start_session 14:09:01 INFO - self.session = self._send_message('newSession', 'value', capabilities=desired_capabilities, session_id=session_id) 14:09:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/decorators.py", line 36, in _ 14:09:01 INFO - return func(*args, **kwargs) 14:09:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 634, in _send_message 14:09:01 INFO - self._handle_error(response) 14:09:01 INFO - File "/builds/slave/test/build/tests/marionette/marionette/marionette.py", line 663, in _handle_error 14:09:01 INFO - "Malformed packet, expected key 'error' to be a dict: %s" % response) 14:09:01 INFO - TEST-INFO took 17ms etc...
Flags: needinfo?(cmanchester)
Summary: Intermittent Mn-e10s est_window_management.py TestSwitchWindow.testShouldLoadAWindowAndThenCloseIt | TimeoutException: TimeoutException: Connection timed out and a lot more after it → Intermittent Mn-e10s test_window_management.py TestSwitchWindow.testShouldLoadAWindowAndThenCloseIt | TimeoutException: TimeoutException: Connection timed out and a lot more after it
I've pushed this to try with a great deal of logging turned on to see if anything obvious shakes out. I'll disable this test when e10s is enabled if it doesn't, and past that we may have to keep these hidden until there's time to properly look into this. Leaving ni set until I have more information.
Well, I can catch this on try with some re-triggers, but when it occurs, the error it complains about is "TypeError: e is undefined", in the catch block starting with "catch (e) { ..." in the marionette server's onPacket callback, which doesn't seem like a thing that can happen. When I re-throw the error, the devtools server comes back with "<failed trying to find error description>". We get window handles out of CPOWs, so guess it would be naive to think something crazy can't happen. I just pushed more logging to try to localize the issue, I'll disable the test later today if that doesn't yield something straightforward.
:jgraham noted on irc that in the case of "throw undefined;" this would happen, so it's not completely crazy, but I'm not really closer to figuring out the problem. Still waiting on re-triggers.
I was able to determine from the additional logging that we never make it past: 2.38 let winId = contentWindow.QueryInterface(Ci.nsIInterfaceRequestor) 2.39 .getInterface(Ci.nsIDOMWindowUtils) 2.40 .outerWindowID; Where "contentWindow" is a CPOW. :erahm reported something very similar today on irc that he's able to reproduce working on AWSY, I've asked him to push what he's working on so I can debug this further.
This is a blocker for e10s support on AWSY (it's 100% reproducible in our test suite).
The cause of this and bug 1125484 is bug 1125377. I think it will be more than a few days to come to an acceptable solution there, but probably not by a lot. Skipping this test would only paper over the issue, which appears to be possible whenever getWindowHandles is called and the browser is in a particular state.
Flags: needinfo?(cmanchester)
Comment 66 is from after bug 1125377, will investigate.
Flags: needinfo?(cmanchester)
Try confirmed this is failing in a similar fashion. Reopened bug 1125377.
Flags: needinfo?(cmanchester)
This has not been hit for over 2 months. Closing these bugs
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → WORKSFORME
Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in before you can comment on or make changes to this bug.