Note: See also the Developer Guide for guidance on how to use the logging framework in practice.

Features

Simple, consistent interface across both C++ and Python (via swig).
Multiple logging levels (trace, debug, info, warn, error, fatal).
Multiple output channels (e.g. console, files, remote server).
Format logging in C++ using either varargs/printf or iostream style interfaces.
Optionally retrieve logging object in C++ for high performance applications.
Optionally include and format metadata including date, time, level, logger name, thread, function, source file, line number.
Optionally add arbitrary thread-scoped metadata (e.g. key/value pairs) to logging context programmatically.
Hierarchical, named loggers with independent configurations (e.g. levels, output channels, metadata, formatting).
Logging context objects automatically handle pushing/popping of names onto/off of global context in either C++ or Python.
Offers alternative interface that is compatible with standard Python logging module.
Configure loggers via single standard log4cxx XML or standard log4j Java properties file.
Designate configuration file programmatically, via environment variable, or using default name and location.
Automatically works without configuration file using default settings (e.g. logs to console).
Programmatically adjust and query level thresholds.
Use of macros in C++ allows conversion of logging/debugging statements into "no ops" in production versions of software.

Basic C++ examples

The varargs/printf style interface:

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

The iostream style interface:

subject = "important stuff";
LOGS("myLogger", LOG_LVL_INFO, "Here is some information about " << 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:

static 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)

lsst.log.warnf("Possible problem {} using {name}", errcode, name=program)
lsst.log.debug("My debugging statement.")

The standard Python logging module may also be used (and it is recommended for applications mixing Python logging and C++ logging):

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

Note that in this case messages from Python logging are forwarded to log4cxx, and they are filtered by both Python logging and log4cxx. It is easiest to avoid filtering on Python side by setting logging level to DEBUG for root logger and instead configure log4cxx with proper logging level.

Alternatively, get a logger through lsst.log:

lgr = lsst.log.getLogger("myLogger")
lgr.setLevel(lgr.DEBUG)
lgr.info("This is an info statement via %s", "lsst.log interface.")

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:

LOG(loggername, level, fmt...) Log a message of level '''level''' with format string '''fmt''' and corresponding comma-separated arguments to the logger named '''loggername'''.
LOG_TRACE(fmt...) Log a message of level LOG_LVL_TRACE with format string '''fmt''' and corresponding comma-separated arguments to the default logger.
LOG_DEBUG(fmt...) Log a message of level LOG_LVL_DEBUG with format string '''fmt''' and corresponding comma-separated arguments to the default logger.
LOG_INFO(fmt...) Log a message of level LOG_LVL_INFO with format string '''fmt''' and corresponding comma-separated arguments to the default logger.
LOG_WARN(fmt...) Log a message of level LOG_LVL_WARN with format string '''fmt''' and corresponding comma-separated arguments to the default logger.
LOG_ERROR(fmt...) Log a message of level LOG_LVL_ERROR with format string '''fmt''' and corresponding comma-separated arguments to the default logger.
LOG_FATAL(fmt...) Log a message of level LOG_LVL_FATAL with format string '''fmt''' and corresponding comma-separated arguments to the default logger.
LOGL_TRACE(logger, fmt...) Log a message of level LOG_LVL_TRACE with format string '''fmt''' and corresponding comma-separated arguments to a logger '''logger'''.
LOGL_DEBUG(logger, fmt...) Log a message of level LOG_LVL_DEBUG with format string '''fmt''' and corresponding comma-separated arguments to a logger '''logger'''.
LOGL_INFO(logger, fmt...) Log a message of level LOG_LVL_INFO with format string '''fmt''' and corresponding comma-separated arguments to a logger '''logger'''.
LOGL_WARN(logger, fmt...) Log a message of level LOG_LVL_WARN with format string '''fmt''' and corresponding comma-separated arguments to a logger '''logger'''.
LOGL_ERROR(logger, fmt...) Log a message of level LOG_LVL_ERROR with format string '''fmt''' and corresponding comma-separated arguments to a logger '''logger'''.
LOGL_FATAL(logger, fmt...) Log a message of level LOG_LVL_FATAL with format string '''fmt''' and corresponding comma-separated arguments to a logger '''logger'''.

