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 rest of the line - from the first non-space character to the last non- space character - is taken exactly for the text of the message. There are no restrictions on what characters may be in this text, other than they be printable. (This means that 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. 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 must include a call to isc::log::initLogger() (described in more detail below) 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 must include a call to isc.log.init() (described in more detail below) 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"); 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. 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. Variant #1, Used by Production Programs --------------------------------------- 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); This is the call that should be used by production programs: 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. buffer 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 LoggerManager's process() calls (if you are using the built-in logging configuration handling in ModuleCCSession, this is automatically handled). 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). Variant #2, Used by Unit Tests ------------------------------ void isc::log::initLogger() 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: 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, "INFO" 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 0. 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. Python ------ To be supplied 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. 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 type of debug output. However, modules are free to set their own debug levels or define additional ones. 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.