[Date Prev][Date Next] [Chronological] [Thread] [Top]

Re: Revamping statslog (loglevel 256) output

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. 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). 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.

- 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...

Thus, this session:

fd=9 ACCEPT from PATH=/ldap/usr/var/run/ldapi (PATH=/ldap/usr/var/run/ldapi)
op=0 SRCH base="" scope=0 deref=0 filter="(?=true)"
op=0 ENTRY dn=""
op=0 SEARCH RESULT tag=101 err=0 nentries=1 text=
op=1 BIND dn="" method=163
op=1 BIND authcid="gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth"
         authzid="gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth"
op=1 RESULT tag=97 err=0 text=
op=1 BIND dn="cn=admin" mech=EXTERNAL ssf=0
op=2 DEL dn="cn=foo,cn=bar"
op=2 RESULT tag=107 err=53 text=no global superior knowledge
op=3 STARTTLS
op=3 AUTHZ anonymous mech=starttls ssf=0
op=3 RESULT oid= err=0 text=
TLS established tls_ssf=256 ssf=256
op=4 BIND dn="uid=hbf,cn=people,dc=uio,dc=no" method=128
op=4 BIND dn="uid=hbf,cn=people,dc=uio,dc=no" mech=SIMPLE ssf=0
op=4 RESULT tag=97 err=0 text=
op=5 SRCH base="dc=uio,dc=no" scope=2 deref=3 filter="(sn=*x*)"
op=5 SEARCH RESULT tag=101 err=11 nentries=0 text=
op=6 BIND anonymous mech=implicit ssf=0
op=6 BIND dn="uid=nobody,cn=people,dc=uio,dc=no" method=128
op=6 RESULT tag=97 err=49 text=
op=7 UNBIND
fd=9 closed

might become:

fd=9 : ACCEPT from PATH=/ldap/usr/var/run/ldapi (PATH=/ldap/usr/var/run/ldapi)
op=0 > SRCH base="" base neverDerefAliases filter="(?=true)"
op=0 <+ENTRY dn=""
op=0 < SRCH success nentries=1 text=
op=1 > BIND dn="" sasl
op=1 +>BIND authcid="gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth"
           authzid="gidNumber=0+uidNumber=0,cn=peercred,cn=external,cn=auth"
op=1 < BIND success text=
op=1 : BIND dn="cn=admin" mech=EXTERNAL ssf=0
op=2 > DEL dn="cn=foo,cn=bar"
op=2 < DEL unwillingToPerform text=no global superior knowledge
op=3 > STARTTLS
op=3 - AUTHZ anonymous mech=starttls ssf=0
op=3 < EXT oid= success text=
    : TLS established tls_ssf=256 ssf=256
op=4 > BIND dn="uid=hbf,cn=people,dc=uio,dc=no" simple
op=4 +>BIND dn="uid=hbf,cn=people,dc=uio,dc=no" mech=SIMPLE ssf=0
op=4 < BIND success text=
op=5 > SRCH base="dc=uio,dc=no" subtree derefAlways filter="(sn=*x*)"
op=5 < SRCH adminLimitExceeded nentries=0 text=
op=6 - BIND anonymous mech=implicit ssf=0
op=6 > BIND dn="uid=nobody,cn=people,dc=uio,dc=no" simple
op=6 < BIND invalidCredentials text=
op=7 > UNBIND
fd=9 : closed

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.

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.

- 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. Of course if we could dispose of those fixed arg number Debug macros with all those format warnings at compile...

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. Adding some descriptive form to numeric codes could be a reasonable step.

p.


   SysNet - via Dossi,8 27100 Pavia Tel: +390382573859 Fax: +390382476497