bind/doc/design/logging

Copyright (C) Internet Systems Consortium, Inc. ("ISC")

See COPYRIGHT in the source root or http://isc.org/copyright.html for terms.

OVERVIEW

The ISC logging system is designed to provide a flexible, extensible
method of writing messages.  Messages can be sent to the system's
logging facility, directly to a file, or into the bitbucket, usually
configured per the desires of the users of the program.  Each message
is associated with a particular category (eg, "security" or
"database") that reflects its nature, and a particular module (such as
the library's source file) that reflects its origin.  Messages are
also each assigned a priority level which states how remarkable the
message is, so that too can be configured by the program's user to
control how much detail is desired.

Libraries which use the ISC logging system can be linked against each
other without fear of conflict.  A program is able to select which, if
any, libraries will write log messages.

FUNDAMENTALS

This section describes the basics of how the system works, introduces
terms and defines C preprocessor symbols used in conjuction with
logging functions.  Actual uses of functions are demonstrated in the
following two sections.

Log messages are associated with three pieces of information that are
used to determine their disposition:  a category, a module, and a
level (aka "priority").

A category describes the conceptual nature of the message, that is,
what general aspect of the code it is concerned with.  For example,
the DNS library defines categories that include the workings of the
database as well security issues.  Macros for naming categories are
typically provided in the library's log header file, such as
DNS_LOGCATEGORY_DATABASE and DNS_LOGCATEGORY_SECURITY in <dns/log.h>
for the two categories in the previous sentence.  The special category
ISC_LOGCATEGORY_DEFAULT is associated with any message that does not
match a particular category (or matches a category but not a module,
as seen in the next paragraph).

A module is loosely the origin of a message.  Though there not be a
one-to-one correspondence of source files with modules, it is typical
that a module's name reflect the source file in which it is used.  So,
for example, the module identifier DNS_LOGMODULE_RBT would be used by
messages coming from within the dns/rbt.c source file.

The specification of the combination of a category and a module for a
message are called the message's "category/module pair".

The level of a message is an indication of its severity.  There are
six standard logging levels, in order here from most to least severe
(least to most common):
  ISC_LOG_CRITICAL      -- An error so severe it causes the program to exit.
  ISC_LOG_ERROR         -- A very notable error, but the program can go on.
  ISC_LOG_WARNING       -- Something is probably not as it should be.
  ISC_LOG_NOTICE        -- Notable events that occur while the program runs.
  ISC_LOG_INFO          -- Statistics, typically.
and finally:
  ISC_LOG_DEBUG(unsigned int level)     -- detailed debugging messages.

ISC_LOG_DEBUG is not quite like the others in that it takes an
argument the defines roughly how detailed the message is; a higher
level means more copious detail, so that values near 0 would be used
at places like the entry to major sections of code, while greater
numbers would be used inside loops.

So, ok, technically there are five + at least 4,294,967,296 levels.
Picky picky.  In any event, the six levels correspond with similar
levels used by Unix's syslog, and when messages using one of those
levels is sent to syslog, the equivalent syslog level is used.  (Note
that this means that any debugging messages go to the singular
LOG_DEBUG priority in syslog, regardless of their level internal to
the ISC logging system.)

The next building block of the logging system is a channel.  A channel
specifies where a message of a particular priority level should go, as
well as any special options for that destination.  There are four
basic destinations, as follows:

  ISC_LOG_TOSYSLOG      -- Send it to syslog.
  ISC_LOG_TOFILE        -- Write to a file.
  ISC_LOG_TOFILEDESC    -- Write to a (previously opened) file descriptor.
  ISC_LOG_TONULL        -- Do not write the message when selected.

A file destination names a path to a log file.  It also specifies the
maximum allowable byte size of the file before it is closed (where 0
means no limit) and the number of versions of a file to keep (where
ISC_LOG_ROLLNEVER means the logging system never renames the log file,
and ISC_LOG_ROLLINFINITE means no cap on the number of versions).
Version control is done just before a file is opened, so a program
that used it would start with a fresh log file (unless using
ISC_LOG_ROLLNEVER) each time it ran.  If you want to use an external
rolling method, use ISC_LOG_ROLLNEVER and ensure that your program has
a mechanism for calling isc_log_closefilelogs().

(ISC_LOG_ROLLINFINITE is not truly infinite; it will stop at INT_MAX.
On 32 bit machines that means the logs would need to roll once per
second for more than sixty years before exhausting the version number
space.)

A file descriptor destination is simply associated with a previously
opened stdio file descriptor.  This is mostly used for associating
stdout or stderr with log messages, but could also be used, for
example, to send logging messages down a pipe that has been opened by
the program.  File descriptor destinations are never closed, have no
maximum size limit, and do not do version control.

Syslog destinations are associated with the standard syslog facilities
available on your system.  They too have no maximum size limit and do
no version control.

Since null channels go nowhere, no additional destination
specification is necessary.

The words "destination" and "channel" can be used interchangably in
some contexts.  Referring to a file channel, for example, means a
channel that has a file destination.

Channels have string names that are their primary external reference.
There are four predefined logging channels:

  "default_stderr" -- Descriptor channel to stderr at priority ISC_LOG_INFO
  "default_debug"  -- Descriptor channel to stderr at priority ISC_LOG_DYNAMIC
  "default_syslog" -- Syslog channel to LOG_DAEMON at priority ISC_LOG_INFO
  "null"           -- Null channel

What's ISC_LOG_DYNAMIC?  That's how you tell the logging system that
you want debugging messages, but only at the current debugging level
of the program.  The debugging level is controlled as described near
the end of the next section.  When the debugging level is 0 (turned
off), then no debugging messages are written to the channel.  If the
debugging level is raised, only debugging messages up to its level are
written to the channel.

You can reuse a channel name.  If you define a channel with the same
name as an existing channel, the new definition is used by all future
references to the name.  The old definition is still used by anything
that was pointing to the name before the redefinition.  This even
applies to redefinitions of the predefined channels, with one
exception:  redefining default_stderr will change the default
destination of messages, as explained in more detail in a few paragraphs.

Channels can additionally have any of five options associated with
them.  The following options are listed in the order which their
corresponding print strings appear in a log message:

  ISC_LOG_PRINTTIME     -- The date and time.
  ISC_LOG_PRINTCATEGORY -- The category name.
  ISC_LOG_PRINTMODULE   -- The module name.
  ISC_LOG_PRINTLEVEL    -- The level.

You can set all four of those options with ISC_LOG_PRINTALL.

Syslog channels do not need ISC_LOG_PRINTTIME, but it is usally a good
idea for file and file descriptor feeds.

The additional option does not affect formatting.  It is
ISC_LOG_DEBUGONLY, and marks a channel as only being eligible for
messages when the debugging level is non-zero.  It acts like the
null channel when the debugging level is zero.

Now with these objects -- the category, module, and channel -- you can
actually direct messages to your desired destinations.  As shown in
the next section, you associate the category/module pair with a
channel.  It is possible to use one function call to say "all modules
coupled with this category" and vice versa, but conceptually the
matching is still referred to as applying to category/module pairs,
since that is what comes in from functions writing messages.

Speaking of functions writing messages, here's what happens when a
function wants to write a message through the logging system.  First
the function calls isc_log_write(), specifying a category, module and
level.

In isc_log_write(), the logging system first looks up a list that
consists of all of the channels associated with a particular category.
It walks down the list looking for each channel that also has the
indicated module associated with it, and writes the message to each
channel it encounters.  If no match is found in the list for the
module, the default channel is used.  Similarly, the default is used
if no channels have been specified for the category at all.

What is the default?  It is ISC_LOGCATEGORY_DEFAULT -- sort of.  You
can specify an association of the channel ISC_LOGCATEGORY_DEFAULT with
any particular module, or more usually all of them, and that's what
will be used for any category/module pair for which you have not
specified a channel.  If you do not associate ISC_LOGCATGORY_DEFAULT
and the indicated module, then the internal default of using the
default_stderr channel is used.  This brings us back to the statement
made a few paragraphs ago about redefining the predefined channels --
if you redefine default_stderr, and a messages comes in for a
category/module pair that has had neither its original pair or
the ISC_LOGCATEGORY_DEFAULT/module pair configured for it, then the
message will go to the _new_ definition of default_stderr.

Here are some other ways to think about how category/module pairs get
matched with regard to using the defaults:

  If a channel is is specified for a category as applying to all modules
  which use that category, then the default channel will be used for no
  combination of that category with any module.

  If a category is specified with one or more explicit modules, any
  modules _not_ using that category still use the default.

As with the BIND 8 logging code, when a log message is not written
because the of the severity level of the channel, the default is _not_
used, because the category and module are considered to have matched.
The default is only used when a category/module pair has not been
specified.  If you want to use the default for some messages but also
send higher (lower?) priority messages someplace else, then you will
need to specify both the default channel and a custom channel for that
category/module pair.

It is important to note that specifying a null destination for a
category/module pair has no effect on any other destinations
associated with that pair, regardless of ordering.  For example,
though it seems reasonable, you cannot say "for category A and all
modules, log to stderr, but for category A and module 2 don't show any
messages."  You would need to specify stderr for category A with all
modules except module 2, and then specify null for A/2.  This could be
inconvenient, especially if you do not know all of the modules
associated with a particular category but you know the one you want to
shut up.  Because of this, it is likely that specifying a null
destination _will_ block other channels that also specify a particular
category/module pair, but the exact mechanism has not yet been
determined.

No attempt is made to filter out duplicate destinations, so it is
certainly possible to define things such that a single log gets more
than one copy of the same message.  This may change in the future.

EXTERNALLY VISIBLE STRUCTURE

Two of the fundamental types used by programs for configuring log
message destinations are isc_log_t and isc_logconfig_t.  The isc_log_t
type is normally created only once by a program, to hold the (relatively)
static information about what categories and modules exist in the program
and some other housekeeping information.  isc_logconfig_t is used to
store the configurable specification of message destinations, which
can be changed during the course of the program.

A starting configuration (isc_logconfig_t) is created implicitly when
the context (isc_log_t) is created.  The pointer to this configuration
is returned via a parameter to isc_log_create so that it can then be
configurated.  A new configuration can be established by creating
it with isc_logconfig_create, configuring it, then installing it as
the active configuration with isc_logconfig_use.

MULTITHREADED PROGRAMS

The entire logging context is thread locked for most of duration of
the isc_log_write.   However, isc_log_write does avoid the delays
caused by locking when it is clear that there are no possible outputs
for a message based on its debugging level --- this is so that a
program can have debugging messages sprinkled liberally throughout it
but not incur any locking penalty when debugging is not enabled.

The logging context is locked when a new configuration is installed
by isc_logconfig_use.

USING LIBRARIES THAT USE THE LOGGING SYSTEM

To enable the messages from a library that uses the logging system,
the following steps need to be taken to initialize it.

1) Include the main logging header file as well as the logging header
file for any additional library you are using.  For example, when
using the DNS library, include the following:

  #include <isc/log.h>
  #include <dns/log.h>

