logo_kerberos.gif

Difference between revisions of "Projects/Trace logging"

From K5Wiki
Jump to: navigation, search
(Selecting Trace Information)
 
(18 intermediate revisions by 2 users not shown)
Line 1: Line 1:
{{project-early}}
+
{{project-rel|1.9}}
   
 
==Background==
 
==Background==
Line 5: Line 5:
 
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:
 
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 is sufficient to be able to be able to log to a file specified by an environment variable.
 
  +
* 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.
 
* 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 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.
 
* 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.
 
* 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.)
   
==Selecting Trace Information==
 
  +
==User Interface==
   
To begin with, tracing will be a binary switch--all tracing information or none of it. If the volume of trace logging information for common operations becomes overwhelming, this can be refined by adding tracing levels or tracing categories.
 
  +
Tracing can be enabled by setting the KRB5_TRACE environment variable to a filename. This will not work for secure contexts.
   
==Implementation concerns==
 
  +
Tracing can be controlled by the application using either of the following APIs:
   
The biggest decision here is whether trace calls require a context. If so:
 
  +
/* 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);
   
* Thread safety is easier (a log file handle can be cached in the context).
 
  +
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.
* The mechanism can be disabled for setuid programs via krb5_init_secure_context.
 
* A macro can elide the function calls when trace logging is not enabled, saving a few cycles.
 
* APIs could be provided to turn tracing on and off, or direct different contexts to different files. (However, API control of tracing is not a requirement.)
 
   
If not:
 
  +
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.
   
* Code which does not have a context available can be traced.
 
  +
==Tracing API==
* Cached information must be global, and therefore locked, probably with some kind of cheat to minimize the performance impact when disabled.
 
  +
* Trace calls become less verbose.
 
  +
Each trace point will have a separate macro; an example invocation for credential acquisition might be:
* The implementation can live in libkrb5support instead of libkrb5.
 
  +
* The facility might be more friendly to plugin code living in our tree.
 
  +
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.

Latest revision as of 13:23, 12 October 2010

This project was completed in release 1.9.


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.