HTTP correlation ID example

In this example, a request to the directory REST API is made and the correlation ID enables finding HTTP-specific log messages that also have LDAP-specific log messages. The response to the API call includes a Correlation-Id header with the value ee919049-6710-4594-9c66-28b4ada4b127.

GET /directory/v1/me?includeAttributes=mail HTTP/1.1
 Accept: /
 Accept-Encoding: gzip, deflate
 Authorization: Bearer ...
 Connection: keep-alive
 Host: localhost:1443
 User-Agent: HTTPie/0.9.9

 HTTP/1.1 200 OK
 Content-Length: 266
 Content-Type: application/hal+json
 Correlation-Id: ee919049-6710-4594-9c66-28b4ada4b127
 Date: Fri, 02 Nov 2018 15:16:50 GMT
 Request-Id: 369

 {
      "_dn": "uid=user.86,ou=People,dc=example,dc=com",
      "_links": {
         "schemas": [
            {
              "href": "https://localhost:1443/directory/v1/schemas/inetOrgPerson"
            }
         ],
         "self": {
              "href": "https://localhost:1443/directory/v1/uid=user.86,ou=People,dc=example,dc=com"
         }
     },
     "mail": [
         "user.86@example.com"
     ]
 }

The correlation ID can be used to search the HTTP trace log for matching log records, as in the following example.

$  grep 'correlationID="ee919049-6710-4594-9c66-28b4ada4b127"' PingDirectory/logs/debug-trace
 [02/Nov/2018:10:16:50.294 -0500] HTTP REQUEST requestID=369 correlationID="ee919049-6710-4594-9c66-28b4ada4b127" product="{pingdir}  Directory Server" instanceName="ds1" startupID="W9ikqA==" threadID=52358 from=[0:0:0:0:0:0:0:1]:58918 method=GET url="https://0:0:0:0:0:0:0:1:1443/directory/v1/me?includeAttributes=mail"
 [02/Nov/2018:10:16:50.526 -0500] DEBUG ACCESS-TOKEN-VALIDATOR-PROCESSING requestID=369 correlationID="ee919049-6710-4594-9c66-28b4ada4b127" msg="Identity Mapper with DN 'cn=User ID Identity Mapper,cn=Identity Mappers,cn=config' mapped ID 'user.86' to entry DN 'uid=user.86,ou=people,dc=example,dc=com'"
 [02/Nov/2018:10:16:50.526 -0500] DEBUG ACCESS-TOKEN-VALIDATOR-PROCESSING requestID=369 correlationID="ee919049-6710-4594-9c66-28b4ada4b127" accessTokenId="201811020831" msg="Token Validator 'Mock Access Token Validator' validated access token with active = 'true', sub = 'user.86', owner = 'uid=user.86,ou=people,dc=example,dc=com', clientId = 'client1', scopes = 'ds', expiration = 'none', not-used-before = 'none', current time = 'Nov 2, 2018 10:16:50 AM CDT' "
 [02/Nov/2018:10:16:50.531 -0500] HTTP RESPONSE requestID=369 correlationID="ee919049-6710-4594-9c66-28b4ada4b127" accessTokenId="201811020831" product="{pingdir}  Directory Server" instanceName="ds1" startupID="W9ikqA==" threadID=52358 statusCode=200 etime=236.932 responseContentLength=266
      [02/Nov/2018:10:16:50.531 -0500] DEBUG HTTP-FULL-REQUEST-AND-RESPONSE requestID=369 correlationID="ee919049-6710-4594-9c66-28b4ada4b127" accessTokenId="201811020831" product="{pingdir}  Directory Server" instanceName="ds1" startupID="W9ikqA==" threadID=52358 from=[0:0:0:0:0:0:0:1]:58918 method=GET url="https://0:0:0:0:0:0:0:1:1443/directory/v1/me?includeAttributes=mail" statusCode=200 etime=236.932 responseContentLength=266 msg="

The LDAP log messages associated with this request can also be located, as in the following example.

$  grep 'correlationID="ee919049-6710-4594-9c66-28b4ada4b127"' PingDirectory/logs/access
 [02/Nov/2018:10:16:50.529 -0500] SEARCH RESULT instanceName="ds1" threadID=52358 conn=-371045 op=1657393 msgID=1657394 origin="Directory REST API" httpRequestID="369" correlationID="ee919049-6710-4594-9c66-28b4ada4b127" authDN="uid=user.86,ou=people,dc=example,dc=com" requesterIP="internal" requesterDN="uid=user.86,ou=People,dc=example,dc=com" requestControls="1.3.6.1.4.1.30221.2.5.2" via="app='PingDirectory-ds1' clientIP='0:0:0:0:0:0:0:1' sessionID='201811020831' requestID='ee919049-6710-4594-9c66-28b4ada4b127'" base="uid=user.86,ou=people,dc=example,dc=com" scope=0 filter="(&)" attrs="mail,objectClass" resultCode=0 resultCodeName="Success" etime=0.684 entriesReturned=1
 [02/Nov/2018:10:16:50.530 -0500] EXTENDED RESULT instanceName="ds1" threadID=52358 conn=-371046 op=1657394 msgID=1657395 origin="Directory REST API" httpRequestID="369" correlationID="ee919049-6710-4594-9c66-28b4ada4b127" authDN="cn=Internal Client,cn=Internal,cn=Root DNs,cn=config" requesterIP="internal" requesterDN="cn=Internal Client,cn=Internal,cn=Root DNs,cn=config" requestControls="1.3.6.1.4.1.30221.2.5.2" via="app='PingDirectory-ds1' clientIP='0:0:0:0:0:0:0:1' sessionID='201811020831' requestID='ee919049-6710-4594-9c66-28b4ada4b127'" requestOID="1.3.6.1.4.1.30221.1.6.1" requestType="Password Policy State" resultCode=0 resultCodeName="Success" etime=0.542 usedPrivileges="bypass-acl,password-reset" responseOID="1.3.6.1.4.1.30221.1.6.1" responseType="Password Policy State" dn="uid=user.86,ou=People,dc=example,dc=com"
 [02/Nov/2018:10:16:50.530 -0500] SEARCH RESULT instanceName="ds1" threadID=52358 conn=-371048 op=1657397 msgID=1657398 origin="Directory REST API" httpRequestID="369" correlationID="ee919049-6710-4594-9c66-28b4ada4b127" authDN="cn=Internal Client,cn=Internal,cn=Root DNs,cn=config" requesterIP="internal" requesterDN="cn=Internal Client,cn=Internal,cn=Root DNs,cn=config" requestControls="1.3.6.1.4.1.30221.2.5.2" via="app='PingDirectory-ds1' clientIP='0:0:0:0:0:0:0:1' sessionID='201811020831' requestID='ee919049-6710-4594-9c66-28b4ada4b127'" base="cn=Default Password Policy,cn=Password Policies,cn=config" scope=0 filter="(&)" attrs="ds-cfg-password-attribute" resultCode=0 resultCodeName="Success" etime=0.065 preAuthZUsedPrivileges="bypass-acl,config-read" entriesReturned=1