# Test new lsst::log logging framework

XMLWordPrintable

#### Details

• Type: Story
• Status: Done
• Resolution: Done
• Fix Version/s: None
• Component/s:
• Labels:
None
• Team:

#### Description

Try out the new lsst::log framework in a few cases, including some tasks and some C++ code that uses lsst::pex::logging::Debug and/or [T]Trace, preferably including multiple logs in one file.

For the record: many packages, including afw use [T]Trace in C++ code. Few packages use Debug at all, and meas_modelfit and xrootd are the only two I found that use it extensively.

#### Activity

Hide
Russell Owen added a comment - - edited

Notes on the port:

lsst.log has no named loggers with methods such as "debug", "info". Those exist as functions that log using name "", which is not useful. I have fixed this by adding a simple Log object to the log package. I suggest removing the functions "debug", "info", etc. at some point. This also adds the ability to create a new Log object with the same threshold as an existing one, which is important for creating tasks.

Such an object would also be useful in the C++ layer, since the usual paradigm is that a unit of code that logs messages logs them all using the same name. Thus it is convenient to create a Log object with that name and log to it.

What is the depth argument for? The Doxygen documentation does not mention it.

Does lsst.log support adding a log destination (preferably using a string value)? The pipe_tasks ArgumentParser supports this using --logdest and so far I've not found a way to emulate it using lsst.log.

Note that the numeric values for thresholds are different than in pex_logging, lsst.log and Python's standard logging module. In that order:
TRACE: N/A, 5000, N/A
DEBUG: -10, 10000, 10
INFO: 0, 20000, 20
WARN[ING]: 10, 30000, 30
ERROR: N/A, 40000, 40
FATAL: 20, 50000, 50
Do we really need all the extra resolution in lsst.log thresholds? I feel the values are inconveniently and needlessly large and we would be better off dividing them by 1000, or at least 100.

How do we want to deal with trace levels, especially the --trace argument to the pipe_tasks argument parser? pex_logging set threshold = -trace level. We can approximate this using threshold = -1000 * (trace - 20). It is not exact due to adding the ERROR level. I propose to ditch trace levels entirely, including the --trace argument and replace the functionality by enhancing --loglevel as per RFC-86.

lsst.log adds two named levels: trace and error. I worry that trace will be too easily confused with pex_logging Trace functionality. Do we really need it?

Show
Russell Owen added a comment - - edited Notes on the port: lsst.log has no named loggers with methods such as "debug", "info". Those exist as functions that log using name "", which is not useful. I have fixed this by adding a simple Log object to the log package. I suggest removing the functions "debug", "info", etc. at some point. This also adds the ability to create a new Log object with the same threshold as an existing one, which is important for creating tasks. Such an object would also be useful in the C++ layer, since the usual paradigm is that a unit of code that logs messages logs them all using the same name. Thus it is convenient to create a Log object with that name and log to it. What is the depth argument for? The Doxygen documentation does not mention it. Does lsst.log support adding a log destination (preferably using a string value)? The pipe_tasks ArgumentParser supports this using --logdest and so far I've not found a way to emulate it using lsst.log. Note that the numeric values for thresholds are different than in pex_logging, lsst.log and Python's standard logging module. In that order: TRACE: N/A, 5000, N/A DEBUG: -10, 10000, 10 INFO: 0, 20000, 20 WARN [ING] : 10, 30000, 30 ERROR: N/A, 40000, 40 FATAL: 20, 50000, 50 Do we really need all the extra resolution in lsst.log thresholds? I feel the values are inconveniently and needlessly large and we would be better off dividing them by 1000, or at least 100. How do we want to deal with trace levels, especially the --trace argument to the pipe_tasks argument parser? pex_logging set threshold = -trace level. We can approximate this using threshold = -1000 * (trace - 20). It is not exact due to adding the ERROR level. I propose to ditch trace levels entirely, including the --trace argument and replace the functionality by enhancing --loglevel as per RFC-86 . lsst.log adds two named levels: trace and error. I worry that trace will be too easily confused with pex_logging Trace functionality. Do we really need it?
Hide
Kian-Tat Lim added a comment -

