logging revision ed301acd3437a28b623f5875c6e6be6e4efb791c
082f42dcf2f38509a8c842013548f680a6ad06f3Mark AndrewsOVERVIEW
09b46c39456ea75a414d8fcdb13127ed4917dac2Automatic Updater
082f42dcf2f38509a8c842013548f680a6ad06f3Mark AndrewsThe ISC logging system is designed to provide a flexible, extensible
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsmethod of writing messages. Messages can be sent to the system's
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewslogging facility, directly to a file, or into the bitbucket, usually
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsconfigured per the desires of the users of the program. Each message
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsis associated with a particular category (eg, "security" or
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrews"database") that reflects its nature, and a particular module (such as
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsthe library's source file) that reflects its origin. Messages are
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsalso each assigned a priority level which states how remarkable the
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsmessage is, so that too can be configured by the program's user to
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewscontrol how much detail is desired.
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrews
082f42dcf2f38509a8c842013548f680a6ad06f3Mark AndrewsLibraries which use the ISC logging system can be linked against each
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsother without fear of conflict. A program is able to select which, if
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsany, libraries will write log messages.
09b46c39456ea75a414d8fcdb13127ed4917dac2Automatic Updater
082f42dcf2f38509a8c842013548f680a6ad06f3Mark AndrewsFUNDAMENTALS
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrews
082f42dcf2f38509a8c842013548f680a6ad06f3Mark AndrewsThis section describes the basics of how the system works, introduces
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsterms and defines C preprocessor symbols used in conjuction with
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewslogging functions. Actual uses of functions are demonstrated in the
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsfollowing two sections.
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrews
082f42dcf2f38509a8c842013548f680a6ad06f3Mark AndrewsLog messages are associated with three pieces of information that are
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsused to determine their disposition: a category, a module, and a
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewslevel (aka "priority").
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrews
082f42dcf2f38509a8c842013548f680a6ad06f3Mark AndrewsA category describes the conceptual nature of the message, that is,
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewswhat general aspect of the code it is concerned with. For example,
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsthe DNS library defines categories that include the workings of the
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsdatabase as well security issues. Macros for naming categories are
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewstypically provided in the library's log header file, such as
082f42dcf2f38509a8c842013548f680a6ad06f3Mark AndrewsDNS_LOGCATEGORY_DATABASE and DNS_LOGCATEGORY_SECURITY in <dns/log.h>
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsfor the two categories in the previous sentence. The special category
082f42dcf2f38509a8c842013548f680a6ad06f3Mark AndrewsISC_LOGCATEGORY_DEFAULT is associated with any message that does not
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsmatch a particular category (or matches a category but not a module,
082f42dcf2f38509a8c842013548f680a6ad06f3Mark Andrewsas seen in the next paragraph).
26b49e84597ab3ebaa9ae1eb0fe01befa46a8107Mark Andrews
26b49e84597ab3ebaa9ae1eb0fe01befa46a8107Mark AndrewsA module is loosely the origin of a message. Though there not be a
26b49e84597ab3ebaa9ae1eb0fe01befa46a8107Mark Andrewsone-to-one correspondence of source files with modules, it is typical
26b49e84597ab3ebaa9ae1eb0fe01befa46a8107Mark Andrewsthat a module's name reflect the source file in which it is used. So,
26b49e84597ab3ebaa9ae1eb0fe01befa46a8107Mark Andrewsfor example, the module identifier DNS_LOGMODULE_RBT would be used by
26b49e84597ab3ebaa9ae1eb0fe01befa46a8107Mark Andrewsmessages coming from within the dns/rbt.c source file.
26b49e84597ab3ebaa9ae1eb0fe01befa46a8107Mark Andrews
26b49e84597ab3ebaa9ae1eb0fe01befa46a8107Mark AndrewsThe specification of the combination of a category and a module for a
26b49e84597ab3ebaa9ae1eb0fe01befa46a8107Mark Andrewsmessage are called the message's "category/module pair".
26b49e84597ab3ebaa9ae1eb0fe01befa46a8107Mark Andrews
fb604d1cee223986d090763292015309adfcf9c7Mark AndrewsThe level of a message is an indication of its severity. There are
fb604d1cee223986d090763292015309adfcf9c7Mark Andrewssix standard logging levels, in order here from most to least severe
fb604d1cee223986d090763292015309adfcf9c7Mark Andrews(least to most common):
fb604d1cee223986d090763292015309adfcf9c7Mark Andrews ISC_LOG_CRITICAL -- An error so severe it causes the program to exit.
fb604d1cee223986d090763292015309adfcf9c7Mark Andrews ISC_LOG_ERROR -- A very notable error, but the program can go on.
fb604d1cee223986d090763292015309adfcf9c7Mark Andrews ISC_LOG_WARNING -- Something is probably not as it should be.
fb604d1cee223986d090763292015309adfcf9c7Mark Andrews ISC_LOG_NOTICE -- Notable events that occur while the program runs.
fb604d1cee223986d090763292015309adfcf9c7Mark Andrews ISC_LOG_INFO -- Statistics, typically.
fb604d1cee223986d090763292015309adfcf9c7Mark Andrewsand finally:
fb604d1cee223986d090763292015309adfcf9c7Mark Andrews ISC_LOG_DEBUG(unsigned int level) -- detailed debugging messages.
fb604d1cee223986d090763292015309adfcf9c7Mark Andrews
fb604d1cee223986d090763292015309adfcf9c7Mark AndrewsISC_LOG_DEBUG is not quite like the others in that it takes an
fb604d1cee223986d090763292015309adfcf9c7Mark Andrewsargument the defines roughly how detailed the message is; a higher
fb604d1cee223986d090763292015309adfcf9c7Mark Andrewslevel 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.
Finally, here is a note about multiprocessing. The entire logging
context is pthread locked for most of duration of the isc_log_write.
That's it, that's the note.
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;
if (isc_mem_create(0, 0, &mctx) != ISC_R_SUCCESS) ||
isc_log_create(mctx, &lctx) != 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(lctx, "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(lctx, "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(lctx, "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(lctx, "default_stderr", DNS_LOGCATEGORY_SECURITY,
NULL) != ISC_R_SUCCESS)
oops_it_didnt_work();
if (isc_log_usechannel(lctx, "null", DNS_LOGCATEGORY_DATABASE, NULL)
!= ISC_R_SUCCESS)
oops_it_didnt_work();
if (isc_log_usechannel(lctx, "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.
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.