 |
Kea
1.9.9-git
|
|
Kea
1.9.9-git
|
The Kea logging system is based on the log4J logging system common in Java development, and includes the following ideas:
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:
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.
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.
(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.
(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.
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:
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.
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.
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.
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.
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:
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:
Lines starting with "%" are message definitions and comprise the message identification and the message text. For example:
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.
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.
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:
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.
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.
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:
... 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()").
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.
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.
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.)
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.
The explanation of the message - the free-form text following the message identification - appears in the Kea message manual. It should:
Describe the severity of the message (debug, informational etc.)
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.
The message compiler is a program built in the src/log/compiler directory. It is invoked by the command:
"-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
A C++ header file (called <message-file-name>.h) holding lines of the form:
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.)
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.
(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.:
The constructor of the isc::log::MessageInitializer object retrieves the singleton global 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.
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.
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.
To use logging in a C++ program or module:
Build the message header file and source file as described above.
In each C++ file in which logging is to be used, declare a logger through which the message will be logged.
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.
Issue logging calls using supplied macros in "log/macros.h", e.g.
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.
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).
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.
Logging Initialization is carried out by calling isc::log::initLogger(). There are two variants to the call, one for use by production programs and one for use by unit tests.
The call that should be used by all production programs is:
Arguments are:
root Name of the root logger. This should be the name of the program (e.g. "kea-auth") and is used when configuring logging.
severity 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 logger.h, i.e.
(The level NONE may be used to disable logging.)
dbglevel 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.
file 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.
buffer 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:
Sets the "root" for the unit test. If not defined, the name "kea" is used.
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.
If KEA_LOGGER_SEVERITY is set to "DEBUG", the debug level. This can be a number between 0 and 99, and defaults to 0.
If defined, points to a local message file. The default is not to use a local message file.
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!
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.
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.
1.8.9.1