This is a continuation of RFC-29, and narrower in scope.

I would like to switch from using pex.logging to lsst.log in pipe_base. After that, all pipeline tasks (task or cmdLineTask) can switch to use lsst.log. With lsst::log (via log4cxx implementation) there are 6 logging levels (trace, debug, info, warn, error, fatal). Arbitrary integers will no longer be accepted as levels. In this framework it’s encouraged to use loggers with distinct, hierarchical names instead of custom levels.

In Python, I plan to use the recently added lsst.log Python interface, not through Python logging and LogHandler. For example:

  logger = lsst.log.Log.getLogger(“a.named.logger”)

  logger.setLevel(Log.INFO)

  logger.trace("This is TRACE")

  logger.debug("This is DEBUG")

  logger.info("This is INFO")

  logger.warn("This is WARN")

  logger.error("This is ERROR")

  logger.fatal("Format %d %g %s", 3, 2.71828, "foo")

For most tasks, little modifications are needed in Python, as long as the task’s own log attribute is used for logging. The “logdebug” method in pex_logging will be replaced by “debug”, and most will be format changes.

For CmdLineTasks, the namespace logging level control from the command line -- loglevel is preserved. The command line option -- logdest will be removed; the file destination is instead set through log4cxx configuration. As I understand, many people use this option for its default formatter with dataId attached with each log record. After switching to lsst::log, dataId can still be included in the logs. I’m thinking two possibilities: an command line option to include the dataId in log records, or an command line option to more easily supply user’s own log4cxx configuration file in which format can be set.

In C++, macros are used, e.g.

    LOG_LOGGER logger = LOG_GET(“a.named.logger“);

For logging one can use either one of the two macro families, the sprintf-based interface:

    LOGL_INFO(logger, "This is INFO");

    LOGL_WARN(“a.named.logger“, "This is WARN");

    LOGL_FATAL(logger, "This is FATAL %d %.4f %s", 65, 42.123, "logging");

and the iostream-based interface:

    LOGLS_INFO(logger, "Format " << 3 << " " << 2.71828 << " foo c++");

    LOGLS_WARN(“a.named.logger“, "This warning is” << “scary”);

The transition plan is to do this in stages: (1) individual logging not chained to CmdLineTask (e.g. daf_butlerUtils, or hard-coded and non-configurable logging), as they are not configurable through the command line task interface anyway. (2) Python-side logging for tasks/CmdLineTasks plus log in C ++. (3) Debug/Trace in C ++. They are typically run with unit tests and each package can be handled separately.

(Proposed documentations)

Use of logger names and log levels

Logger names should generally start with the (fully-qualified) name of the module/file containing the logger. 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++.

Example:

log = lsst.log.Log.getLogger("meas.algorithms.starSelector")

log.info("This is information about the star selector algorithm execution. %f", 3.14)

In Python, comma-separated arguments are preferred over the string formatting so it is done only if the log record is to be printed.

Log levels should be used 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
• WARNING: 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.

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.

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 "TRACE1", "TRACE2", "TRACE3", etc. to indicate increasing verbosity.

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)

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);

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".

Getting a logger object and logging to that is preferred over logging using a string as the logger name. The latter can be used, for examples:

lsst.log.log("meas.algorithms.starSelector.psfCandidate", lsst.log.WARN, "Failed to make a psfCandidate")

lsst.log.log("TRACE4.meas.algorithms.starSelector.psfCandidate", lsst.log.DEBUG, "Making a psfCandidate from star %d=", starId)

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

LOGL_DEBUG("TRACE4.meas.algorithms.starSelector.psfCandidate", "Making a psfCandidate from star %d=", starId)

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