Ludo Sketches

Many 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 ?