2) Initialize a logging context.  A logging context needs a valid
memory context in order to work, so the following code snippet shows a
rudimentary initialization of both.

  isc_mem_t *mctx;
  isc_log_t *lctx;
  isc_logconfig_t *lcfg;

  isc_mem_create(&mctx);
  if (isc_log_create(mctx, &lctx, &lcfg) != ISC_R_SUCCESS))
          oops_it_didnt_work();

3) Initalize any additional libraries.  The convention for the name of
the initialization function is {library}_log_init, with just a pointer
to the logging context as an argument.  The function can only be
called once in a program or it will generate an assertion error.

  dns_log_init(lctx);

If you do not want a library to write any log messages, simply do not
call its the initialization function.

4) Create any channels you want in addition to the internal channels
of default_syslog, default_stderr, default_debug and null.  A
destination structure needs to be filled for any destination other
than null.  The following examples show use of a file log, a file
descriptor log, and syslog.

  isc_logdestination_t destination;

  destination.file.name = "/var/log/example";
  destination.file.maximum_size = 0;              /* No byte limit. */
  destination.file.versions = ISC_LOG_ROLLNEVER;  /* External rolling. */
  if (isc_log_createchannel(lcfg, "sample1" ISC_LOG_TOFILE, ISC_LOG_DYNAMIC,
                            &destination, ISC_LOG_PRINTTIME) != ISC_R_SUCCESS)
          oops_it_didnt_work();

  destination.file.stream = stdout;
  if (isc_log_createchannel(lcfg, "sample2" ISC_LOG_TOFILEDESC, ISC_LOG_INFO,
                            &destination, ISC_LOG_PRINTTIME) != ISC_R_SUCCESS)
          oops_it_didnt_work();

  destination.facility = LOG_ERR;
  if (isc_log_createchannel(lcfg, "sample3" ISC_LOG_SYSLOG, ISC_LOG_ERROR,
                            &destination, 0) != ISC_R_SUCCESS)
          oops_it_didnt_work();

