Rate this page

Troubleshooting

Invariably, your application will not work as expected, and you’ll need to roll up your sleeves to determine the cause of the problem and its solution. The Ping Identity Data Governance Broker provides a rich set of loggers and tools to help you quickly analyze and resolve issues.

Before discussing these particulars, it’s important to note that good troubleshooting relies on knowledge and technique as much as it relies upon tools. A good troubleshooting procedure can be generalized into the following steps:

  1. Reproduce the issue.
  2. Attempt to identify the cause by forming a hypothesis, ruling out factors that you expect to be irrelevant.
  3. Test the hypothesis.
  4. Refine the hypothesis and test again.

For your troubleshooting to be effective, it’s crucial that you understand both your application and the server. Your thinking should be informed by knowledge of the Data Governance Broker’s architecture from this guide, as well as the Ping Identity Data Governance Broker Administration Guide.

Using the server logs

The Data Governance Broker provides a number of useful logs that you can consult when troubleshooting a problem, chief among them the trace log (located at logs/trace)and the error log (located at logs/errors). You may define new logs for your own purposes or customize the existing logs under Log Publishers in dsconfig or the Administrative Console.

The trace log is especially valuable for client developers, as it traces activity within the server as it receives a request and generates a response. This activity includes operations related to OAuth 2 processing, authentication API processing, and SCIM requests and responses.

The following abridged example shows processing for an OpenID Connect request in which both an access token and an ID token are granted:

[17/Sep/2016:18:26:35.998 -0500] OAUTH AUTHZ-REQUEST requestID=55631 clientId="my-client" responseType="token id_token" scopes="email openid" redirectUri="https://example.com/callback/" state="Q0hBUkFDVEVSIElTIEZBVEU=" nonce="ce97895493524c8abdef8ae6cfd51703" prompt="" acrValues="Default"

[17/Sep/2016:18:26:36.014 -0500] XACMLPOLICY RESULT requestID=55631 subjectId="My Client" actionId="accept-authentication" resourceId="Default" decision="PERMIT" policies="urn:pingidentity:policy:Login,urn:pingidentity:policy:AuthenticationPolicySet,urn:pingidentity:policy:SecondFactorAuthentication,urn:pingidentity:policy:AccountVerification"

[17/Sep/2016:18:26:36.062 -0500] XACMLPOLICY RESULT requestID=55631 subjectId="My Client" actionId="grant" resourceId="openid" decision="PERMIT" policies="urn:pingidentity:policy:OAuth2PolicySet,urn:pingidentity:policy:OAuth2ScopePolicy"

[17/Sep/2016:18:26:36.063 -0500] XACMLPOLICY RESULT requestID=55631 subjectId="My Client" actionId="grant" resourceId="email" decision="PERMIT" policies="urn:pingidentity:policy:OAuth2PolicySet,urn:pingidentity:policy:OAuth2ScopePolicy"

[17/Sep/2016:18:26:36.087 -0500] OAUTH TOKEN-GRANTED requestID=55631 accessTokenId="a.Pda9dg" client="My Client" resourceTypeEndpoint="Users" resourceID="1a73fbda-4097-4703-9dcc-4c0adf76f029" grantType="implicit" scopes="openid email" expiresIn="432000"

[17/Sep/2016:18:26:36.108 -0500] OAUTH ID-TOKEN-GRANTED requestID=55631 client="My Client" resourceTypeEndpoint="Users" resourceID="1a73fbda-4097-4703-9dcc-4c0adf76f029" expiresIn="900" authenticationTime="17/Sep/2016:18:25:03.000 -0500"

