Logging - ULJ-Yale/qunexsdk GitHub Wiki

Logging

A QuNex command reports what it did through a log object. This page is the working guide to doing that well: the ideas you need, the shape a command takes, the vocabulary available to you, the rules that hold across the code base, and the mistakes that are easy to make and hard to notice.

For the full account — how the machinery is put together, where the files go, and every setting — see The QuNex logging whitepaper. The classes are listed in Developer utilities and classes.

The ideas you need

There are two logs. The runlog is QuNex's account of one invocation: the call that was made, each session's report, and a closing manifest. One qunex call leaves one of them, named Log-<command>-<timestamp>.log. A comlog is the record of one external call — FSL, FreeSurfer, MATLAB — holding the tool's raw output together with the report lines recorded while it ran.

A command reports into a log object. It builds a SessionLog or is handed a ReportLog, and records lines on it as it works. The object holds the report until the command is done with it.

The log spells the line. A call site names what the line is — a step, a detail, a warning, an error — and the log renders the marker and the indent that go with it.

Severity is status. log.error(...) adds to the log's error count, and that count decides how the session is reported, what the run's manifest says, and the exit status of the process.

The log package is a leaf. general/log imports general.exceptions and general.parsing and nothing else from the tree. So the helpers that run commands and check files live in processing/core.py and general/core.py, and take the log as a trailing keyword argument.

The shape of a command

A processing command

import qx_utilities.general.log as gl
import qx_utilities.processing.core as pc


def my_command(sinfo, options, overwrite=False, thread=0):
    # the session log; its header is written as it is created
    log = gl.SessionLog(sinfo, options, "My pipeline")

    log.step("checking the data")
    # the helper records "present" or, as an error, "missing", and returns the status
    if not pc.check_for_file(path, "present", "missing", bad_level="error", _log=log):
        return log.finish("My pipeline failed", failed=1)

    # one comlog for every external call this command makes
    with pc.combined_comlog(log, options, "my_command", thread=sinfo["id"]):
        try:
            pc.run_external_for_file(
                checkfile,  # the file that proves it ran
                command,  # the command to run
                "running my pipeline",  # its description in the report
                overwrite=overwrite,
                thread=sinfo["id"],
                task="my_task",
                logfolder=options["comlogs"],
                _log=log,
            )
        except pc.ExternalFailed as errormessage:
            log.raw(str(errormessage))  # the tool's error message, verbatim
            return log.finish("My pipeline failed", failed=1)

    # the summary; the failure count is derived from the errors recorded
    return log.finish("My pipeline completed")

A processing command returns its log object. general/process.py writes the report into the runlog with log.write_to(run) and reads log.status from it — the (session_id, summary, failed) triple. State the summary with finish(), which hands the log back so that return log.finish(...) is the natural last line, or by assigning log.report and log.failed and returning the log.

A utility command

def my_utility(sourcefolder=None, _log=None):
    # `_log` is supplied by the runner; log_or_console also covers the cases
    # where this function is called directly from python
    log = gl.log_or_console(_log)

    log.step("reading the source folder")
    log.detail(f"source: {sourcefolder}")
    ...
    return copied  # whatever a python caller of this function wants

Declaring _log=None is how a utility command opts in. general.core.run_with_log builds a ReportLog and hands it to any command whose signature declares one. Opening with log = gl.log_or_console(_log) gives you a log to write to on every path — including the ones the runner does not reach, such as logging switched off, run_recipe without sessions, or a call from another python function.

A utility command reports a failure by recording an error or by raising. The value it returns is for a python caller.

The vocabulary

Method The line it produces Reach for it when
log.step(msg) ---> msg a processing step is starting
log.detail(msg) ... msg you are adding a particular of that step
log.warning(msg) ---> WARNING: msg the run carries on, and the user should know
log.error(msg) ---> ERROR: msg something failed — and this counts
log.info(msg) msg prose with no marker: a header, a parameter block
log.blank(n) n newlines you want vertical space
log.rule() a full width rule you are separating one part of the report from the next
log.raw(text) the text as given tool output, exception text, a line's tail
log.action(word, msg, run) ---> Running msg, or ---> Test running msg under --test the verb depends on the run mode
log.section(title) a step, and indents the block several lines belong under one heading
log.pipeline_command(cmd) a framed block, one flag per line you are showing the external command
log.trace(text) text for the attached comlog the text belongs in this call's record, not in the run's report

Nesting comes from the log as well:

log.step("preparing the BOLD runs")  # ---> preparing the BOLD runs
log.detail("bold 1: rest")  #      ... bold 1: rest

with log.section("checking the fieldmaps"):  # ---> checking the fieldmaps
    log.detail("SE-FM 1 found")  #           ... SE-FM 1 found

log.error("no usable fieldmap", depth=1)  #      ---> ERROR: no usable fieldmap

log.indent() and log.dedent() do the same by hand where a block does not fit. A section restores the depth when it ends, including when it ends with an exception.