Alternative set of macros allows one to use iostream-based formatting. In the macros below expression is any C++ expression which can appear on the right side of the stream insertion operator, e.g. LOGS_DEBUG("coordinates: x=" << x << " y=" << y);. Usual caveat regarding commas inside macro arguments applies to expression argument:

LOGS(loggername, level, expression) Log a message of level '''level''' to the logger named '''loggername'''.
LOGS_TRACE(expression) Log a message of level LOG_LVL_TRACE to the default logger.
LOGS_DEBUG(expression) Log a message of level LOG_LVL_DEBUG to the default logger.
LOGS_INFO(expression) Log a message of level LOG_LVL_INFO to the default logger.
LOGS_WARN(expression) Log a message of level LOG_LVL_WARN to the default logger.
LOGS_ERROR(expression) Log a message of level LOG_LVL_ERROR to the default logger.
LOGS_FATAL(expression) Log a message of level LOG_LVL_FATAL to the default logger.
LOGLS_TRACE(logger, expression) Log a message of level LOG_LVL_TRACE to the logger '''logger'''.
LOGLS_DEBUG(logger, expression) Log a message of level LOG_LVL_DEBUG to the logger '''logger'''.
LOGLS_INFO(logger, expression) Log a message of level LOG_LVL_INFO to the logger '''logger'''.
LOGLS_WARN(logger, expression) Log a message of level LOG_LVL_WARN to the logger '''logger'''.
LOGLS_ERROR(logger, expression) Log a message of level LOG_LVL_ERROR to the logger '''logger'''.
LOGLS_FATAL(logger, expression) Log a message of level LOG_LVL_FATAL to the logger '''logger'''.

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 calling the % operator directly, to avoid unnecessarily formatting log messages that do not meet the level threshold.

log(loggername, level, fmt, *args) Log a message of level '''level''' with format string '''fmt''' and variable arguments '''*args''' to the logger named '''loggername'''.
trace(fmt, *args) Log a message of level TRACE with format string '''fmt''' and corresponding arguments '''*args''' to the default logger.
debug(fmt, *args) Log a message of level DEBUG with format string '''fmt''' and corresponding arguments '''*args''' to the default logger.
info(fmt, *args) Log a message of level INFO with format string '''fmt''' and corresponding arguments '''*args''' to the default logger.
warn(fmt, *args) Log a message of level WARN with format string '''fmt''' and corresponding arguments '''*args''' to the default logger.
error(fmt, *args) Log a message of level ERROR with format string '''fmt''' and corresponding arguments '''*args''' to the default logger.
fatal(fmt, *args) Log a message of level FATAL with format string '''fmt''' and corresponding arguments '''*args''' to the default logger.

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:

LOG_CONFIG(filename) Initialize log4cxx using the XML or Java properties configuration file '''filename''' (see below).
LOG_CONFIG() Initialize log4cxx with default configuration file if found, otherwise using basic configuration (see below).
LOG_CONFIG_PROP(string) Initialize log4cxx using the Java properties syntax in a string.

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

configure(filename) Initialize log4cxx using the XML or Java properties configuration file '''filename''' (see below).
configure() Initialize log4cxx with default configuration file if found, otherwise using basic configuration (see below).
configure_prop(string) Initialize log4cxx using the Java properties syntax in a string.

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 (or Python methods), 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 as if LOG_CONFIG(filename) was called, if errors happen during file parsing then LOG4CXX prints error messages but continues to run in un-configured state. If LSST_LOG_CONFIG is not set or its value does not refer to readable file then log4cxx is configured using pre-defined configuration:

