Logging¶

This page provides guidance to developers for using logging with lsst.log in the Science Pipelines code base. For reference documentation on the logging framework refer to the Doxygen 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 lsst.log 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, without the leading lsst.. Some example logger names are afw.image.MaskedImage and meas.algorithms.starSelector.

If the logger is saved as a variable in a class, it is often appropriate to name the logger after the class.

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

Basic Usage in Python¶

The basic Python interface of lsst.log is made to be somewhat similar to Python logging. The simplest way to log is:

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

The example logs to the default (root) logger.

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

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

In Python, two string formatting options can be used for log messages. The standard methods, such as info and warn, use a %-format string in the message and pass in additional arguments containing variable information, which lsst.log will internally merge into the message string with % formatting if the log record is to be printed. Another set of methods with a trailing f, for example infof and warnf, can use format() string interpolation using curly braces.

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

logger.setLevel(lsst.log.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("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¶

lsst.log has six levels; in increasing order of severity the are: TRACE < DEBUG < INFO < WARN < ERROR < FATAL. The guideline of using the log levels is as follows:

FATAL: for severe errors that may prevent further execution of the component.
ERROR: for errors that may still allow the execution to continue.
WARN: for conditions that may indicate a problem but that allow continued execution.
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.
TRACE: for detailed information when debugging.

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 = lsst.log.Log.getLogger("meas.algorithms.starSelector.catalogReader")
debugLogger.debug("Catalog reading took %f seconds", finish - start)
debugLogger.debugf("Took {} seconds and found {count} sources", elapsed, count=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.debugf("Coadding {} 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 command line tasks, the --loglevel command line argument can be used to set the threshold for specific components. For example, to make the calibrate stage of processCcd less verbose:

processCcd.py [input/output/id] --loglevel processCcd.calibrate=WARN

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

and in Python:

traceLogger = lsst.log.Log.getLogger("TRACE2.meas.algorithms.starSelector")
traceLogger.debug("On %d-th iteration of star selection", iteration)
innerTraceLogger = lsst.log.getLogger("TRACE2.meas.algorithms.starSelector.catalogReader")
innerTraceLogger.debugf("Reading catalog {}", catalogName)
# Or log to a component directly
lsst.log.log("TRACE4.meas.algorithms.starSelector.psfCandidate", lsst.log.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.log.utils.traceSetAt() is provided to adjust logging level of a group of loggers so to display messages with trace number <= NUMBER. This is demostrated in the following example:

import lsst.log.utils


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

    In application code, they may appear either in Python or C++ codebase
    """
    lsst.log.info("Writing 6 debug messages")
    for n in range(6):
        lsst.log.log("TRACE%d.example.component" % n, lsst.log.DEBUG, "Fine tracing to TRACE%d" % n)


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

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

$ python logging_snippets/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

Porting from pex_logging¶

Logging in the Science Pipelines codes is being migrated from using lsst.pex.logging to lsst.log. Below, some examples are listed that may be used as a starting point for porting:

Examples for porting pex_logging to log¶
lsst.pex.logging	lsst.log
lsst.pex.logging.getDefaultLog()	lsst.log.Log.getDefaultLogger()
lsst.pex.logging.Debug(component)	lsst.log.Log.getLogger(component)
Log(Log.getDefaultLog(), component)	Log.getLogger(component)
Trace_setVerbosity(component, num)	lsst.log.setLevel(component, level)
logger.setThresholdFor()	lsst.log.setLevel(component, level)
logger.setThreshold()	logger.setLevel()
logger.getThreshold()	logger.getLevel()
logger.logdebug()	logger.debug() or logger.trace()
#include “lsst/pex/logging.h”	#include “lsst/log/Log.h”
#include “lsst/pex/logging/Trace.h”	#include “lsst/log/Log.h”
pex::logging::Log logger()	LOG_LOGGER logger = LOG_GET()
pex::logging::Trace::setVerbosity()	LOG_SET_LVL(“component”, LOG_LVL_X)

Other common cleanups during the transition:

Explicit package dependency should be listed in the ups files (.table and .cfg).
Remove unused header inclusion or imports.
Use named logger when possible. The nameless default logger was used often and should be replaced if appropriate.
The old usage log.log(log.WARN, "message") should be changed to log.warn("message").