LSSTApplications  10.0-2-g4f67435,11.0.rc2+1,11.0.rc2+12,11.0.rc2+3,11.0.rc2+4,11.0.rc2+5,11.0.rc2+6,11.0.rc2+7,11.0.rc2+8
LSSTDataManagementBasePackage
lsst::log; the LSST Logging Framework
Warning
This package still under development. Development on LSST Science Pipelines should continue to use lsst::pex::logging until lsst::log has been approved for general use. See RFC-29 for further discussion.

Features

Basic C++ examples

The varargs/printf style interface: 

subject = "important stuff";
LOG("myLogger", LOG_LVL_INFO, "Here is some information about %s.", subject);

The boost::format style interface: 

subject = "important stuff";
LOGF("myLogger", LOG_LVL_INFO, "Here is some information about %s." % subject);

Using the default logger: 

LOG_DEBUG("My debugging statement.")

A logger object may be retrieved and used to avoid the cost of excessive lookups: 

LOG_LOGGER logger = LOG_GET("myLogger");
LOG(logger, LOG_LVL_WARN, "Here is a warning sent using a logging object.");

Basic Python examples

subject = "important stuff"
lsst.log.log("myLogger", lsst.log.INFO, "Here is some information about %s.", subject)



lssglog.debug("My debugging statement.")

The standard Python logging module may also be used: 

lgr = logging.getLogger()
lgr.setLevel(logging.INFO)
lgr.addHandler(lsst.log.LogHandler())
lgr.info("This is an info statement via the logging module.")

Example output

20140313 00:30:06,226 0x7f1f06bf6700 INFO  Here is some information about important stuff.
20140313 00:30:06,226 0x7f1f06bf6700 DEBUG My debugging statement.



2014-03-05 17:04:32,380 [0x7feca357e700] INFO  myLogger qserv::master::AsyncQueryManager::add (bld/control/AsyncQueryManager.cc:149) - Here is some information about important stuff.

The first two examples above use the following formatting string to display the date, time, thread id, log level, and log message: 

"%d{yyyyMMdd HH:mm:ss,SSS} %t %-5p %m%n"

The last example above uses the following formatting string to display the date, time, thread id, log level, logger name, function, source file, source line number, and log message: 

"%d [%t] %-5p %c{2} %M (%F:%L) - %m%n"

Logging Functions

In C++, the following varargs/printf style logging macros are available:

In addition to the above macros, in C++, the following boost::format style logging macros are offered:

In Python, the following logging functions are available in the lsst.log module. These functions take a variable number of arguments following a format string in the style of printf(). The use of *args is recommended over the use of the % operator so that formatting of log messages that do not meet the level threshold can be avoided.

Initialization

The underlying log4cxx system can be initialized explicitly from either the C++ or Python layers or default-initialized.

In C++, the following macros can be used:

In Python, the following function is available in the lsst.log module:

If none of the above methods is called by user code then logging is default-initialized and configured according to the rules described below.

Configuration

The logging system is configured either using a standard log4cxx XML config file, a standard log4j Java properties, or using the default configuration. While log4cxx allows for programmatic configuration, as of this writing, only the adjustment of logging level threshold (see below) is exposed via the lsst.log API. All other configuration (e.g. outputs and formatting) are controlled via a configuration file.

In the absence of an explicit call to one of the configuration macros, lsst.log tries first to configure itself from a default configuration file. The name of this default confgiuration file is determined from a value of LSST_LOG_CONFIG environment variable. If this variable is set and points to an existing readable file then that file is used for configuration. It can be in one of the formats supported by LOG_CONFIG(filename). If LSST_LOG_CONFIG is not set or its value does not refer to readable file then log4cxx is configured using log4cxx's BasicConfigurator, which is hardwired to add to the root logger a ConsoleAppender. In this case, the output will be formatted using a PatternLayout set to the pattern "%-4r [%t] %-5p %c %x - %m%n".

