Logging

This page provides guidance to developers for using logging in the Science Pipelines code base. In general, all logging in Python code should be done with the standard logging package. All logging from C++ code should be done using the lsst.log package; reference documentation on that logging framework can be found at the Doxygen page on logging. Application code that uses both Python and C++ logging should include configuration code to forward C++ log messages to the Python logging system. This is handled automatically when using, for example, the pipetask command. For an example of configuring the logging framework in pipeline tasks, see the pipelines.lsst.io page on logging.

Developers are encouraged to insert log messages whenever and wherever they might be useful, with appropriate component names and levels.

Whether using logging or any other logging mechanism, timestamps recorded in logs should use Internet RFC 3339 format, which is sortable and includes the timezone. See the discussion in DM-1203 for history.

Logger Names

Logger names should generally start with the fully qualified name of the module/file containing the logger, with the leading lsst.. Some example logger names are lsst.afw.image.MaskedImage and lsst.meas.algorithms.starSelector. A common Python recommendation is to create the logger name from the module hierarchy automatically:

log = logging.getLogger(__name__)

If the logger is saved as a variable in a class, it is often appropriate to name the logger after the class. Such a logger can be derived from the module logger using log.getChild().

Logger names use . as component separators, not ::, even in C++.

Basic Usage in Python

The simplest way to log is:

import logging
logging.info('Some information during normal operation')
logging.warning('Here is a warning!')

The example logs to the default (root) logger. By default Python logs warning messages and no other log messages. This means that the above example code will only write a single log message. Application code is required to configure the logging state for libraries and this is generally done by calling logging.basicConfig() to set a default logger level and default log format. For example, to enable INFO level output reporting the name of the logger and log message level as well as the message use the following:

logging.basicConfig(level=logging.INFO, format="{name} {levelname}: {message}", style="{")

Our execution environment and butler commands configure this automatically.

A better naming practice is to use a named logger following our name convention to indicate where the logging messages originate. For example:

logger = logging.getLogger("lsst.meas.algorithms.starSelector")
logger.info("This is information about the star selector algorithm execution. %f", 3.14)

The standard methods, such as info() and warning(), use a %-format string in the message and pass in additional arguments containing variable information, which logging.Logger will internally merge into the message string with % formatting if the log record is to be printed. This deferred string interpolation can be very important if the variable being inserted into the log message is a complex class and converting it to a string is an expensive operation. For example, do not write:

log.debug(f"Some message: {myvar}")

since that would do the f-string interpolation even if the logger is only configured to show warning messages. Instead this code should be written as:

log.debug("Some message: %s", myvar)

To specify the threshold or the lowest-severity log messages a logger handles, setLevel() can be used:

logger.setLevel(logging.DEBUG)

Basic Usage in C++

To use lsst.log in C++, the header file to include is:

#include "lsst/log/Log.h"

Typically one of the logging macros should be used. You can choose either sprintf style formatting (the LOGL_ family) or iostream style formatting (the LOGLS_ family) to log to a logger. The following shows an example to get a logger object and log using it:

LOG_LOGGER _log = LOG_GET("lsst.afw.image.ExposureInfo");
LOGLS_INFO(_log, "Empty WCS extension, using FITS header");
LOGLS_WARN(_log, "Missing empty chunks info for " << "something");
LOGL_DEBUG(_log, "St. Dev = %g", sd);

The full list of available macros and more details of the lsst.log features are described in its package documentation.

Getting a logger object and logging to that is preferred over logging using a string as the logger name, but the latter can also be used. For example:

LOGL_WARN("meas.algorithms.starSelector.psfCandidate", "Failed to make a psfCandidate")

Log Levels