I added a log object in the u/ktlim/getLogger branch, but I think you did things differently.

Log destinations are typically done through configuration. I'm not sure we need them to be set from the program (or the command-line).

I'd rather not change the numeric values of thresholds from those in log4cxx; they should never be used by users or developers anyway. There's already an adaptation from Python standard logging thresholds to the log4cxx ones, I believe.

We should dump the pex_logging Trace class, but keep the TRACE threshold level since RHL really wants something beyond DEBUG (although I argue that finer-grained components are a better solution).

Show
Kian-Tat Lim added a comment - I added a log object in the u/ktlim/getLogger branch, but I think you did things differently. Log destinations are typically done through configuration. I'm not sure we need them to be set from the program (or the command-line). I'd rather not change the numeric values of thresholds from those in log4cxx ; they should never be used by users or developers anyway. There's already an adaptation from Python standard logging thresholds to the log4cxx ones, I believe. We should dump the pex_logging Trace class, but keep the TRACE threshold level since RHL really wants something beyond DEBUG (although I argue that finer-grained components are a better solution).
Hide
Russell Owen added a comment - - edited

Regarding numeric values for logging thresholds: they may be used by users. For instance lsst.pipe.base.ArgumentParser offers two command-line arguments that accept numeric thresholds: --loglevel (which also accepts names) and --trace (which does not, and whose value is negated to make a log threshold).

One possibility is simply to multiply user-entered numbers by 1000, but I am not keen on this, as it sounds confusing to differ from the underlying log package. However, if if we replace --trace with --loglevel as per RFC-86 then we can use names for trace-like arguments, and that ought to make the use of numeric values rare enough that the large values will be tolerable.

Show
Russell Owen added a comment - - edited Regarding numeric values for logging thresholds: they may be used by users. For instance lsst.pipe.base.ArgumentParser offers two command-line arguments that accept numeric thresholds: --loglevel (which also accepts names) and --trace (which does not, and whose value is negated to make a log threshold). One possibility is simply to multiply user-entered numbers by 1000, but I am not keen on this, as it sounds confusing to differ from the underlying log package. However, if if we replace --trace with --loglevel as per RFC-86 then we can use names for trace-like arguments, and that ought to make the use of numeric values rare enough that the large values will be tolerable.
Hide
Russell Owen added a comment - - edited

Kian-Tat Lim Regarding adding a Log object, your solution on the u/ktlim/getLogger branch is more complete than mine, so I will try using it for the rest of my testing. These comments are with respect to that version of lsst.log:

lsst.log.Log has static Log::setLevel(Log logger, int level) but would it not be simpler to have non-static Log::setLevel(int level)? Similar for getting a level. In essence Log pretends as if it does not know its own name, but in reality is it possible to get that name. Similarly I'd like to see a Log::getContextName() method.

I find it confusing that lsst.log uses "level" instead of "threshold" when describing the threshold at which a logged message will be seen. I feel it conflates two different (though closely related) concepts.

I am not yet convinced that hierarchical contexts are useful. Is there an example showing why they are handier then simply specifying the full name or offering a Log::getSubLogger(subName) method?

pipe_base and pipe_tasks are done and pushed on tickets/DM-3532 but untested (since I can't yet build log on my Mac and haven't tried the code on lsst-dev). On to C++ code next.

One issue with C++ code is how to handle trace levels used by pex_logging Trace, TTrace and Debug. In pex_logging these were integers 1-9 that mapped were negated to produce log levels. Thus smaller trace levels were more important, ranging from almost as important as INFO to not quite as unimportant as DEBUG. We could simply replace them with huge integers, e.g. 1->19000 to 9->11000, but that's clearly ugly. On a HipChat discussion Tim Jenness proposed adding constants TRACE1-TRACE9 to C++ and Python (and for use on the command line). That sounds best to me since it allows us to exactly replicate the old behavior in a simple way, while avoiding use of the huge integer values for logging levels. I also propose to eliminate the TRACE constant (existing code can use TRACE5 instead).

