wiki:LoggingCppApiDesign

C++ API

The requirements outlined in the requirements document are consistent with a number of hierarchical packages such as log4cxx and Pantheios. For this reason, the logging API closely follows this idea: an implementation is most likely a thin layer over one of these, the abstraction allowing the logging package to be easily changed at some point in the future.

As with these products, the logging API supports:

  • Variety of loggers. Logging is done through a component called a "logger"; programs (and components) may define as many or as few loggers as they wish. Loggers are hierarchical in that there is a package-supplied root logger, and every program-defined logger is either the child of the root or of another logger.
  • Multi-level logging. When a message is logged, an attempt it made to log it at the current level. If unsuccessful (or if requested), an attempt it made to log it at the next higher-level, and so on up the tree.
  • Multiple output streams. Each logger can have one or more appenders which format and route output to a destination. If multiple appenders are present in a logger, the message is output once with each appender.

Note: In fact, the implementation chosen is log4cplus (see this bind10-dev thread for details)

Logging Hierarchy

The envisaged logging hierarchy for BIND-10 involves two levels, program and component: each logging component (logger) is a child of the program's logger, which corresponds to the underlying package's root logger. This means that setting options for the program logger applies to all logging in the program unless overridden by options set for a component-level logger; e.g. log the program at "INFO" except for the DNS library, where logging should be set to "DEBUG". In logging output, the source of messages is identified by a combination of the program and component logger, e.g. b10-auth.dnslib. As each program has its own set of logging options, a consequence of this is that the logging parameters for a component may be different in different programs.

In most cases, each module from which a message originated (e.g. the DNS library) will have its own logger. In other cases, the same logger could be used in different modules; for example, messages output in the process of tracing a query through the system could logged using a special "query trace" logger.

Logging

A logger is declared by instantiating an object of the Logger class and passing to it the name of the component, e.g.

Logger logger("dnslib")

Note that it is the name given to the logger that defines the origin of a message and hence the "component" from which it comes. Typically most messages originating within a single module would use the same logger, although a different logger may be used for cross-module messages (such as for tracing queries).

Multiple logging objects of the same name may be declared, in which case they refer to the same logger, and so have the same level filters, output destination etc.

Actual logging takes place through the following calls:

Logger::info(code).arg(arg1).arg(arg2)...
Logger::warn(code).arg(arg1).arg(arg2)...
Logger::error(code).arg(arg1).arg(arg2)...
Logger::fatal(code).arg(arg1).arg(arg2)...

"code" is a message code corresponding to a message defined in an external file. Arguments are specified using the ".arg()" method, and there may be up to 9 arguments associated with each message. (The limitation on the number of arguments is a consequence of the implementation. Arguments are substituted into the message, their position being indicated by the place holders %1, %2 .... A place holder of %10 would not be recognised - the "%1" would be replaced when processing the first argument.)

In standard appenders, the messages will be preceded by the string:

root-name.child-name

... indicating the program and component that logged the error.

Debug Logging

The log4j style of debugging gives two debug levels, DEBUG and TRACE. Typically DEBUG is bare output and TRACE is verbose output. This was felt to be too restrictive, so the current system includes the notion of a "debug level". Each debug statement is associated with a level between 0 and 99, with lower numbers being for the most important debug information. A debug message is only output if the logging level is set to DEBUG and the debug level is equal to or greater than the the number associated with the statement. So for example, in a component processing a DNS response, the QNAME and RCODE might be output at a debug level of 0, but a formatted dump of the packet might be output at a debug level of 50. The actual levels used for each message are up to the developer.

Debug messages are output in the same way as the other logging messages, i.e.

Logger::debug(code, debug_level).arg(arg1).arg(arg2)...

However, there is a drawback: debug messages are most likely to be suppressed in normal use. In addition, debugging information may be relatively expensive to collect, so a statement of the form:

logger.debug(code, level).arg(expensive_call_to_format_data());

could lead to the situation where a lot of CPU cycles are expended to produce the argument to the "arg()" call, only for it not to be used because debugging is disabled. To get round this, a LOG_DEBUG macro is supplied, with the call sequence:

LOG_DEBUG(logger, debug_level).arg(arg1).arg(arg2)...

If debugging is disabled for the given logger and debug level, the arguments ("arg1", "arg2"...) will not be evaluated.

As the same situation could arise for other logging levels, similar macros (LOG_INFO, LOG_WARN etc.) have been supplied for these levels. For consistency's sake, all code should output log messages using them.

Control

By default, no logging level is set for any components apart from the root logger of a program, where the default will be INFO. (This means that all loggers will output "INFO" messages.) If no destination is specified, "syslog" (see below) is assumed.

Loggers will look for configuration items of the form:

logging = [ { logger-spec }, { logger-spec }, ...]

Each logger-spec is of the form:

{ name: <logger-name>, severity: <severity>, debug: <debug-level>, additive: <true:false>, 
        output: [{output-options}, {output-options}, ...] }

name: <logger-name>
Name of the logger (typically the name of the component using this logger). This will be either the name of the program or the name of a component within the program. (As each program has its own logging configuration, a single name is sufficient to identify the component.)

severity: <severity>
Severity is one of DEBUG, INFO, WARN, ERROR, FATAL, NONE. The default is "INFO". If not specified, the severity is retrieved from the program's logger (which defaults to INFO if not set).

