🐛 Avoid importing and calling close in __del__ during shutdown#7322
Conversation
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## main #7322 +/- ##
==========================================
+ Coverage 79.89% 79.92% +0.04%
==========================================
Files 568 568
Lines 43984 43988 +4
==========================================
+ Hits 35136 35153 +17
+ Misses 8848 8835 -13 ☔ View full report in Codecov by Sentry. 🚀 New features to boost your workflow:
|
|
Regarding codecov I am not sure how much sense it makes to test that a warning intended for developer is emitted. |
| warnings.warn(f'RabbitmqBroker was not closed explicitly: {self!r}', ResourceWarning, stacklevel=1) | ||
| self.close() | ||
| if not sys.is_finalizing(): | ||
| self.close() |
There was a problem hiding this comment.
If you are OCD about green checkmarks (like me), you can try adding:
| self.close() | |
| self.close() # pragma: no cover |
See https://coverage.readthedocs.io/en/latest/excluding.html
There was a problem hiding this comment.
I think I want to add a test for this line actually. When I come back on this PR I add a test and merge it.
There was a problem hiding this comment.
done added tests
|
Thanks @agoscinski! I will give this a spin now. |
Hmm, I am pretty sure the python logging module should still work during Python shutdown. (don't ask me how I know, but there are specific regression tests in cpython that ensure that logging calls work in |
|
Quick field test: |
It was something that we added to the stdlib logger in our logging system that did not make it work when I tried it out (maybe some font styling?). I can investigate it again when I am doing the logging overhaul, because it would be useful to log also these cases. Interestingly emitting a warning through the stdlib warning module also does not print a warning in this part of the code when it is finalizing, and it might be bug in CPython. It only happened because some other code holded a reference of something related to warnings. I attach the result with agent here (test_warn_bug.zip) but it looked like a rabbit hole I did not want to go into. |
061a74d to
675ddd5
Compare
| """Test ``__del__`` closes the backend when Python is not finalizing.""" | ||
|
|
||
| class DummyStorageBackend: | ||
| __del__ = StorageBackend.__del__ |
There was a problem hiding this comment.
Its really tricky to test this properly. Using a fixture will not work because pytest still has a reference to the object after deletion. Inheriting from StorageBackend is not trivial because we need to implement its interface which makes the test more complicated than necessary. I don't have a better idea than this.
There was a problem hiding this comment.
So we could do this instead, but I am not sure if this is better.
def test_del_closes_backend_when_not_finalizing(aiida_profile, monkeypatch):
"""Test `__del__` closes the backend when Python is not finalizing."""
backend = aiida_profile.storage_cls(aiida_profile)
session_factory = backend._session_factory
assert session_factory is not None
engine = session_factory.bind
assert engine is not None
original_dispose = engine.dispose
dispose = MagicMock(side_effect=original_dispose)
monkeypatch.setattr(engine, 'dispose', dispose)
with pytest.warns(ResourceWarning, match='StorageBackend was not closed explicitly'):
del backend
gc.collect()
dispose.assert_called_once_with()We cannot really test through the storage backend interface because we are deleting it. By mocking the underlying resource we basically only test if the close is invoked. So we can simplify the test to just as it is if close was invoked.
| def is_closed(self): | ||
| return self._state['closed'] | ||
|
|
||
| state = {'closed': False} |
There was a problem hiding this comment.
note that we need a bool in a dict because we need an object that we still can reference after the deletion
|
Okay added tests. I iterated a bit on them. They seem a bit dump but it is just impossible to test if an object is correctly closed if we delete the object without making the test also dependent on the implementation details of close, and I think these added tests should not depend on the implementation detail of close. |
|
OK,
|
a6a9b14 to
17e821a
Compare
Two related fixes to prevent 'Exception ignored in __del__' errors during Python shutdown: 1. Move 'import warnings' to module level in `RabbitmqBroker` and `StorageBackend` to avoid `ImportError` when `sys.meta_path` is `None` during shutdown. 2. Guard `__del__` with `sys.is_finalizing()` to skip the `close()` call during Python shutdown when asyncio/kiwipy event loop infrastructure is already torn down, preventing `AttributeError` in pytray's `await_` method. During shutdown: - `sys.meta_path` becomes `None`, making imports unavailable - Module globals are set to `None` before garbage collection - `asyncio.run_coroutine_threadsafe()` fails with `AttributeError` By deferring the import and skipping close during finalization, we avoid both issues since the process is exiting anyway. Fixes aiidateam#7309
|
Added feedback from review and merging. |
…am#7322) Mark all 11 existing per-logger options as advanced via `json_schema_extra`. Add `Option.advanced` property and `--advanced` flag to `verdi config list` with a footer hint. Update `verdi_loglevel` description to clarify it is a source-level filter only.
Add `logging.terminal_loglevel` and `logging.logfile_loglevel` to `ProfileOptionsSchema`. Wire `terminal_loglevel` as handler level on `console` and `cli` handlers. Replace hardcoded `DEBUG` in the daemon file handler with `logfile_loglevel`. Extend `CLI_LOG_LEVEL` to also override the `cli` handler level so `verdi --verbosity` still works.
…am#7322) Mark all 11 existing per-logger options as advanced via `json_schema_extra`. Add `Option.advanced` property and `--advanced` flag to `verdi config list` with a footer hint. Update `verdi_loglevel` description to clarify it is a source-level filter only.
Add `logging.terminal_loglevel` and `logging.logfile_loglevel` to `ProfileOptionsSchema`. Wire `terminal_loglevel` as handler level on `console` and `cli` handlers. Replace hardcoded `DEBUG` in the daemon file handler with `logfile_loglevel`. Extend `CLI_LOG_LEVEL` to also override the `cli` handler level so `verdi --verbosity` still works.
…m#7322 Mark all 11 existing per-logger options as advanced via `json_schema_extra`. Add `Option.advanced` property and `--advanced` flag to `verdi config list` with a footer hint. Update `verdi_loglevel` description to clarify it is a source-level filter only.
Add `logging.terminal_loglevel` and `logging.logfile_loglevel` to `ProfileOptionsSchema`. Wire `terminal_loglevel` as handler level on `console` and `cli` handlers. Replace hardcoded `DEBUG` in the daemon file handler with `logfile_loglevel`. Extend `CLI_LOG_LEVEL` to also override the `cli` handler level so `verdi --verbosity` still works.
…m#7322 Mark all 11 existing per-logger options as advanced via `json_schema_extra`. Add `Option.advanced` property and `--advanced` flag to `verdi config list` with a footer hint. Update `verdi_loglevel` description to clarify it is a source-level filter only.
Add `logging.terminal_loglevel` and `logging.logfile_loglevel` to `ProfileOptionsSchema`. Wire `terminal_loglevel` as handler level on `console` and `cli` handlers. Replace hardcoded `DEBUG` in the daemon file handler with `logfile_loglevel`. Extend `CLI_LOG_LEVEL` to also override the `cli` handler level so `verdi --verbosity` still works.
…m#7322 Mark all 11 existing per-logger options as advanced via `json_schema_extra`. Add `Option.advanced` property and `--advanced` flag to `verdi config list` with a footer hint. Update `verdi_loglevel` description to clarify it is a source-level filter only.
Add `logging.terminal_loglevel` and `logging.logfile_loglevel` to `ProfileOptionsSchema`. Wire `terminal_loglevel` as handler level on `console` and `cli` handlers. Replace hardcoded `DEBUG` in the daemon file handler with `logfile_loglevel`. Extend `CLI_LOG_LEVEL` to also override the `cli` handler level so `verdi --verbosity` still works.
…am#7322) Mark all 11 existing per-logger options as advanced via `json_schema_extra`. Add `Option.advanced` property and `--advanced` flag to `verdi config list` with a footer hint. Update `verdi_loglevel` description to clarify it is a source-level filter only.
Add `logging.terminal_loglevel` and `logging.logfile_loglevel` to `ProfileOptionsSchema`. Wire `terminal_loglevel` as handler level on `console` and `cli` handlers. Replace hardcoded `DEBUG` in the daemon file handler with `logfile_loglevel`. Extend `CLI_LOG_LEVEL` to also override the `cli` handler level so `verdi --verbosity` still works.
…m#7322 Mark all 11 existing per-logger options as advanced via `json_schema_extra`. Add `Option.advanced` property and `--advanced` flag to `verdi config list` with a footer hint. Update `verdi_loglevel` description to clarify it is a source-level filter only.
Add `logging.terminal_loglevel` and `logging.logfile_loglevel` to `ProfileOptionsSchema`. Wire `terminal_loglevel` as handler level on `console` and `cli` handlers. Replace hardcoded `DEBUG` in the daemon file handler with `logfile_loglevel`. Extend `CLI_LOG_LEVEL` to also override the `cli` handler level so `verdi --verbosity` still works.
Two related fixes to prevent 'Exception ignored in del' errors during Python shutdown:
Move 'import warnings' to module level in
RabbitmqBrokerandStorageBackendto avoidImportErrorwhensys.meta_pathisNoneduring shutdown.Guard
__del__withsys.is_finalizing()to skip theclose()call during Python shutdown when asyncio/kiwipy event loop infrastructure is already torn down, preventingAttributeErrorin pytray'sawait_method.During shutdown:
sys.meta_pathbecomesNone, making imports unavailableNonebefore garbage collectionasyncio.run_coroutine_threadsafe()fails withAttributeErrorBy deferring the import and skipping close during finalization, we avoid both issues since the process is exiting anyway.
Fixes #7309
Further changes in the future
When doing the overhaul of the logging system in #7323 I will change the warning to using the logger system so it is properly tracked. ResourceWarnings are only shown when a certain env is on or python is run in developer mode. Both is not really useful for us. The logger system only works however when not finalizing. So we cannot track places where resources were not close during a python shutdown, which is fine.