jaraco/irc

ResourceWarnings in test_reconnects_are_stable

jaraco opened this issue · 6 comments

jaraco commented 
irc/tests/test_bot.py::TestBot::test_reconnects_are_stable
  /Users/jaraco/code/jaraco/irc/irc/tests/test_bot.py:139: ResourceWarning: unclosed <socket.socket fd=12, family=2, type=1, proto=0, laddr=('127.0.0.1', 54781)>
    bot.reactor.process_once()
  Enable tracemalloc to get traceback where the object was allocated.
  See https://docs.pytest.org/en/stable/how-to/capture-warnings.html#resource-warnings for more info.

irc/tests/test_bot.py::TestBot::test_reconnects_are_stable
  /Users/jaraco/code/jaraco/irc/irc/tests/test_bot.py:139: ResourceWarning: unclosed <socket.socket fd=12, family=2, type=1, proto=0, laddr=('127.0.0.1', 54782)>
    bot.reactor.process_once()
  Enable tracemalloc to get traceback where the object was allocated.
  See https://docs.pytest.org/en/stable/how-to/capture-warnings.html#resource-warnings for more info.

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html

Here's the more info.

jaraco commented 
 irc main [5] 🐚 env PYTHONTRACEMALLOC=20 .tox/py/bin/pytest -p no:cov -p no:mypy -p no:ruff -k reconnects
=============================================================== test session starts ===============================================================
platform darwin -- Python 3.12.4, pytest-8.2.2, pluggy-1.5.0
rootdir: /Users/jaraco/code/jaraco/irc
configfile: pytest.ini
plugins: typeguard-4.3.0, checkdocs-2.13.0, enabler-3.1.1
collected 36 items / 35 deselected / 1 selected                                                                                                   

irc/tests/test_bot.py .                                                                                                                     [100%]