The same configuration algorithm applies to the C++ macro LOG_CONFIG() and the Python lsst.log module function configure(), which do not take a file path argument (which makes calls to this method/macro optional).

Below is an example of an XML file that configures three appenders and two loggers: the root logger and the named logger "debugs". Each of the appenders contains a layout that defines which metadata to display and how to format log messages.

<?xml version="1.0" encoding="UTF-8" ?>
 <log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

  <appender name="appxConsoleAppender" class="org.apache.log4j.ConsoleAppender">
    <param name="Target" value="System.out"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{yyyyMMdd HH:mm:ss,SSS} %t %-5p %m%n"/>
        </layout>
  </appender>


  <appender name="appxFileAppender" class="org.apache.log4j.FileAppender">
    <param name="file" value="/u1/bchick/sandbox2/modules/var/log/qserv-master.log" />
    <param name="append" value="true" />
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%d %-5p %c{2} - %m%n" />
    </layout>
  </appender>


  <appender name="debugsAppender" class="org.apache.log4j.FileAppender">
    <param name="file" value="/u1/bchick/sandbox2/modules/var/log/debugs.log" />
    <param name="append" value="true" />
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%d [%t] %-5p %c{2} %M (%F:%L) - %m%n" />
    </layout>
  </appender>

  <root>
        <priority value="info" />
        <appender-ref ref="appxFileAppender"/>
        <appender-ref ref="appxConsoleAppender"/>
  </root>


  <category name="debugs" additivity="false" >
        <priority value ="debug" />
        <appender-ref ref="debugsAppender"/>
  </category>

 </log4j:configuration>

The root logger is setup to append to both the console and the file var/log/qserv-master.log with a threshold of "INFO". The named logger "debugs", meanwhile, is set to exclusively append to the file var/log/debugs.log with a threshold of "DEBUG". In this way, "debugs" may capture and isolate verbose debugging messages without polluting the main log. This behavior is triggered by setting the additivity attribute of the category tag to "false". If additivity were set to "true" (the default value), all messages sent to "debugs" that met its threshold of "DEBUG" would also be sent to the console and var/log/qserv-master.log, the targets of the appenders associated with the root logger.

Note that as an alternative to XML, a configuration file containing log4j Java properties may be used. Here's a trivial example of a log4j properties file that corresponds to the BasicConfigurator previously mentioned: 

# Set root logger level to DEBUG and its only appender to A1.
log4j.rootLogger=DEBUG, A1

# A1 is set to be a ConsoleAppender.
log4j.appender.A1=org.apache.log4j.ConsoleAppender

# A1 uses PatternLayout.
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n

Values in the configuration file can include Unix environment variables using the "`${ENVVAR}`" notation. In addition, "`${user.home}`" and "`${user.name}`" may be useful substitutions. Note that "`~`" substitution does ''not'' work.

Useful appenders include:

For the PatternLayout, all the conversion specifiers from this document should work.

Read more about log4cxx configuration here.

Programmatic Control of Threshold

The threshold level of any logger can be set or queried programmatically in both the C++ and Python layers.

In C++, the following macros are available:

In Python, the lsst.log module includes the following functions and variables:

Logging Contexts

The logging context is maintained via a global stack onto which names can be pushed and popped using the lsst.log macros LOG_PUSHCTX(name) and LOG_POPCTX() within C++ or the lsst.log functions pushContext(name) and {{{popContext()}}} within Python. The default logger name is dynamically constructed each time a name is pushed onto or popped from the logging context. For example, within the Qserv demo, the following code can be found within app.py: 

lsst.log.initLog("/u1/bchick/sandbox2/modules/etc/Log4cxxConfig.xml")
lsst.log.pushContext("czar")
[...]
lsst.log.debug("This is a debug statement!")

The debugging statement is sent to the default logger, which in this case is ''czar''. Later, within the {{{submitQuery3()}}} function of {{{control/dispatcher.cc}}}, we have: 