Note that to use Log objects with these new levels we will also want new LOGLF_level macros for the new named levels. As K-T said on the HipChat discussion: The difference between fixed levels and variable levels was benchmarked at 164 nanosec per call, so fixed is nicer. This probably explains why there is no log macro that accepts a Log object and allows the user to specify an arbitrary log level.

lsst.log Log.h has too many macros, including a pair for each level that logs to the default log (with no name) and can probably be eliminated.

The difference in names between the sprintf macros and boost formatting macros is too subtle, in my opinion. I recommend we adopt one as the default standard, use short names for that version (e.g. LOG_WARN if we ditch the default log) and a longer and very clear name for the deprecated version (e.g. LOG_SPRINTF_WARN or LOG_BOOST_WARN, depending which is deprecated). Or maybe just use the long names for both. The code will be easier to read!

Show
Russell Owen added a comment - - edited Kian-Tat Lim Regarding adding a Log object, your solution on the u/ktlim/getLogger branch is more complete than mine, so I will try using it for the rest of my testing. These comments are with respect to that version of lsst.log: lsst.log.Log has static Log::setLevel(Log logger, int level) but would it not be simpler to have non-static Log::setLevel(int level) ? Similar for getting a level. In essence Log pretends as if it does not know its own name, but in reality is it possible to get that name. Similarly I'd like to see a Log::getContextName() method. I find it confusing that lsst.log uses "level" instead of "threshold" when describing the threshold at which a logged message will be seen. I feel it conflates two different (though closely related) concepts. I am not yet convinced that hierarchical contexts are useful. Is there an example showing why they are handier then simply specifying the full name or offering a Log::getSubLogger(subName) method? pipe_base and pipe_tasks are done and pushed on tickets/ DM-3532 but untested (since I can't yet build log on my Mac and haven't tried the code on lsst-dev). On to C++ code next. One issue with C++ code is how to handle trace levels used by pex_logging Trace, TTrace and Debug. In pex_logging these were integers 1-9 that mapped were negated to produce log levels. Thus smaller trace levels were more important, ranging from almost as important as INFO to not quite as unimportant as DEBUG. We could simply replace them with huge integers, e.g. 1->19000 to 9->11000, but that's clearly ugly. On a HipChat discussion Tim Jenness proposed adding constants TRACE1-TRACE9 to C++ and Python (and for use on the command line). That sounds best to me since it allows us to exactly replicate the old behavior in a simple way, while avoiding use of the huge integer values for logging levels. I also propose to eliminate the TRACE constant (existing code can use TRACE5 instead). Note that to use Log objects with these new levels we will also want new LOGLF_level macros for the new named levels. As K-T said on the HipChat discussion: The difference between fixed levels and variable levels was benchmarked at 164 nanosec per call, so fixed is nicer. This probably explains why there is no log macro that accepts a Log object and allows the user to specify an arbitrary log level. lsst.log Log.h has too many macros, including a pair for each level that logs to the default log (with no name) and can probably be eliminated. The difference in names between the sprintf macros and boost formatting macros is too subtle, in my opinion. I recommend we adopt one as the default standard, use short names for that version (e.g. LOG_WARN if we ditch the default log) and a longer and very clear name for the deprecated version (e.g. LOG_SPRINTF_WARN or LOG_BOOST_WARN, depending which is deprecated). Or maybe just use the long names for both. The code will be easier to read!
Hide
Russell Owen added a comment - - edited

Steps for converting C++ code:

• Remove setDestination statements because lsst.log already logs to stdout if not otherwise specified, e.g. remove

 .*Trace::setDestination.*\n

• Replace all includes of pex/logging files, e.g.:

 #include "lsst/pex/logging.*

with

 #include "lsst/log/Log.h"

• Replace Trace::setVerbosity with setLevel, e.g. replace

 ( +).*Trace::setVerbosity$$(".*"), (\d)$$;

with

 \tlsst::log::Log::setLevel(\2, TRACE\3);