================================================================ warnings summary =================================================================
irc/tests/test_bot.py::TestBot::test_reconnects_are_stable
  /Users/jaraco/code/jaraco/irc/irc/tests/test_bot.py:139: ResourceWarning: unclosed <socket.socket fd=14, family=2, type=1, proto=0, laddr=('127.0.0.1', 64398)>
    bot.reactor.process_once()
  
  Object allocated at:
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_callers.py", line 103
      res = hook_impl.function(*args)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/main.py", line 364
      item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_hooks.py", line 513
      return self._hookexec(self.name, self._hookimpls.copy(), kwargs, firstresult)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_manager.py", line 120
      return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_callers.py", line 103
      res = hook_impl.function(*args)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/runner.py", line 116
      runtestprotocol(item, nextitem=nextitem)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/runner.py", line 135
      reports.append(call_and_report(item, "call", log))
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/runner.py", line 240
      call = CallInfo.from_call(
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/runner.py", line 341
      result: Optional[TResult] = func()
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/runner.py", line 241
      lambda: runtest_hook(item=item, **kwds), when=when, reraise=reraise
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_hooks.py", line 513
      return self._hookexec(self.name, self._hookimpls.copy(), kwargs, firstresult)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_manager.py", line 120
      return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_callers.py", line 103
      res = hook_impl.function(*args)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/runner.py", line 173
      item.runtest()
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/python.py", line 1632
      self.ihook.pytest_pyfunc_call(pyfuncitem=self)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_hooks.py", line 513
      return self._hookexec(self.name, self._hookimpls.copy(), kwargs, firstresult)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_manager.py", line 120
      return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_callers.py", line 103
      res = hook_impl.function(*args)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/python.py", line 162
      result = testfunction(**testargs)
    File "/Users/jaraco/code/jaraco/irc/irc/tests/test_bot.py", line 139
      bot.reactor.process_once()

irc/tests/test_bot.py::TestBot::test_reconnects_are_stable
  /Users/jaraco/code/jaraco/irc/irc/tests/test_bot.py:139: ResourceWarning: unclosed <socket.socket fd=14, family=2, type=1, proto=0, laddr=('127.0.0.1', 64399)>
    bot.reactor.process_once()
  
  Object allocated at:
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_callers.py", line 103
      res = hook_impl.function(*args)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/main.py", line 364
      item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_hooks.py", line 513
      return self._hookexec(self.name, self._hookimpls.copy(), kwargs, firstresult)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_manager.py", line 120
      return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_callers.py", line 103
      res = hook_impl.function(*args)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/runner.py", line 116
      runtestprotocol(item, nextitem=nextitem)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/runner.py", line 135
      reports.append(call_and_report(item, "call", log))
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/runner.py", line 240
      call = CallInfo.from_call(
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/runner.py", line 341
      result: Optional[TResult] = func()
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/runner.py", line 241
      lambda: runtest_hook(item=item, **kwds), when=when, reraise=reraise
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_hooks.py", line 513
      return self._hookexec(self.name, self._hookimpls.copy(), kwargs, firstresult)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_manager.py", line 120
      return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_callers.py", line 103
      res = hook_impl.function(*args)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/runner.py", line 173
      item.runtest()
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/python.py", line 1632
      self.ihook.pytest_pyfunc_call(pyfuncitem=self)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_hooks.py", line 513
      return self._hookexec(self.name, self._hookimpls.copy(), kwargs, firstresult)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_manager.py", line 120
      return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/pluggy/_callers.py", line 103
      res = hook_impl.function(*args)
    File "/Users/jaraco/code/jaraco/irc/.tox/py/lib/python3.12/site-packages/_pytest/python.py", line 162
      result = testfunction(**testargs)
    File "/Users/jaraco/code/jaraco/irc/irc/tests/test_bot.py", line 139
      bot.reactor.process_once()

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
================================================== 1 passed, 35 deselected, 2 warnings in 5.12s ===================================================
jaraco commented

I tried adding a disconnect at the end.

diff --git a/irc/tests/test_bot.py b/irc/tests/test_bot.py
index 213eca3..c91a897 100644
--- a/irc/tests/test_bot.py
+++ b/irc/tests/test_bot.py
@@ -139,6 +139,7 @@ class TestBot:
             bot.reactor.process_once()
             time.sleep(0.01)
         assert len(bot.reactor.scheduler.queue) <= 1
+        bot.disconnect()
 
 
 def test_version():

But that made matters worse:

=============================================================== test session starts ===============================================================
platform darwin -- Python 3.12.4, pytest-8.2.2, pluggy-1.5.0
rootdir: /Users/jaraco/code/jaraco/irc
configfile: pytest.ini
plugins: typeguard-4.3.0, checkdocs-2.13.0, enabler-3.1.1
collected 36 items / 35 deselected / 1 selected                                                                                                   

irc/tests/test_bot.py .                                                                                                                     [100%]

================================================================ warnings summary =================================================================
irc/tests/test_bot.py::TestBot::test_reconnects_are_stable
  /Users/jaraco/code/jaraco/irc/irc/tests/test_bot.py:139: ResourceWarning: unclosed <socket.socket fd=14, family=2, type=1, proto=0, laddr=('127.0.0.1', 64871)>
    bot.reactor.process_once()
  Enable tracemalloc to get traceback where the object was allocated.
  See https://docs.pytest.org/en/stable/how-to/capture-warnings.html#resource-warnings for more info.

irc/tests/test_bot.py::TestBot::test_reconnects_are_stable
  /Users/jaraco/code/jaraco/irc/irc/tests/test_bot.py:139: ResourceWarning: unclosed <socket.socket fd=14, family=2, type=1, proto=0, laddr=('127.0.0.1', 64872)>
    bot.reactor.process_once()
  Enable tracemalloc to get traceback where the object was allocated.
  See https://docs.pytest.org/en/stable/how-to/capture-warnings.html#resource-warnings for more info.

irc/tests/test_bot.py::TestBot::test_reconnects_are_stable
  /Users/jaraco/code/jaraco/irc/irc/client.py:542: ResourceWarning: unclosed <socket.socket fd=15, family=2, type=1, proto=0, laddr=('127.0.0.1', 64873)>
    del self.socket
  Enable tracemalloc to get traceback where the object was allocated.
  See https://docs.pytest.org/en/stable/how-to/capture-warnings.html#resource-warnings for more info.

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
================================================== 1 passed, 35 deselected, 3 warnings in 0.64s ===================================================
jaraco commented

I managed to get a bit more detail about what's happening by passing --log-cli-level 0.

------------------------------------------------------------------ live log call ------------------------------------------------------------------
DEBUG    irc.client:client.py:164 connect(server='127.0.0.1', port=50516, nickname='reconnect_test', ...)
DEBUG    irc.client:client.py:672 TO SERVER: NICK reconnect_test
DEBUG    irc.client:client.py:672 TO SERVER: USER reconnect_test 0 * :reconnect_test
Level 8  irc.client:client.py:888 process_once()
Level 8  irc.client:client.py:854 process_data()
DEBUG    irc.client:client.py:1218 _dispatcher: disconnect
Level 8  irc.client:client.py:888 process_once()
DEBUG    irc.client:client.py:164 connect(server='127.0.0.1', port=50516, nickname='reconnect_test', ...)
DEBUG    irc.client:client.py:672 TO SERVER: NICK reconnect_test
DEBUG    irc.client:client.py:672 TO SERVER: USER reconnect_test 0 * :reconnect_test
Level 8  irc.client:client.py:888 process_once()
Level 8  irc.client:client.py:854 process_data()
DEBUG    irc.client:client.py:1218 _dispatcher: disconnect
DEBUG    irc.client:client.py:164 connect(server='127.0.0.1', port=50516, nickname='reconnect_test', ...)
DEBUG    irc.client:client.py:672 TO SERVER: NICK reconnect_test
DEBUG    irc.client:client.py:672 TO SERVER: USER reconnect_test 0 * :reconnect_test
Level 8  irc.client:client.py:888 process_once()
Level 8  irc.client:client.py:854 process_data()
DEBUG    irc.client:client.py:1218 _dispatcher: disconnect
PASSED                                                                                                                                      [100%]
jaraco commented

I suspect the issue lies in the Client.disconnect method:

irc/irc/client.py

Lines 523 to 543 in 2f6ba71

def disconnect(self, message=""):
"""Hang up the connection.
Arguments:
message -- Quit message.
"""
try:
del self.connected
except AttributeError:
return
self.quit(message)
try:
self.socket.shutdown(socket.SHUT_WR)
self.socket.close()
except OSError:
pass
del self.socket
self._handle_event(Event("disconnect", self.server, "", [message]))

After learning a bit about the relationship between socket.shutdown and socket.close, I'm pretty sure the issue is that socket.close() never gets called when the peer disconnected because self.quit() fails or socket.shutdown fails.

Indeed, applying the following diff, there are no more resource warnings:

diff --git a/irc/client.py b/irc/client.py
index 4d269a9..52262f3 100644
--- a/irc/client.py
+++ b/irc/client.py
@@ -532,13 +532,15 @@ class ServerConnection(Connection):
         except AttributeError:
             return
 
-        self.quit(message)
+        # self.quit(message)
 
         try:
             self.socket.shutdown(socket.SHUT_WR)
-            self.socket.close()
         except OSError:
             pass
+
+        self.socket.close()
+
         del self.socket
         self._handle_event(Event("disconnect", self.server, "", [message]))
jaraco commented

Oof. The Connection.quit logic is tricky, because .quit will call .disconnect which calls .quit. The only thing that prevents that from becoming an infinite loop is the check for self.connected 😬 .

jaraco commented

Oh! I don't need to be concerned about Connection.quit for this issue. It didn't need to be commented out to address the warnings.