debug: <debug level>
Optional, but only interpreted if the severity is DEBUG, this is the debug level. (If not specified when the logging severity is DEBUG, a value of 0 is used.)

additive: <true:false>
Optional. Setting this to true for one of the derived loggers will mean that if he message is output by this logger, it is also passed to the the program's logger for output. (A message not output by a component logger is automatically passed to the program's logger, regardless of the setting of this option.) The default is false, which means that if the message is logged by this logger, it will not be passed on.

output: <target>
A list of output targets for this appender. The list comprises a set of keyword/value pairs (in the form of a Python dictionary), each set specifying one destination. The keywords and allowed values are:

destination: <dest>
Identifies the type of destination. This is mandatory and must be one of:

  • syslog - Output to the syslog file
  • console - Output to stdout or stderr
  • file - Output to a file.

stream: <dest>
Optional, but if present, only valid if the destination is "console" and indicates to which stream console output is sent <dest> can be one of "stdout" or "stderr". (Defaults to stderr if not specified.)

flush: <true|false>
Optional, but if present only valid if the destination is "console" or "file". It indicates whether the output stream is flushed after each event. Setting it to true impacts performance but does mean that in the event of a crash, all preceding logging events will have been written to the file.

facility: <what>
Optional, but if present only valid if the destination is "syslog". It is one of the facility names mentioned in the "syslog.h" file and is the facility under which the BIND 10 messages are logged.

filename: <filename>
Optional, but if present only valid if the destination is "file" and indicates the name of the file to which messages are logged. If the file already exists, messages are appended to it.

maxsize: <size>
Optional, but if present only valid if the destination is "file" and determines the maximum file size (in bytes. Use a kB or MB suffix to indicate kibiBytes or Mebibytes.) Once the file reaches this size, it is closed, renamed (a version number is appended to it) and a new version of the file opened. If not specified, the file will grow to unlimited size.

maxver: <number>
Optional, but if present only valid if the destination is "file" and determines the number of versions of the file to keep. When a file is rolled, the file is renamed <filename>.1, the current ".1" version to ".2" etc. The oldest version is deleted. Note that this is ignored unless the 'maxsize' keyword is specified.

An example of logging configuration is:

logger = [ 
    {
        name: "b10auth",
        severity: "WARN",
        output: [
            {
                destination: "syslog"
            }
        ]
    },
    {
        name: "dnslib",
        severity: "DEBUG",
        debug: 5,
        output: [
            {
                destination: "file",
                filename: "/var/log/dnslib.log",
                maxsize: 25MB,
                maxver: 5
            },
            {
                destination: "console"
            }
        ]
 
     },
]

Here, messages at warning level or higher (WARN, ERROR, or CRITICAL) are sent to syslog, with the exception of messages logged by the dnslib component, where debug messages of level 5 or above set sent to two destinations:

  • A file /var/log/dnslib.log, which is rotated when the file size reaches 25 Mebibytes (previous files being renamed to dnslib.log.1 etc.)
  • stderr (the default for a "console" destination if no stream is specified).

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

C++

Logging Initialization is carried out by calling initLogger(). There are two variants to the call, one for use by production programs and one for use by unit tests.

Initialization for Production Programs

The signature for this is:

void isc::log::initLogger(const std::string& root,
                          isc::log::Severity severity = isc::log::INFO,
                          int dbglevel = 0, const char* file = NULL);

root: Name of the program (e.g. "b10-auth"). This is also the name of the root logger 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. (This may be set by a command-line parameter.)

dbglevel: The debug level used if "severity" is set to isc::log::DEBUG.

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.

Initialization for Unit Tests

The signature for this is:

void isc::log::initLogger()

This is the call that should be used by unit tests. In this variant, as the unit tests will not access the configuration database, all the logging options are supplied by environment variables. (This variant should not be used for production programs to avoid the program operation being affected by inadvertently-defined environment variables.)

The environment variables are:

B10_LOGGER_ROOT: Sets the "root" for the unit test. If not defined, the name "bind10" is used.

B10_LOGGER_SEVERITY: 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, "DEBUG" is used.

B10_LOGGER_DBGLEVEL: If B10_LOGGER_SEVERITY is set to "DEBUG", the debug level. This can be a number between 0 and 99, and defaults to 99.

B10_LOGGER_LOCALMSG: If defined, points to a local message file. The default is not to use a local message file.

B10_LOGGER_DESTINATION: The location to which log message are written. This can be one of:

stdout Message are written to stdout
stderr Messages are written to stderr
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.)
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.

In the case of "stdout", "stderr" and "syslog", they must be written exactly as is - no leading or trailing spaces, and in lower-case.

Note that the default is DEBUG severity at maximum detail. This can lead to the tests generating lot of messages, which can be suppressed if B10_LOGGER_DESTINATION is set to /dev/null. This method of suppression is preferred to setting B10_LOGGER_SEVERITY to NONE as it exercises all the code. As indicated above, the expansion of the LOG_DEBUG macro results in code similar to:

if (logger.isDebugEnabled()) {
logger.debug(code, level).arg(expensive_call_to_format_data());
}

Testing all code paths, including the call to expensive_call_to_format_data(), requires running unit tests such that they log everything with maximum detail. In this case, routing output to /dev/null will suppress the messages.

Python

To be supplied

Implementation Notes

  • The idea of messages in external files is described in more detail here.
Last modified 6 years ago Last modified on Jul 4, 2011, 10:33:28 AM