• Replace TTrace<n>(name, msg,...) with LOGL_TRACEn(name, msg,...) if using sprintf formatting (as current code does) e.g. replace

 ( *).*TTrace<(\d)> *$$(.*)$$;

with

 \1LOGL_TRACE\2(\3);

• Some afw code (formatters) define a function execTrace that calls Trace, and this function uses a default trace level of 20, which is out of our usual trace range. However, I believe 20 can easily be replaced with TRACE9, because no other code uses a trace level as low as 9. To convert this code I added a _log object to the formatter objects and replaced every call to execTrace with LOGL_TRACE9. This reduces overhead by creating only one Log object and re-using it. Also, Kian-Tat Lim reports that it is faster to log to a Log object than using a string for a name.
• Uses of pex::logging::Debug and pex::logging::Trace can switch to lsst::log::Log with appropriate trace levels. If the code logs multiple messages from one piece of code then create a Log object and log to that with macros. Otherwise, one can log using a string for the log name.
• Users of pex::logging::Log can switch to lsst::log::Log; the first argument to the former is a default log object, which is not needed or wanted by log.
• Logging using boost::format should change by eliminating the boost::format() wrapper around the format string, still listing the arguments afterwards with % separators and use LOGLF_<level>. I admit I am not thrilled with this; it looks strange and hides the fact that we are using boost::format. But it appears to be the right way to do things based on log's tests//logTest.cc.
Show
Russell Owen added a comment - - edited Steps for converting C++ code: Remove setDestination statements because lsst.log already logs to stdout if not otherwise specified, e.g. remove .*Trace::setDestination.*\n Replace all includes of pex/logging files, e.g.: #include "lsst/pex/logging.* with #include "lsst/log/Log.h" Replace Trace::setVerbosity with setLevel, e.g. replace ( +).*Trace::setVerbosity$$(".*"), (\d)$$; with \tlsst::log::Log::setLevel(\2, TRACE\3); Replace TTrace<n>(name, msg,...) with LOGL_TRACEn(name, msg,...) if using sprintf formatting (as current code does) e.g. replace ( *).*TTrace<(\d)> *$$(.*)$$; with \1LOGL_TRACE\2(\3); Some afw code (formatters) define a function execTrace that calls Trace , and this function uses a default trace level of 20, which is out of our usual trace range. However, I believe 20 can easily be replaced with TRACE9 , because no other code uses a trace level as low as 9. To convert this code I added a _log object to the formatter objects and replaced every call to execTrace with LOGL_TRACE9 . This reduces overhead by creating only one Log object and re-using it. Also, Kian-Tat Lim reports that it is faster to log to a Log object than using a string for a name. Uses of pex::logging::Debug and pex::logging::Trace can switch to lsst::log::Log with appropriate trace levels. If the code logs multiple messages from one piece of code then create a Log object and log to that with macros. Otherwise, one can log using a string for the log name. Users of pex::logging::Log can switch to lsst::log::Log ; the first argument to the former is a default log object, which is not needed or wanted by log . Logging using boost::format should change by eliminating the boost::format() wrapper around the format string, still listing the arguments afterwards with % separators and use LOGLF_<level>. I admit I am not thrilled with this; it looks strange and hides the fact that we are using boost::format. But it appears to be the right way to do things based on log's tests//logTest.cc .
Hide
Russell Owen added a comment -

I did this awhile ago, based on what was in the log package at the time. As per the above comments, some changes are suggested before we replace pex_logging in the DM stack. I had left this open expecting such changes to occur sooner, but at this point I suggest opening a new ticket when we are ready to revisit this topic.

Show
Russell Owen added a comment - I did this awhile ago, based on what was in the log package at the time. As per the above comments, some changes are suggested before we replace pex_logging in the DM stack. I had left this open expecting such changes to occur sooner, but at this point I suggest opening a new ticket when we are ready to revisit this topic.

#### People

Assignee:
Russell Owen
Reporter:
Russell Owen
Watchers:
Hsin-Fang Chiang, Kian-Tat Lim, Russell Owen, Tim Jenness, Yusra AlSayyad