Re: Revamping statslog (loglevel 256) output

[Hallvard B Furuseth <h.b.furuseth@usit.uio.no>]

Pierangelo Masarati writes:
>Hallvard B Furuseth wrote:
>> I'd like to make Statslog output from slapd more readable:
>>
>> - Replace numeric codes with their names, e.g. result codes,
>>   search scopes, tag numbers.
>
> I'd rather use both; something like
>
>     "err=X (msgX)"
>
> so that it gets both machine and human readable.

I'd kind of hoped to avoid making the log lines noticeably longer...
Would "err=timeLimitExceeded" be enough?

> Since this requires two formats expansion, it could exploit a
> pre-cooked slap API that returns a string in the above form, which
> could be initialized at startup to allow consistent numerical code
> extension, even run-time (e.g. error codes and messages added by
> modules that implement standard or even private extensions).

Nice idea, though I'm not sure which codes slapd itself can get away
with not knowing about.  Something like this?

typedef enum {
   Slapcode_result, Slapcode_searchscope, Slapcode_deref, ...
} Slapcode_t;

slap_create_code(Slapcode_t namespace, ber_int_t code, const char *name);
slap_destroy_code(Slapcode_t namespace, ber_int_t code);

> Don't forget that most of those numerical codes result from some
> standard track, so they are supposed to be quite portable and
> recognizable across implementations.

Yes, I intended to use the ASN.1 names when convenient.  Though
"deref=derefInSearching", if that's treated like err= above, looks
rather cumbersome.  Could use the ldapsearch parameter names instead for
that and scope, I suppose.

>> - Start each log line - after the "conn= op=" part - with a character or
>>   two which indicates what kind of I/O, if any, it represents.  E.g.:
>>   :  Not an LDAPMessage (connect, disconnect, TLS, etc).
>>   >  Request.
>>   +> More info about a previously logged ">" request.
>>   <+ Intermediate response, search result entry/referral.
>>   <  Final response to a request (or maybe unsolicited notification).
>>   -  Not I/O, just change of state or something.
>
> Well, I don't much see the point of eliminating numbers because they're
> not readable enough, and then use yet another set of even more obscure
> symbols...

Heh.  I thought documenting it in slapd.conf:loglevel would answer that,
by maybe not...  Could add them and keep "RESULT", so the log can be
read without understanding these character codes.

_Something_ is needed though, so a statslog parser can tell the
difference between requests, intermediate responses, final responses and
other log lines.  Currently a parser which wants to do something with
individual requests has to recognize most log messages slapd can
produce, so it e.g. can tell when a request is finished.

>> Some notes, now that I'm looking at the above:
>>
>> - The Bind logging is weird:
>>
>>   For op=6, it looks like slapd reverts to anonymous before receiving
>>   the Bind request.  Those log lines ought to be swapped.  Also, I
>>   suppose the implicit "BIND anonymous" should be "AUTHZ anonymous".
>
> That's exactly what it's doing: the connection is set to anonymous right
> before it starts processing the bind.

Yes, but after it _receives_ the Bind.  And that "BIND anonymous" is not
the bind request, nor a response it sends, just an internal change of
state.

>>   For op=1, four log messages for one authentication seems a bit much.
>>   The "cn=admin" comes from sasl-regexp.
>
> Agree.  But I think it comes from the fact that those logs occur in
> different stages of the operation, from different modules, and that was
> easier than bringing all the knowledge of how each module was behaving
> along with the op to have a single log at the end that depends on the
> contribution of each module.

Maybe such modules should just set a "info yet to be logged" flag
which could be logged all in one request.

>> - The "TLS established" log lines without "op=" in front need some
>>   indentation, or to get hold of the StartTLS operation number even
>>   though "TLS established" itself is not an LDAP operation.
>
> Better have the "conn, op" prefix, to avoid concurrency
> misunderstanding.  The o_log_prefix was essentially introduced to save
> one field in the Debug macros and allow more expressive one-line logs.

starttls_extop() does not negotiate TLS, it just sets a flag which tells
connection_read() to negotiate TLS.  There is also no op to get at after
ACCEPT to an ldaps:/// listener.  So as far as slapd is concerned, TLS
negotiation is not related to any particular op.

We could change starttls_extop() to save the "conn, op" prefix so TLS
establishment could use it, though then "TLS established" log lines from
StartTLS and ldaps:/// would differ.  So I think it would be better to
just insert some whitespace so they'd be properly aligned with the
StartTLS/response log lines.

> Of course if we could dispose of those fixed arg number Debug macros
> with all those format warnings at compile...

gcc-4 -Wformat=2 -Wno-format-extra-args  works fine, though it does lose
genuine warnings about too many args.

We could define Statslog1, Statslog2, etc for different number of args.
With some preprocessor magic, it should be enough to have one macro
with the big body of Statslog, and have Statslog[12345] be one-liners.

> In any case, I agree in having logs more readable and expressive,
> although I'd rather try to improve the existing in a step by step
> fashion.

I disagree with that "in theory".  Then one has to change parsers each
time the logs are changed.  Of course, in practice it might be easier to
deal with small changes.

> Adding some descriptive form to numeric codes could be a
> reasonable step.

-- 
Hallvard