Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ResourceWarnings in test_reconnects_are_stable #224

Closed
jaraco opened this issue Mar 28, 2024 · 6 comments
Closed

ResourceWarnings in test_reconnects_are_stable #224

jaraco opened this issue Mar 28, 2024 · 6 comments

Comments

@jaraco
Copy link
Owner

jaraco commented Mar 28, 2024 •
edited
Loading 

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
Copy link
Owner Author

jaraco commented Jul 12, 2024 

 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
Copy link
Owner Author

jaraco commented Jul 12, 2024 •
edited
Loading

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
Copy link
Owner Author

jaraco commented Jul 12, 2024 •
edited
Loading

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
Copy link
Owner Author

jaraco commented Jul 12, 2024

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
Copy link
Owner Author

jaraco commented Jul 12, 2024

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
Copy link
Owner Author

jaraco commented Jul 12, 2024

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.

@jaraco jaraco closed this as completed in d93e50d Jul 12, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@jaraco