[trac1040] Update README file

src/lib/log/README

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