fwl-io configures its logger with an incorrect name

[nichollsh]

Problem

All FWL modules need to setup their loggers with names that have the prefix fwl- in order for them to be captured together into a single logger stream. Without this, when calling one module from another, logs will be lost.

This is currently active on PROTEUS and fwl-io main branches. When running PROTEUS simulations, the terminal stdout shows things like:

Downloading data from 'doi:10.5281/zenodo.15727899/halfh2o2h500K1mbar.txt' to file '/home/harrison/Projects/FWL_DATA/.fwl-io-staging/tmppjj9gxsl/halfh2o2h500K1mbar.txt'.

But these do not appear in the PROTEUS log file and do not have the same log-formatting, because the fwl-io module isn't configuring its logger properly.

Solution

The fwl-io module should configure its logger as: log = logging.getLogger("fwl."+__name__) rather than log = logging.getLogger(__name__).

People

@egpbos @timlichtenberg

[timlichtenberg]

Reopening this. #35 fixes the logger naming and that was worth doing on its own, but the line I quoted in the report above still bypasses the logfile, so the symptom this issue describes is still present on main.

To be clear about the part that is fixed: fwl-io emits 17 records, and before #35 they reached fwl_io.*, propagated to a root logger with no handler, and terminated at logging.lastResort. That drops INFO entirely, which is why log.info('fetched %s from shared cache %s', ...) never appeared, and it prints WARNING unformatted to stderr without the record ever entering the logfile. Naming them fwl.* recovers all of that and matches what CALLIOPE, MORS, JANUS and aragog already do.

The download line is not ours, though. pooch/core.py:232 emits "%s data from '%s' to file '%s'." with the verb set to "Downloading" at core.py:784, character for character the message I pasted above, and grep -rn "Downloading data from" src/ in fwl-io returns nothing. Pooch's logger also cannot be reached from the fwl tree by renaming anything we own, because pooch/utils.py:27 builds it as logging.Logger("pooch") and line 28 attaches a StreamHandler to it. Constructing a Logger directly rather than through getLogger leaves parent is None and keeps it out of logging.Logger.manager.loggerDict, so its records stop at its own stderr handler no matter what we call ours. I measured this rather than reasoning about it: a capture handler on fwl sees nothing from pooch.get_logger().info(...), and sees the record fine from fwl.fwl_io.fetch. Checked against pooch 1.9.0.

The remedy fits in one place. fetch.py is the only module that touches pooch and _retrieve_once is the only call into pooch.retrieve, so alongside the module logger:

# pooch builds its logger with logging.Logger("pooch") rather than getLogger,
# so it has no parent and its records never propagate; its own stderr handler
# is the only way out, which is why download lines bypass the caller's
# formatting and logfile. Reparenting it under our logger sends them through
# whichever handler the application attached to 'fwl'. Its private handler is
# dropped only when the fwl tree can take the records, so a standalone fwl-io
# run keeps the download output it has today.
_pooch_log_routed = False


def _route_pooch_logging() -> None:
    global _pooch_log_routed
    if _pooch_log_routed:
        return
    pooch_log = pooch.get_logger()
    pooch_log.parent = log
    if logging.getLogger('fwl').hasHandlers():
        pooch_log.handlers.clear()
    _pooch_log_routed = True

and a call to it at the top of _retrieve_once. I ran the reparenting part and the download line then arrives at the fwl handler, formatted, and no longer goes straight to stderr. Two caveats worth a comment in the source: get_logger() is public pooch API but reassigning .parent is not, and the hasHandlers() check is what keeps standalone use working, since cli.py configures no logging at all and an unconditional handlers.clear() would leave those users with nothing below WARNING.

Second thing this needs is a regression test. There is no caplog usage anywhere in the fwl-io suite, so nothing pins the logger tree and the next refactor can undo #35 silently. Roughly three cases: one parametrised over fetch, manifest and mirror asserting each module logger is a descendant of fwl; one asserting a pooch.get_logger().info(...) record reaches a handler attached to fwl after the routing call; and one asserting pooch keeps its own handler when the fwl tree has none, which is the standalone case the conditional exists for. All three touch process-global logging state, so they want a fixture that restores the handler list and resets the routing flag.

Happy to do this myself if you would rather not carry it.

[egpbos]

I'm wondering whether fwl-io is the place to implement this (especially the handlers part), or whether it should go in PROTEUS. This also makes a better place for testing the integration, because it would make fwl-io CI much heavier to have to install PROTEUS here as well just to test integration. Although, I guess you could mock, but then the mock needs to be kept in sync with PROTEUS behaviour, an extra maintenance step.

I was also thinking about whether it's a good idea at all (main trigger was the global, which is always a red flag, although logging is a known exception). I checked the pooch docs and concluded it's fine to hijack the logger, they explicitly note that we're welcome to use the Logger methods in fancy ways https://www.fatiando.org/pooch/latest/logging.html. If we could get rid of the global, I think that would be better, though. Can we not just call this code (doesn't even have to be in a function) directly after import pooch? If someone imports fetch.py, surely they will at some point use pooch too, so we don't have to overengineer it. I didn't verify this in the code, so maybe I am overlooking things.

[timlichtenberg]

Fixed by f35f4d0, which sets every module's logger to the fwl. prefix, and released in 26.08.31 (https://github.com/FormingWorlds/fwl-io/releases/tag/26.08.31). PROTEUS picks up the fix when its fwl-io floor is bumped to that release.