LSST Applications g1653933729+34a971ddd9,g1a997c3884+34a971ddd9,g28da252d5a+32b12a4112,g2bbee38e9b+ffc559ee46,g2bc492864f+ffc559ee46,g2cdde0e794+704103fe75,g3156d2b45e+6e87dc994a,g347aa1857d+ffc559ee46,g35bb328faa+34a971ddd9,g3a166c0a6a+ffc559ee46,g3e281a1b8c+8ec26ec694,g4005a62e65+ba0306790b,g414038480c+9f5be647b3,g41af890bb2+686ab7cd58,g4e1a3235cc+1fd785b14f,g7b55021d1b+da0d0eec6b,g80478fca09+6e21f9dc20,g82479be7b0+6fa35d7547,g858d7b2824+356eaf3287,g9125e01d80+34a971ddd9,ga5288a1d22+ba1f9bb3ef,gae0086650b+34a971ddd9,gb4748cc0e8+fd26a265a0,gb4ec7eb0ab+356eaf3287,gb58c049af0+ace264a4f2,gc081298178+30f12d1e69,gc28159a63d+ffc559ee46,gcf0d15dbbd+4adb3139bd,gd6b7c0dfd1+aae9efebf5,gda3e153d99+356eaf3287,gda6a2b7d83+4adb3139bd,gdaeeff99f8+7774323b41,gdd5a9049c5+ea78b51778,ge2409df99d+fa478de0b0,ge33fd446bb+356eaf3287,ge79ae78c31+ffc559ee46,gf0baf85859+890af219f9,gf5289d68f6+e11c78aeea,w.2024.41
LSST Data Management Base Package
|
iostream
style interfaces.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.");
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.")
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"
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.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.
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:
ConsoleAppender
is added to the root logger,PatternLayout
set to the pattern "%c %p: %m%n"
,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
propertiesorg.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
propertiesFor the PatternLayout
, all the conversion specifiers from this document should work.
Read more about log4cxx configuration here.
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).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")
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
'''.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
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 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.
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.
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.
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.
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));