diff --git a/doc/design/logging b/doc/design/logging new file mode 100644 index 0000000000..925ee62202 --- /dev/null +++ b/doc/design/logging @@ -0,0 +1,447 @@ +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 four 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. + +Syslog channels do not need ISC_LOG_PRINTTIME, but it is usally a good +idea for file and file descriptor feeds. + +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 +determine. + +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 + #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; + + 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, "sample2" 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 +modulemeans "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. This is necessary + + 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 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 + +The category/module names passed into the registration functions need +to have a colon-space (": ") at the end of each name. + +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.