single ConsoleAppender is added to the root logger,
the output of the appender is sent to standard output,
the output is formatted using a PatternLayout set to the pattern "%c %p: %m%n",
logging level is set to INFO, suppressing DEBUG and TRACE messages by default.

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).

LOG_CONFIG(filename) takes name of the file which contains LOG4CXX configuration. If file name ends with .xml extension then it is assumed to be a standard log4cxx XML configuration, otherwise it should contain standard log4j Java properties as explained below. If parsing of the file fails then LOG4CXX will print error messages to standard error but will continue to run (likely in un-configured state).

LOG_CONFIG_PROP(string) takes a string which is a representation of log4j Java properties (including new lines), this is a useful short-cut for cases when configuration has to be included in the application itself.

All configuration macro and their Python wrappers reset existing logging configuration before applying new one, there is no way to configure logging incrementally using these constructs.

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/">
  <!-- Output the log message to system console.
    -->
  <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>

  <!-- Output the log message to log file
    -->
  <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>

  <!-- My debugging file
    -->
  <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>

  <!-- Specify the level and appender for my logger -->
  <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 default configuration described above:

# Set root logger level to INFO and its only appender to A1.
log4j.rootLogger=INFO, 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=%c %p: %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:

org.apache.log4j.ConsoleAppender, taking a target property with values System.out and System.err
org.apache.log4j.FileAppender, taking file and append properties
org.apache.log4j.rolling.RollingFileAppender, taking a rollingPolicy property (but which can currently only be configured using an XML file, not a properties file)
org.apache.log4j.SyslogAppender, taking facility and syslogHost properties

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:

LOG_SET_LVL(loggername, level) Assign '''level''' as the threshold of the logger named '''loggername'''.
LOG_GET_LVL(loggername) Returns the threshold level of the logger named '''loggername'''.
LOG_CHECK_LVL(loggername, level) Returns true/false indicating whether a logging message of level '''level''' meets the threshold associated with the logger named '''loggername'''.
LOG_CHECK_TRACE() Returns true/false indicating whether a logging message of level '''trace''' meets the threshold associated with the default logger.
LOG_CHECK_DEBUG() Returns true/false indicating whether a logging message of level '''debug''' meets the threshold associated with the default logger.
LOG_CHECK_INFO() Returns true/false indicating whether a logging message of level '''info''' meets the threshold associated with the default logger.
LOG_CHECK_WARN() Returns true/false indicating whether a logging message of level '''warn''' meets the threshold associated with the default logger.
LOG_CHECK_ERROR() Returns true/false indicating whether a logging message of level '''error''' meets the threshold associated with the default logger.
LOG_CHECK_FATAL() Returns true/false indicating whether a logging message of level '''fatal''' meets the threshold associated with the default logger.
LOG_LVL_TRACE Trace logging level (5000).
LOG_LVL_DEBUG Debug logging level (10000).
LOG_LVL_INFO Info logging level (20000).
LOG_LVL_WARN Warn logging level (30000).
LOG_LVL_ERROR Error logging level (40000).
LOG_LVL_FATAL Fatal logging level (50000).

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