logging has five standard levels; in increasing order of severity the are: DEBUG < INFO < WARNING < ERROR < CRITICAL. The guideline of using the log levels is as follows:

  • CRITICAL: for severe errors that may prevent further execution of the component (FATAL is also allowed as an alias).

  • ERROR: for errors that may still allow the execution to continue.

  • WARNING: for conditions that may indicate a problem but that allow continued execution (WARN is also allowed as an alias).

  • INFO: for information that is of interest during normal execution including production.

  • DEBUG: for information that is of interest to developers but not of interest during production.

In addition there are two additional log levels allowed for specialist pipelines-specific loggers (such as those used for lsst.pipe.base.Task):

  • VERBOSE: for messages of a more detailed nature than would normally be expected to be shown by default but that will not swamp the user in the way that DEBUG messages would if that level of output was enabled. The numeric log level for VERBOSE logs is 15.

  • TRACE: for detailed information when debugging, particularly inside loops. The TRACE numeric log level spans a range from 1-5 (e.g. for use with the log-cli-level argument to pytest).

An alternative approach for TRACE and VERBOSE is to consider using DEBUG messages with a separate logger name that can be enabled when desired, as described below. Remember though that the default output level for general users is usually INFO and for large-scale pipeline processing it is VERBOSE. This means that VERBOSE logging will be available by default when analyzing log output for big processing runs in a way that would not happen if specially named loggers were used which had to be explicitly enabled by the person submitting the job.

For loggers used at DEBUG and TRACE levels, it is often desirable to add further components to the logger name; these would indicate which specific portion of the code or algorithm that the logged information pertains to. For example:

debugLogger = logging.getLogger(__name__).getChild("catalogReader")
debugLogger.debug("Catalog reading took %f seconds", finish - start)
debugLogger.debug("Took %f seconds and found %d sources", elapsed, nstars)

The idea here is that the author understands the intent of the log message and can simply name it, without worrying about its relative importance or priority compared with other log messages in the same component. A person debugging the code would typically be looking at it and so would be able to determine the appropriate name to enable. The hierarchy allows all components to be easily enabled or disabled together.

Logging within the Task framework

Pipeline tasks (subclasses of lsst.pipe.base.Task or lsst.pipe.base.CmdLineTask) should use the lsst.pipe.base.Task.log attribute logger:

self.log.verbose("Coadding %d exposures", len(calExpRefList))
self.log.info("Not applying color terms because %s", applyCTReason)
self.log.warn("Failed to make a psfCandidate from star %d: %s", star.getId(), err)

When running pipetask or similar commands, the --log-level command line argument can be used to set the threshold for specific components. For example, to make the calibrate stage of processCcd less verbose:

pipetask --log-level processCcd.calibrate=WARN run [pipeline options]

Getting log output in a notebook

The Rubin Science Platform (RSP) automatically configures log output to appear in RSP notebooks via an ipython startup file (~/.ipython/profile_default/startup/20-logging.py) that is automatically copied into place if no such file exists. For stand-alone jupyter notebooks, you have to configure the log output yourself, otherwise log messages will not appear in a notebook. Running the following code at the start of your notebook will result in output of logs at INFO-level and above:

from lsst.daf.butler.cli.cliLog import CliLog
CliLog.initLog(longlog=False)

Note that if you use the above configuration, you won’t get the same logging output as you would with the RSP configuration.

To further configure which logs will appear, set the log level for the "lsst" namespace as described at the end of the python section above inside your notebook:

import logging
logging.getLogger("lsst").setLevel(logging.DEBUG)

Fine-level Verbosity in Tracing

As an alternative for TRACE loggers where there are different messages at increasing levels of verbosity but no specific component names that would be appropriate, or where increasing verbosity spans a number of levels of the component hierarchy, logger names can be prefixed with “TRACEn”, where n=0-5, to indicate increasing verbosity. For example, in C++:

