Copyright (C) 2004 Internet Systems Consortium, Inc. ("ISC") Copyright (C) 1999-2001 Internet Software Consortium. See COPYRIGHT in the source root or http://isc.org/copyright.html for terms. $Id: logging,v 1.10 2004/03/05 05:04:46 marka 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 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 #include 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 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 #include #include 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.