Copyright (C) 1999, 2000 Internet Software Consortium.

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

$Id: logging,v 1.6 2000/06/22 21:53:52 tale Exp $

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;

if (isc_mem_create(0, 0, &mctx) != ISC_R_SUCCESS) ||

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.