From this log excerpt, we can see quite a bit.

  • In the first line, we see from the response_type that the client used the implicit grant type. Other information in this line includes the client ID, the requested scopes, and the requested ACR (which may have been inferred by the server as a default value).
  • In the next three lines, we see the results of the Broker’s policy processing. First, it determines that the “Default” authentication context class has been satisfied, then it grants two scopes.
  • Next, we see that an access token is granted. We can see the unique ID of the user on behalf of whom the access token was granted, the client name, the granted scopes (which match the requested scopes), and so on. Of particular interest is the accessTokenId field. This is a non-sensitive unique alias for the access token. When the client goes on to make resource server requests, this token ID will be logged, allowing us to correlate the resource server requests with this set of events.
  • Finally, the log records the granting of an OpenID Connect ID token.

Custom logs

You can use the server’s configuration tools to customize the default loggers or to create your own. This is essential if you wish to exclude detail that is likely to be irrelevant to your troubleshooting.

The following example creates a trace logger tailored to the needs of a client developer. You’ll note that it excludes requests for static file assets, such as CSS stylesheets and images.

dsconfig create-log-publisher --publisher-name "Example Trace Logger" \
  --type file-based-trace \
  --set "description:Example trace logger for development" \
  --set enabled:true \
  --set oauth-message-type:authz-request \
  --set oauth-message-type:code-consumed \
  --set oauth-message-type:code-granted \
  --set oauth-message-type:consent-deleted \
  --set oauth-message-type:consent-denied \
  --set oauth-message-type:consent-permitted \
  --set oauth-message-type:consent-requested \
  --set oauth-message-type:exception \
  --set oauth-message-type:id-token-granted \
  --set oauth-message-type:token-granted \
  --set oauth-message-type:token-revoked \
  --set oauth-message-type:token-validation \
  --set xacml-policy-message-type:result \
  --set scim-message-type:request \
  --set scim-message-type:result \
  --set authentication-message-type:account-flow \
  --set authentication-message-type:login \
  --set authentication-message-type:logout \
  --set authentication-message-type:second-factor \
  --set 'exclude-path-pattern:/**/*.css' \
  --set 'exclude-path-pattern:/**/*.eot' \
  --set 'exclude-path-pattern:/**/*.gif' \
  --set 'exclude-path-pattern:/**/*.ico' \
  --set 'exclude-path-pattern:/**/*.jpg' \
  --set 'exclude-path-pattern:/**/*.js' \
  --set 'exclude-path-pattern:/**/*.png' \
  --set 'exclude-path-pattern:/**/*.svg' \
  --set 'exclude-path-pattern:/**/*.ttf' \
  --set 'exclude-path-pattern:/**/*.woff' \
  --set 'exclude-path-pattern:/**/*.woff2' \
  --set 'exclude-path-pattern:/console/**/template/**' \
  --set log-file:logs/example-trace \
  --set "rotation-policy:24 Hours Time Limit Rotation Policy" \
  --set "rotation-policy:Size Limit Rotation Policy" \
  --set "retention-policy:File Count Retention Policy" \
  --set "retention-policy:Free Disk Space Retention Policy"

If you require more detailed information about requests and responses received by the Data Governance Broker, you may wish to enable the http-full-request-and-response debug message type, which will cause the logger to record the raw requests received and raw responses produced by the server.

dsconfig set-log-publisher-prop --publisher-name "Example Debug Trace Logger" \
  --set debug-message-type:http-full-request-and-response

Using the search-logs tool

The Data Governance Broker provides a helpful tool for searching through logs, search-logs.

At its simplest, it may be used as a kind of glorified grep. For example, say that we want to trace an application’s activity as it makes SCIM resource server requests. We can do this by tracing the use of an access token through the logs. The trace log doesn’t actually record the access token itself, which would be a security liability; instead, it records a non-sensitive unique identifier for the access token. This identifier is added to the access token JWT itself as the jti claim, but we may also find the identifier if we have the log message for the token grant event:

[17/Sep/2016:15:05:26.305 -0500] OAUTH TOKEN-GRANTED requestID=49654 accessTokenId="a.Lufr5Q" client="My Client" resourceTypeEndpoint="Users" resourceID="39fde12e-ec3d-4b8d-a99d-c1898ac09797" grantType="implicit" scopes="openid email" expiresIn="86400"

