Report through logging instead of print() - #101
Merged
Conversation
Every message in src/ivert/ now goes through a module-level logging.getLogger(__name__) at a level matching what it is: info() for progress, warning() for a recoverable problem, error()/exception() for a failure. Output can now be filtered, redirected or silenced at runtime. --verbosity already chose a level; it now actually governs the validation output, which was previously printed unconditionally. The wording of the messages is unchanged. Two exceptions, both deliberate: a handler supplies the WARNING:/ERROR: prefix that a few of them used to spell out, and the paired "Reading X ..." / "done." progress lines became single completed-action messages, since a log record is a whole line. Validation sub-processes now configure their own logging. validate_dem() runs its work in a spawned child process, which starts with the logging module unconfigured and inherits no handlers or level from its parent. Left alone, every info() call in the child would have fallen through to logging's last-resort handler, which drops anything below WARNING, and almost all of the validation output would have vanished. The parent's level is passed across in the worker's keyword arguments and reinstated by configure_worker_logging() as the child's first act. The handler is rebuilt there rather than reused, because LoggerProc replaces sys.stdout/sys.stderr before calling its target and a StreamHandler binds whichever stream it was built against, so job logfiles still capture the run. The verbose parameter is gone from the validation API, since log levels now do its job. validate_dem(), validate_dem_parallel(), validate_list_of_dems(), write_summary_stats_file(), export_error_results(), IS2Database.open_gdf() and the others no longer accept it, and cli.py no longer translates a log level back into a boolean to pass down. Callers should drop the argument and set the log level instead. One behavioural wrinkle went with it: in _compute_photon_overlap(), the early return for a DEM with no land cells sat inside an "if verbose:" block, so it only happened when verbose was on. The check that follows returned anyway, so the outcome is the same, but it no longer depends on the verbosity setting. T201 (print) comes off the Ruff ignore list to keep this from regressing. The few remaining print() calls are the ones whose output is the result rather than a report about it: a tabulate table, the is_aws/is_conda script helpers, and loggerproc's self-test, whose prints are the fixture under test. Each carries a # noqa: T201 and a comment. The convention is written up in CONTRIBUTING.md. Closes #6.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Closes #6.
Replaces IVERT's
print()output with the standardloggingmodule, so output can be filtered, redirected or silenced at runtime rather than only by wrapping the process.--verbosity debug|info|warning|error(and theverbosityconfig setting) already chose a level; it now actually governs the validation output, which was previously printed unconditionally.Scope
The issue was written a while ago and is stale in places: it points at
src/client.py, which no longer exists, and its item 4 — have the CLI configure the root logger — was already done.cli.pyhad--verbosity, a config default, and no prints.The scope is also smaller than a raw grep suggests: all 37 "prints" in
utils/cuboid_funcs.pysit inside commented-out dead code. That leaves 131 live statements, now 146 logger calls across 16 modules.The part worth reviewing carefully
validate_dem()always runs its work in aspawn-started child process, and ~50 of that file's prints execute inside it. A spawned child inherits no logging configuration from its parent, so a mechanical print→logging swap would have silently dropped nearly all validation output at default verbosity — everything below WARNING falls through to logging's last-resort handler.I checked this empirically rather than assuming it:
WARNINGarrives — INFO lostWARNING:-prefixed warningLoggerProcThe parent's level rides across in the worker's kwargs and
configure_worker_logging()reinstates it as the child's first act. The handler is rebuilt there rather than reused:LoggerProcreplacessys.stdout/sys.stderrbefore calling its target, and aStreamHandlerbinds whichever stream it was constructed against — reusing one would have sent job output to the real terminal instead of the logfile.Verifying the messages didn't change
Rather than eyeball 131 conversions, I rendered each original
print()and its replacement with identical placeholder tokens and diffed them: 70 identical, and every one of the 46 differences is intentional —WARNING:/ERROR:prefixes removed, because a formatter now supplies them (so terminal output is unchanged;infostays bare,warning+ gets labelled, anddebuglabels everything)"Reading X ..."/"done."progress pairs collapsed into 5 completed-action records, since a log record is a whole lineprint(e)folded intologger.exception, which now carries the tracebackThe two messages I restructured by hand were checked to render byte-identically at runtime.
Ruff runs
select = ["ALL"], soG002/G003/G004are live: every call uses lazy%sarguments, never f-strings. Thousands separators pass a pre-formatted argument, e.g.logger.info("%s cells", f"{n:,}").Breaking change
The
verboseparameter is gone from the validation API, since log levels now do its job.validate_dem(),validate_dem_parallel(),validate_list_of_dems(),write_summary_stats_file(),export_error_results(),IS2Database.open_gdf()and 19 others no longer accept it, andcli.pyno longer translates a log level back into a boolean to pass down. Callers that passedverbose=should drop the argument and set the log level instead; passing it now raisesTypeError. The externaltransformez.generate_grid(verbose=False)call is untouched.A latent bug this surfaced
In
_compute_photon_overlap(), the earlyreturn Nonefor a DEM with no land cells sat inside theif verbose:block — so it only fired when verbose was on. The check immediately after it returns anyway, so the outcome is unchanged, but it no longer depends on the verbosity setting.Lint
T201(print) comes off the Ruff ignore list, which keeps this from regressing and continues #40. The 7 remaining prints are the ones whose output is the result rather than a report about it — atabulatetable, theis_aws/is_condahelpers whose whole purpose as scripts is the value they write to stdout, andloggerproc's self-test, whose prints are the fixture under test. Each carries a# noqa: T201and a comment saying why. The convention is written up inCONTRIBUTING.md.Checks
prek run --all-filespasses, every module still imports, the CLI works, and--verbosity errorcorrectly suppresses a config warning that appears at the default level.Unrelated and pre-existing, not touched here:
ivert.utils.list_photon_tilesimports a removedivert.s3module and fails to import onmaintoo. Probably worth its own issue.🔍 Docs preview: https://ivert--101.org.readthedocs.build/en/101/