kea/src/lib/log

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

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

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 initLogger (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.


Message Files
=============

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.
An example file could be:

-- BEGIN --

# Example message file
# $ID:$

$PREFIX TEST_
$NAMESPACE isc::log
TEST1 message %1 is much too large
+ This message is a test for the general message code

UNKNOWN unknown message
+ Issued when the message is unknown.

-- END --

Points to note:
* Leading and trailing space are trimmed from the line. Although the above
example 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, two directives are recognised:

* $PREFIX, which has one argument: the string used to prefix symbols. If
absent, there is no prefix to the symbols. (Prefixes are explained below.)
* $NAMESPACE, which has one argument: the namespace in which the symbols are
created. In the absence of a $NAMESPACE directive, symbols will be put
in the global namespace.

* Lines starting + indicate an explanation for the preceding message. These
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.

* Message lines. These comprise a symbol name and a message, which may
include zero or more %1, %2... placeholder tokens. Symbol names will be
upper-cased by the compiler.


Message Compiler
----------------
The message compiler is a program built in the src/log/compiler directory.
It is invoked by the command:

message [-h] [-v]

("-v" prints the version number and exits; "-h" prints brief help text.)
The message compiler processes the message file to produce two files:

1) A C++ header file (called .h) that holds lines of
the form:

namespace {
extern const isc::log::MessageID PREFIX_IDENTIFIER;
:
}

The symbols define the keys in the global message dictionary.

The namespace enclosing the symbols is set by the $NAMESPACE directive.

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 identifier
ABC with "MSG_" to give the symbol MSG_ABC. Similarly "$PREFIX E" would
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 .cc) that holds the definitions
of the global symbols and code to insert the symbols and messages into the map.

Symbols are defined to be equal to strings holding the identifier, e.g.

extern const isc::log::MessageID MSG_DUPLNS = "DUPLNS";

(The implementation allows symbols to be compared. However, use of strings
should not be assumed - a future implementation may change this.)

In addition, the file declares an array of identifiers/messages and an object
to add them to the global dictionary:

namespace {
const char* values[] = {
identifier1, text1,
identifier2, text2,
:
NULL
};

const isc::log::MessageInitializer initializer(values);
}

The constructor of the MessageInitializer object retrieves the singleton
global Dictionary object (created using standard methods to avoid the
"static initialization fiasco") and adds each identifier and text to it.
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

isc::log::RootLoggerName("b10-auth");

This can be declared inside or outside an execution unit.

2. In the code that needs to do logging, declare a logger with a given name,
e.g.

#include
:
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);

(The argument is required to support a possible future implementation of
logging. Currently it has no effect.)

3. The main program unit should include a call to isc::log::initLogger()
(defined in logger_support.h) to set the logging severity, debug log level,
and external message file.

a) The logging severity is one of the enum defined in logger.h, i.e.

isc::log::DEBUG
isc::log::INFO
isc::log::WARN
isc::log::ERROR
isc::log::FATAL
isc::log::NONE

b) The debug log level is only interpreted when the severity is DEBUG and
is an integer ranging 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 any directives. (A single directive
of a particular type 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).arg("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 %1 have timed out

At present, the only logging is to the console.


Severity Guidelines
===================
When using logging, the question arises, what severity should a message be
logged at? The following is a suggestion - as always, the decision must be
made in the context of which the message is logged.

FATAL
-----
The program has encountered an error that is so severe that it cannot
continue (or there is no point in continuing). When a fatal error has been
logged, the program will usually exit immediately (via a call to abort()) or
shortly afterwards, after dumping some diagnostic information.

ERROR
-----
Something has happened such that the program can continue but the results
for the current (or future) operations cannot be guaranteed to be correct,
or the results will be correct but the service is impaired. For example,
the program started but attempts to open one or more network interfaces failed.

WARN
----
An unusual event happened. Although the program will continue working
normally, the event was sufficiently out of the ordinary to warrant drawing
attention to it. For example, at program start-up a zone was loaded that
contained no resource records,

INFO
----
A normal but significant event has occurred that should be recorded,
e.g. the program has started or is just about to terminate, a new zone has
been created, etc.

DEBUG
-----
This severity is only enabled on for debugging purposes. A debug level is
associated with debug messages, level 0 (the default) being for high-level
messages and level 99 (the maximum) for the lowest level. How the messages
are distributed between the levels is up to the developer. So if debugging
the NSAS (for example), a level 0 message might record the creation of a new
zone, a level 10 recording a timeout when trying to get a nameserver address,
but a level 50 would record every query for an address. (And we might add
level 51 to record every update of the RTT.)

Note that like severities, levels are cumulative; so if level 25 is set as the
debug level, all debug levels from 0 to 25 will be output. In fact, it is
probably easier to visualise the debug levels as part of the severity system:

FATAL High
ERROR
WARN
INFO
DEBUG level 0
DEBUG level 1
:
DEBUG level 99 Low

When a particular severity is set, it - and all severities and/or debug
levels above it - will be logged.

Logging Sources v Logging Severities
------------------------------------
When logging events, make a distinction between events related to the server
and events related to DNS messages received. Caution needs to be exercised
with the latter as, if the logging is enabled in the normal course of events,
such logging could be a denial of service vector. For example, suppose that
the main authoritative service logger were to log both zone loading and
unloading as INFO and a warning message if it received an invalid packet. An
attacker could make the INFO messages unusable by flooding the server with
malformed packets.

There are two approaches to get round this:

a) Make the logging of packet-dependent events a DEBUG-severity message.
DEBUG is not enabled by default, so these events will not be recorded unless
DEBUG is specifically chosen.

b) Record system-related and packet-related messages via different loggers
(e.g. in the example given, server events could be logged using the logger
"auth" and packet-related events at that level logged using the logger
"pkt-auth".) As the loggers are independent and the severity levels
independent, fine-tuning of what and what is not recorded can be achieved.


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.


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


log4cxx Issues
==============
Some experimental code to utilise log4cxx as an underlying implementation
is present in the source code directory although it is not currently used.
The files are:

logger_impl_log4cxx.{cc,h}
xdebuglevel.{cc,h}