Skip to content

Configure the fwl logger at CLI entry points (#708)#776

Draft
egpbos wants to merge 5 commits into
mainfrom
fix/708-configure-logger-at-cli-entrypoints
Draft

Configure the fwl logger at CLI entry points (#708)#776
egpbos wants to merge 5 commits into
mainfrom
fix/708-configure-logger-at-cli-entrypoints

Conversation

@egpbos

@egpbos egpbos commented Jul 23, 2026

Copy link
Copy Markdown
Member

Description

The fwl logger only received handlers inside Proteus.start() and a few CLI commands, but records are emitted earlier: Proteus.__init__ calls set_directories(), which logs at INFO, and the grid-summarise / grid-pack commands never configure logging at all. With no handler on fwl, those records fall through to logging.lastResort, which emits only WARNING and above, so INFO/DEBUG output was silently lost.

This adds bootstrap_logger(), which attaches a stdout handler to fwl only when it has none, and calls it from the top-level CLI group callback so every subcommand has console logging active before it runs. It is idempotent and non-destructive: setup_logger() still clears handlers and installs the file-backed logger once the output directory is known, so there is no duplicate output and file logging is unchanged.

Closes #708

Two loggers, two purposes (note for reviewers)

bootstrap_logger is deliberately not a replacement for setup_logger; they play complementary roles:

  • bootstrap_logger: the lightweight, non-destructive fallback installed at CLI entry. Its job is to guarantee there is at least something catching console output before a command knows its output directory. It no-ops if a handler already exists and never opens a logfile, so it cannot clobber a real configuration.
  • setup_logger: the authoritative configuration, used once the output directory is known, both from the CLI and from the Python API. It clears handlers, installs the file-backed logger, and sets the exception hook.

setup_logger cannot simply be called at CLI entry in place of bootstrap_logger because it unconditionally opens a FileHandler at a path that is not known until the config is parsed inside the subcommand. The shared console-handler and level-validation code is factored into two private helpers (_resolve_level, _console_handler) so the two entry points stay consistent without duplication.

Grid manager logging: merged into the shared setup_logger (input wanted)

Harrison, Tim: while wiring bootstrap_logger in, I found that proteus grid doubled every log line, and I would like your read on the fix.

Root cause: grid/manage.py had its own local setup_logger that configured the root logger, whereas bootstrap_logger and the main setup_logger configure the fwl logger. Once bootstrap_logger installs a handler on fwl at CLI entry, a grid log record (emitted on fwl.proteus.grid.manage) was handled by the fwl handler and propagated up to the root handler the grid installed, so it printed twice. Measured: 1 line before this PR, 2 lines with bootstrap_logger and the old grid function.

Fix in this PR: point the grid manager at the shared proteus.utils.logs.setup_logger and delete the local copy. Because the shared function clears the fwl handlers before installing its own, the bootstrap console handler is replaced rather than stacked, so grid logs print exactly once again (verified).

The old grid function differed from the shared one in three ways. Two are now preserved, one is a genuine behaviour change I want you to sanity-check:

  • Log format (preserved): the grid logfile used a plain, timestamped, colourless layout [%(asctime)s] %(message)s. I added an optional fmt / datefmt to setup_logger and the grid passes that exact format, so manager.log is byte-for-byte the same style as before. This one looked intentional to me (clean, timestamped logs are useful), which is why I kept it rather than dropping it.
  • Level API (preserved in effect): the local function took an int level (1 -> INFO via a match); the shared one takes the string names used everywhere else. The only call site passed 1, now level='INFO'.
  • Target logger (changed): the local function configured the root logger, so manager.log also captured records from non-fwl (third-party) loggers. The shared function configures fwl only. Configuring fwl is what removes the double-logging and matches the rest of PROTEUS, but it does narrow what manager.log captures.

Question: were these divergences (root logger, int levels, the timestamped format) intended design choices, or incidental historical drift from before the fwl convention settled? In particular, does the grid rely on manager.log capturing root-level / third-party logs, or is narrowing to fwl fine? If capturing root is wanted, I will keep it on fwl for de-duplication but can widen capture another way.

Validation of changes

  • tests/utils/test_logs.py (49 tests) and tests/grid/test_manage.py (44 tests): all pass locally. The logs file adds 6 tests for bootstrap_logger and 2 for the new fmt / datefmt path; the grid file drops the tests for the removed local setup_logger.
  • The bootstrap_logger tests use an autouse fixture that snapshots and restores the shared fwl singleton so logger state does not leak between tests.
  • Behaviour verified directly: bootstrap_logger then setup_logger yields exactly one stdout handler (no duplicate); a grid-style bootstrap_logger + setup_logger(fmt=...) sequence prints a grid record once (the double-logging fix) in the preserved timestamped format.
  • ruff check and ruff format --check pass on src/ and tests/ (ruff 0.15.22).
  • Not run to completion: the @pytest.mark.slow tests/grid/test_grid.py. Its test_grid_pack fails on a missing per-case runtime_helpfile.csv, which is produced by the proteus start subprocess and is unavailable in this environment; it is unrelated to logging (the manager.log assertions in the same test pass, and manager.log has the correct timestamped format). This tier runs nightly, not in the PR checks.

Test configuration: macOS; PROTEUS conda environment (Python 3.12, the supported version).

Checklist

  • I have followed the contributing guidelines
  • My code follows the style guidelines of this project
  • I have performed a self-review of my code
  • My changes generate no new warnings or errors
  • I have checked that the tests still pass on my computer
  • I have updated the docs, as appropriate
  • I have added tests for these changes, as appropriate
  • I have checked that all dependencies have been updated, as required

The 'fwl' logger was only given handlers inside Proteus.start() (and a few
CLI commands), but records are emitted earlier: Proteus.__init__ calls
set_directories(), which logs at INFO, and the grid-summarise / grid-pack
commands never configure logging at all. With no handler on 'fwl', those
records fall through to logging.lastResort, which emits only WARNING and
above, so INFO/DEBUG output was silently lost.

Add bootstrap_logger(), which attaches a stdout handler to 'fwl' only when it
has none, and call it from the top-level CLI group callback so every
subcommand has console logging active before it runs. It is idempotent and
non-destructive: setup_logger() still clears handlers and installs the
file-backed logger once the output directory is known, so there is no
duplicate output and file logging is unchanged.

Refs #708
@codecov

codecov Bot commented Jul 23, 2026

Copy link
Copy Markdown

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 92.60%. Comparing base (9881061) to head (f5ecbe4).
⚠️ Report is 1 commits behind head on main.

Additional details and impacted files
@@            Coverage Diff             @@
##             main     #776      +/-   ##
==========================================
- Coverage   92.66%   92.60%   -0.07%     
==========================================
  Files         110      110              
  Lines       15807    16006     +199     
  Branches     2846     2906      +60     
==========================================
+ Hits        14648    14822     +174     
- Misses       1159     1170      +11     
- Partials        0       14      +14     
Flag Coverage Δ
unit-tests 83.94% <100.00%> (+0.31%) ⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

egpbos added 4 commits July 24, 2026 16:41
Extract _resolve_level and _console_handler so setup_logger and
bootstrap_logger no longer duplicate the level check and the stdout handler
construction. The two entry points keep their distinct, complementary roles:

  bootstrap_logger is the lightweight, non-destructive fallback the CLI
  installs at entry. It guarantees there is always a console handler before a
  command knows its output directory, no-ops if a handler already exists, and
  never opens a logfile.

  setup_logger is the authoritative configuration used once the output
  directory is known, both from the CLI and from the Python API. It clears
  handlers, installs the file-backed logger, and sets the exception hook.

Neither public contract changes; behaviour is unchanged.
The grid manager had its own setup_logger that configured the root logger,
while bootstrap_logger and the main setup_logger configure the 'fwl' logger.
With bootstrap_logger now installed at CLI entry, both a 'fwl' handler and the
grid's root handler emitted every grid log line, so grid console output was
duplicated.

Point the grid manager at the shared proteus.utils.logs.setup_logger, which
configures 'fwl' and clears its handlers first, so grid logs print once. Add an
optional fmt/datefmt to setup_logger so the grid keeps its plain, timestamped
manager.log layout; all other callers are unchanged. Remove the grid-local
setup_logger and the tests that covered it, since that behaviour is now the
shared function's, covered under tests/utils/test_logs.py.
Comment thread tests/utils/test_logs.py
logging.getLogger('fwl').info('PLAINMARK')
for h in logging.getLogger('fwl').handlers:
h.flush()
contents = open(logpath).read().strip()
Comment thread tests/utils/test_logs.py
logging.getLogger('fwl').info('TAGMARK')
for h in logging.getLogger('fwl').handlers:
h.flush()
contents = open(logpath).read().strip()
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

logger is not configured at all times, logs get lost

1 participant