LOG_LOGGER traceLogger = LOG_GET("TRACE2.lsst.meas.algorithms.starSelector");
LOGL_DEBUG(traceLogger, "On %d-th iteration of star selection", iteration);
LOG_LOGGER innerTraceLogger = LOG_GET("TRACE2.lsst.meas.algorithms.starSelector.catalogReader");
LOGL_DEBUG(innerTraceLogger, "Reading catalog %s", catalogName);
// Or log to a component directly
LOGL_DEBUG("TRACE4.lsst.meas.algorithms.starSelector.psfCandidate", "Making a psfCandidate from star %d", starId)

and in Python:

traceLogger = logging.getLogger("TRACE2.lsst.meas.algorithms.starSelector")
traceLogger.debug("On %d-th iteration of star selection", iteration)
innerTraceLogger = traceLogger.getChild("catalogReader")
innerTraceLogger.debug("Reading catalog %s", catalogName)
logging.getLogger("TRACE4.meas.algorithms.starSelector.psfCandidate").log(logging.DEBUG, "Making a psfCandidate from star %d", starId)

Notice that all loggers in the hierarchy under a given component at a given trace level can be enabled easily using, e.g., TRACE2.lsst.meas.algorithms.starSelector. Besides, a utility function lsst.utils.logging.trace_set_at is provided to adjust logging level of a group of loggers so to display messages with trace number <= NUMBER. This is demonstrated in the following example:

import logging
import sys
import lsst.utils.logging

logging.basicConfig(level=logging.INFO, stream=sys.stdout)
root_logger = logging.getLogger()


def writeMessages():
    """Write debugging messages under TRACEn.example.component

    In application code, they may appear either in Python or C++ codebase
    """
    root_logger.info("Writing 6 debug messages")
    for n in range(6):
        logging.getLogger(f"TRACE{n}.example.component").debug("Fine tracing to TRACE%d", n)


# Demonstrate using the utility function trace_set_at to set the levels for a
# group of loggers so it display messages with trace number <= the threshold
for threshold in range(6):
    root_logger.info("Setting trace at %d", threshold)
    lsst.utils.logging.trace_set_at("example.component", threshold)
    writeMessages()

The example can be run if lsst.log is setup:

$ python examples/tracing.py
INFO  root: Setting trace at 0
INFO  root: Writing 6 debug messages
DEBUG TRACE0.example.component: Fine tracing to TRACE0
INFO  root: Setting trace at 1
INFO  root: Writing 6 debug messages
DEBUG TRACE0.example.component: Fine tracing to TRACE0
DEBUG TRACE1.example.component: Fine tracing to TRACE1
INFO  root: Setting trace at 2
INFO  root: Writing 6 debug messages
DEBUG TRACE0.example.component: Fine tracing to TRACE0
DEBUG TRACE1.example.component: Fine tracing to TRACE1
DEBUG TRACE2.example.component: Fine tracing to TRACE2
INFO  root: Setting trace at 3
INFO  root: Writing 6 debug messages
DEBUG TRACE0.example.component: Fine tracing to TRACE0
DEBUG TRACE1.example.component: Fine tracing to TRACE1
DEBUG TRACE2.example.component: Fine tracing to TRACE2
DEBUG TRACE3.example.component: Fine tracing to TRACE3
INFO  root: Setting trace at 4
INFO  root: Writing 6 debug messages
DEBUG TRACE0.example.component: Fine tracing to TRACE0
DEBUG TRACE1.example.component: Fine tracing to TRACE1
DEBUG TRACE2.example.component: Fine tracing to TRACE2
DEBUG TRACE3.example.component: Fine tracing to TRACE3
DEBUG TRACE4.example.component: Fine tracing to TRACE4
INFO  root: Setting trace at 5
INFO  root: Writing 6 debug messages
DEBUG TRACE0.example.component: Fine tracing to TRACE0
DEBUG TRACE1.example.component: Fine tracing to TRACE1
DEBUG TRACE2.example.component: Fine tracing to TRACE2
DEBUG TRACE3.example.component: Fine tracing to TRACE3
DEBUG TRACE4.example.component: Fine tracing to TRACE4
DEBUG TRACE5.example.component: Fine tracing to TRACE5