Basic Ideas

The Kea logging system is based on the log4J logging system common in Java development, and includes the following ideas:

A set of severity levels.
A hierarchy of logging sources.
Separation of message use from message text.

Message Severity

Each message logged by Kea has a severity associated with it, ranging from FATAL - the most severe - to DEBUG - messages output as the code executes to facilitate debugging. In order of decreasing severity, the levels are:

FATAL

The program has encountered an error that is so severe that it cannot continue (or there is no point in continuing). For example, an unhandled exception generated deep within the code has been caught by the top-level program. When a fatal error has been logged, the program will 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

(Warning) 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, the authoritative server loaded a zone that contained no resource records.

INFO

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

Debug messages are output at this severity. Each message also has a debug level associated with it, ranging from 0 (the default) for high-level messages and level 99 (the maximum) for the lowest level.

When logging is enabled for a component, it is enabled for a particular severity level and all higher severities. So if logging is enabled for INFO messages, WARN, ERROR and FATAL messages will also be logged, but not DEBUG ones. If enabled for ERROR, only ERROR and FATAL messages will be logged.

As noted above, DEBUG messages are also associated with a debug level. This allows the developer to control the amount of debugging information produced; the higher the debug level, the more information is output. For example, if debugging the NSAS (nameserver address store), debug levels might be assigned as follows: a level 0 debug message records the creation of a new zone, a level 10 logs every timeout when trying to get a nameserver address, a level of 50 records every query for an address and a level of 70 records every update of the round-trip time.

Like severities, levels are cumulative; so if level 25 is set as the debug level, all debug messages associated levels 0 to 25 (inclusive) will be output. In fact, it is probably easier to visualize the debug levels as part of the severity system:

FATAL            Most severe
ERROR
WARN
INFO
DEBUG level 0
DEBUG level 1
   :
DEBUG level 99   Least severe

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

To try to ensure that the information from different modules is roughly comparable for the same debug level, a set of standard debug levels has been defined for common types of debug output. (These can be found in log_dbglevels.h) However, modules are free to set their own debug levels or define additional ones.

Hierarchical Logging System

When a program writes a message to the logging system, it does so using an instance of the isc::log::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 logger associated with the resolver's cache code could write debugging and other messages to a file while all other components only write messages relating to errors 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; this does not have a parent. The reason for this hierarchy is that unless a logger explicitly assigns a value to an attribute (such as severity of messages it should log), it picks it up the value from the parent. In Kea, each component (kea-dhcp4, kea-dhcp-ddns etc.) has a root logger (named after the program) and every other logger in the component is a child of that. So in the example above, the error/syslog attributes could be associated with the kea-resolver logger while the logger associated with the cache sets its own values for the debug/file attributes.

More information about the logging hierarchy can be found in the section on Logging configuration in the Kea Administrator Reference Manual.

Separation of Messages Use from Message Text

Separating the use of the message from the text associated with it - in essence, defining message text in an external file - allows for the replacement the supplied text of the messages with a local language version. It also means that other attributes can be associated with the message, for example, an explanation of the meaning of the message and other information such as remedial action in the case of errors.

Each message has an identifier such as "LOG_WRITE_ERROR". Within the program, this is the symbol passed to the logging system which uses the symbol as an index into a dictionary to retrieve the message associated with it (e.g. "unable to open %1 for input"), after which it substitutes any message parameters (in this example, the name of the file where the write operation failed) and logs the result to the destination.

In Kea, 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.

Note: Local message files have not yet been implemented in Kea.

Using Logging in a Kea Component

The steps in using the logging system in a Kea component (such as an executable or library) are:

Create a message file. This defines messages by an identification string and text that explains the message in more detail. Ideally the file should have a file type of ".mes".
Run it through the message compiler to produce the files for your module. This step should be included in the build process. The message compiler is a Kea program and is one of the first programs built and linked in the build process. As a result, it should be available for compiling the message files of all Kea components and libraries.