Note that ISC_LOG_DYNAMIC is used to define a channel that wants any
of the messages up to the current debugging level of the program
(described below).  ISC_LOG_DEBUG(level) can define a channel that
_always_ gets messages up to the debug level specified, regardless of
the debugging state of the server.

Remember that you can redefine these internal channels, and that in
particular redefining default_stderr will change the default logging
method.

5) Direct the various log categories and modules to the desired
destination.  This step is not necessary if the normal behavior of
sending all messages to default_stderr is acceptable.  The following
examples sends DNS security messages to stderr, DNS database messages
to null, and all other messages to syslog.

  if (isc_log_usechannel(lcfg, "default_stderr", DNS_LOGCATEGORY_SECURITY,
                         NULL) != ISC_R_SUCCESS)
          oops_it_didnt_work();

  if (isc_log_usechannel(lcfg, "null", DNS_LOGCATEGORY_DATABASE, NULL)
      != ISC_R_SUCCESS)
          oops_it_didnt_work();

  if (isc_log_usechannel(lcfg, "default_syslog", ISC_LOGCATEGORY_DEFAULT,
                         NULL) != ISC_R_SUCCESS)
          oops_it_didnt_work();

Providing a NULL argument for the category means "associate the
channel with the indicated module in all known categories" ---
including ISC_CATEGORY_DEFAULT.  Providing a NULL argument for the
module means "associate the channel with all modules that use this
category."

