Closed Bug 1124966 Opened 9 years ago Closed 9 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: 9 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.