This page provides guidance to developers for using logging with
lsst.log in the Science Pipelines code base.
Developers are encouraged to insert log messages whenever and wherever they might be useful, with appropriate component names and levels.
Logger names should generally start with the fully qualified name of the module/file containing the logger, without the leading
Some example logger names are
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)
In Python, 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.
To specify the threshold or the lowest-severity log messages a logger handles,
setLevel can be used:
Basic Usage in C++¶
lsst.log in C++, the header file to include is:
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")
lsst.log has six levels; in increasing order of severity the are:
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)
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.CmdLineTask) should use the
lsst.pipe.base.Task.log attribute logger:
self.log.debug("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 command line tasks, the
--loglevel command line argument can be used to set the threshold for specific components.
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.debug("Reading catalog %s", 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.,
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
Below, some examples are listed that may be used as a starting point for porting:
|Trace_setVerbosity(component, num)||lsst.log.setLevel(component, level)|
|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()|
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