wiki:LoggingHowto
Last modified 10 years ago Last modified on 12/08/2008 03:46:56 PM

Using the Logging Framework

The Logging framework (found in the pex_logging package) provides interfaces for recording timestamped messages from any place in our software. Log users generally do not need to worry about configuring Logs or even care where the messages are going. They mainly need to:

  • grab the default log (or create a log from the default log)
  • send messages to the log.

Most messages will be simple text; however, it also possible to attach arbitrary data properties to a log message.

In DC2, we 2 ways of spitting out messages: logging and tracing. In DC3, tracing (meant for debug messages) is being integrated into logging framwork. Logging differs from DC2 tracing in that:

  • all messages are timestamped
  • it is designed for operating in a parallel environment
  • the messages are recorded for review and analysis later.

(More information about tracing and debug messages will be available with the next version of the logging package.)

The logging framework supports a notion of hierarchical topics. A Log object is attached uniquely to a single topic; when messages sent to a Log get recorded, the record will be tagged with the topic name. The so-called root log is the Log attached to the root of the topic hierarchy (having a zero-length topic name). Child logs, or more generally, descendent logs, can be created from any Log instance; their names have a dot-delimited form like "harness.slice.process". Topic names are typically chosen to identify the piece of code that is sending the message.

In addition to this document, you can learn more about how to use the logging framework by consulting the doxygen documentation for the Log.h source file as well as examples/log.cc and examples/log.py files.

Basics

We'll start with some typical uses; the latter sections provide more explanation. First, in python:

   import lsst.pex.logging as log
   from lsst.pex.logging import Log, Rec, Prop

   # create a log for my application
   mylog = log.Log(log.getDefaultLog(), "harness.slice")

   # send a simple message to the log
   mylog.log(Log.INFO, "Constructing the Slice")

   # attach a property (note: normally, properties are not printed to the screen by default)
   Rec(mylog, Log.WARN) << "Premature end of pipeline" << Prop("nimages", 5) << Rec.endr

The same in C++:

#include "lsst/mwi/logging/Log.h"

using lsst::mwi::logging::Log;
using lsst::mwi::logging::Rec;
using lsst::mwi::logging::Prop;

{
   Log mylog(Log::getDefaultLog(), "harness.slice");

   // send a simple message to the log
   mylog.log(Log::INFO, "Constructing the Slice");

   // attach a property; not that Prop is a templated item
   Rec(mylog, Log::WARN) << "Premature end of pipeline" << Prop<int>("nimages", 5) << Rec::endr
}

Getting the Root Log

It is intended that a root log is created and configured right at the beginning of a program to fit the context of the application execution. Application code (i.e. stage implementations and the application classes it uses) generally should not be creating their own root log. Instead, application code should retrieve the root log from the getDefaultLog() function. For example, in python,

   import lsst.pex.logging as log

   // notice that this function is a member of the lsst.pex.logging module
   root = log.getDefaultLog()

It is similar in C++:

   using lsst::pex::logging::Log;

   // notice that this function is a static function of the 
   // lsst::pex::logging::Log class
   Log root = Log::getDefaultLog();

You can now start sending logging messages (see next section); although, it is more typical to first create a child log with a topic that identifies the code that will be sending messages (see "Child Logs" below).

What happens to messages sent to this root log depends on the context? Within your test and example programs, the default log is configured to send messages just to the screen (and the verbosity threshold is set to INFO; see below). In the context of the pipeline harness, the default log is configured to send messages to the event stream where all messages from all nodes are aggregated together and saved into a database, as well as written to a file.

Child Logs

The purpose of the topic name is to give some indication of where in the system the message is coming from. The hierarchical nature of the names is intended to reflect the hierarchical structure of the call stack or container relationship the objects producing the messages (the choice is up to the user). For example, a sequence of code that uses the name "harness.slice" is expected to be "inside" the sequence that uses the name "harness". In the parlence of the logging framework, the log with the name "harness" is considered the parent log to the log with the name "harness.slice", the child log.

When you create a child log, it inherits the configuration of its parent, including the destinations of the messages and the verbosity threshold (unless explicitly overridden; see below). To create a child log, one normally passes the desired parent node to the Log constructor:

    // create a child of the root log called "harness
    Log harnesslog(Log::getDefaultLog(), "harness");

    // create a grandchild of the root log, "harness.slice", via the child log
    Log slicelog(harnesslog, "slice");

    // create a grandchild of the root log, "harness.pipeline", via the root log
    Log pipelinelog(Log::getDefaultLog(), "harness.pipeline");

Notice that the name passed in is not the full name of the log but just part relative to the name of the log it is constructed from.

There is also a factory method for child logs that return them as pointers appropriate for wrapping as shared pointers:

    // create a log pointer
    shared_ptr<Log> logptr(Log::getDefaultLog().createChildLog("harness.pipeline"));

A word about choosing log topic names

In many cases, it may seem natural to pick log topic names to simply reflect the name of the class using the log, e.g.

class MyClass {
private:
    Log _log;
public:
    MyClass() : _log(Log::getDefaultLog(), "MyClass") {

    }

However, if this class is used in more than one context, then you can't really use the topic name to distinguish them. It's better if the names reflect either the container relationship of class instances or the call stack. That way, you can more easily select log messages from class A when called from class B. To enable this, you might consider passing either topic names (as illustrated in the recipe of the preceding section) or parent log objects themselves as arguments to constructors and/or functions.

Verbosity and Thresholds

Like Trace, the user has the ability to control the verbosity of the log by setting a threshold of importance that the message must meet in order to be recorded. One can set the threshold either as part of the construction of the Log or explicitly via the setThreshold() method.