In the above log message, we find a field called accessTokenId, with a value of a.Lufr5Q. With this value, we can use search-logs to find all log messages with this access token ID.

$ PingDataGovernance/bin/search-logs --logFile PingDataGovernance/logs/example-trace "accessTokenId=\"a.Lufr5Q\""

example-trace:[17/Sep/2016:15:05:26.305 -0500] OAUTH TOKEN-GRANTED requestID=49654 accessTokenId="a.Lufr5Q" client="My Client" resourceTypeEndpoint="Users" resourceID="39fde12e-ec3d-4b8d-a99d-c1898ac09797" grantType="implicit" scopes="openid email" expiresIn="86400"

example-trace:[17/Sep/2016:15:05:27.425 -0500] SCIM REQUEST requestID=49657 accessTokenId="a.Lufr5Q" scimOpID="27" op="retrieve" opPath="Users/39fde12e-ec3d-4b8d-a99d-c1898ac09797"

example-trace:[17/Sep/2016:15:05:27.440 -0500] XACMLPOLICY RESULT requestID=49657 accessTokenId="a.Lufr5Q" scimOpID="27" subjectId="My Client" actionId="retrieve" resourceId="Users/39fde12e-ec3d-4b8d-a99d-c1898ac09797" decision="PERMIT" policies="urn:pingidentity:policy:ScopeValidationPolicy,urn:pingidentity:policy:SCIMResourcePolicySet,urn:pingidentity:policy:TokenValidationPolicy" obligations="include-attributes(attributeNames='emails')"

example-trace:[17/Sep/2016:15:05:27.444 -0500] SCIM RESULT requestID=49657 accessTokenId="a.Lufr5Q" scimOpID="27" op="retrieve" opPath="Users/39fde12e-ec3d-4b8d-a99d-c1898ac09797" status="2XX"

...

A more powerful feature of search-logs is its ability to find all log messages within a specified time range. This is done using the --startTime and --endTime arguments, as in the following example:

$ PingDataGovernance/bin/search-logs --logFile PingDataGovernance/logs/example-trace --excludeRotated  --startTime "[17/Sep/2016:15:03:00.000 -0500]" --endTime "[17/Sep/2016:15:04:00.000 -0500]"

example-trace:[17/Sep/2016:15:03:47.259 -0500] HTTP REQUEST requestID=49593 product="Ping Identity Data Governance Broker" instanceName="broker1" startupID="V9wR0A==" threadID=268 from=10.5.0.238:41260 method=GET url="https://example.com/oauth/authorize?response_type=token&client_id=my-client&redirect_uri=https%3A%2F%2Fexample.com%2Fcallback.html&scope=openid%20email&state=TElHSFROSU5HIElTIFRIRSBMT1JEIE9GIEVWRVJZVEhJTkc="

example-trace:[17/Sep/2016:15:03:47.286 -0500] OAUTH AUTHZ-REQUEST requestID=49593 clientId="my-client" responseType="token" scopes="openid email" redirectUri="http://localhost:3004/callback.html" state="TElHSFROSU5HIElTIFRIRSBMT1JEIE9GIEVWRVJZVEhJTkc=" prompt="" acrValues="Default"

example-trace:[17/Sep/2016:15:03:47.305 -0500] HTTP RESPONSE requestID=49593 product="Ping Identity Data Governance Broker" instanceName="broker1" startupID="V9wR0A==" threadID=268 statusCode=302 etime=36.269 responseContentLength=0

...

Using HTTP tools

Sometimes an IDE doesn’t provide the best vantage point for seeing a problem clearly. Using the Data Governance Broker API Reference as a guide, try exploring the APIs interactively at the HTTP protocol level. Doing this can help you to see details that you might otherwise miss.

Some popular HTTP tools that you might use include:

The Data Governance Broker also includes a useful API Explorer web application that you can use to interactively try out the Broker’s SCIM APIs. This tool can be accessed from your server’s /docs/explorer path.

