Commit b4c068b2 authored by Stephen Morris's avatar Stephen Morris
Browse files

Logger run-time initialization

Completing run-time initialization code and associated tests.  Also updated
documentation.
parent 3be13632
......@@ -716,6 +716,7 @@ AC_OUTPUT([src/bin/cfgmgr/b10-cfgmgr.py
src/lib/dns/tests/testdata/gen-wiredata.py
src/lib/cc/session_config.h.pre
src/lib/cc/tests/session_unittests_config.h
src/lib/log/tests/run_time_init_test.sh
], [
chmod +x src/bin/cmdctl/run_b10-cmdctl.sh
chmod +x src/bin/xfrin/run_b10-xfrin.sh
......@@ -740,6 +741,7 @@ AC_OUTPUT([src/bin/cfgmgr/b10-cfgmgr.py
chmod +x src/bin/msgq/tests/msgq_test
chmod +x src/lib/dns/gen-rdatacode.py
chmod +x src/lib/dns/tests/testdata/gen-wiredata.py
chmod +x src/lib/log/tests/run_time_init_test.sh
])
AC_OUTPUT
......
// Copyright (C) 2010 Internet Systems Consortium, Inc. ("ISC")
//
// Permission to use, copy, modify, and/or distribute this software for any
// purpose with or without fee is hereby granted, provided that the above
// copyright notice and this permission notice appear in all copies.
//
// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
// AND FITNESS. IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
// PERFORMANCE OF THIS SOFTWARE.
// $Id$
#ifndef __APPENDER_H
#define __APPENDER_H
#include <message.h>
/// \brief Abstract Appender Class
///
/// This class is responsible for writing messages generated by loggers
/// to destinations. It is an abstract class; particular appenders will
/// control different destinations.
///
/// Multiple appenders can be attached to a logger. Output is routed to
/// all appenders attached to a logger. The logger hierachy is then walked
/// and the message passed to the appenders in parent loggers.
class AbstractAppender {
public:
/// \brief Write the Output
///
/// Formats the message and writes it to the specified output.
void write(Message& message);
};
#endif // __APPENDER_H
......@@ -24,8 +24,8 @@
/// of variables declared outside execution units. (In this way we avoid the
/// "static initialization fiasco" problem.)
#define MIN_DEBUG_LEVEL 0
#define MAX_DEBUG_LEVEL 99
#define MIN_DEBUG_LEVEL (0)
#define MAX_DEBUG_LEVEL (99)
#define NUM_DEBUG_LEVEL (MAX_DEBUG_LEVEL - MIN_DEBUG_LEVEL + 1)
#endif // __DBGLEVELS_H
This directory holds the first release of the logging system.
Basic Ideas
===========
The BIND-10 logging system merges two ideas:
* A hierarchical logging system similar to that used in Java (i.e. log4j)
* Separation of message definitions and text
Hierarchical Logging System
===========================
When a program writes a message to the logging system, it does so using an
instance of the Logger class. As well as performing the write of the message,
the logger identifies the source of the message: different sources can write
to different destinations and can log different severities of messages. For
example, the "cache" logger could write messages of DEBUG severity or above
to a file while all other components write messages of "INFO" severity or above
to the Syslog file.
The loggers are hierarchical in that each logger is the child of another logger.
The top of the hierarchy is the root logger, which does not have a parent. The
point of the hierarchy is that unless a logger is explicitly assigned an
attribute (such as severity of message being logger), it picks it up from the
parent. (In BIND-10, there is the root logger (named after the program) and
every other logger is a child of that.) So in the example above, the
INFO/Syslog attributes could be associated with the root logger while the
DEBUG/file attributes are associated with the "cache" logger.
Separation of Messages Definitions And Text
===========================================
The reason for this is to allow the message text to be overridden by versions
in a local language. To do this, each message is identified by an identifier
e.g. "OPENIN". Within the program, this is the symbol passed to the logging
system. The logger system uses the symbol as an index into a dictionary to
retrieve the message associated with it (e.g. "unable to open %s for input").
substitutes any message parameters (in this example, the string that is an
invalid filename) and logs it to the destination.
In the BIND-10 system, a set of default messages are linked into the program.
At run-time. each program reads a message file, updating the stored definitions;
this updated text is logged. However, to aid support, the message identifier
so in the example above, the message finally logged would be something like:
OPENIN, unable to open a.txt for input
Using The System
================
The steps in using the system are:
1. Create a message file. Ideally it should have a file type of ".msg".
2. Run it through the message compiler to produce the .h and .cc files.
3. Include the .h file in your source code to define message symbols. Also
include the file logger.h to create loggers and to log error messages.
The ".cc" file needs to be linked into the program - static initialization
will add the symbols to the global dictionary.
1. Create a message file. This defines messages by an identification - a
mnemonic for the message, typically 6-12 characters long - and a message.
The file is described in more detail below.
Ideally the file should have a file type of ".msg".
Outstanding
===========
* Ability to configure system according to configuration database.
* Writing of suitable appenders and formatters.
* Overrididing message at run-time with a localised file.
* Update the build procedure to create .cc and .h files from the .msg file
during the build process. (Requires that the message compiler is built first.)
2. Run it through the message compiler to produce the .h and .cc files. It
is intended that this step be included in the build process. However, for
not run the compiler (found in the "compiler" subdirectory) manually. The
only argument is the name of the message file: it will produce as output
two files, having the same name as the input file but with file types of
".h" and ".cc".
The compiler is built in the "compiler" subdirectory of the "src/lib/log"
directory.
Message Storage
===============
Each message is identified by a string identifier, e.g. "INVFILNAM", which is
associated with some text (e.g. "%s is an invalid file name"). These are stored
in a single std::map, in a class called the Dictionary.
3. Include the .h file in your source code to define message symbols, and
make sure that the .cc file is compiled and linked into your program -
static initialization will add the symbols to the global dictionary.
4. Declare loggers in your code and use them to log messages. This is described
in more detail below.
5. To set the debug level and run-time message file, call runTimeInit (declared
in logger_support.h) in the main program unit. This is a temporary solution
for Year 2, and will be replaced at a later date, the information coming from
the configuration database.
The message identifier (along with parameters) is passed through the logging
system to an appender, which uses the identifier to look up the message in
the dictionary. The message is then formatted and written out.
Message Files
=============
1) File Contents and Format
File Contents and Format
------------------------
A message file is a file containing message definitions. Typically there will
be one message file for each component that declares message symbols.
A example file could be:
be one message file for each component that declares message symbols. An
example file could be:
-- BEGIN --
......@@ -53,34 +102,45 @@ UNKNOWN unknown message
-- END --
Point to note:
* Leading and trailing space are trimmed from the line.
* Blank lines are ignored
* Lines starting with "#" are comments are are ignored.
Points to note:
* Leading and trailing space are trimmed from the line. Although the above
exampl,e has every line starting at column 1, the lines could be indented if
desired.
* Blank lines are ignored.
* Lines starting with "#" are comments are are ignored. Comments must be on
a line by themselves - inline comments will be interpreted as part of the
text of the line.
* Lines starting $ are directives. At present, the only directive recognised
is $PREFIX, which has one argument: the string used to prefix symbols. If
there is no facility directive, there is no prefix to the symbols. (Prefixes
are explained below.)
* Lines starting + indicate an explanation for the preceding message. These
are processed by a separate program and used to generate an error messages
manual. However they are treated like comments here.
* Message lines. These comprise a symbol name and a message, which may
include one or more instances of the "%s" the C-style substitution string.
(The logging system only recognises the "%s" string.)
are intended to be processed by a separate program and used to generate an
error messages manual. However they are treated like comments by the message
compiler. As with comments, these must be on a line by themselves; if inline,
the text (including the leading "+") will be interpreted as part of the line.
2) Message Compiler
The message compiler is a program built in the src/log/compiler directory. It
processes the message file to produce two files:
* Message lines. These comprise a symbol name and a message, which may
include zero or more printf-style tokens. Symbol names will be upper-cased
by the compiler.
1) A C++ header file (called <message-file-name>.h) that holds lines of the
form:
namespace {
Message Compiler
----------------
The message compiler is a program built in the src/log/compiler directory.
It processes the message file to produce two files:
isc::log::MessageID PREFIX_IDENTIFIER = "IDENTIFIER";
:
1) A C++ header file (called <message-file-name>.h) that holds lines of
the form:
}
namespace {
isc::log::MessageID PREFIX_IDENTIFIER = "IDENTIFIER";
:
}
The symbols define the keys in the global message dictionary. At present
they are defined as std::strings, but a future implementation could redefine
......@@ -89,22 +149,23 @@ them as numeric values.
The "PREFIX_" part of the symbol name is the string defined in the $PREFIX
the argument to the directive. So "$PREFIX MSG_" would prefix the identifer
ABC with "MSG_" to give the symbol MSG_ABC. Similarly "$PREFIX E" would
prefix it with "E" to give the symbol EABC.
prefix it with "E" to give the symbol EABC. If no $PREFIX is given, no
prefix appears (so the symbol in this example would be ABC).
2) A C++ source file (called <message-file-name>.cpp) that holds the code to
2) A C++ source file (called <message-file-name>.cc) that holds the code to
insert the symbols and messages into the map.
This file declares an array of identifiers/messages in the form:
namespace {
const char* values[] = {
identifier1, text1,
identifier2, text2,
:
NULL
};
}
namespace {
const char* values[] = {
identifier1, text1,
identifier2, text2,
:
NULL
};
}
(A more complex structure to group identifiers and their messages could be
imposed, but as the array is generated by code and will be read by code,
......@@ -112,12 +173,12 @@ it is not needed.)
It then declares an object that will add information to the global dictionary:
MessageInitializer <message-file-name>_<time>(values);
MessageInitializer <message-file-name>_<time>(values);
(Declaring the object as "static" or in the anonymous namespace runs the risk
of it being optimised away when the module is compiled with optimisation. But
giving it a standard name would cause a clash when multiple files are used,
hence an attempt at disambiguation.)
of it being optimised away when the module is compiled with optimisation.
But giving it a standard name would cause a clash when multiple files are
used, hence an attempt at disambiguation.)
The constructor of the MessageInitializer object retrieves the singleton
global Dictionary object (created using standard methods to avoid the
......@@ -126,39 +187,100 @@ A check is made as each is added; if the identifier already exists, it is
added to "overflow" vector; the vector is printed to the main logging output
when logging is finally enabled (to indicate a programming error).
Using the Logging
=================
To use the current version of the logging:
1. Build message header file and source file as describe above.
2. In the main module of the program, declare an instance of the
RootLoggerName class to define the name of the program's root logger, e.g.
#include <log/root_logger_name.h>
isc::log::RootLoggerName("b10-auth");
It should be declared outside an execution unit to allow other statically-
declared loggers to pick it up.
2. In the code that needs to do logging, declare a logger with a given name,
e.g.
#include <log/logger.h>
:
isc::log::Logger logger("myname"); // "myname" can be anything
#include <log/logger.h>
:
isc::log::Logger logger("myname"); // "myname" can be anything
The above example assumes declaration outside a function. If declaring
non-statically within a function, declare it as:
isc::log::Logger logger("myname", true);
This is due to an apparent bug in the underlying log4cxx, where the deletion
of a statically-declared object at program termination can cause a segment
fault. (The destruction of internal memory structures can sometimes happen
out of order.) By default the Logger class creates the structures in its
constructor but does not delete them in the destruction. The default
behavious works because instead of reclaiming memory at program run-down,
the operating system reclaims it when the process is deleted.
Setting the second argument "true" causes the Logger's destructor to delete
the log4cxx structures. This does not cause a problem if the program is
not terminating. So use the second form when declaring an automatic
instance of isc::log::Logger on the stack.
3. The main program unit should include a call to isc::log::runTimeInit()
(defined in logger_support.h) to set the logging severity, debug log level,
and external message file.
3. Issue logging calls using methods on logger, e.g.
a) The logging severity is one of the enum defined in logger.h, i.e.
logger.error(DPS_NSTIMEOUT, "isc.org");
isc::log::Logger::DEBUG
isc::log::Logger::INFO
isc::log::Logger::WARN
isc::log::Logger::ERROR
isc::log::Logger::FATAL
isc::log::Logger::NONE
b) The debug log level is only interpreted when the severity is DEBUG and
is an integer raning from 0 to 99. 0 should be used for the highest-level
debug messages and 99 for the lowest-level (and typically more verbose)
messages.
c) Name of an external message file. This is the same as a standard message
file, although it should not include the $PREFIX directive. (A single
$PREFIX directive will be ignored; multiple directives will cause the
read of the file to fail with an error.) If a message is replaced, the
message should include the same printf-format directives in the same order
as the original message.
4. Issue logging calls using methods on logger, e.g.
logger.error(DPS_NSTIMEOUT, "isc.org");
(where, in the example above we might have defined the symbol in the message
file with something along the lines of:
$PREFIX DPS_
:
NSTIMEOUT queries to all nameservers for %s have timed out
$PREFIX DPS_
:
NSTIMEOUT queries to all nameservers for %s have timed out
At present, the only logging is to the console.
As noted above, presently the only logging is to the console using the default
log4cxx format (which is somewhat awkward to read).
Outstanding Issues
==================
* Ability to configure system according to configuration database.
* Update the build procedure to create .cc and .h files from the .msg file
during the build process. (Requires that the message compiler is built first.)
Notes
=====
The message compiler is written in C++ (instead of Python) because it contains
a component that reads the message file. This component is used in both the
message compiler and the server; in the server it is used when the server
starts up (or when triggered by a command) to read in a message file to
overwrite the internal dictionary. Writing it in C++ means there is only
one piece of code that does this functionality.
The message compiler is written in C++ (instead of Python) because it
contains a component that reads the message file. This component is used
in both the message compiler and the server; in the server it is used when
the server starts up (or when triggered by a command) to read in a message
file to overwrite the internal dictionary. Writing it in C++ means there
is only one piece of code that does this functionality.
......@@ -76,12 +76,15 @@ void Logger::initLogger() {
log4cxx::LoggerPtr sys_root_logger = log4cxx::Logger::getRootLogger();
sys_root_logger->addAppender(console);
// Set the default logging to INFO
sys_root_logger->setLevel(log4cxx::Level::getInfo());
// All static stuff initialized
init_ = true;
}
// Initialize this logger. Name this as to whether the BIND-10 root logger
// name has beens set.
// name has been set. (If not, this mucks up the hierarchy :-( ).
string root_name = RootLoggerName::getName();
if (root_name.empty() || (name_ == root_name)) {
loggerptr_ = new log4cxx::LoggerPtr(log4cxx::Logger::getLogger(name_));
......@@ -122,33 +125,23 @@ void Logger::initLogger() {
void Logger::setSeverity(Severity severity, int dbglevel) {
switch (severity) {
case NONE:
getLogger()->setLevel(
log4cxx::Level::toLevel(
log4cxx::Level::OFF_INT));
getLogger()->setLevel(log4cxx::Level::getOff());
break;
case FATAL:
getLogger()->setLevel(
log4cxx::Level::toLevel(
log4cxx::Level::FATAL_INT));
getLogger()->setLevel(log4cxx::Level::getFatal());
break;
case ERROR:
getLogger()->setLevel(
log4cxx::Level::toLevel(
log4cxx::Level::ERROR_INT));
getLogger()->setLevel(log4cxx::Level::getError());
break;
case WARNING:
getLogger()->setLevel(
log4cxx::Level::toLevel(
log4cxx::Level::WARN_INT));
getLogger()->setLevel(log4cxx::Level::getWarn());
break;
case INFO:
getLogger()->setLevel(
log4cxx::Level::toLevel(
log4cxx::Level::INFO_INT));
getLogger()->setLevel(log4cxx::Level::getInfo());
break;
case DEBUG:
......@@ -263,7 +256,7 @@ void Logger::debug(int dbglevel, isc::log::MessageID ident, ...) {
if (isDebugEnabled(dbglevel)) {
char message[MESSAGE_SIZE];
FORMAT_MESSAGE(message);
LOG4CXX_DEBUG(getLogger(), message);
LOG4CXX_DEBUG(getLogger(), ident << ", " << message);
}
}
......@@ -271,7 +264,7 @@ void Logger::info(isc::log::MessageID ident, ...) {
if (isInfoEnabled()) {
char message[MESSAGE_SIZE];
FORMAT_MESSAGE(message);
LOG4CXX_INFO(getLogger(), message);
LOG4CXX_INFO(getLogger(), ident << ", " << message);
}
}
......@@ -279,7 +272,7 @@ void Logger::warn(isc::log::MessageID ident, ...) {
if (isWarnEnabled()) {
char message[MESSAGE_SIZE];
FORMAT_MESSAGE(message);
LOG4CXX_WARN(getLogger(), message);
LOG4CXX_WARN(getLogger(), ident << ", " << message);
}
}
......@@ -287,7 +280,7 @@ void Logger::error(isc::log::MessageID ident, ...) {
if (isErrorEnabled()) {
char message[MESSAGE_SIZE];
FORMAT_MESSAGE(message);
LOG4CXX_ERROR(getLogger(), message);
LOG4CXX_ERROR(getLogger(), ident << ", " << message);
}
}
......@@ -295,7 +288,7 @@ void Logger::fatal(isc::log::MessageID ident, ...) {
if (isFatalEnabled()) {
char message[MESSAGE_SIZE];
FORMAT_MESSAGE(message);
LOG4CXX_FATAL(getLogger(), message);
LOG4CXX_FATAL(getLogger(), ident << ", " << message);
}
}
......
......@@ -77,7 +77,7 @@ public:
/// means that the log4cxx objects are not destroyed at program rundown;
/// instead memory is reclaimed and files are closed when the process is
/// destroyed, something that does not trigger the bug.
Logger(const std::string& name, bool exit_delete = true) :
Logger(const std::string& name, bool exit_delete = false) :
loggerptr_(), name_(name), exit_delete_(exit_delete)
{}
......
......@@ -30,4 +30,16 @@ run_unittests_LDADD += $(top_builddir)/src/lib/log/liblog.la
run_unittests_LDADD += -llog4cxx
endif
TESTS += logger_support_test
logger_support_test_SOURCES = logger_support_test.cc
logger_support_test_CPPFLAGS = $(AM_CPPFLAGS) $(GTEST_INCLUDES)
logger_support_test_LDFLAGS = $(AM_LDFLAGS)
logger_support_test_LDADD = $(top_builddir)/src/lib/log/liblog.la
logger_support_test_LDADD += -llog4cxx
noinst_PROGRAMS = $(TESTS)
# Additional test using the shell
PYTESTS = run_time_init_test.sh
check-local:
$(SHELL) $(abs_builddir)/run_time_init_test.sh
# Copyright (C) 2011 Internet Systems Consortium, Inc. ("ISC")
#
# Permission to use, copy, modify, and/or distribute this software for any
# purpose with or without fee is hereby granted, provided that the above
# copyright notice and this permission notice appear in all copies.
#
# THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
# REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
# AND FITNESS. IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
# INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
# LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
# OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
# PERFORMANCE OF THIS SOFTWARE.
# \brief Local Definitions
#
# Holds local definitions of some of the messages produced by the program
# logger_support_test, and is used as input to check that run-time message
# replacement works.
NOTHERE this message is not in the global dictionary
READERR replacement read error, parameters: '%s' and '%s'
UNRECDIR replacement unrecognised directive message, parameter is '%s'
// Copyright (C) 2010 Internet Systems Consortium, Inc. ("ISC")
//
// Permission to use, copy, modify, and/or distribute this software for any
// purpose with or without fee is hereby granted, provided that the above
// copyright notice and this permission notice appear in all copies.
//
// THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
// AND FITNESS. IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
// OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
// PERFORMANCE OF THIS SOFTWARE.
// $Id: $
/// \brief Example Program
///
/// Simple example program showing how to use the logger.
#include <unistd.h>
#include <string.h>
#include <iostream>
#include <log/logger.h>
#include <log/logger_support.h>
#include <log/root_logger_name.h>
// Include a set of message definitions.
#include <log/messagedef.h>
using namespace isc::log;
// Declare root logger and a logger to use an example.
//RootLoggerName root_name("testing");
RootLoggerName root("alpha");
Logger logger_ex("example");
Logger logger_dlm("dlm");
// The program is invoked:
//
// logger_support_test [-s severity] [-d level ] [local_file]
//
// "severity" is one of "debug", "info", "warn", "error", "fatal"
// "level" is the debug level, a number between 0 and 99
// "local_file" is the name of a local file.
//
// The program sets the attributes on the root logger. Looking
// at the output determines whether the program worked.e root logger. Looking
// at the output determines whether the
int main(int argc, char** argv) {
Logger::Severity severity = Logger::INFO;
int dbglevel = -1;
const char* localfile = NULL;
int option;
// Parse options
while ((option = getopt(argc, argv, "s:d:")) != -1) {
switch (option) {
case 's':
if (strcmp(optarg, "debug") == 0) {
severity = Logger::DEBUG;
} else if (strcmp(optarg, "info") == 0) {
severity = Logger::INFO;
} else if