Logging framework transition

Data Management DM Notifications
#1

With the merge of DM-6999, Task’s logs are now switched to use lsst.log instead of lsst.pex.logging per RFC-203. A few outstanding differences you may notice:

Levels

  • lsst.pex.logging has four formal levels: DEBUG (-10) < INFO (0) < WARN (10) < FATAL (20), but also allows any integers to be used as a verbosity level through its Trace and Debug. Typically the tracing verbosity number are between -1 to -9.
  • lsst.log has six formal levels: TRACE < DEBUG < INFO < WARN < ERROR < FATAL

From the discussions at AHM, we found out that it was surprising to some developers that pex.logging DEBUG is typically more verbose than pex.logging Trace. And decided to generally convert pex.logging DEBUG logs (through log.logdebug()) to lsst.log log.debug() unless there are reasons otherwise.

For running command line tasks, the --loglevel command line argument can still be used as a logging level control. However it no longer accepts arbitrary numbers. Level of specific components can be set like before. For example, --loglevel ERROR processCcd.calibrate=DEBUG will show log messages at ERROR level or above, but show log messages under namespace processCcd.calibrate at DEBUG level or above.

The --logdest command line argument is removed. As I understand many people use this option for its default formatter with dataId attached with each log record. An --longlog option is added, and that will give you a format with the data ID included in each task log record.

pex.logging Trace/Debug used in c++ code is not changed in this ticket. pex.logging dependency is not completely removed in some pipeline packages.

Please let me know or file tickets to me if you see issues related to these changes. The conversion of the log records is not a one-to-one mapping, and in some cases it might make sense to refactor the codes to better take advantage of the log package. For more details of the log package, please see here and RFC-203.

1 Like
DM Weekly Highlights 2016-08-31 to 2016-09-06
#2

Neat.

Do you recommend using this in our unittests? Many tests have either if verbose: print("debug message"), or even just naked print statements, and it would be helpful to have a better way to manage such output. If you have an example of using lsst.log in a test, I’d be interested in seeing it.

#3

If you want the output to be captured by the test runner then you need to print it (to stdout or stderr). If you want it to appear in a log file for later inspection then use the logger. We might need to adjust Jenkins to make log files available through the web interface. This would be especially important if you want them to be readable even if a build is successful. Of course, SQuaRE might have a much cleverer scheme for harvesting logs from CI runs. @josh?

One thing I learned today was that if you send something to stdout/stderr in the test module code outside the test class, then pytest will drop it on the floor – the messages have to be associated with a specific test.

#4

I think the plan is to use our Logstash → Elasticsearch → Kibana stack deployment. Kibana being the awesome log dashboard.

#5

Since we can’t control a verbose variable from the test runner it does make sense for these to go to a logger and have Jenkins enable full debugging logs.

#6

My first thought is to get a logger in your unit test, and log to it in the debug or trace level. You can control whether the debug messages are shown. For example,

logger = lsst.log.Log.getLogger("testGreatNewFeature")
logger.debug("helpful messages of interest to developers but not of interest during production")
logger.trace("detailed messages when debugging")

The current default level is INFO and log outputs to stderr, but this is configurable. One way to set the level for your logger:
logger.setLevel(lsst.log.DEBUG)
to see messages at DEBUG or above.

pipe_tasks testPhotoCal.py is an example in the stack.

As for whether the outputs are captured by Jenkins, I think SQusRE has plans, as mentioned. They might write or use a suitable appender to direct all logs. Maybe for easier overall control it’s worth having a convention for tests’ logger names, if log records from tests should be treated somewhat differently from log records from the science code.

#7

One extra note…

Before the C++ codes are converted to use lsst.log, the --loglevel command line argument cannot control the log level for those c++ log records (because they still use lsst.pex.logging). From RFC-203 I understand that developers typically use them with unit tests, so I hope the inconvenience is not too horrible. pex.logging Trace_setVerbosity can still be used in unit tests or wherever in your code or executable for debugging, as they are independent from the command line task interface. Similarly, individual logging not through the Task framework may not be controllable through the command line task interface, unless they use lsst.log.