Skip to content

Report through logging instead of print() - #101

Merged
mmacferrin merged 1 commit into
mainfrom
print-to-logging
Sep 2, 2026
Merged

Report through logging instead of print()#101
mmacferrin merged 1 commit into
mainfrom
print-to-logging

Conversation

@mmacferrin

@mmacferrin mmacferrin commented Sep 2, 2026

Copy link
Copy Markdown
Collaborator

Closes #6.

Replaces IVERT's print() output with the standard logging module, so output can be filtered, redirected or silenced at runtime rather than only by wrapping the process. --verbosity debug|info|warning|error (and the verbosity config 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.py had --verbosity, a config default, and no prints.

The scope is also smaller than a raw grep suggests: all 37 "prints" in utils/cuboid_funcs.py sit 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 a spawn-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:

case result
spawned child without the level handoff only WARNING arrives — INFO lost
spawned child with the handoff at INFO INFO + WARNING:-prefixed warning
spawned child with the handoff at DEBUG all three levels, each labelled
via LoggerProc logfile captured the records

The 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: LoggerProc replaces sys.stdout/sys.stderr before calling its target, and a StreamHandler binds 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

  • 10 literal WARNING:/ERROR: prefixes removed, because a formatter now supplies them (so terminal output is unchanged; info stays bare, warning+ gets labelled, and debug labels everything)
  • 8 "Reading X ..." / "done." progress pairs collapsed into 5 completed-action records, since a log record is a whole line
  • print(e) folded into logger.exception, which now carries the traceback

The two messages I restructured by hand were checked to render byte-identically at runtime.

Ruff runs select = ["ALL"], so G002/G003/G004 are live: every call uses lazy %s arguments, never f-strings. Thousands separators pass a pre-formatted argument, e.g. logger.info("%s cells", f"{n:,}").

Breaking change

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 19 others no longer accept it, and cli.py no longer translates a log level back into a boolean to pass down. Callers that passed verbose= should drop the argument and set the log level instead; passing it now raises TypeError. The external transformez.generate_grid(verbose=False) call is untouched.

A latent bug this surfaced

In _compute_photon_overlap(), the early return None for a DEM with no land cells sat inside the if 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 — a tabulate table, the is_aws/is_conda helpers whose whole purpose as scripts is the value they write to stdout, and loggerproc's self-test, whose prints are the fixture under test. Each carries a # noqa: T201 and a comment saying why. The convention is written up in CONTRIBUTING.md.

Checks

prek run --all-files passes, every module still imports, the CLI works, and --verbosity error correctly suppresses a config warning that appears at the default level.

Unrelated and pre-existing, not touched here: ivert.utils.list_photon_tiles imports a removed ivert.s3 module and fails to import on main too. Probably worth its own issue.


🔍 Docs preview: https://ivert--101.org.readthedocs.build/en/101/

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.
@mmacferrin
mmacferrin merged commit f988fd5 into main Sep 2, 2026
5 checks passed
@mmacferrin
mmacferrin deleted the print-to-logging branch September 2, 2026 02:38
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.

Replace print() statements with logging throughout codebase

1 participant