For C++ development, the message compiler produces two files in the default directory, having the same name as the input file but with file types of ".h" and ".cc".
Include the resultant files in your source code to define message symbols, and compile the code and link it into your program.
Declare loggers in your code and use them to log messages.
Call the logger initialization function in the program's main module.

The following sections describe these steps in more detail.

Create a Message File

A message file contains message definitions. Typically there will be one message file for each component that uses Kea logging. An example file could be:

# Example message file
 
$NAMESPACE isc::log
 
% LOG_UNRECOGNIZED_DIRECTIVE line %1: unrecognized 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 recognized 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.

Points to note are:

Leading and trailing spaces are trimmed from each line before it is processed. Although the above example has every line starting at column 1, the lines could be indented if desired.
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 that line.
Lines starting with "$" are directives. At present, just one directive is recognized:

$NAMESPACE <namespace-name>

The sole argument is the name of the namespace in which the symbols are created. In the absence of a $NAMESPACE directive, symbols will be put in the anonymous namespace.
Lines starting with "%" are message definitions and comprise the message identification and the message text. For example:
% 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 must not start with a digit.
The rest of the line - from the first non-space character to the last non- space character - is the text of the message. There are no restrictions on what characters may be in this text, other than they be printable (so both single-quote (') and double-quote (") characters are allowed). The message text may include replacement tokens (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. Otherwise, the message is printed unmodified.</li> <li>Remaining lines indicate an explanation for the preceding message. The explanation can comprise multiple paragraphs, the paragraphs being separated by blank lines. These lines are intended to be processed by a separate program to generate an error messages manual; they are ignored by the message compiler.</li> <li>Except when used to separate paragraphs in the message explanation, blank lines are ignored.</li> </ul> Although there are few restriction on what can be in the message identification and text, there are a number of conventions used by Kea, both in the contents of the message and in the usage. All code should adhere to these: <ul> <li>Message identifications should include at least one underscore. The component before the first underscore is a string indicating the origin of the message, and the remainder describes the condition. 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.</li> <li>The part of the message identification describing the error (e.g. "WRITE_ERROR" in the example above) should comprise no more than two or three words separated by underscores. An excessive number of words or overly long message identification should be avoided; such information should be put in the text of the message. For example, "RECEIVED_EMPTY_HOSTNAME_FROM_CLIENT" is excessively long, "EMPTY_HOSTNAME" being better.</li> <li>Similarly, the text of the message should be reasonably concise. It should include enough information (possibly supplied at run-time in the form of parameters) to allow further investigations to be undertaken if required. Taking the above example, a suitable error message to indicate that the resolver has failed to read a name from an upstream authoritative server could be: @code % RESOLVER_FETCH_ERROR fetch from %1 failed, error code %2 (%3) @endcode ... where %1 indicates the name or IP address of the server to which the fetch was sent, %2 the errno value returned and %3 the message associated with that error number (retrieved via a call to "strerror()"). </li> <li>The message should not have a comma after the message identification. The message text should neither start with a capital letter (unless the first word is a proper noun or is normally written in capitals) nor end with a period. The message reporting system takes care of such punctuation.</li> <li>The parameters substituted into the message text should not include line breaks. Messages are normally output to the syslog file which has the inbuilt assumption of one line per message. Splitting a message across multiple lines makes it awkward to search the file for messages and associated information.</li> <li>The message identifier should be unique across the entire Kea system. (An error will be reported at system start-up if an identifier is repeated.)</li> <li>A particular message identifier should only be used at one place in the Kea code. In this way, if the message indicates a problem, the code in question can be quickly identified.</li> <li>The explanation of the message - the free-form text following the message identification - appears in the Kea message manual. It should: <ul> <li>Describe the severity of the message (debug, informational etc.)</li> <li>Expand on the text of the message. In some cases, such as debug messages, the message text may provide more or less sufficient description. For warnings and errors, the explanation should provide sufficient background to the problem to allow a non-developer to understand the issue and to begin fault-finding. If possible, the explanation should also include suggested remedial action.</li> </ul> </ul> @subsection logSourceFiles Produce Source Files The message file created in the previous step is then run through the message compiler to produce source files that are included in the Kea programs. @subsubsection logMessageCompiler Message Compiler The message compiler is a program built in the src/log/compiler directory. It is invoked by the command: @code kea-msg-compiler [-h] [-v] [-d dir] <message-file> @endcode "-v" prints the version number and exits; "-h" prints brief help text. Finally, the "-d" switch directs the compiler to produce the output files in the specified directory (the default being the current working directory). C++ Files <ol> <li>A C++ header file (called <message-file-name>.h) holding lines of the form: @code namespace <namespace-name> { extern const isc::log::MessageID LOG_BAD_DESTINATION; extern const isc::log::MessageID LOG_BAD_SEVERITY; : } @endcode The symbols define 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.)</li> <li>A C++ source file (called <message-file-name>.cc) that holds the definitions of the global symbols and code to insert the symbols and messages into an internal dictionary. Symbols are defined to be equal to strings equal to the identifier, e.g. @code extern const isc::log::MessageID LOG_BAD_DESTINATION = "LOG_BAD_DESTINATION"; extern const isc::log::MessageID LOG_BAD_SEVERITY = "LOG_BAD_SEVERITY"; : @endcode (The current 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, e.g.: @code namespace { const char* values[] = { "LOG_BAD_DESTINATION", "unrecognized log destination: %1", "LOG_BAD_SEVERITY", "unrecognized log severity: %1", : NULL }; const isc::log::MessageInitializer initializer(values); } @endcode The constructor of the @ref isc::log::MessageInitializer object retrieves the singleton global @ref isc::log::MessageDictionary object (created using standard methods to avoid the "static initialization fiasco") and adds each identifier and associated text to it. These constructors are run when the program starts; a check is made as each identifier is added and, if the identifier already exists in the dictionary, a warning message is printed to the main logging output when logging is finally enabled. The appearance of such a message indicates a programming error. </li> </ol> @subsubsection logMakefile Include Message Compilation in Makefile The source file for the messages is the ".mes" file, but the files used by the code which must be compiled and linked are the output of the message compiler. (The compiler is produced very early on in the Kea build sequence, so is available for use in the building of subsequent components.) To allow this, certain dependencies must be included in the Makefile.am for each component that uses logging. Including Message files in C++ Component Builds The following segment from the "hooks" Makefile.am illustrates the entries needed. @code # Ensure that the message file is included in the distribution EXTRA_DIST = hooks_messages.mes # If we want to get rid of all generated messages files, we need to use # make maintainer-clean. The proper way to introduce custom commands for # that operation is to define maintainer-clean-local target. However, # make maintainer-clean also removes Makefile, so running configure script # is required. To make it easy to rebuild messages without going through # reconfigure, a new target messages-clean has been added. maintainer-clean-local: rm -f hooks_messages.h hooks_messages.cc # To regenerate messages files, one can do: # # make messages-clean # make messages # # This is needed only when a .mes file is modified. messages-clean: maintainer-clean-local if GENERATE_MESSAGES # Define rule to build logging source files from message file messages: hooks_messages.h hooks_messages.cc @echo Message files regenerated hooks_messages.h hooks_messages.cc: hooks_messages.mes $(top_builddir)/src/lib/log/compiler/kea-msg-compiler $(top_srcdir)/src/lib/hooks/hooks_messages.mes else messages hooks_messages.h hooks_messages.cc: @echo Messages generation disabled. Configure with --enable-generate-messages to enable it. endif @endcode The first rule adds a hook to make maintainer-clean which is the standard way to regenerate all messages files. The second rule adds the new messages-clean target to regenerate local messages files. The GENERATE_MESSAGES conditional part is the (re)generation of the messages files. When configured with –enable-generate-messages and the source (.mes file) is newer these files are generated using the Kea message compiler. When configured without –enable-generate-messages (the default) and the source (.mes file) is newer a message is emitted. Not shown are the Makefile.am lines where the .h and .cc file are used. These are the same as other lines specifying .h and .cc source files. And finally please note the message header (e.g. hooks_messages.h) should be installed, i.e. in the include_HEADERS list. @subsection logUsage Using Logging Files in Program Development @subsubsection logCppUsage Use in a C++ Program or Module To use logging in a C++ program or module: <ol> <li>Build the message header file and source file as described above.</li> <li>In each C++ file in which logging is to be used, declare a logger through which the message will be logged. @code isc::log::Logger logger("name"); @endcode This declaration can be per-function, or it can be declared statically in file scope. The string passed to the constructor is the name of the logger (it can be any string) and is used when configuring it. (Remember though that the name of root logger for the program will be prepended to the name chosen. So if, for example, the name "cache" is chosen and the model is included in the "kea-resolver" program, the full name of the logger will be "kea-resolver.cache".) Loggers with the same name share the same configuration. For this reason if, as is usual, messages logged in different files in the same component (e.g. hooks module, nameserver address store, etc.) originate from loggers with the same name, the logger declaration can be placed into a header file.</li> <li>Issue logging calls using supplied macros in "log/macros.h", e.g. @code LOG_ERROR(logger, LOG_WRITE_ERROR).arg("output.txt"); LOG_DEBUG(nsas_logger, NSAS_DBG_TRACE, NSAS_LOOKUP_CANCEL).arg(zone); @endcode All macros (with the exception of LOG_DEBUG) take two arguments: the C++ logger object that will be used to log the message, and the identification of the message to be logged. LOG_DEBUG takes three arguments, the additional one being the debug level associated with the message. The .arg() call appended to the end of the LOG_XXX() macro handles the arguments to the message. A chain of these is used in cases where a message takes multiple arguments, e.g. @code LOG_DEBUG(nsas_logger, NSAS_DBG_RTT, NSAS_UPDATE_RTT) .arg(addresses_[family][index].getAddress().toText()) .arg(old_rtt).arg(new_rtt); @endcode Using the macros is more efficient than direct calls to the methods on the logger class: they avoid the overhead of evaluating the parameters to arg() if the logging settings are such that the message is not going to be output (e.g. it is a DEBUG message and the logging is set to output messages of INFO severity or above).</li> <li>The main program unit must include a call to isc::log::initLogger() (described in more detail below) to set the initial logging severity, debug log level, and external message file. </ol> @subsection logInitialization Logging Initialization In all cases, if an attempt is made to use a logging method before the logging has been initialized, the program will terminate with a LoggingNotInitialized exception. @subsection logInitializationCpp C++ Initialization Logging Initialization is carried out by calling @ref isc::log::initLogger(). There are two variants to the call, one for use by production programs and one for use by unit tests. @subsubsection logInitializationCppVariant1 Variant #1, Used by Production Programs The call that should be used by all production programs is: @code void isc::log::initLogger(const std::string& root, isc::log::Severity severity = isc::log::INFO, int dbglevel = 0, const char* file = NULL, bool buffer = false); @endcode Arguments are: <dl> <dt><code>root</code></dt> <dd>Name of the root logger. This should be the name of the program (e.g. "kea-auth") and is used when configuring logging.</dd> <dt><code>severity</code></dt> <dd>Default severity that the program will start logging with. Although this may be overridden when the program obtains its configuration from the configuration database, this is the severity that it used until then. The logging severity is one of the enum defined in @ref logger.h, i.e. @code isc::log::DEBUG isc::log::INFO isc::log::WARN isc::log::ERROR isc::log::FATAL isc::log::NONE @endcode (The level NONE may be used to disable logging.) </dd> <dt><code>dbglevel</code></dt> <dd>The debug log level is only interpreted when the severity is isc::log::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.</dd> <dt><code>file</code></dt> <dd>The name of a local message file. This will be read and its definitions used to replace the compiled-in text of the messages. The default value of NULL indicates that no local message file is supplied.</dd> <dt><code>buffer</code></dt> <dd>If set to true, initial log messages will be internally buffered, until the first time a logger specification is processed. This way the program can use logging before even processing its logging configuration. As soon as any specification is processed (even an empty one), the buffered log messages will be flushed according to the specification. Note that if this option is used, the program SHOULD call one of the @ref isc::log::LoggerManager::process() calls. If the program exits before this is done, all log messages are dumped in a raw format to stdout (so that no messages get lost).</dd> </dl> @subsubsection logInitializationCppVariant2 Variant #2, Used by Unit Tests @code void isc::log::initLogger() @endcode This is the call that should be used by unit tests. In this variant, all the options are supplied by environment variables: it should not be used for production programs to avoid the chance that the program operation is affected by inadvertently-defined environment variables. The environment variables are: <dl> <dt>KEA_LOGGER_ROOT</dt> <dd>Sets the "root" for the unit test. If not defined, the name "kea" is used.</dd> <dt>KEA_LOGGER_SEVERITY</dt> <dd>The severity to set for the root logger in the unit test. Valid values are "DEBUG", "INFO", "WARN", "ERROR", "FATAL" and "NONE". If not defined, "INFO" is used.</dd> <dt>KEA_LOGGER_DBGLEVEL</dt> <dd>If KEA_LOGGER_SEVERITY is set to "DEBUG", the debug level. This can be a number between 0 and 99, and defaults to 0.</dd> <dt>KEA_LOGGER_LOCALMSG</dt> <dd>If defined, points to a local message file. The default is not to use a local message file.</dd> <dt>KEA_LOGGER_DESTINATION</dt> <dd>The location to which log message are written. This can be one of: <ul> <li>stdout Message are written to stdout.</li> <li>stderr Messages are written to stderr.</li> <li>syslog[:facility] Messages are written to syslog. If the optional "facility" is used, the messages are written using that facility. (This defaults to "local0" if not specified.)</li> <li>Anything else Interpreted as the name of a file to which output is appended. If the file does not exist, a new one is opened.</li> </ul> In the case of "stdout", "stderr" and "syslog", they must be written exactly as is - no leading or trailing spaces, and in lower-case.

Hooks Specific Notes

All hooks libraries should use Kea logging mechanisms. The loggers and the library specific log messages are created in the same way as for the core Kea modules. The loggers created within the hook library belong to the logging hierarchy of the Kea process and their configuration can be controlled from the Kea configuration file. If the configuration file doesn't contain the specific configuration for the logger used in the library, this logger is given the configuration of the root Kea logger.

The hook libraries are loaded dynamically. This requires that the global log messages dictionary, holding the mapping of specific log message identifiers to the actual messages, is updated to include the messages specified in the hook library when the library is loaded. Conversely, the messages have to be removed from the dictionary when the library is unloaded.

The new messages are added to the global dictionary using the isc::log::MessageInitializer::loadDictionary static function. It is called by the isc::hooks::LibraryManager::loadLibrary for each loaded library.

When the library is unloaded, the instance of the isc::log::MessageInitializer defined in the library is destroyed and its destructor removes the messages registered by the destroyed instance from the global dictionary.

The hook library itself must not perform any action to register or unregister log messages in the global dictionary!

Notes on the Use of Logging

One thing that should always be kept in mind is whether the logging could be used as a means 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. As a general rule, if the message can be triggered by a user action, it can be used as an attack vector.

There are two approaches to get round this:

Log messages generated by such user actions as DEBUG messages. DEBUG is not enabled by default, so these events will not be recorded unless DEBUG is specifically enabled. Choosing a suitable debug level for such messages will select only those messages and not the more general debug messages.
Record system-related and packet-related messages via different loggers. As the loggers are independent and the severity levels independent, fine-tuning of what and what is not recorded can be achieved.

Multi-Threading Consideration for Logging

Logging is thread safe: messages emitted at the same time do not mix.

When the KEA_LOCKFILE_DIR environment variable is not set to none Logging to files is multi-process safe too: for instance two servers can be configured to put log messages in the same file.

The isc::log::Logger class initializes its implementation in a lazy (i.e. on demand) but thread safe way so it is always initialized at most once even in a multi-threaded environment.