Skip to content

Keep the devmode logging bootstrap idempotent across re-execution - #391

Merged
JarryShaw merged 4 commits into
mainfrom
fix/devmode-handler-stacking
Sep 15, 2026
Merged

JarryShaw merged 4 commits into
mainfrom
fix/devmode-handler-stacking

Conversation

@JarryShaw

Copy link
Copy Markdown
Owner

Follow-up to #384, addressing the Copilot comment it merged with. The observation is correct and reproducible.

The defect

#384's devmode guard tested object identity:

if handler not in logger.handlers:
    logger.addHandler(handler)

But handler is constructed when the module runs. Re-executing the module — which the test suite does via load_module(), and which importlib.reload does — builds a new handler object, so the identity test is true on every pass and one stderr handler accumulates per reload.

Measured under PCAPKIT_DEVMODE=1:

stderr handlers
after import 1
after 2 reloads 3

The fix

Test for what would actually duplicate — a stream handler already writing to the same stream — rather than for the identity of one particular object. After the change: 1 handler however many times the module executes, with the devmode level still DEBUG.

Non-devmode is unaffected: one NullHandler whatever the reload count.

Verification

New test in LoggingImportTimeTests asserting exactly this, and it fails against the previous guard (assertEqual(streams(), 1) after the reload loop) and passes after. Full suite: 546 passed, 4 skipped, 369 subtests.

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.
@JarryShaw
JarryShaw requested a lite review from Copilot September 15, 2026 04:04

Copilot AI left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Warning

Copilot couldn't run its full agentic review because it didn't start before the timeout. Make sure your repository has a runner available, or add a copilot-code-review.yml file specifying one with the runs-on attribute. See the docs for more details.

Pull request overview

Makes the devmode logging bootstrap idempotent across module re-execution/reload, preventing multiple stderr StreamHandlers from accumulating.

Changes:

  • Add a regression test ensuring devmode re-execution does not stack stderr handlers and keeps DEBUG level.
  • Replace reload-unsafe handler identity membership check with a stream-target-based duplication guard.
  • Introduce a small helper to detect whether an installed handler writes to a given stream.

Reviewed changes

Copilot reviewed 2 out of 2 changed files in this pull request and generated 2 comments.

File Description
tests/utilities/test_logging.py Adds a regression test that reloads the logging module under devmode and asserts only one stderr stream handler is present.
pcapkit/utilities/logging.py Updates devmode handler guard to prevent duplication across reloads by checking stream destination rather than handler identity.

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

Comment thread tests/utilities/test_logging.py Outdated
Comment thread pcapkit/utilities/logging.py Outdated
@JarryShaw

Copy link
Copy Markdown
Owner Author

@copilot Fix the code for all comments in this review thread.

When a review comment includes a suggested change, apply the suggestion exactly.

Do not make changes beyond what is described in the linked review thread.

Copilot AI left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Warning

Copilot couldn't run its full agentic review because it didn't start before the timeout. Make sure your repository has a runner available, or add a copilot-code-review.yml file specifying one with the runs-on attribute. See the docs for more details.

Pull request overview

Copilot reviewed 2 out of 2 changed files in this pull request and generated 2 comments.

Comment thread tests/utilities/test_logging.py
Comment thread pcapkit/utilities/logging.py Outdated
@JarryShaw

Copy link
Copy Markdown
Owner Author

@copilot Fix the code for all comments in this review thread.

When a review comment includes a suggested change, apply the suggestion exactly.

Do not make changes beyond what is described in the linked review thread.

Co-authored-by: JarryShaw <15666417+JarryShaw@users.noreply.github.com>

Copilot AI commented Sep 15, 2026

Copy link
Copy Markdown
Contributor

@copilot Fix the code for all comments in this review thread.

When a review comment includes a suggested change, apply ...

Implemented the requested review-thread fixes in 353c3da: the devmode re-execution test now restores PCAPKIT_DEVMODE, logger handlers, and logger level via cleanup, and the long _writes_to return expression is wrapped for readability.

Copilot AI commented Sep 15, 2026

Copy link
Copy Markdown
Contributor

@copilot Fix the code for all comments in this review thread.

When a review comment includes a suggested change, apply ...

All comments from review thread 5205669645 are already addressed in 353c3da.

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.
@JarryShaw

Copy link
Copy Markdown
Owner Author

Kept the _writes_to line wrap from 353c3dafc, reverted the test cleanup in the same commit — with an apology to Copilot, because the reasoning looked right and the premise just wasn't.

The claim was that test_re_executing_the_module_under_devmode_does_not_stack_handlers leaks PCAPKIT_DEVMODE. It doesn't: LoggingImportTimeTests.setUp already saves the variable and tearDown restores it, then calls pristine() to strip the handlers and put the level and propagation back to the library-neutral state.

The second restore didn't just duplicate that, it fought it — unittest runs cleanups after tearDown:

setUp -> test -> tearDown -> cleanup-from-test -> cleanup-from-setUp

So root.handlers = old_handlers; root.setLevel(old_level) ran after pristine() had normalised the logger, reinstating this test's captured state instead. That inverts the invariant the fixture exists to hold — tearDown should be the last word on logger state, which matters here because every test in this file reloads pcapkit.utilities.logging and reads the handler list.

Checked instead of assumed. With a sentinel in the variable before the run:

Ran 31 tests ... OK
env before = sentinel-value | after = sentinel-value
logger level after = 0 (NOTSET)
handlers after = ['NullHandler']

Left a comment at the assignment saying who owns that state, so the next reader doesn't re-add it.

@JarryShaw
JarryShaw merged commit 0700f9d into main Sep 15, 2026
49 checks passed
@JarryShaw
JarryShaw deleted the fix/devmode-handler-stacking branch September 17, 2026 01:08
@JarryShaw JarryShaw added the fix Pull requests that fix a defect (fix: subject prefix) label Sep 22, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

fix Pull requests that fix a defect (fix: subject prefix)

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants