25.8. Troubleshooting Client Operations

By default OpenDJ logs information about all LDAP client operations in logs/access, and all HTTP client operations in logs/http-access. The following lines are wrapped for readability, showing a search for the entry with uid=bjensen as traced in the LDAP access log. In the access log itself, each line starts with a time stamp.

[27/Jun/2011:17:23:00 +0200] CONNECT conn=19 from=127.0.0.1:56641
 to=127.0.0.1:1389 protocol=LDAP
[27/Jun/2011:17:23:00 +0200] SEARCH REQ conn=19 op=0 msgID=1
 base="dc=example,dc=com" scope=wholeSubtree filter="(uid=bjensen)" attrs="ALL"
[27/Jun/2011:17:23:00 +0200] SEARCH RES conn=19 op=0 msgID=1
 result=0 nentries=1 etime=3
[27/Jun/2011:17:23:00 +0200] UNBIND REQ conn=19 op=1 msgID=2
[27/Jun/2011:17:23:00 +0200] DISCONNECT conn=19 reason="Client Unbind"

As you see, each client connection and set of LDAP operations are traced, starting with a time stamp and information about the operation performed, then including information about the connection, the operation number for the sequence of operations performed by the client, a message identification number, and additional information about the operation.

To match HTTP client operations with related internal server operations, first prevent OpenDJ from suppressing internal operations from the LDAP access log by using the dsconfig command to set the LDAP access log publisher suppress-internal-operations advanced property to false. Then match the values of the x-connection-id field in the HTTP access log with conn=id values in the LDAP access log.

For example, consider an HTTP GET request for the _id field of the user newuser, which is handled by connection 4 as shown in logs/http-access.

-  192.168.0.12  bjensen  22/May/2013:16:27:52 +0200
  GET  /users/newuser?_fields=_id  HTTP/1.1  200
  curl/7.21.4  4  12

With internal operations logged in logs/access, log lines for the related operations have conn=4.

[22/May/2013:16:27:52 +0200] CONNECT conn=4
  from=192.168.0.12:63593 to=192.168.0.12:8080 protocol=HTTP/1.1
[22/May/2013:16:27:52 +0200] SEARCH REQ conn=4
  op=0 msgID=0 base="ou=people,dc=example,dc=com" scope=wholeSubtree
   filter="(&(objectClass=inetOrgPerson)(uid=bjensen))" attrs="1.1"
[22/May/2013:16:27:52 +0200] SEARCH RES conn=4
  op=0 msgID=0 result=0 nentries=1 etime=5
[22/May/2013:16:27:52 +0200] BIND REQ conn=4
  op=1 msgID=1 version=3 type=SIMPLE
   dn="uid=bjensen,ou=People,dc=example,dc=com"
[22/May/2013:16:27:52 +0200] BIND RES conn=4
  op=1 msgID=1 result=0 authDN="uid=bjensen,ou=People,dc=example,dc=com"
   etime=3
[22/May/2013:16:27:52 +0200] SEARCH REQ conn=4
  op=2 msgID=2 base="uid=newuser,ou=people,dc=example,dc=com" scope=baseObject
   filter="(objectClass=*)" attrs="uid,etag"
[22/May/2013:16:27:52 +0200] SEARCH RES conn=4
   op=2 msgID=2 result=0 nentries=1 etime=4
[22/May/2013:16:27:52 +0200] UNBIND REQ conn=4
   op=3 msgID=3
[22/May/2013:16:27:52 +0200] DISCONNECT conn=4
   reason="Client Unbind"

To help diagnose errors due to access permissions, OpenDJ supports the get effective rights control. The control OID, 1.3.6.1.4.1.42.2.27.9.5.2, is not allowed by the default global ACIs. You must therefore add access to use the get effective rights control when not using it as Directory Manager.