2.15. Troubleshooting: Check Server Log Files

If you can read the directory server access log, then you can check what the server did with your application's request. For example, the following OpenDJ access log excerpt shows a successful connection from cn=My Killer App,ou=Apps,dc=example,dc=com performing a simple bind after Start TLS, and then a simple search before unbind. The lines are wrapped for readability, whereas in the log each record starts with the time stamp.

[20/Apr/2012:13:31:05 +0200] CONNECT conn=5
 from=127.0.0.1:51561 to=127.0.0.1:1389 protocol=LDAP
[20/Apr/2012:13:31:05 +0200] EXTENDED REQ conn=5 op=0 msgID=1 name="StartTLS"
 oid="1.3.6.1.4.1.1466.20037"
[20/Apr/2012:13:31:05 +0200] EXTENDED RES conn=5 op=0 msgID=1 name="StartTLS"
 oid="1.3.6.1.4.1.1466.20037" result=0 etime=0
[20/Apr/2012:13:31:07 +0200] BIND REQ conn=5 op=1 msgID=2 version=3 type=SIMPLE
 dn="cn=My Killer App,ou=Apps,dc=example,dc=com"
[20/Apr/2012:13:31:07 +0200] BIND RES conn=5 op=1 msgID=2 result=0
 authDN="cn=My Killer App,ou=Apps,dc=example,dc=com" etime=1
[20/Apr/2012:13:31:07 +0200] SEARCH REQ conn=5 op=2 msgID=3
 base="dc=example,dc=com" scope=wholeSubtree
 filter="(uid=kvaughan)" attrs="isMemberOf"
[20/Apr/2012:13:31:07 +0200] SEARCH RES conn=5 op=2 msgID=3
 result=0 nentries=1 etime=6
[20/Apr/2012:13:31:07 +0200] UNBIND REQ conn=5 op=3 msgID=4
[20/Apr/2012:13:31:07 +0200] DISCONNECT conn=5 reason="Client Unbind"

Notice that each operation type is shown in upper case, and that the server tracks both the connection (conn=5), operation (op=[0-3]), and message ID (msgID=[1-4]) numbers to make it easy to filter records. The etime refers to how long the server worked on the request in milliseconds. Result code 0 corresponds to ResultCode.SUCCESS, as described in RFC 4511.