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
