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 use from message 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 Use from Message Text
============================================
By separating the use of the message from the text associated with this -
in essence, defining message text in an external file - it is possible to
replace the supplied text of the messages with a local language version.

Each message is identified by an identifier e.g. "LOG_WRITE_ERROR".
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"). It then substitutes any message parameters (in this example,
the name of the file where the write operation failed) and logs it to
the destination.

In BIND-10, a the default text for each message is linked into the
program. Each program is able to read a locally-defined message file
when it starts, updating the stored definitions with site-specific text.
When the message is logged, the updated text is output. However, the
message identifier is always included in the output so that the origin
of the message can be identified even if the text has been changed.


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, the convention being that these are a few
words separated by underscores - and text that explains the message in
more detail. The file is described in more detail below.

Ideally the file should have a file type of ".mes".

2. Run it through the message compiler to produce the .h and .cc files. This
step should be included in the build process. (For an example of how to
do this, see src/lib/nsas/Makefile.am.) During development though, the
message compiler (found in the "src/lib/log/compiler" directory) will need
to be run manually. The only argument is the name of the message file: it
will produce as output two files in the default directory, having the same
name as the input file but with file types of ".h" and ".cc".

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.


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

$NAMESPACE isc::log

% LOG_UNRECOGNISED_DIRECTIVE line %1: unrecognised directive '%2'
A line starting with a dollar symbol was found, but the first word on the line
(shown in the message) was not a recognised message compiler directive.

% LOG_WRITE_ERROR error writing to %1: %2
The specified error was encountered by the message compiler when writing to
the named output file.

-- 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, just one directive is
recognised:

* $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 anonymous namespace.

* Message lines. These start with a "%" and are followed by the message
identification and the message text, the latter including zero or more
replacement tokens, e.g.

% LOG_WRITE_ERROR error writing to %1: %2

* There may be zero or more spaces between the leading "%" and the message
identification (which, in the example above, is the string
"LOG_WRITE_ERROR").

* The message identification can be any string of letters, digits and
underscores, but should not start with a digit. The convention adopted
in BIND 10 is for the first component (before the first underscore) to be
a string indicating the origin of the message, and the remainder to
describe the message. So in the example above, the LOG_ indicates that
the error originated from the logging library and the "WRITE_ERROR"
indicates that there was a problem in a write operation.

* The replacement tokens are the strings "%1", "%2" etc. When a message
is logged, these are replaced with the arguments passed to the logging
call: %1 refers to the first argument, %2 to the second etc. Within the
message text, the placeholders can appear in any order and placeholders
can be repeated.

* Remaining lines 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. They are ignored by the message 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] -p]

("-v" prints the version number and exits; "-h" prints brief help text.) The
compiler produces source files for C++ and Python.

C++ Files
---------
Without the "-p" option, 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 LOG_WRITE_ERROR;
:
}

The symbols define the keys in the global message dictionary, with the
namespace enclosing the symbols set by the $NAMESPACE directive.

(This is the reason for the restriction on message identifiers - they
have to be valid C++ symbol names.)

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 LOG_WRITE_ERROR = "LOG_WRITE_ERROR";

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

Python Files
------------
If the "-p" option is given, the compiler produces a Python module defining
the messages. The format of this is:

import isc.log
:
LOG_WRITE_ERROR = isc.log.create_message("LOG_WRITE_ERROR",
"error writing to %1 : %2")

(The definition is output on one line - it is split across two lines in this
document for readability.)

The module can be imported into other Python code, and messages logged
in a similar way to C++ using the Python logging library.

Using the Logging - C++
=======================
1. Build message header file and source file as describe above.

2. 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) The external message file. If present, 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.)

The settings remain in effect until the logging configuration is read,
and so provide the default logging during program initialization.

3. Declare a logger through which the message will be logged.

isc::log::Logger logger("name");

The string passed to the constructor is the name of the logger (it
can be any string) and is used when configuring it. Loggers with
the same name share the same configuration.

4. Issue logging calls using supplied macros in "log/macros.h", e.g.

LOG_ERROR(logger, LOG_WRITE_ERROR).arg("output.txt");

(The macros are more efficient that calls to the methods on the logger
class: they avoid the overhead of evaluating the parameters to arg()
if the settings are such that the message is not going to be output.)

Using the Logging - Python
==========================
1. Build message module as describe above.

2. The main program unit should include a call to isc.log.init() to
set the to set the logging severity, debug log level, and external
message file:

a) The logging severity is one of the strings:

DEBUG
INFO
WARN
ERROR
FATAL
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) The external message file. If present, this is the same as a
standard message file, although it should not include any
directives. (Any that are there will be ignored.)

The settings remain in effect until the logging configuration is read,
and so provide the default logging during program initialization.

3. Declare a logger through which the message will be logged.

isc.log.Logger logger("name")

The string passed to the constructor is the name of the logger (it
can be any string) and is used when configuring it. Loggers with
the same name share the same configuration.

4. Issue calls to the logging methods:

logger.error(LOG_WRITE_ERROR, "output.txt");


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.

One thing that should always be borne in mind is whether the logging
could be used as a vector for a DOS attack. For example, if a warning
message is logged every time an invalid packet is received, an attacker
could simply send large numbers of invalid packets. (Of course, warnings
could be disabled (or just warnings for that that particular logger),
but nevertheless the message is an attack vector.)

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