6) If you are sending any messages to syslog, call
isc_log_opensyslog().  Currently the arguments to this function are
exactly the same as to syslog's openlog() function, but it is expected
that this will change when the logging library is made to work with the
system logging facility on Windows NT.

  isc_log_opensyslog(NULL, LOG_PID, LOG_DAEMON);

Now the libraries used by your program will write messages according
to your specifications.

7) If you want to swap in a new configuration to replace the existing
configuration, first create the new configuration with:

  result = isc_logconfig_create(lctx, &newlcfg);

and then configure newlcfg with isc_log_createchannel() and
isc_log_usechannel().  When it is all ready:

  result = isc_logconfig_use(lctx, newlcfg);

If the new configration is successfully installed, then the old one
will be destroyed, freeing all memory it used.

There are three additional functions you might find useful in your
program to control logging behavior, two to work with the debugging
level and one to control the closing of log files.

void isc_log_setdebuglevel(isc_log_t *lctx, unsigned int level) and
unsigned int isc_log_getdebuglevel(isc_log_t *lctx) set and retrieve
the current debugging level of the program.  isc_log_getdebuglevel()
can be used so that you need not keep track of the level yourself in
another variable.  One use for these functions would be in a daemon
that could have its debugging level raised with a USR1 signal or lowered
with a USR2 signal.

