[krbdev.mit.edu #8630] Logging from KDC/kadmind plugin modules

[Greg Hudson via RT]

KDC and kadmind plugin modules should be able to write log messages 
to facilitate operational debugging and transitions.  For example, 
the PKINIT kdcpreauth module should be able to log whether the client 
sent a freshness token, to allow a KDC administrator to determine 
when it is practical to require freshness tokens.  For this ticket, I 
am going to ignore the problem of associating module log information 
with core KDC log information about an AS or TGS request, and focus 
on being able to write log messages at all.

A module can link against libkadm5srv and call krb5_klog_syslog() 
like the KDC and kadmind do.  Of the modules in the krb5 source tree, 
only securid_sam2 does this, always logging at LOG_INFO severity.  
For some modules linking against libkadm5srv is undesirable; for 
instance, the PKINIT shared object is both a clpreauth and a 
kdcpreauth module, and the clpreauth module shouldn't drag in the 
server-side libraries.

krb5kdc and kadmind install a custom com_err handler which causes 
com_err() calls to write to the logging device.  This handler is 
potentially useful because modules have access to com_err() even if 
they don't link against libkadm5srv.  Within the KDC, com_err() is 
invoked in a few places (mostly just at startup) via the kdc_err() 
wrapper, which ensures that extended error messages are used when 
fetching the error message for the com_err code.  Within plugin 
modules in the krb5 source tree, the securid_sam2 and OTP modules 
make calls to com_err().  securid_sam2 passes a whoami value of 
"krb5kdc"; OTP passes a whoami value of "otp".  Plugin modules cannot 
make extended error messages used for the com_err code as they do not 
have access to the krb5_context object registered with the com_err 
handler.

The current behavior of the custom com_err handler is full of 
interesting corners:

* If the first byte of the format has a value between 1 and 8 
inclusive, that byte is treated as a severity level.  I'm not aware 
of any uses of this, and using it would be awkward ("\5format" to log 
at warning level).

* It doesn't go through krb5_klog_syslog(); it has its own separate 
loop and switch statement to write to the logging outputs.

* For file/device/console/stderr logging, it does not follow the 
format of krb5_klog_syslog() at all, so a log might look like:

    Dec 25 08:54:56 equal-rites krb5kdc[23873](info): setting up 
network...
    krb5kdc: setsockopt(9,IPV6_V6ONLY,1) worked
    krb5kdc: setsockopt(11,IPV6_V6ONLY,1) worked
    Dec 25 08:54:56 equal-rites krb5kdc[23873](info): set up 4 
sockets

  where the first and fourth lines were generated with 
krb5_klog_syslog() and the second and third were generated with 
com_err().

* For syslog output, if no severity was given in the format string, 
the default severity is used if one was given in the SYSLOG: 
specification for the logging spec.  (The default severity is 
LOG_ERR.)  This is the only use of the default severity.  
Conceptually, a default severity doesn't make much sense, as log 
event severity should be a property of an individual logging call, 
not a logging output.

* For syslog output, the whoami value passed to com_err() is ignored 
in favor of the value passed to openlog() at krb5_klog_init() time.  
For other outputs, the whoami value passed to com_err() is included 
in the message.

The PKINIT module currently does no logging via the KDC/kadmind log 
framework.  It outputs some messages to the trace log, and it also 
has an extensive set of debugging output calls which are compiled out 
by default.  Some of these messages would be appropriate for trace 
logging, some for traditional logging, and some are only potentially 
interesting for debugging the code without using gdb.