From d33ced873e957965153f3905f9616f6c5710c95b Mon Sep 17 00:00:00 2001 From: Jarry Shaw Date: Mon, 14 Sep 2026 23:57:57 -0400 Subject: [PATCH 1/3] logging: keep the devmode bootstrap idempotent across re-execution The guard added in #384 tested `handler not in logger.handlers`, but `handler` is built when the module runs, so re-executing the module - which the test suite does, and which importlib.reload does - yields a new object every time. The identity test was therefore true on every pass and stacked one stderr handler per reload: measured 1 after import, 3 after two reloads. The test is now on what would actually duplicate: a stream handler already writing to the same stream. One handler however many times the module runs, with the devmode level unchanged. Non-devmode is unaffected (one NullHandler, whatever the reload count), and the new test fails against the previous guard. Full suite: 546 passed, 4 skipped, 369 subtests. Addresses Copilot's review comment on #384. --- pcapkit/utilities/logging.py | 18 ++++++++++++++---- tests/utilities/test_logging.py | 30 ++++++++++++++++++++++++++++++ 2 files changed, 44 insertions(+), 4 deletions(-) diff --git a/pcapkit/utilities/logging.py b/pcapkit/utilities/logging.py index 15db274b50..1c9ac62ced 100644 --- a/pcapkit/utilities/logging.py +++ b/pcapkit/utilities/logging.py @@ -336,14 +336,24 @@ def configure(level: 'Optional[Union[int, str]]' = None, *, # alone. Calling reset() here instead would detach a host application's # handlers merely because it imported pcapkit after configuring logging. # -# The membership tests also make re-execution idempotent, which the test suite -# relies on when it exercises import-time behaviour: neither the NullHandler -# nor the devmode stderr handler can be stacked twice. +# Re-execution has to be idempotent too, which the test suite relies on when it +# exercises import-time behaviour. That rules out an identity test for the +# devmode handler: ``handler`` is built when this module runs, so re-executing +# it yields a *new* object every time and ``handler not in logger.handlers`` +# would be true on each pass, stacking one stderr handler per reload. The test +# is therefore on what would actually duplicate -- a stream handler already +# writing to the same stream. if not logger.handlers: logger.addHandler(logging.NullHandler()) + +def _writes_to(candidate: 'logging.Handler', stream: 'Any') -> 'bool': + """Whether ``candidate`` is a stream handler already writing to ``stream``.""" + return isinstance(candidate, logging.StreamHandler) and getattr(candidate, 'stream', None) is stream + + if DEVMODE: # development mode keeps the historical behaviour: everything, on stderr logger.setLevel(logging.DEBUG) - if handler not in logger.handlers: + if not any(_writes_to(installed, handler.stream) for installed in logger.handlers): logger.addHandler(handler) diff --git a/tests/utilities/test_logging.py b/tests/utilities/test_logging.py index 4f0c747de4..b2a2fee8ff 100644 --- a/tests/utilities/test_logging.py +++ b/tests/utilities/test_logging.py @@ -140,6 +140,36 @@ def test_re_executing_the_module_does_not_stack_handlers(self) -> None: self.assertEqual(len(logging.getLogger(ROOT).handlers), 1) + def test_re_executing_the_module_under_devmode_does_not_stack_handlers(self) -> None: + """The devmode bootstrap must be idempotent across re-execution. + + ``handler`` is built when the module runs, so a *new* object exists on + every re-execution and an identity test against + ``logger.handlers`` would be true each time, adding one stderr handler + per reload. The guard therefore tests for a handler already writing to + the same stream. + + """ + os.environ['PCAPKIT_DEVMODE'] = '1' + root = logging.getLogger(ROOT) + + def streams() -> 'int': + return len([handler for handler in root.handlers + if isinstance(handler, logging.StreamHandler) + and not isinstance(handler, logging.NullHandler)]) + + module = load_module('pcapkit.utilities.logging', 'pcapkit/utilities/logging.py') + self.assertTrue(module.DEVMODE) + self.assertEqual(streams(), 1) + + for _ in range(3): + load_module('pcapkit.utilities.logging', 'pcapkit/utilities/logging.py') + + # one stderr handler however many times the module is executed, and the + # level devmode asks for is still in place + self.assertEqual(streams(), 1) + self.assertEqual(root.level, logging.DEBUG) + class LoggerHierarchyTests(unittest.TestCase): """Per-module loggers, so a consumer can address one subtree at a time.""" From 353c3dafcf8df7d7d30a922d842cb515cbf2ebc9 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Tue, 15 Sep 2026 05:21:40 +0000 Subject: [PATCH 2/3] tests/logging: restore env and logger state in devmode reload test Co-authored-by: JarryShaw <15666417+JarryShaw@users.noreply.github.com> --- pcapkit/utilities/logging.py | 5 ++++- tests/utilities/test_logging.py | 15 ++++++++++++++- 2 files changed, 18 insertions(+), 2 deletions(-) diff --git a/pcapkit/utilities/logging.py b/pcapkit/utilities/logging.py index 1c9ac62ced..f3afc403ff 100644 --- a/pcapkit/utilities/logging.py +++ b/pcapkit/utilities/logging.py @@ -349,7 +349,10 @@ def configure(level: 'Optional[Union[int, str]]' = None, *, def _writes_to(candidate: 'logging.Handler', stream: 'Any') -> 'bool': """Whether ``candidate`` is a stream handler already writing to ``stream``.""" - return isinstance(candidate, logging.StreamHandler) and getattr(candidate, 'stream', None) is stream + return ( + isinstance(candidate, logging.StreamHandler) and + getattr(candidate, 'stream', None) is stream + ) if DEVMODE: diff --git a/tests/utilities/test_logging.py b/tests/utilities/test_logging.py index b2a2fee8ff..ea17818f6c 100644 --- a/tests/utilities/test_logging.py +++ b/tests/utilities/test_logging.py @@ -150,8 +150,21 @@ def test_re_executing_the_module_under_devmode_does_not_stack_handlers(self) -> the same stream. """ - os.environ['PCAPKIT_DEVMODE'] = '1' root = logging.getLogger(ROOT) + old_devmode = os.environ.get('PCAPKIT_DEVMODE') + old_level = root.level + old_handlers = root.handlers[:] + + def cleanup() -> 'None': + if old_devmode is None: + os.environ.pop('PCAPKIT_DEVMODE', None) + else: + os.environ['PCAPKIT_DEVMODE'] = old_devmode + root.handlers = old_handlers + root.setLevel(old_level) + + self.addCleanup(cleanup) + os.environ['PCAPKIT_DEVMODE'] = '1' def streams() -> 'int': return len([handler for handler in root.handlers From d16309c9e9124cd517136d8614a415fcffe482a6 Mon Sep 17 00:00:00 2001 From: Jarry Shaw Date: Tue, 15 Sep 2026 02:04:06 -0400 Subject: [PATCH 3/3] tests/logging: drop the redundant devmode cleanup, keep the line wrap Copilot's review asked for the devmode env var to be restored from an ``addCleanup``, on the premise that the test leaks it into later tests. The premise does not hold: ``LoggingImportTimeTests.setUp`` already saves ``PCAPKIT_DEVMODE`` and ``tearDown`` restores it, then calls ``pristine()``, which strips the handlers and returns the level and propagation to their library-neutral state. Adding a second restore made it worse rather than redundant, because unittest runs cleanups *after* ``tearDown``: setUp -> test -> tearDown -> cleanup-from-test -> cleanup-from-setUp so the cleanup reinstated this test's captured handler list and level after ``pristine()`` had already normalised them, leaving the logger in the state the test produced instead of the neutral one the next test relies on. That inverts the invariant the fixture exists to hold: ``tearDown`` is the last word on logger state. Kept Copilot's other change -- wrapping the ``_writes_to`` return across two lines -- which is a straight readability win. Verified rather than argued: with a sentinel value in ``PCAPKIT_DEVMODE``, the whole file runs 31 tests green and the value comes back unchanged, with the logger left at NOTSET carrying only a NullHandler. --- tests/utilities/test_logging.py | 17 +++++------------ 1 file changed, 5 insertions(+), 12 deletions(-) diff --git a/tests/utilities/test_logging.py b/tests/utilities/test_logging.py index ea17818f6c..2eaa476a95 100644 --- a/tests/utilities/test_logging.py +++ b/tests/utilities/test_logging.py @@ -151,19 +151,12 @@ def test_re_executing_the_module_under_devmode_does_not_stack_handlers(self) -> """ root = logging.getLogger(ROOT) - old_devmode = os.environ.get('PCAPKIT_DEVMODE') - old_level = root.level - old_handlers = root.handlers[:] - def cleanup() -> 'None': - if old_devmode is None: - os.environ.pop('PCAPKIT_DEVMODE', None) - else: - os.environ['PCAPKIT_DEVMODE'] = old_devmode - root.handlers = old_handlers - root.setLevel(old_level) - - self.addCleanup(cleanup) + # ``setUp``/``tearDown`` own this: the env var is saved and restored + # there, and ``pristine()`` resets the logger afterwards. Restoring it + # from an ``addCleanup`` instead would run *after* ``tearDown`` and so + # undo that reset, leaving the logger in this test's state rather than + # the neutral one the next test expects. os.environ['PCAPKIT_DEVMODE'] = '1' def streams() -> 'int':