Writing a script for parsing openldap logs I found that, for some of my connections, the BIND log entry precedes the corresponding ACCEPT entry (which as far as i understand must logically precede the BIND)
example: 2016-01-25T12:54:02.131094+01:00 HOSTNAME slapd[15258]: conn=91596 op=0 BIND dn="" method=128 2016-01-25T12:54:02.131099+01:00 HOSTNAME slapd[15258]: conn=91596 op=0 RESULT tag=97 err=0 text= 2016-01-25T12:54:02.131103+01:00 HOSTNAME slapd[15258]: conn=91596 fd=93 ACCEPT from [CUT]
slapd is started with the '-l local4' parameter, and rsyslogd is configured to send local4.* to the openldap.log file
suspecting some rsyslogd problems i tried running slapd using the "-d 256" parameter, but in the output i found
56a6202b conn=1004 op=0 BIND dn="" method=128 56a6202b conn=1004 op=0 RESULT tag=97 err=0 text= 56a6202b conn=1004 fd=13 ACCEPT from [CUT]
Is there any way to guarantee openldap to generate ordered logs?
thanks, dario
On 25. jan. 2016 14:36, Dario Zanzico wrote:
Writing a script for parsing openldap logs I found that, for some of my connections, the BIND log entry precedes the corresponding ACCEPT entry (which as far as i understand must logically precede the BIND) (...) Is there any way to guarantee openldap to generate ordered logs?
Maybe it would work to move Statslog( ... ACCEPT ...) above ldap_pvt_thread_mutex_unlock( &c->c_mutex ); at the end of servers/slapd/connection.c:connection_init(). Holding on to the mutex longer would make slapd a bit less responsive, though. No idea how much.
Another variant: Put the cost in the log parser instead. When you see an ACCEPT, delay processing log lines until you've seen some more lines, in case they are out of order. I've got an old tweak to contrib/slapd-tools/statslog which does that and some other stuff, here: http://folk.uio.no/hbf/OpenLDAP/statslog.reorder
Don't remember why I haven't committed it. Maybe it isn't quite finished or I hoped to optimize it, since it does slow the script down. I'd be glad to hear of any improvements from you:-)
Come to think of it, statslog is quite old. It might need some tweaks to catch up with whatever has been done to OpenLDAP logs since it was written.
On Tue, Jan 26, 2016, at 05:24 PM, Hallvard Breien Furuseth wrote:
Maybe it would work to move Statslog( ... ACCEPT ...) above ldap_pvt_thread_mutex_unlock( &c->c_mutex ); at the end of servers/slapd/connection.c:connection_init(). Holding on to the mutex longer would make slapd a bit less responsive, though. No idea how much.
That's kinda what I initially expected openldap to do :D
Another variant: Put the cost in the log parser instead.
yep, that's the way I worked around this problem
When you see an ACCEPT, delay processing log lines until you've seen some more lines, in case they are out of order. I've got an old tweak to contrib/slapd-tools/statslog which does that and some other stuff, here: http://folk.uio.no/hbf/OpenLDAP/statslog.reorder
I was sending my logs through syslog=>logstash=>elasticsearch correlating binds and accepts in logstash (whose filters prevented me to easily implement delays) So, considering the rarity of the mixed log entries, I decided to: 1) save both accept and bind entries in elasticsearch 2) keep correlating events in passing through logstash, if possible 3) schedule a script which "correlates uncorrelated" binds and deletes old connections data from elasticsearch
Don't remember why I haven't committed it. Maybe it isn't quite finished or I hoped to optimize it, since it does slow the script down. I'd be glad to hear of any improvements from you:-)
Perl scares me :)
Come to think of it, statslog is quite old. It might need some tweaks to catch up with whatever has been done to OpenLDAP logs since it was written.
I suppose it would be nice to have an option to force Openldap to write ordered logs (obviously with a performance penalty). Or maybe enabling logging the real operation timestamp (as in: generated just before the operation itself), enabling a simple filter to reorder logs.
Thanks
Hallvard
dario
openldap-technical@openldap.org
-
Dario Zanzico -
Hallvard Breien Furuseth