LOG_PUSHCTX("control");

At this point, any logging statements that do not specify a logger name will be associated with a default logger of ''czar.control''. This mechanism allows dynamic hierarchical logging without hardcoding full logger names in order to accommodate better code re-use. Logging could then be configured, for example, so that the ''czar.control'' context is redirected or copied to a special file with a unique logging level.

To pop a name from the logging context, invoke the {{{lsst.log.popContext()}}} function within Python or the {{{LOG_POPCTX()}}} macro within C++.

The context determines the default logger, which is used whenever a logger is not explicitly indicated or an empty string is provided as the logger name.

To summarize, within C++, we have the following macros:

And in Python, the following functions are available in the lsst.log module:

Context Objects

Requiring that developers properly pop each context name is error prone. Therefore, we also provide logging context objects in both C++ and Python, which automatically pop names when the object is discarded.

In C++, the context object will pop the provided name in its destructor. Contexts can therefore be managed as follows: 

{
    LOG_CTX context("demo");
    LOG_INFO("Info statement within demo context.");
}
LOG_INFO("Info statement outside demo context.");

In this example, if the context were initially "nameOne.nameTwo", the first logging statement would be sent to the logger named "nameOne.nameTwo.demo" and the second logging statement would be sent to the logger named "nameOne.nameTwo".

The LogContext class defined in the Python layer is compatible with Python's with statement, and therefore, the above example can be implemented in Python as follows: 

with LogContext(name="demo") as context:
    lsst.log.info("Info statement within demo context.")
lsst.log.info("Info statement outside demo context.")

Fine-level Debugging Example

The following is a simple recipe for emulating additional debugging levels using the above API within Python. Analogous code can be readily written in C++ using the corresponding macros.

def debugLoggerName(num):
    """
    Returns the logger name that corresponds to fine-level debugging number NUM.
    """
    return '%s.debug%d' % (lsst.log.getDefaultLoggerName(), num)

def debugAt(num, fmt, *args):
    """
    Sends the log message created from FMT and *ARGS to the logger corresponding to fine-level debugging number NUM.
    """
    lsst.log.log(debugLoggerName(num), lsst.log.DEBUG, fmt, *args)

def debugSetAt(num):
    """
    Adjusts logging level thresholds to emulate debugging with fine-level NUM.
    """
    for i in range(5):
        lsst.log.setLevel(debugLoggerName(i), lsst.log.INFO if i < num else lsst.log.DEBUG)

debugSetAt(1)
debugAt(1, "Debug 1 statement that will display")
debugAt(2, "Debug 2 statement that will display")
debugAt(3, "Debug 3 statement that will display")
debugAt(4, "Debug 4 statement that will display")
debugAt(5, "Debug 5 statement that will display")
debugSetAt(2)
debugAt(1, "Debug 1 statement that will NOT display")
debugAt(2, "Debug 2 statement that will display")
debugAt(3, "Debug 3 statement that will display")
debugAt(4, "Debug 4 statement that will display")
debugAt(5, "Debug 5 statement that will display")
debugSetAt(3)
debugAt(1, "Debug 1 statement that will NOT display")
debugAt(2, "Debug 2 statement that will NOT display")
debugAt(3, "Debug 3 statement that will display")
debugAt(4, "Debug 4 statement that will display")
debugAt(5, "Debug 5 statement that will display")
debugSetAt(4)
debugAt(1, "Debug 1 statement that will NOT display")
debugAt(2, "Debug 2 statement that will NOT display")
debugAt(3, "Debug 3 statement that will NOT display")
debugAt(4, "Debug 4 statement that will display")
debugAt(5, "Debug 5 statement that will display")
debugSetAt(5)
debugAt(1, "Debug 1 statement that will NOT display")
debugAt(2, "Debug 2 statement that will NOT display")
debugAt(3, "Debug 3 statement that will NOT display")
debugAt(4, "Debug 4 statement that will NOT display")
debugAt(5, "Debug 5 statement that will display")