Horizontal division comes from log.rule(). It draws the full width rule that separates one session's report from the next — the same rule framed() uses, and the one a reader scanning a runlog looks for:

log.rule()  # the rule that opens a session report
log.info(f"Session id: {sinfo['id']}")

log.rule(before=1, after=1)  # a blank line above it and below it
log.rule(char=".")  # a lighter division, for a block inside the report

before and after are the blank lines around it. char picks what it is drawn with — a dotted rule around a traceback reads as a lighter division than the dashed one that ends a session. The width does not change with it. Rules of one length stack into a page that can be read; a report whose rules are all slightly different lengths cannot.

The rules

1. State the severity, and let the log spell the marker. The line log.detail("ERROR: no fieldmap") produces ... ERROR: no fieldmap, which reads plausibly and is counted as an ordinary detail: the failure count does not see it, and neither does the manifest. Write log.error("no fieldmap", depth=1) for the same indent with the marker the renderer puts there. Where a helper writes the line, pass the severity — bad_level="error".

2. Interpolate with f-strings. log.error(f"{path} does not exist!"). The level methods take the message and an optional depth, so a format string with separate arguments is a TypeError where you wrote it. (One line in the tree uses %, because it interpolates a string containing a backslash, which an f-string slot accepts only from Python 3.12.)

3. A log parameter is named _log. The plain name belongs to the comlog retention setting: process.arglist carries ["log", "keep", str], so options["log"] is --log, remapped for every command before dispatch. The underscore also keeps the parameter off the command line, since the registry builder leaves out signature parameters beginning with _, and a registry test holds that in place.

4. A helper takes the log and appends to it. Pass _log and record into it, so that one command's work reads as one report.

5. A command called as a step of another takes the caller's log as _log and reports into it. The caller's report then holds the whole story, and the caller's error count includes what the step found.

6. Collect a command's external calls in one comlog with pc.combined_comlog. Under --test nothing is opened.

7. A function that declares _log reports through it. The signature advertises a log, and the body should use it for what it has to say. python/tests/test_print_baseline.py keeps a per-module budget of prints and names the exemptions.

Pitfalls

  • ERROR: written into an info() reads like a failure and counts as success. This is the most common way a command misreports its outcome. The severity has to be in the method.
  • Catching an exception, reporting it and returning leaves the run looking successful. Record the error — which fails the run through the derived count — or raise.
  • Re-adding a whole report to itself. pc.ExternalFailed carries the error message alone, because everything leading up to it is already in the log. The handler adds log.raw(str(errormessage)) and no more.
  • Hand-typed indentation, newlines and rules. Leading spaces in a message, a \n at the front of a line, or a row of dashes typed into a string all fight with the renderer. section() and depth= give nesting, blank() gives space, rule() gives the rule. A rule typed by hand also comes out whatever length the fingers stopped at, and a runlog is read down its left edge.
  • A paragraph of prose carrying its own \n . A preamble folded into one long string with the wrapping written into it is unreviewable in a diff and goes ragged the moment an interpolated value changes width. Keep the prose in a module level triple-quoted constant, wrap it with textwrap.fill if it has substitutions in it, and hand the result to info(). processing/workflow.py's four preambles are the pattern.
  • A parameter block written as one format string. Seven --flag: {value} slots in a single line drift from options the first time a parameter is renamed. Keep the names in a list and loop: log.step("Using parameters") then a log.detail each.
  • raw() used as a general-purpose method. It is right for verbatim tool output, for exception text, and for the tail of a line already started. Ask whether the line has a severity; if it has, a level method spells it. Ask whether it is furniture; if it is, blank(), rule() or framed() draws it.
  • Building a second log inside a function that was given one. Take _log and use it, so the report and the error count stay in one place.

Getting the most out of the tools

  • gl.log_or_console(_log) — for a function called both with and without a log. It keeps the body reading as log.step(...) throughout. For a function with only two or three messages, pc._say(_log, level, message) is the lighter option, since it takes the level as an argument.
  • log.section(title) — whenever a block of lines would otherwise repeat a prefix.
  • log.action(word, message, options["run"]) — for a line whose verb changes under --test. The plain gl.action(word, run) function returns the word itself, for the places that need it in the middle of a sentence.
  • log.trace(text) — for text that belongs in the record of one external call rather than in the run's report.
  • with log.stream_to(comlog) — attaches a comlog for a block, so that everything recorded goes into it as well. pc.combined_comlog is the usual way in.
  • python/tests/log_render_diff.py — a development tool rather than a collected test. It renders the report of two revisions of a file and diffs them, which turns "I rewrote these log lines and I think the output is the same" into something you can demonstrate. It imports the renderer from the log package, so it stays in step with it. It models the level methods, raw(), and plain %s/%d slots.
  • python/tests/test_print_baseline.py — the print budget per module, with its exemptions and the reasoning for each.
  • python/tests/test_log_is_a_leaf.py — fails if general/log gains an import from elsewhere in the tree, wherever it is written.
⚠️ **GitHub.com Fallback** ⚠️