|
@@ -1,11 +1,12 @@
|
|
|
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 definitions and text
|
|
|
+* Separation of message use from message text
|
|
|
|
|
|
|
|
|
Hierarchical Logging System
|
|
@@ -28,23 +29,26 @@ 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 Definitions And Text
|
|
|
-===========================================
|
|
|
-The reason for this is to allow the message text to be overridden by versions
|
|
|
-in a local language. To do this, each message is identified by an identifier
|
|
|
-e.g. "OPENIN". 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").
|
|
|
-substitutes any message parameters (in this example, the string that is an
|
|
|
-invalid filename) and logs it to the destination.
|
|
|
+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.
|
|
|
|
|
|
-In the BIND-10 system, a set of default messages are linked into the
|
|
|
-program. At run-time. each program reads a message file, updating the
|
|
|
-stored definitions; this updated text is logged. However, to aid support,
|
|
|
-the message identifier so in the example above, the message finally logged
|
|
|
-would be something like:
|
|
|
+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.
|
|
|
|
|
|
- FAC_OPENIN, unable to open a.txt for input
|
|
|
+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
|
|
@@ -52,8 +56,9 @@ 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, typically 6-12 characters long - and a message.
|
|
|
- The file is described in more detail below.
|
|
|
+ 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".
|
|
|
|
|
@@ -73,9 +78,7 @@ The steps in using the system are:
|
|
|
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. This is a temporary solution
|
|
|
- for Year 2, and will be replaced at a later date, the information coming
|
|
|
- from the configuration database.
|
|
|
+ in logger_support.h) in the main program unit.
|
|
|
|
|
|
|
|
|
Message Files
|
|
@@ -90,16 +93,16 @@ An example file could be:
|
|
|
-- BEGIN --
|
|
|
|
|
|
# Example message file
|
|
|
-# $ID:$
|
|
|
|
|
|
-$PREFIX TEST_
|
|
|
$NAMESPACE isc::log
|
|
|
|
|
|
-% TEST1 message %1 is much too large
|
|
|
-This message is a test for the general message code
|
|
|
+% 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.
|
|
|
|
|
|
-% UNKNOWN unknown message
|
|
|
-Issued when the message is unknown.
|
|
|
+% 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 --
|
|
|
|
|
@@ -114,10 +117,8 @@ Points to note:
|
|
|
a line by themselves - inline comments will be interpreted as part of the
|
|
|
text of the line.
|
|
|
|
|
|
-* Lines starting $ are directives. At present, two directives are recognised:
|
|
|
-
|
|
|
- * $PREFIX, which has one optional argument: the string used to prefix symbols.
|
|
|
- If absent, there is no prefix to the symbols (prefixes are explained below).
|
|
|
+* 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
|
|
@@ -127,10 +128,19 @@ Points to note:
|
|
|
identification and the message text, the latter including zero or more
|
|
|
replacement tokens, e.g.
|
|
|
|
|
|
- % TEST message %1 is larger than the permitted length of %2
|
|
|
+ % 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 word "TEST").
|
|
|
+ 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
|
|
@@ -147,42 +157,36 @@ Message Compiler
|
|
|
The message compiler is a program built in the src/log/compiler directory.
|
|
|
It is invoked by the command:
|
|
|
|
|
|
- message [-h] [-v] <message-file>
|
|
|
+ message [-h] [-v] -p] <message-file>
|
|
|
+
|
|
|
+("-v" prints the version number and exits; "-h" prints brief help text.) The
|
|
|
+compiler produces source files for C++ and Python.
|
|
|
|
|
|
-("-v" prints the version number and exits; "-h" prints brief help text.)
|
|
|
-The message compiler processes the message file to produce two files:
|
|
|
+C++ Files
|
|
|
+---------
|
|
|
+Without the "-p" option, the message compiler processes the message file
|
|
|
+to produce two files:
|
|
|
|
|
|
1) A C++ header file (called <message-file-name>.h) that holds lines of
|
|
|
the form:
|
|
|
|
|
|
namespace <namespace> {
|
|
|
- extern const isc::log::MessageID PREFIX_IDENTIFIER;
|
|
|
+ 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.
|
|
|
|
|
|
-The "PREFIX_" part of the symbol name is the string defined in the $PREFIX
|
|
|
-the argument to the directive. So "$PREFIX MSG_" would prefix the identifier
|
|
|
-ABC with "MSG_" to give the symbol MSG_ABC. Similarly "$PREFIX E" would
|
|
|
-prefix it with "E" to give the symbol EABC. If no $PREFIX is given, no
|
|
|
-prefix appears (so the symbol in this example would be ABC).
|
|
|
-
|
|
|
-The prefix is "syntactic sugar". Generally all symbols in a given message file
|
|
|
-will be prefixed with the same set of letters. By extracting these into
|
|
|
-a separate prefix, it becomes easier to disambiguate the different symbols.
|
|
|
-
|
|
|
-There may be multiple $PREFIX directives in a file. A $PREFIX directive applies
|
|
|
-to all message definitions between it an the next $PREFIX directive. A $PREFIX
|
|
|
-directive with no arguments clears the current prefix.
|
|
|
+(This is the reason for the restriction on message identifiers - they
|
|
|
+have to be valid C++ symbol names.)
|
|
|
|
|
|
2) 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 the map.
|
|
|
|
|
|
Symbols are defined to be equal to strings holding the identifier, e.g.
|
|
|
|
|
|
- extern const isc::log::MessageID MSG_DUPLNS = "MSG_DUPLNS";
|
|
|
+ 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.)
|
|
@@ -208,16 +212,29 @@ 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")
|
|
|
|
|
|
-Using the Logging
|
|
|
-=================
|
|
|
-To use the current version of the logging:
|
|
|
+(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:
|
|
|
+ (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.
|
|
|
|
|
@@ -228,88 +245,134 @@ To use the current version of the logging:
|
|
|
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.
|
|
|
+ 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.
|
|
|
|
|
|
- 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.)
|
|
|
+4. Issue logging calls using supplied macros in "log/macros.h", e.g.
|
|
|
|
|
|
- The settings remain in effect until the logging configuration is read, and
|
|
|
- so provide the default logging during program initialization.
|
|
|
+ LOG_ERROR(logger, LOG_WRITE_ERROR).arg("output.txt");
|
|
|
|
|
|
-3. Issue logging calls using supplied macros in "log/macros.h", e.g.
|
|
|
+ (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.)
|
|
|
|
|
|
- LOG_ERROR(logger, DPS_NSTIMEOUT).arg("isc.org");
|
|
|
+Using the Logging - Python
|
|
|
+==========================
|
|
|
+1. Build message module as describe above.
|
|
|
|
|
|
- (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.)
|
|
|
+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:
|
|
|
|
|
|
- Note: in the example above we might have defined the symbol in the message
|
|
|
- file with something along the lines of:
|
|
|
+ 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");
|
|
|
|
|
|
- $PREFIX DPS_
|
|
|
- :
|
|
|
- NSTIMEOUT queries to all nameservers for %1 have timed out
|
|
|
|
|
|
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.
|
|
|
+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.)
|
|
|
+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.
|
|
|
+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.
|
|
|
+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,
|
|
|
+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.
|
|
|
+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:
|
|
|
+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
|
|
@@ -325,38 +388,34 @@ 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.
|
|
|
+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.
|
|
|
+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.
|
|
|
+(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.
|
|
|
-
|
|
|
-
|
|
|
-Outstanding Issues
|
|
|
-==================
|
|
|
-* Ability to configure system according to configuration database.
|
|
|
+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.
|