Mapped Diagnostic Context

User-specified metadata in the form of key/value pairs may be given to lsst.log using the macro LOG_MDC(key, value) within C++, or the lsst.log function MDC(key, value) within Python. These metadata may then be automatically included as part of any/all subsequent log messages by specifying the corresponding key in the appender's formatting string as per standard log4cxx. These metadata are handled using log4cxx's mapped diagnostic context (MDC) feature, which has thread-level scope.

For example, a session id may be included by using the following formatting string: 

"%d [%t] %-5p %c{2} (%X{session}) %m%n"

In C++, the following MDC macros are available:

In Python, the lsst.log module provides the following MDC functions:

Display PID in the LSST logs

PID can be displayed in the logs using code below:

In C++: 

#include/lsst/log/Log.h
...

Add a PID key in MDC LOG_MDC("PID", std::to_string(getpid())); Then configure lsst/log ...

In python: 

import lsst.log as log
...
# Add a PID key in MDC
log.MDC("PID", os.getpid())
# Then configure lsst/log
...

This has to be done after fork() and corresponding formatting code needs to be added to the logger configuration: 

log4j.appender.FILE.layout.conversionPattern=%X{PID} - %m%n

Benchmarks

Measuring the performance of lsst.log when actually writing log messages to output targets such as a file or socket provides little to no information due to buffering and the fact that in the absence of buffering these operations are I/O limited. Conversely, timing calls to log functions when the level threshold is not met is quite valuable since an ideal logging system would add no appreciable overhead when deactivated. Basic measurements of the performance of Log have been made with the level threshold such that logging messages are not written. These measurements are made within a single-node instance of Qserv running on lsst-dev03 without significant competition from other system activity. The average time required to submit the following suppressed log message is 26 nanoseconds: 

LOG_INFO("Hello default logger!");

The same holds for the boost::format style interface (also 26 nanoseconds): 

LOGF_INFO("Hello default logger!");

Importantly, the overhead is unaffected when formatting is introduced since the CPU will not encounter these instructions when the logging threshold is not met. For example, the average time required to submit the following suppressed log message is also 26 nanoseconds: 

const char* info_stuff = "important stuff";
LOGF_INFO("Hello default logger with %s." % info_stuff);

Note that these timings are indistinguishable from those using log4cxx directly, without the Log layer.

Meanwhile, the situation is quite different when looking up the logger by name. For instance, the average time required to submit the following suppressed log message is 1.0 microseconds (~40X slower): 

LOG("myLogger", LOG_LVL_INFO, "Hello my logger!");

The same holds when using the boost::format style interface or when formatting. That is, the following the example also takes 1.0 microseconds: 

const char* info_stuff = "important stuff";
LOGF("myLogger", LOG_LVL_INFO, "Hello my logger with %s." % info_stuff);

As an alternative to using the default logger, intermediate performance can be achieved for suppressed log messages using logger objects. Retrieve the logger object by name: 

LOG_LOGGER myLogger = LOG_GET("myLogger");

Now, the following suppressed log message takes 190 nanoseconds: 

LOG(myLogger, LOG_LVL_INFO, "Hello my logger!");

The 190 - 26 = 164 nanoseconds differential between this and the LOG_INFO example above is attributable to looking up the logging level LOG_LVL_INFO.

These measurement were made using the OpenMP API with code like the following: 

int iterations = 1000;
double start, stop;
LOG_SET_LVL("", LOG_LVL_WARN);
assert(!LOG_CHECK_LVL("", LOG_LVL_INFO));
start = omp_get_wtime();
for (int i=0; i < iterations; i++)

These log messages will not print. LOG_INFO("Hello default logger!"); stop = omp_get_wtime(); LOG_WARN("LOG_INFO(...): avg time = %f" % ((stop - start)/iterations));

Generated on Wed Sep 16 2015 13:35:37 for LSSTApplications by   doxygen 1.8.5