1997872 - --debugger=gdb reports "OSError: Process has been unexpectedly closed" error when running test_marionette.py :: TestMarionette.test_disable_enable_new_connections

Status: NEW

(Testing :: Marionette Client and Harness, defect, P3)

Description

[Edgar Chen [:edgar]]

Bug 1261180 tried to add --debugger supports for marionette test, but with --debugger=gdb, it can start Firefox process and start runing the test, but it also reports "OSError: Process has been unexpectedly closed" error.

[Socket 4595, Main Thread] WARNING: Shutting down Socket process early due to a crash!: file /home/edgar/Workspace/git/firefox/main/netwerk/ipc/SocketProcessChild.cpp:240
 0:38.55 TEST_END: ERROR, expected PASS - OSError: Process has been unexpectedly closed (Exit code: -9) (Reason: [Errno 111] Connection refused)
Traceback (most recent call last):
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/harness/marionette_harness/marionette_test/testcases.py", line 226, in run
    self.tearDown()
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/harness/marionette_harness/marionette_test/testcases.py", line 399, in tearDown
    self.marionette.start_session()
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/client/marionette_driver/decorators.py", line 34, in _
    m._handle_socket_failure()
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/client/marionette_driver/marionette.py", line 848, in _handle_socket_failure
    raise OSError(
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/client/marionette_driver/decorators.py", line 24, in _
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/client/marionette_driver/marionette.py", line 1358, in start_session
    self.protocol, _ = self.client.connect()
                       ^^^^^^^^^^^^^^^^^^^^^
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/client/marionette_driver/transport.py", line 286, in connect
    self._socket_context = SocketContext(
                           ^^^^^^^^^^^^^^
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/client/marionette_driver/transport.py", line 95, in __init__
    self._sock.connect((host, port))

Comment 1

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

Edgar, would you mind testing with the socketprocess:5 MOZ_LOG set? It might indicate some more details.

Comment 2

[Edgar Chen [:edgar]]

Attachment: log.txt

The crash seems happen while running TestMarionette.test_disable_enable_new_connections test.

The command I used for reproducing the crash:
MOZ_LOG=socketprocess:5 ./mach marionette-test --gecko-log=- -vv testing/marionette/harness/marionette_harness/tests/unit/test_marionette.py --debugger=gdb

Log:

 0:23.03 TEST_START: testing/marionette/harness/marionette_harness/tests/unit/test_marionette.py TestMarionette.test_disable_enable_new_connections
1762185636466   Marionette      DEBUG   Accepted connection 8 from 127.0.0.1:42018
1762185636467   Marionette      DEBUG   8 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
1762185636468   Marionette      DEBUG   Waiting for initial application window
1762185636469   RemoteAgent     TRACE   [4] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=40000 waitForExplicitStart=false
1762185636469   RemoteAgent     TRACE   [4] ProgressListener Setting unload timer (40000ms)
1762185636469   RemoteAgent     TRACE   [4] Wait for initial navigation: isInitial=false, isLoadingDocument=false
1762185636469   RemoteAgent     TRACE   [4] Document already finished loading: about:blank
1762185636470   RemoteAgent     TRACE   [4] ProgressListener Stop: has error=false url=about:blank
1762185636471   Marionette      DEBUG   8 <- [1,1,null,{"sessionId":"88a270b9-cf8e-413b-a33c-8349d86a5435","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"146.0a1","platformName":"linux","unhandledPromptBehavior":"dismiss and notify","userAgent":"Mozilla/5.0 (X11; Linux x86_64; rv:146.0) Gecko/20100101 Firefox/146.0","moz:buildID":"20251102231546","moz:headless":false,"moz:platformVersion":"6.8.0-86-generic","moz:processID":23178,"moz:profile":"/tmp/tmp1m_uk6k9.mozrunner","moz:shutdownTimeout":60000,"pageLoadStrategy":"normal","timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"setWindowRect":true,"strictFileInteractability":true,"moz:accessibilityChecks":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
1762185636473   Marionette      DEBUG   8 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
1762185636473   Marionette      DEBUG   8 <- [1,2,null,{"value":null}]
1762185636474   Marionette      DEBUG   8 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
1762185636474   Marionette      DEBUG   8 <- [1,3,null,{"value":null}]
1762185636475   Marionette      DEBUG   8 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
1762185636475   Marionette      DEBUG   8 <- [1,4,null,{"value":null}]
1762185636476   Marionette      DEBUG   8 -> [0,5,"Marionette:AcceptConnections",{"value":true}]
1762185636477   Marionette      DEBUG   8 <- [1,5,null,{"value":null}]
1762185636478   Marionette      DEBUG   8 -> [0,6,"Marionette:AcceptConnections",{"value":false}]
1762185636478   Marionette      INFO    Stopped listening on port 2828
1762185636478   Marionette      DEBUG   8 <- [1,6,null,{"value":null}]
1762185636480   Marionette      DEBUG   8 -> [0,7,"WebDriver:ExecuteScript",{"script":"return 1","args":[],"newSandbox":true,"sandbox":"default","line":73,"filename":"testing/marionette/harness/marionette_harness/tests/unit/test_marionette.py"}]
1762185636502   RemoteAgent     TRACE   WebDriverProcessData actor created for PID 23277
1762185636510   Marionette      TRACE   [4] MarionetteCommands actor created for window id 6442450945
1762185636536   Marionette      DEBUG   8 <- [1,7,null,{"value":1}]
1762185636538   Marionette      DEBUG   8 -> [0,8,"WebDriver:DeleteSession",{}]
1762185636539   Marionette      TRACE   [4] MarionetteCommands actor destroyed for window id 6442450945
1762185636542   Marionette      DEBUG   8 <- [1,8,null,{"value":null}]
1762185636545   Marionette      DEBUG   Closed connection 8
[Thread 0x7fff8e07d6c0 (LWP 23342) exited]
[New Thread 0x7fff8e07d6c0 (LWP 23443)]
[New Thread 0x7fff752696c0 (LWP 23444)]
 0:24.30 TEST_END: ERROR, expected PASS - OSError: Process has been unexpectedly closed (Exit code: -9) (Reason: [Errno 111] Connection refused)
Traceback (most recent call last):
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/harness/marionette_harness/marionette_test/testcases.py", line 226, in run
    self.tearDown()
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/harness/marionette_harness/marionette_test/testcases.py", line 399, in tearDown
    self.marionette.start_session()
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/client/marionette_driver/decorators.py", line 34, in _
    m._handle_socket_failure()
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/client/marionette_driver/marionette.py", line 848, in _handle_socket_failure
    raise OSError(
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/client/marionette_driver/decorators.py", line 24, in _
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/client/marionette_driver/marionette.py", line 1358, in start_session
    self.protocol, _ = self.client.connect()
                       ^^^^^^^^^^^^^^^^^^^^^
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/client/marionette_driver/transport.py", line 286, in connect
    self._socket_context = SocketContext(
                           ^^^^^^^^^^^^^^
  File "/home/edgar/Workspace/git/firefox/main/testing/marionette/client/marionette_driver/transport.py", line 95, in __init__
    self._sock.connect((host, port))

Comment 3

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

Hm, strange that MOZ_LOG=socketprocess:5 didn't produce any extra log output. Maybe I missed something to make it work.

But nevertheless Edgar, so it means you only see this behavior with the gdb debugger for this particular tests and for all the other tests it works as expected and you can step through? If yes, maybe you also could step through the Python test with pdb and check in which exact line this happens? Note that in line 86 we force closing the browser.

Comment 4

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

Hi Edgar, could you please check my last comment if you have the time for? It would be good if only this particular test is showing this issue for you. Thanks.

Comment 5

[Edgar Chen [:edgar]]

(In reply to Henrik Skupin [:whimboo][⌚️UTC+2] from comment #3)

But nevertheless Edgar, so it means you only see this behavior with the gdb debugger for this particular tests and for all the other tests it works as expected and you can step through?

It seems like it only happens on test_marionette.py, I tried to run other tests, like test_click.py, test_chrome.py and test_checkbox.py, they works good.

If yes, maybe you also could step through the Python test with pdb and check in which exact line this happens?

I don't have time to do that recently.

Comment 6

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

(In reply to Edgar Chen [:edgar] from comment #5)

It seems like it only happens on test_marionette.py, I tried to run other tests, like test_click.py, test_chrome.py and test_checkbox.py, they works good.

Thanks for confirming. So this is a less important bug then.

If yes, maybe you also could step through the Python test with pdb and check in which exact line this happens?

I don't have time to do that recently.

No problem. We most likely don't need it even at this point if it's only happening for this particular single test.