About auditing LDAP operations…

OpenDJ LogoMany years ago, when I’ve started working on LDAP directory services, we needed to have some auditing of the operations occurring on the server. So, the server had a “Access” log which contained a message when an operation was received, and one when it was returned to the client, which included the processing time on the server side (the etime parameter). On Netscape and Sun directory servers, the etime was measured in seconds. This format allowed us to detect requests that were taking a long time, or were started but not finished.

In OpenDJ, we switched the etime resolution to milliseconds, but there’s an option to set it to nano-seconds. Yet, with millisecond resolution, there are still a number of log entries with an etime value of 0. The truth is that the server is faster, but so are the machines and processors.

At a rate of 50 000 operations per seconds (which can easily be sustained on my laptop), having two messages per operation does generate a lot of data to write to disk. That’s why we have introduced a new audit log format, not well advertised I must say, in OpenDJ 2.6.0. To enable the new format, use the following dsconfig command:

dsconfig set-log-publisher-prop -h localhost -p 4444 -X -n \
 -D "cn=directory manager" -w password \
 --publisher-name File-Based\ Access\ Logger  --set log-format:combined

And now instead of having 2 lines per operations, there is a single one.

Before:

[23/Feb/2015:08:56:31 +0100] SEARCH REQ conn=0 op=4 msgID=5 base="cn=File-Based Access Logger,cn=Loggers,cn=config" scope=baseObject filter="(objectClass=*)" attrs="1.1"
[23/Feb/2015:08:56:31 +0100] SEARCH RES conn=0 op=4 msgID=5 result=0 nentries=1 etime=0
[23/Feb/2015:08:56:31 +0100] SEARCH REQ conn=0 op=5 msgID=6 base="cn=File-Based Access Logger,cn=Loggers,cn=config" scope=baseObject filter="(objectClass=*)" attrs="objectclass"
[23/Feb/2015:08:56:31 +0100] SEARCH RES conn=0 op=5 msgID=6 result=0 nentries=1 etime=0

After, in combined mode:

[23/Feb/2015:13:00:28 +0100] SEARCH conn=48 op=8215 msgID=8216 base="dc=example,dc=com" scope=wholeSubtree filter="(uid=user.1)" attrs="ALL" result=0 nentries=1 etime=0
[23/Feb/2015:13:00:28 +0100] SEARCH conn=60 op=10096 msgID=10097 base="dc=example,dc=com" scope=wholeSubtree filter="(uid=user.6)" attrs="ALL" result=0 nentries=1 etime=0

The benefits of enabling the combined log format are multiple. Less data is written to disk for each operation, less I/O operations are involved, resulting in overall better throughput for the server. And it allows to keep more history of operations with the same volume of log files.

Do you think that OpenDJ 3.0 access log files should use the combined format by default ?

5 thoughts on “About auditing LDAP operations…

  1. Chee Chong 24 February 2015 / 11:45

    Yes, I prefer combined format by default.

  2. Pete O 26 February 2015 / 21:18

    I agree with Chee…I’ve only done in PreProd so far, but already I am finding them easy to use, and I think will make it easier for Ops people to understand. This post has also made me go back to figure out how I missed it in the documentation, which is probably a good thing in itself.

    Nice post. Thanks.

  3. Nicolas Seigneur 26 February 2015 / 23:50

    I like the new format better, brings many advantages, yay for 3.0 default.

  4. Ajeeth 01 April 2015 / 12:26

    +1 for combined format as default in 3.0

  5. Brad Tumy 04 April 2015 / 00:59

    I agree. I like the new combined format. Would like to see that as the default.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s