Trace logging project

[Nicolas Williams]

On Sat, Sep 12, 2009 at 12:14:06AM -0400, Greg Hudson wrote:
> On Fri, 2009-09-04 at 17:17 -0400, ghudson at MIT.EDU wrote:
> > Based on recent feedback from krb5 users, I've written up an early
> > project page on trace logging:
> 
> It sounds like no one has strong opinions about this, which is fine;
> it's not going to be very intricate.

Well, I'd just missed this that's all :)

I would like this to see this requirement:

 - zero cost when tracing is disabled at build time
 - only interesting events should be traceable, for a definition of
   interesting (function entry/exit tracing is not interesting to me)

Also, I think you should consider a DTrace USDT provider.  If at all
possible you should have a single set of macros that can expand into
USDT provider points or calls to an MIT krb5-specific trace framework.

(DTrace runs on MacOS X, FreeBSD, and, of course, Solaris.)

> I'm going to start with a simple binary switch: you turn on tracing (by
> specifying a filename in KRB5_TRACE) and you get everything.  If there
> turns out to be a need for pre-filtering, that can be added later,
> although it will of course mean marking up all of the existing trace
> calls.

One of the nice things about DTrace is that you don't have to add
filtering features to the victim code.

> Trace calls will require a context.  I don't think there's any important
> code to trace with no access to a context, and it makes it simple to
> avoid tracing for secure contexts.

Context initialization is interesting, and should be traceable without a
context, for obvious reasons.

> When I went to add my first tracing call, I realized that we'll need a
> custom formatter to deal with principal names and krb5_data structures
> and the like.  Fortunately, there already is one in
> lib/krb5/os/sendto_kdc.c, which was easy to adapt.

That could be useful for a DTrace USDT provider, actually (with
if-enabled probes).

> I've adjusted the project page and kicked into review status, with an
> end date of September 18th (one week).  I have the plumbing written now,
> and can commence the work of littering the code base with tracing calls.

Ugh.  I think we should trace *interesting* events, not all function
entry/exit (since plenty of tools can do _that_).  I'd hate to see the
code littered with trace macros/function calls in all function entries,
before gotos, before returns.

You should aim to have relatively few traces, compared to the number of
actual functions (and function entries/exits).

Nico
--