The void isc_log_closefilelogs(isc_log_t *lcxt) function closes any
open log files.  This is useful for programs that do not want to do
file rotation as with the internal rolling mechanism.  For example, a
program that wanted to keep daily logs would define a channel which
used ISC_LOG_ROLLNEVER, then once a day would rename the log file and
call isc_log_closefilelogs().  The next time a message needs to be
written a file that has been closed, it is reopened.

WRITING LIBRARIES THAT USE THE LOGGING SYSTEM

This section describes how a new library, libfoo.a, would use the ISC
logging system internally.

1) Provide a header file that does the following:
  * includes isc/log.h
  * declares foo_lctx, a logging context that will be used throughout
        the library.
  * declares the structures that specify the categories and modules
        known by the library.
  * defines the macros that provide convenient access to the library's
        categories and modules.
  * prototypes the library's log initialization function.

  See <dns/log.h> for a sample.

2) Write a C source module that includes the library's log.h,
  provides storage for the library's logging context,
  initializes the category and module structures, and defines the
  initialization function, foo_log_init().  log.c from libdns.a looks
  like this (trimmed down):

  #include <isc/result.h>
  #include <isc/log.h>
  #include <dns/log.h>

  isc_logcategory_t dns_categories[] = {
          { "dns_general", 	0 },
          { "dns_database", 	0 },
          { "dns_security", 	0 },
          { NULL, 		0 }
  };
  isc_logmodule_t dns_modules[] = {
          { "db", 	0 },
          { "rbtdb", 	0 },
          { NULL, 	0 }
  };

  isc_log_t *dns_lctx;

  dns_result_t
  dns_log_init(isc_log_t *lctx) {
          isc_result_t result;

          REQUIRE(dns_lctx == NULL);

          result = isc_log_registercategories(lctx, dns_categories);

          if (result == ISC_R_SUCCESS) {
                  isc_log_registermodules(lctx, dns_modules);
                  dns_lctx = lctx;
          }

          return (result);
  }

Note that the init function is what associates that library's logging
context with the one that the calling program must create and
initialize.  If the init function is never called, the library's
logging context will be NULL, so any calls by other library functions
to log messages will simply return with no message being written.

3) Use the isc_log_write() function to have messages written according
to the definitions in the logging context.  Its arguments are the
logging context, a category, a module, a logging level, a printf(3)
format string, and any additional arguments that are necessary for the
format string.  For example:

	isc_log_write(dns_lctx, DNS_LOGCATEGORY_GENERAL, DNS_LOGMODULE_RBT,
		      ISC_LOG_CRITICAL, "%s",
		      "Node %d in red-black tree is crimson!", node);

No newline should be included, nor should the program name.  Usually
the source file name or the function name should not be included
either, since location information can be attained, if desired, with
ISC_LOG_PRINTMODULE.  On rare occasion it might be necessary to
differentiate very similar messages in the same module.

When available, include standard library return codes via %s in the
format string, with strerrr(errno) from the system libary or functions
like isc_result_totext(result) and dns_result_totext(result).

THINGS I AM NOT KEEN ABOUT

I am not happy that using a null channel for a category/module pair
has no effect on other associations with that pair.  It seems to me
that it would be nice to say "send all DATABASE category messages to
syslog, except for those from the RBT base code."  I am not sure of
how I want it specified though.  One way to do it is to simply say
that null overrides any previously defined matches for the
category/module, so that internally when walking down the channel
list, the first category/module match to a null channel stops
processing.