setLevel(loggername, level) Assign '''level''' as the threshold of the logger named '''loggername'''.
getLevel(loggername) Returns the threshold level of the logger named '''loggername'''.
isEnabledFor(loggername, level) Returns true/false indicating whether a logging message of level '''level''' meets the threshold associated with the logger named '''loggername'''.
TRACE Trace logging level (5000).
DEBUG Debug logging level (10000).
INFO Info logging level (20000).
WARN Warn logging level (30000).
ERROR Error logging level (40000).
FATAL Fatal logging level (50000).

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 'MyLogger.debug{}'.format(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"

or alternatively using %X format code without additional key to display full MDC:

"%d [%t] %-5p %c{2} %m%n MDC=%X"

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

LOG_MDC(key, value) Map the value '''value''' to the global key '''key''' such that it may be included in subsequent log messages by including the directive %X{'''key'''} in the formatting string of an associated appender.
LOG_MDC_REMOVE(key) Delete the existing value from the global map that is associated with '''key'''.
LOG_MDC_SCOPE(key, value) Adds key/value to MDC and restores previous value when execution leaves the scope. Typically used at the beginning of the function if one needs to define MDC key/value for the whole duration of the function.

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

MDC(key, value) Map the value '''value''' to the global key '''key''' such that it may be included in subsequent log messages by including the directive %X{'''key'''} in the formatting string of an associated appender. Note that value is converted to a string by Python before it is stored in the MDC.
MDCRemove(key) Delete the existing value from the global map that is associated with '''key'''.

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

Display thread ID

The conversion pattern in log4cxx has special conversion code (%t) to render "thread ID", the rendered value is a pointer to thread_t object (on POSIX systems) and is rendered as a long string of hexadecimal digits which makes it difficult to read for non-hardcore programmers. lsst.log provides more human-friendly way to print thread-identifying information. Special function lsst::log::lwpID() returns light-weight process ID (LWP) on the platforms that support this feature and small incremental integer number on other platforms. Using this function one can add LWP to MDC and configure output format to include this special MDC key:

In C++:

#include "lsst/log/Log.h"
...
  -- Add LWP key to MDC
  LOG_MDC("LWP", std::to_string(lsst::log::lwpID()));

In Python:

import lsst.log as log
...
# Add LWP key to MDC
log.MDC("LWP", log.lwpID())

MDC and multi-threading

MDC is a great tool to associate some context information with the messages but its use in multi-threaded applications can be complicated. MDC is per-thread instance and it is initialized as empty in every new thread. If application adds something to MDC in main thread this information will not exist in other threads unless it is explicitly set in those other threads. This may be an issue for applications which do not have complete control over thread lifetime.

This package provides a mechanism to initialize MDC in all threads started by a process. Special macro LOG_MDC_INIT(function) can be used to register a function to be called in in every new thread (and in current thread) before any logging message is sent to a logging system. This function can do anything but its main purpose is to initialize MDC with useful values.

Here is an example of this:

#include "lsst/log/Log.h"
...
void init_mdc() { LOG_MDC("PID", std::to_string(getpid())); }
...
int main(int, char**) {
    LOG_MDC_INIT(init_mdc);
    ....
}

or in Python:

import lsst.log as log
...
def init_mdc()
    log.MDC("PID", os.getpid())
...
log.MDCRegisterInit(init_mdc)

LOG_MDC_INIT(function) returns some unspecified integer value, this can be used to do one-time initialization (e.g. in some shared library):

#include "lsst/log/Log.h"
...
void init_mdc() { LOG_MDC("MY_CONTEXT", "data"); }
...
void foo() {
    static int dummyMdcInit = LOG_MDC_INIT(init_mdc);
    ....
}

One should note that this initialization function will only be called in the current thread from which LOG_MDC_INIT() was called and all new threads, if there are some other threads running at a time of this call the function will not be called for them. Normally the function registered with LOG_MDC_INIT() will be called only once per thread but under some circumstances it may be called more than once. Registering the same function multiple times will result is multiple calls to the same function.

Redirecting to Python logging

For many Python applications it is preferable to have everything forwarded to the Python logging system. This package implements a special log4cxx appender class that supports this functionality. To simply forward all log4cxx events to Python one needs to configure log4cxx using this special appender (and which is naturally done from Python):

import lsst.log

PROP = """
log4j.rootLogger = INFO, PyLog
log4j.appender.PyLog = PyLogAppender
"""
lsst.log.configure_prop(PROP)

Logging level configuration needs some special care in this case, e.g. if DEBUG level output is needed then DEBUG level needs to be enabled in both log4cxx and logging. Alternative is to always configure log4cxx with TRACE level and adjust logging configuration to a selected level. Latter option has performance implications as all logging messages will be generated and formatted at C++ level which can slow down things significantly.

One complication with this scheme is support for MDC. PyLogAppender converts MDC to a Python dictionary-like object and adds it as an MDC attribute to a LogRecord instance to make MDC accessible on Python side. If MDC attribute already exists in LogRecord (e.g. it is added by record factory) PyLogAppender assumes that it behaves like a dictionary and updates it with MDC contents. Unfortunately accessing MDC attribute in a portable way is not very easy in Python. One can render MDC using a regular "%(MDC)s" expressions in a logging format string, but that requires MDC attribute to be present in every instance of LogRecord which may not be true for records originated from other sources. There are two possible workarounds to handle this complication described below.

Rendering MDC in log4cxx

One option is to render MDC into the log message before it is passed to Python. This can be done by specifying MessagePattern configuration option for the appender, e.g.:

PROP = """
log4j.rootLogger = INFO, PyLog
log4j.appender.PyLog = PyLogAppender
log4j.appender.PyLog.MessagePattern = %m (%X{LABEL})
"""
lsst.log.configure_prop(PROP)

MessagePattern value has the same format as ConversionPattern option of PatternLayout and can potentially include other items. If MessagePattern is missing it has the same effect as specifying m. In this example if MDC contains "LABEL" key it will be added to a message enclosed in parentheses. Note that final message formatting still happens in Python, above configuration only changes the message part of the output and not the whole record format.

Rendering MDC in logging

It is also possible to specify MDC formatting in a logging format string but one has to make sure that corresponding attribute exists in every generated record. The easiest way to guarantee that is to implement a logging record factory method following this pattern:

import lsst.log
import logging

old_factory = logging.getLogRecordFactory()

def record_factory(*args, **kwargs):
    record = old_factory(*args, **kwargs)
    record.MDC = lsst.log.MDCDict()
    return record

logging.setLogRecordFactory(record_factory)

PROP = """
log4j.rootLogger = INFO, PyLog
log4j.appender.PyLog = PyLogAppender
"""

lsst.log.configure_prop(PROP)
logging.basicConfig(
    level=logging.INFO,
    format="%(levelname)s %(asctime)s %(name)s (%(MDC)s) %(filename)s:%(lineno)s - %(message)s")

The record factory adds an MDC attribute to every record using special MDCDict class instance, same type that is used by PyLogAppender when MDC attribute does not exist in LogRecord. Potentially any Python dictionary can be used in place of MDCDict() in the code above, MDCDict class is just a sub-class of a dict with a modified formatting which is more suitable for logging output. It also acts similarly to defaultdict returning empty string for any key that does not exist in a dictionary, which is useful when format string specifies individual key access as in example below, but key does not exist in MDC.

Above detailed code can be replaces by a call to a convenience method:

import lsst.log
import logging

lsst.log.configure_pylog_MDC("INFO")
logging.basicConfig(
    level=logging.INFO,
    format="%(levelname)s %(asctime)s %(name)s (%(MDC)s) %(filename)s:%(lineno)s - %(message)s")

It is possible to render individual MDC items in formatted message using format-style option for format string which supports indexing access in format expressions:

logging.basicConfig(
    level=logging.INFO,
    style="{",
    format="{levelname} {asctime} {name} ({MDC[LABEL]}) {filename}:{lineno} - {message}")

If "LABEL" key is present in MDC then it will appear in the output, if "LABEL" is missing then empty string is rendered thanks to defaultdict-like behavior of MDCDict objects. As before this depends on MDC being present in every LogRecord so it has to be added by a record factory.

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 iostream style interface (also 26 nanoseconds):

LOGS_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";
LOGS_INFO("Hello default logger with " << 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 iostream style interface or when formatting. That is, the following the example also takes 1.0 microseconds:

const char* info_stuff = "important stuff";
LOGS("myLogger", LOG_LVL_INFO, "Hello my logger with " << 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));