/** @page Introduction Short introduction to log4cxx This document is largely inspired of the Short introduction to log4j by Ceki Gülcü @section Contents - @ref Abstract - @ref IntroductionIntroduction - @ref LoggersAppendersAndLayouts - @ref LoggerHierarchy - @ref AppendersAndLayouts . - @ref Configuration - @ref DefaultInitializationProcedure - @ref NDC - @ref Performance - @ref Conclusion @section Abstract This document describes the log4cxx API, its unique features and design rationale. Log4cxx is an open source project based on the work of several authors. It allows the developer to control which log statements are output with arbitrary granularity. It is fully configurable at runtime using external configuration files. Best of all, log4cxx has a gentle learning curve. Beware: judging from user feedback, it is also quite addictive. @section IntroductionIntroduction Introduction The log4cxx framework is based on log4j, see http://logging.apache.org/log4j for more information on log4cxx. The package is distributed under the Apache Software License , a fully-fledged open source license certified by the open source initiative. The latest log4cxx version, including full-source code, class files and documentation can be found at http://logging.apache.org/log4cxx . Almost every large application includes its own logging or tracing API. Inserting log statements into code is a low-tech method for debugging it. It may also be the only way because debuggers are not always available or applicable. This is usually the case for multithreaded applications and distributed applications at large. Experience indicates that logging was an important component of the development cycle. It offeres several advantages. It provides precise context about a run of the application. Once inserted into the code, the generation of logging output requires no human intervention. Moreover, log output can be saved in persistent medium to be studied at a later time. In addition to its use in the development cycle, a sufficiently rich logging package can also be viewed as an auditing tool. Logging does have its drawbacks. It can slow down an application. If too verbose, it can cause scrolling blindness. To alleviate these concerns, log4cxx is designed to be reliable, fast and extensible. Since logging is rarely the main focus of an application, the log4cxx API strives to be simple to understand and to use. @section LoggersAppendersAndLayouts Loggers, Appenders and Layouts Log4cxx has three main components: loggers, appenders and layouts. These three types of components work together to enable developers to log messages according to message type and level, and to control at runtime how these messages are formatted and where they are reported. @subsection LoggerHierarchy Logger hierarchy The first and foremost advantage of any logging API over plain std::cout resides in its ability to disable certain log statements while allowing others to print unhindered. This capability assumes that the logging space, that is, the space of all possible logging statements, is categorized according to some developer-chosen criteria. Loggers are named entities. Logger names are case-sensitive and they follow the hierarchical naming rule:
|
com.foo
is a parent of the logger
named com.foo.Bar
. Similarly, cpp
is a parent of
cpp.util
and an ancestor of cpp.util.Vector
.
This naming scheme should be familiar to most developers.
The root logger resides at the top of the logger hierarchy. It is exceptional
in two ways:
-# it always exists,
-# it cannot be retrieved by name.
Invoking the class static log4cxx::Logger::getRootLogger method retrieves it.
All other loggers are instantiated and retrieved with the class static
log4cxx::Logger::getLogger method. This method takes the name of the desired
logger as a parameter.Some of the basic methods in the Logger class are listed
below.
@code
#include
|
Logger name | Assigned level |
Inherited level |
---|---|---|
root | Proot | Proot |
X | none | Proot |
X.Y | none | Proot |
X.Y.Z | none | Proot |
Proot
, is inherited by the
other loggers X
, X.Y
and
X.Y.Z
.
Logger name | Assigned level |
Inherited level |
---|---|---|
root | Proot | Proot |
X | Px | Px |
X.Y | Pxy | Pxy |
X.Y.Z | Pxyz | Pxyz |
Logger name | Assigned level |
Inherited level |
---|---|---|
root | Proot | Proot |
X | Px | Px |
X.Y | none | Px |
X.Y.Z | Pxyz | Pxyz |
root
, X
and
X.Y.Z
are assigned the levels Proot
,
Px
and Pxyz
respectively. The logger
X.Y
inherits its level value from its parent
X
.
Logger name | Assigned level |
Inherited level |
---|---|---|
root | Proot | Proot |
X | Px | Px |
X.Y | none | Px |
X.Y.Z | none | Px |
root
and X
and are assigned the levels Proot
and Px
respectively. The loggers X.Y
and X.Y.Z
inherits their level value from their nearest parent X
having an assigned level..
Logging requests are made by invoking one of the printing methods
of a logger instance. These printing methods are {@link log4cxx::Logger::debug
debug}, {@link log4cxx::Logger::info info}, {@link log4cxx::Logger::warn
warn}, {@link log4cxx::Logger::error error}, {@link log4cxx::Logger::fatal
fatal} and {@link log4cxx::Logger::log log}.
By definition, the printing method determines the level of a
logging request. For example, if c
is a logger
instance, then the statement c.info("..")
is a logging
request of level INFO.
A logging request is said to be enabled if its level is
higher than or equal to the level of its logger. Otherwise, the
request is said to be disabled. A logger without an
assigned level will inherit one from the hierarchy. This rule is
summarized below.
|
getLogger
method with the same name will
always return a reference to the exact same logger object.
For example, in
@code
LoggerPtr x = Logger::getLogger("wombat");
LoggerPtr y = Logger::getLogger("wombat");
@endcode
x
and y
refer to exactly the same
logger object.
Thus, it is possible to configure a logger and then to retrieve
the same instance somewhere else in the code without passing around
references. In fundamental contradiction to biological parenthood,
where parents always preceed their children, log4cxx loggers can be
created and configured in any order. In particular, a "parent"
logger will find and link to its descendants even if it is
instantiated after them.
Configuration of the log4cxx environment is typically done at
application initialization. The preferred way is by reading a
configuration file. This approach will be discussed shortly.
Log4cxx makes it easy to name loggers by software
component. This can be accomplished by statically instantiating
a logger in each class, with the logger name equal to the fully
qualified name of the class. This is a useful and straightforward
method of defining loggers. As the log output bears the name of the
generating logger, this naming strategy makes it easy to identify
the origin of a log message. However, this is only one possible,
albeit common, strategy for naming loggers. Log4cxx does not restrict
the possible set of loggers. The developer is free to name the
loggers as desired.
Nevertheless, naming loggers after the class where they are
located seems to be the best strategy known so far.
@subsection AppendersAndLayouts Appenders and Layouts
The ability to selectively enable or disable logging requests based
on their logger is only part of the picture. Log4cxx allows logging
requests to print to multiple destinations. In log4cxx speak, an output
destination is called an appender. Currently, appenders exist
for the {@link log4cxx::ConsoleAppender console}, {@link
log4cxx::FileAppender files}, GUI components, {@link
log4cxx::net::SocketAppender remote socket} servers, {@link
log4cxx::nt::NTEventLogAppender NT Event Loggers}, and remote UNIX {@link
log4cxx::net::SyslogAppender Syslog} daemons.
It is also possible to log {@link log4cxx::AsyncAppender asynchronously}.
More than one appender can be attached to a logger.
The {@link log4cxx::Logger::addAppender addAppender}
method adds an appender to a given logger.
Each enabled logging
request for a given logger will be forwarded to all the appenders in
that logger as well as the appenders higher in the hierarchy. In
other words, appenders are inherited additively from the logger
hierarchy. For example, if a console appender is added to the root
logger, then all enabled logging requests will at least print on the
console. If in addition a file appender is added to a logger, say
C, then enabled logging requests for C and
C's children will print on a file and on the
console. It is possible to override this default behavior so that
appender accumulation is no longer additive by {@link
log4cxx::Logger::setAdditivity setting
the additivity flag} to false
.
The rules governing appender additivity are summarized below.
|
Logger Name | Added Appenders | Additivity Flag | Output Targets | Comment |
---|---|---|---|---|
root | A1 | not applicable | A1 | The root logger is anonymous but can be accessed with the Logger::getRootLogger() method. There is no default appender attached to root. |
x | A-x1, A-x2 | true | A1, A-x1, A-x2 | Appenders of "x" and root. |
x.y | none | true | A1, A-x1, A-x2 | Appenders of "x" and root. |
x.y.z | A-xyz1 | true | A1, A-x1, A-x2, A-xyz1 | Appenders in "x.y.z", "x" and root. |
security | A-sec | false | A-sec | No appender accumulation since the additivity flag is set to
false .
|
security.access | none | true | A-sec | Only
appenders of "security" because the additivity flag in "security" is
set to false .
|
printf
function.
For example, the PatternLayout with the conversion pattern "\%r [\%t]
\%-5p \%c - \%m\%n" will output something akin to:
176 [12345] INFO org.foo.Bar - Located nearest gas station.The first field is the number of milliseconds elapsed since the start of the program. The second field is the identifier of the thread making the log request. The third field is the level of the log statement. The fourth field is the name of the logger associated with the log request. The text after the '-' is the message of the statement. @section Configuration Inserting log requests into the application code requires a fair amount of planning and effort. Observation shows that approximately 4 percent of code is dedicated to logging. Consequently, even moderately sized applications will have thousands of logging statements embedded within their code. Given their number, it becomes imperative to manage these log statements without the need to modify them manually. The log4cxx environment is fully configurable programmatically. However, it is far more flexible to configure log4cxx using configuration files. Currently, configuration files can be written in XML or in properties (key=value) format.
Let us give a taste of how this is done with the help of an
imaginary application MyApp
that uses log4cxx.
@code
// file MyApp.cpp
#include "com/foo/bar.h";
using namespace com::foo;
// include log4cxx header files.
#include MyApp
begins by including log4cxx related headers. It
then defines a static logger variable with the name
MyApp
which happens to be the fully qualified name of the
class.
MyApp
uses the Bar
class defined in the
header file com/foo/bar.h
and the source file bar.cpp
.
@code
// file Level::DEBUG
.
The output of MyApp is:
0 [12345] INFO MyApp - Entering application.
36 [12345] DEBUG com.foo.Bar - Did it again!
51 [12345] INFO MyApp - Exiting application.
As a side note, let me mention that in log4cxx child loggers link
only to their existing ancestors. In particular, the logger named
com.foo.Bar
is linked directly to the root
logger, thereby circumventing the unused com
or
com.foo
loggers. This significantly increases
performance and reduces log4cxx's memory footprint.
The MyApp
class configures log4cxx by invoking
BasicConfigurator::configure
method. Other classes only
need to include the
header file,
retrieve the loggers they wish to use, and log away.
The previous example always outputs the same log information.
Fortunately, it is easy to modify MyApp
so that the log
output can be controlled at run-time. Here is a slightly modified
version.
@code
// file MyApp2.cpp
#include "com/foo/bar.h";
using namespace com::foo;
// include log4cxx header files.
#include MyApp
instructs
PropertyConfigurator
to parse a configuration file and
set up logging accordingly.
Here is a sample configuration file that results in exactly same
output as the previous BasicConfigurator
based example.
It can be noticed that the PropertyConfigurator file format is the same as in log4j.
Suppose we are no longer interested in seeing the output of any
component belonging to the
# 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
com::foo
namespace. The following
configuration file shows one possible way of achieving this.
The output of
log4j.rootLogger=DEBUG, A1
log4j.appender.A1=org.apache.log4j.ConsoleAppender
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
# Print the date in ISO 8601 format
log4j.appender.A1.layout.ConversionPattern=\%d [\%t] \%-5p \%c - \%m\%n
# Print only messages of level WARN or above in the namespace com::foo.
log4j.logger.com.foo=WARN
MyApp
configured with this file is shown below.
2000-09-07 14:07:41,508 [12345] INFO MyApp - Entering application.
2000-09-07 14:07:41,529 [12345] INFO MyApp - Exiting application.
As the logger com.foo.Bar
does not have an assigned
level, it inherits its level from com.foo
, which
was set to WARN in the configuration file. The log statement from the
Bar::doIt
method has the level DEBUG, lower than the
logger level WARN. Consequently, doIt()
method's log
request is suppressed.
Here is another configuration file that uses multiple appenders.
Calling the enhanced MyApp with the this configuration file will
output the following on the console.
log4j.rootLogger=debug, stdout, R
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
# Pattern to output the caller's file name and line number.
log4j.appender.stdout.layout.ConversionPattern=%5p [%t] (%F:%L) - %m%n
log4j.appender.R=org.apache.log4j.RollingFileAppender
log4j.appender.R.File=example.log
log4j.appender.R.MaxFileSize=100KB
# Keep one backup file
log4j.appender.R.MaxBackupIndex=1
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%p %t %c - %m%n
INFO [main] (MyApp2.cpp:31) - Entering application.
DEBUG [main] (Bar.h:16) - Doing it again!
INFO [main] (MyApp2.cpp:34) - Exiting application.
In addition, as the root logger has been allocated a second
appender, output will also be directed to the example.log
file. This file will be rolled over when it reaches 100KB. When
roll-over occurs, the old version of example.log
is
automatically moved to example.log.1
.
Note that to obtain these different logging behaviors we did not
need to recompile code. We could just as easily have logged to a UNIX
Syslog daemon, redirected all com.foo
output to an NT
Event logger, or forwarded logging events to a remote log4cxx server,
which would log according to local server policy, for example by
forwarding the log event to a second log4cxx server.
@section DefaultInitializationProcedure Default Initialization Procedure
The log4cxx library does not make any assumptions about its
environment. In particular, there are no default log4cxx
appenders. Under certain well-defined circumstances however, the
initialization of the logger hierarchy will attempt to
automatically configure log4cxx.
The exact default initialization algorithm is defined as follows:
-# Set the configurationOptionStr
string variable to the value of
the log4j.configuration environment variable. The preferred
way to specify the default initialization file is through the
log4j.configuration environment variable. In case the environment
variable log4j.configuration is not defined, then set the
string variable configurationOptionStr
to its default value
"log4j.properties".
@n @n
-# Attempt to convert the configurationOptionStr
variable to a
valid file name.
@n @n
-# If no file could be found, abort default
initialization. Otherwise, configure log4cxx from the file name.
@n @n
The {@link log4cxx::PropertyConfigurator PropertyConfigurator}
will be used to parse the file to configure log4cxx unless the file name ends
with the ".xml" extension, in which case the {@link
log4cxx::xml::DOMConfigurator DOMConfigurator}
will be used. You can optionaly specify a custom configurator. The
value of the log4j.configuratorClass environment variable is taken
as the fully qualified class name of your custom configurator. The
custom configurator you specify must implement the {@link
log4cxx::spi::Configurator Configurator} interface.
@section NDC Nested Diagnostic Contexts
Most real-world systems have to deal with multiple clients
simultaneously. In a typical multithreaded implementation of such a
system, different threads will handle different clients. Logging is
especially well suited to trace and debug complex distributed
applications. A common approach to differentiate the logging output of
one client from another is to instantiate a new separate logger for
each client. This promotes the proliferation of loggers and
increases the management overhead of logging.
A lighter technique is to uniquely stamp each log request initiated
from the same client interaction. Neil Harrison described this method
in the book "Patterns for Logging Diagnostic Messages," in Pattern
Languages of Program Design 3, edited by R. Martin, D. Riehle,
and F. Buschmann (Addison-Wesley, 1997).
To uniquely stamp each request, the
user pushes contextual information into the NDC, the abbreviation of
Nested Diagnostic Context. The NDC class is shown below.
@code
class NDC
{
public:
// Used when printing the diagnostic
static String get();
// Remove the top of the context from the NDC.
static String pop();
// Add diagnostic context for the current thread.
static void push(const String& message);
// Remove the diagnostic context for this thread.
static void remove();
};
@endcode
The NDC is managed per thread as a stack of contextual
information. Note that all methods of the log4cxx::NDC
class are static. Assuming that NDC printing is turned on, every time
a log request is made, the appropriate log4cxx component will include
the entire NDC stack for the current thread in the log
output. This is done without the intervention of the user, who is
responsible only for placing the correct information in the NDC by
using the push
and pop
methods at a few
well-defined points in the code. In contrast, the per-client logger
approach commands extensive changes in the code.
To illustrate this point, let us take the example of a server
delivering content to numerous clients. The server can build the NDC
at the very beginning of the request before executing other code. The
contextual information can be the client's host name and other
information inherent to the request, typically caller identity.
Hence, even if the server is serving multiple clients
simultaneously, the logs initiated by the same code, i.e. belonging to
the same logger, can still be distinguished because each client
request will have a different NDC stack. Contrast this with the
complexity of passing a freshly instantiated logger to all code
exercised during the client's request.
Nevertheless, some sophisticated applications, such as virtual
hosting web servers, must log differently depending on the virtual
host context and also depending on the software component issuing the
request. Recent log4cxx releases support multiple hierarchy trees. This
enhancement allows each virtual host to possess its own copy of the
logger hierarchy.
@section Performance
One of the often-cited arguments against logging is its
computational cost. This is a legitimate concern as even moderately
sized applications can generate thousands of log requests. Much
effort was spent measuring and tweaking logging performance. Log4cxx
claims to be fast and flexible: speed first, flexibility second.
The user should be aware of the following performance issues.
-# Logging performance when logging is turned off.
@n @n
When logging is turned
off entirely or just for a {@link log4cxx::Hierarchy::setThreshold
set of levels}, the cost of a log request consists of a method
invocation plus an integer comparison. On a 233 MHz Pentium II
machine this cost is typically in the 5 to 50 nanosecond range.
@n @n
However, The method invocation involves the "hidden" cost of
parameter construction.
@n @n
For example, for some logger logger
, writing,
@code
logger->debug("The user named [" + strName + "] is logged");
@endcode
incurs the cost of constructing the message parameter, i.e.
concatenating intermediate strings,
regardless of whether the message will be logged or not.
@n @n
This cost of parameter construction can be quite high and it
depends on the size of the parameters involved.
@n @n
To avoid the parameter construction cost write:
@code
if(logger->isDebugEnabled()
{
logger->forcedLog(Level::DEBUG,
"The user named [" + strName + "] is logged");
}
@endcode
or in a simpler way:
@code
LOG4CXX_DEBUG(logger, "The user named [" + strName + "] is logged");
@endcode
@n
Certain users resort to preprocessing or compile-time techniques to compile out
all log statements. This leads to perfect performance efficiency with respect
to logging. However, since the resulting application binary does not contain
any log statements, logging cannot be turned on for that binary. In my opinion
this is a disproportionate price to pay in exchange for a small performance
gain.
@n @n
-# The performance of deciding whether to log or not to log when
logging is turned on.
@n @n
This is essentially the performance of walking the logger
hierarchy. When logging is turned on, log4cxx still needs to compare
the level of the log request with the level of the request
logger. However, loggers may not have an assigned
level; they can inherit them from the logger hierarchy. Thus,
before inheriting a level, the logger may need to search its
ancestors.
@n @n
There has been a serious effort to make this hierarchy walk to
be as fast as possible. For example, child loggers link only to
their existing ancestors. In the BasicConfigurator
example shown earlier, the logger named com.foo.Bar
is
linked directly to the root logger, thereby circumventing the
nonexistent com
or com.foo
loggers. This
significantly improves the speed of the walk, especially in "sparse"
hierarchies.
@n @n
The typical cost of walking the hierarchy is typically 3
times slower than when logging is turned off entirely.
@n @n
-# Actually outputting log messages
This is the cost of formatting the log output and sending it to
its target destination. Here again, a serious effort was made to
make layouts (formatters) perform as quickly as possible. The same
is true for appenders. The typical cost of actually logging is
about 100 to 300 microseconds.
Although log4cxx has many features, its first design goal was speed.
Some log4cxx components have been rewritten many times to improve
performance. Nevertheless, contributors frequently come up with new
optimizations. You should be pleased to know that when configured with
the {@link log4cxx::SimpleLayout SimpleLayout}
performance tests have shown log4cxx to log as quickly as
std::cout
.
@section Conclusion
Log4cxx is a popular logging package written in C++. One of its
distinctive features is the notion of inheritance in loggers. Using
a logger hierarchy it is possible to control which log statements
are output at arbitrary granularity. This helps reduce the volume of
logged output and minimize the cost of logging.
One of the advantages of the log4cxx API is its manageability. Once
the log statements have been inserted into the code, they can be
controlled with configuration files. They can be selectively enabled
or disabled, and sent to different and multiple output targets in
user-chosen formats. The log4cxx package is designed so that log
statements can remain in shipped code without incurring a heavy
performance cost.
*/