1305659 - [e10s] Calling forward() and an remoteness change involved cause Marionette to hang with: IOError: Process has been unexpectedly closed (Exit code: -15) (Reason: [Errno 61] Connection refused)

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Attachment: test_minimized.py

I noticed that behavior while working on bug 1259055. When updating TestAboutPages.test_back_forward() with a call to forward() Marionette hangs until the socket timeout and gets killed:

 2:16.56 TEST_END: MainThread ERROR, expected PASS
Traceback (most recent call last):
  File "/Volumes/data/code/gecko/testing/marionette/harness/marionette/marionette_test/testcases.py", line 163, in run
    testMethod()
  File "/Volumes/data/code/gecko/_a/test_minimized.py", line 27, in test_back_forward_remote_non_remote
    self.marionette.navigate(self.remote_uri)
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/marionette.py", line 1488, in navigate
    self._send_message("get", {"url": url})
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/decorators.py", line 55, in _
    m.force_shutdown()
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/decorators.py", line 42, in _
    return func(*args, **kwargs)
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/marionette.py", line 682, in _send_message
    msg = self.client.request(name, params)
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/transport.py", line 274, in request
    self.send(cmd)
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/transport.py", line 236, in send
    self.connect()
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/transport.py", line 214, in connect
    self.sock.connect((self.addr, self.port))
  File "/usr/local/Cellar/python/2.7.12/Frameworks/Python.framework/Versions/2.7/lib/python2.7/socket.py", line 228, in meth
    return getattr(self._sock,name)(*args)
IOError: Process has been closed (Exit code: -15) (Reason: [Errno 61] Connection refused)

Here the last successful commands then the communication stopped working:

> 1474965609246	Marionette	TRACE	conn5 -> [0,9,"goForward",null]
> 1474965609363	Marionette	TRACE	conn5 <- [1,9,null,{}]
> 1474965609375	Marionette	TRACE	conn5 -> [0,10,"getCurrentUrl",null]

We never get a response with the current URI here.

This is an e10s only related issue.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Here the actual failure message:

  File "/Volumes/data/code/gecko/testing/marionette/harness/marionette/marionette_test/testcases.py", line 166, in run
    testMethod()
  File "/Volumes/data/code/gecko/_a/test_second.py", line 27, in test_back_forward_remote_non_remote
    self.marionette.navigate(self.remote_uri)
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/marionette.py", line 1624, in navigate
    self._send_message("get", {"url": url})
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/decorators.py", line 28, in _
    m.handle_socket_failure()
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/decorators.py", line 23, in _
    return func(*args, **kwargs)
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/marionette.py", line 707, in _send_message
    msg = self.client.request(name, params)
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/transport.py", line 283, in request
    self.send(cmd)
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/transport.py", line 245, in send
    self.connect()
  File "/Volumes/data/code/gecko/testing/marionette/client/marionette_driver/transport.py", line 223, in connect
    self.sock.connect((self.addr, self.port))
  File "/usr/local/Cellar/python/2.7.12_2/Frameworks/Python.framework/Versions/2.7/lib/python2.7/socket.py", line 228, in meth
    return getattr(self._sock,name)(*args)

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

So a debug build actually shows an assertion:

[Child 14272] ###!!! ASSERTION: no SHEntry for a non-transient viewer?: 'NS_IsAboutBlank(mCurrentURI)', file /builds/slave/m-cen-m64-d-000000000000000000/build/src/docshell/base/nsDocShell.cpp, line 11601

It means that somehow the communication dies for Marionette components and Firefox finally gets killed by the OS due to no data received over the socket. It also means that we are blocked on bug 1301399 now.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

The IOError is caused by Marionette as it kills Firefox after 60s with a socket timeout due to get() doesn't respond within that time period - the default page load timeout is 300s. See bug 1322277 for how we can improve that.

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+2]]

This most likely depends on bug 1330348.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

With my patch on bug 1330348 landed this is no longer an issue.