API Explorer

Troubleshooting CORS

A typical JavaScript client of the Data Governance Broker follows this pattern:

  1. Request a protected resource, such as /scim/v2/Me.
  2. If the resource server responds with a 401, then make an OAuth 2 or OpenID Connect request to obtain an access token.
  3. Repeat the first request using the new access token.

If the server again responds with a 401 during the third step, then a CORS problem is likely, meaning that the web browser prevented your client from making a SCIM request from its origin to the resource server’s origin.

As an initial sanity check, you can look at the trace log to confirm that an access token was in fact granted to your client. Here’s an example:

[17/Sep/2016:14:20:59.833 -0500] OAUTH TOKEN-GRANTED requestID=48304 accessTokenId="a.sASbuw" client="My Client" resourceTypeEndpoint="Users" resourceID="e094d3e6-177e-419d-b80b-f98868e3995c" grantType="implicit" scopes="openid email profile" expiresIn="86400"

If the server did grant an access token to your client, this strengthens the hypothesis that this is a CORS problem. If you open your web browser’s developer tools and look at the console, you’re likely to see a set of errors like this:

[Error] Failed to load resource: the server responded with a status of 401 (Unauthorized) (Me, line 0)
[Error] Failed to load resource: Origin https://my-client is not allowed by Access-Control-Allow-Origin. (Me, line 0)
[Error] XMLHttpRequest cannot load https://example.com/scim/v2/Me. Origin https://my-client is not allowed by Access-Control-Allow-Origin.

The solution, then, is simple: Register your client’s origin in the Data Governance Broker configuration, then enable a CORS policy.

dsconfig set-oauth2-client-prop --client-name "My Client" \
  --set trusted-cors-origin:https://my-client
# 'Per-Application Origins' is a default CORS policy
dsconfig set-http-servlet-extension-prop --extension-name SCIM2 \
  --set "cross-origin-policy:Per-Application Origins"

Problems with CORS preflight requests may manifest themselves differently. If you find an unexpected failure when using an HTTP method such as POST, PUT, PATCH, or DELETE, then it’s likely that the CORS preflight request failed. Look in your developer tools console for a 403 response to an OPTIONS request.

The UnboundID Community

The UnboundID Community hosts a number of discussion forums and knowledge base articles where you might find the answers that you need. And if not, you’re likely to find help if you ask a question.

Using the collect-support-data tool

The collect-support-data tool, included with the Data Governance Broker and Directory Server, can be used to produce a zip file of troubleshooting information for submission to a support representative. This tool captures server log files and the server configuration, as well as output from various diagnostic tools, such as jps, jstack, and jstat.

Running the tool without arguments captures a default set of files.

$ PingDataGovernance/bin/collect-support-data

collect-support-data Ping Identity Data Governance Broker 6.0.0.0 24169
Server Root: /home/example/PingDataGovernance
LDAP Connection: example.com:8636
Archiving config ..... Done
Archiving lib ..... Done
Archiving logs ..... Done
...
Finished writing support-data-broker-example.com-20160917133258-zip

See /home/example/PingDataGovernance/logs/tools/support-data-broker-example.com.log
for a detailed log of this operation.

The tool’s output file will be named with the pattern support-data-*-zip.

By default, collect-support-data will exclude any file likely to include sensitive data. This includes any trace logs that are configured to record debug message types. If you are working with test data, you may wish to provide a more complete set of logs by overriding this data security setting with the --securityLevel argument.

$ PingDataGovernance/bin/collect-support-data --securityLevel none

collect-support-data Ping Identity Data Governance Broker 6.0.0.0 24169
Server Root: /home/example/PingDataGovernance
LDAP Connection: example.com:8636
Archiving config ..... Done
Archiving lib ..... Done
Archiving logs ..... Done
...
Finished writing support-data-broker-example.com-20160917133841-zip

See /home/example/PingDataGovernance/logs/tools/support-data-broker-example.com.log
for a detailed log of this operation.