XMLWordPrintable

#### Details

• Type: RFC
• Status: Implemented
• Resolution: Done
• Component/s:
• Labels:
None

#### Description

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.

#### Activity

Hide
Hsin-Fang Chiang added a comment -

DM-8009 is added to reduce verbosity in starting tasks and changing those lines in Robert Lupton's snippet to DEBUG. If you have opinions about that please leave comments in that ticket.

Show
Hsin-Fang Chiang added a comment - DM-8009 is added to reduce verbosity in starting tasks and changing those lines in Robert Lupton 's snippet to DEBUG. If you have opinions about that please leave comments in that ticket.
Hide
Tim Jenness added a comment -

All triggering tickets are complete. Hsin-Fang Chiang are we waiting on DM-7997 before marking this RFC implemented? If we are please, change the linkage, else mark as implemented.

Show
Tim Jenness added a comment - All triggering tickets are complete. Hsin-Fang Chiang are we waiting on DM-7997 before marking this RFC implemented? If we are please, change the linkage, else mark as implemented.
Hide
Hsin-Fang Chiang added a comment -

Adding DM-7000 as the last ticket triggered by this RFC.

I'm not sure what the recent replan/WBS changes mean to the logging framework transition work; if Fritz Mueller Joel Plutchak John Swinbank Simon Krughoff do not object, I will plan to do DM-7000 later this cycle. Please advise if that should be assigned differently.

Show
Hsin-Fang Chiang added a comment - Adding DM-7000 as the last ticket triggered by this RFC. I'm not sure what the recent replan/WBS changes mean to the logging framework transition work; if Fritz Mueller Joel Plutchak John Swinbank Simon Krughoff do not object, I will plan to do DM-7000 later this cycle. Please advise if that should be assigned differently.
Hide
John Swinbank added a comment -

Formally, none of the replan changes take effect until after a baseline change request has been approved, which won't be until next year.

Practically, the plan for the rest of this cycle (which is only the next three and a bit weeks) is already locked in.

The upshot is: I certainly don't object to Hsin-Fang Chiang's plan.

Show
John Swinbank added a comment - Formally, none of the replan changes take effect until after a baseline change request has been approved, which won't be until next year. Practically, the plan for the rest of this cycle (which is only the next three and a bit weeks) is already locked in. The upshot is: I certainly don't object to Hsin-Fang Chiang 's plan.
Hide
Hsin-Fang Chiang added a comment -

With the merge of DM-7000, pipe_tasks no longer depends on pex_logging.

Although beyond the scope of this RFC, I filed a few tickets for some downstream packages that still use pex_logging: ci_hsc DM-8356, meas_modelfit DM-8357, meas_mosaic DM-8358, ctrl_pool DM-8359 for the TCAMs to decide where they should go.

Show
Hsin-Fang Chiang added a comment - With the merge of DM-7000 , pipe_tasks no longer depends on pex_logging . Although beyond the scope of this RFC, I filed a few tickets for some downstream packages that still use pex_logging : ci_hsc DM-8356 , meas_modelfit DM-8357 , meas_mosaic DM-8358 , ctrl_pool DM-8359 for the TCAMs to decide where they should go. This page has been used to track the migration progress: https://confluence.lsstcorp.org/display/DM/Logging+Migration

#### People

Assignee:
Hsin-Fang Chiang
Reporter:
Hsin-Fang Chiang
Watchers:
Gregory Dubois-Felsmann, Hsin-Fang Chiang, Jim Bosch, John Swinbank, Kian-Tat Lim, Merlin Fisher-Levine, Paul Price, Robert Lupton, Russell Owen, Tim Jenness
0 Vote for this issue
Watchers:
10 Start watching this issue

#### Dates

Created:
Updated:
Resolved:
Planned End:

#### Jenkins

No builds found.