   mylog = Log(Log.getDefaultLog(), "harness.slice", Log::INFO)   // INFO, WARN, and FATAL messages will get recorded
   mylog.log(Log::INFO, "log created");                           // This will get recorded

   mylog.setThreshold(Log::WARN)                    // Now less verbose, passing only WARN and FATAL messages.  
   mylog.log(Log::INFO, "log threshold set")        // This will *not* get recorded

If the threshold is not set explicitly at construction or later, the threshold will be set to that of the so-called parent log that it was constructed from (in the above case, the root log). More specifically, the threshold will change as the parent log's threshold changes until it is explicitly overridden.

Note that once the verbosity threshold has been set for a Log with a particular topic name, it will be remembered even after that Log object has been deleted.

If you have a class that will be sending log messages in a variety of places, here's a recommended recipe:

  1. Add a log object (or a shared_ptr if you prefer) to your set of private data members
    private:
        Log log;
    
  2. Initialize it in your constructor, setting the desired threshold.
        MyClass(const string& logtopic) : _log(Log::getDefaultLog(), logtopic) {
            _log.setThreshold(Log::WARN);
        }
    
  3. Use your private log directly or create children from it as necessary
        void MyClass::transform() {
            log(_log, "transform");   // has the name logtopic+".transform"
    
            log.log(Log::INFO, "starting transform")  
        }
    

Simple messages

A simple logging message is just a line of formatted text. To send one, you can use the log() function (in python):

   log.log(Log::INFO, "Starting PSF determination")   # this is an informational message
   log.log(Log::WARN, "Using default values")         # this is a warning message

The first argument sets the verbosity level of the message based on the type of message it is. The predefined verbosity levels include (in order) DEBUG, INFO, WARN, and FATAL. (See next section.)

In C++, you can also make use of the boost::format to do formatted messages:

   log.log(Log::DEBUG, boost::format("Finished %d iterations") % niter);

however, be careful: you will always pay the cost of formatting a message created in this way, even if the log verbosity causes it not to be sent.

Note: It is expected that we will add support for internal use of boost::format via a "varargs" signature, much like has been done for Trace.

Creating your own root Log

As mentioned above, if you do logging outside of the pipeline framework, the default log is configured to just print log messages to the screen. If you want take more control within, say, a test program or script, then you can create your own root log. The Log constructors provides full flexibility for configuring the destinations for log messages. However, there are some special purpose Log sub-classes that provide common configurations.

If you want, for example, to send messages to both the screen and a log file, you can create a DualLog to use instead:

from lsst.mwi.logging import DualLog, Log

filethreshold = Log.DEBUG
screenthreshold = Log.WARN
mylog = DualLog("test.log", filethreshold, screenthreshold)

mylog.log(Log.INFO, "starting test")

You probably will want to make this the default log so that your classes can access it via getDefaultLog(). To do this, use createDefaultLog():

from lsst.mwi.logging import DualLog, Log

filethreshold = Log.DEBUG
screenthreshold = Log.WARN
DualLog.createDefaultLog("test.log", filethreshold, screenthreshold)
mylog = Log.getDefaultLog()

mylog.log(Log.INFO, "starting test")

In the both examples, the file will accept messages with a DEBUG loudness or louder, while the screen will only get WARN and FATAL messages.

Note that the logging framework actually uses two different thresholds. One is the threshold we've seen so far: it controls what messages get received from the client. There is also a second threshold that sits in front of the log destination. Thus each destination can have its own threshold. Remember, though, it the client-side threshold blocks a message, it will not get recorded anywhere, regardless of the destination thresholds.

Including Data Properties

You can tag your log messages with arbitrary data properties. To do this, you use a streaming interface. For example, in C++:

    using lsst::mwi::Rec;
    using lsst::mwi::Prop;

    Rec(mlog, Log::WARN) << "No convergence reached"
                         << Prop("iterations", 541)
                         << Prop("rms", 0.0032)
                         << Rec::endr;

In python:

    from lsst.mwi.logging import LogRec

    Rec(mlog, Log.WARN) << "No convergence reached"
                        << Prop("iterations", 541)
                        << Prop("rms", 0.0032)
                        << Rec.endr;

Note: If you write a little test python script that uses the above example, you may not actually see the comments getting printed. This is because the default Log has been configured only to print the text part of the message to the screen. The default Log in this case is a ScreenLog. If you create one of these your self (see previous section), you can display the message by using its setScreenVerbose() function:

    mylog = ScreenLog()
    mylog.setScreenVerbose(True)

The DualLog class supports this as well.

You can also send a whole PropertySet along with a log message. In C++:

    PropertySet ps;
    // set the contents of the PropertySet

    Rec(mlog, Log::INFO) << "switching algorithms" << ps << Rec::endr;

In python, a dictionary will stand in for a PropertySet:

    ps = { "iterations": 458, "rms": 0.00245, "converged": False } 
    Rec(mlog, Log.INFO) << "working with properties" << ps << Rec.endr;

Note that it is possible to send properties of any type to the log without failure; however, only a limited set of types will actually get recorded. These types include: int, long, long long, float, double, bool, and string.

FAQ

1. What's the difference between ''logging'' and ''tracing''?
2. What is a root log?
2. Why/When should I create a child log?
4. How do I send messages to both the screen and a file?
5. How do I make the log file output more verbose than the screen?
6. I'm not seeing the DataProperties I send showing up on the screen; what happened to them?
1. What's the difference between ''logging'' and ''tracing''?

2. What is a root log?

3. Why/When should I create a child log?

4. How do I send messages to both the screen and a file?

5. How do I make the log file output more verbose than the screen?

6. I'm not seeing the DataProperties I send showing up on the screen; what happened to them?