Revamping statslog (loglevel 256) output

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

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.

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

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

  For op=1, four log messages for one authentication seems a bit much.
  The "cn=admin" comes from sasl-regexp.

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

-- 
Hallvard