Projects/Trace logging
Background
Multiple users of Kerberos have expressed a desire for logging to assist in the diagnosis of configuration failures. As a secondary benefit, such a facility may also be useful for debugging work by Kerberos developers. Requirements include:
- It must be possible to turn on tracing for some processes and not others.
- It must be possible to enable tracing for a program with no special application support for tracing.
- It must be possible to enable and disable tracing dynamically within a running process. It is acceptable, though not desirable, for this functionality to require application support.
- It is important that it be possible to enable trace logging in a standard build, such as the one shipped by the operating system vendor, because it is generally not possible to substitute specially compiled code in a customer deployment.
- The facility must not compromise the security of setuid programs by allowing the invoking user to leak information or write log files using elevated privileges.
- The facility must have a minimal impact on performance when not enabled.
- It should be possible to explicitly disable the facility at compile-time for embedded deployments or kernel code.
- Trace points must be symbolically distinct, and not distinguished only by a text string. (This is important for integration with vendor-supported tracing systems such as DTrace.)
User Interface
Tracing can be enabled by setting the KRB5_TRACE environment variable to a filename. This will not work for secure contexts.
Tracing can be controlled by the application using either of the following APIs:
/* This structure may be extended to contain more fields in the future. */
struct krb5_trace_info {
const char *message;
};
typedef void (*krb5_trace_callback)(krb5_context context, struct krb5_trace_info *info, void *cb_data);
krb5_error_code krb5_set_trace_filename(krb5_context context, const char *filename);
krb5_error_code krb5_set_trace_callback(krb5_context context, krb5_trace_callback fn, void *cb_data);
Either callback can be invoked with NULL to disable tracing. The use of either API to enable tracing will disable any previous tracing. When a trace callback is disabled (either through destruction of the krb5_context or through a subsequent call to one of the above APIs), the callback will be invoked with a NULL info argument to allow destruction of cb_data.
To disable tracing at compile time, the builder will specify --disable-tracing to configure. In this case, the aforementioned APIs will still exist, but will return KRB5_TRACE_NOSUPP.
Tracing API
Each trace point will have a separate macro; an example invocation for credential acquisition might be:
TRACE_GET_CREDS(context, in_creds->client, in_creds->server, options)
The header file k5-trace.h (included by k5-int.h) will define the tracing macros in terms of the function krb5int_trace, which has the signature:
static void krb5int_trace(krb5_context *context, const char *fmt, ...);
Each macro will supply a format string to krb5int_trace and pass in its arguments. krb5int_trace will implement a custom formatter, adapted from the debugging code previously in lib/krb5/os/sendto_kdc.c, to allow stringification of data types such as krb5_principal and krb5_data. Macro expansions will not evaluate arguments if tracing is disabled either at compile time or runtime, so arguments to these macros must not have side-effects.
Vendors can use k5-trace.h as an integration point for tracing systems such as DTrace, but we will not supply any such integrations at this time.
Implementation Design
The krb5_context structure will gain the following new fields:
krb5_trace_callback trace_callback; void *trace_callback_data;
In the simple case where trace output is being directed to a file (either via the KRB5_TRACE environment variable or the krb5_set_trace_filename API), trace_callback will be set to a built-in callback function and trace_callback_data will point to the file descriptor.
Status
The trace logging infrastructure has been implemented for 1.9. Trace events have been added for:
- AS-REQ client code, including FAST and preauth
- TGS-REQ client code
- AP-REQ and AP-REP code (client and server)
- sendto_kdc
- Selected ccache operations
- Selected keytab operations
More trace events should be added for the 1.9 release, including:
- rcache
- PKINIT
- KDC do_as_req
- KDC do_tgs_req
- KDC preauth
- Authdata
- S4U
- GSSAPI krb5 mech
- GSSAPI SPNEGO mech
Also, experience adding trace log events suggests that perhaps there should be two levels of tracing detail. Current trace events are designed not to drown the user in output, but this means omitting sometimes useful information, such as PKINIT Diffie-Hellman results.
