Troubleshooting IG/OpenIG

This book provides information on troubleshooting various issues in IG/OpenIG including collecting useful troubleshooting information such as logs, heap dumps and stack traces.


Sending troubleshooting data to ForgeRock Support for analysis

The purpose of this article is to provide information on sending troubleshooting and diagnostic data that ForgeRock Support has requested for analysis using ticket attachments.

Sending data for analysis

You can attach troubleshooting and diagnostic data to tickets in BackStage. When using BackStage to access tickets, there are no limits to the attachment size; this is the recommended method of sending us troubleshooting and diagnostic data.

See Uploading Files for further information on uploading files to BackStage.

See Also

Best practice for raising a ticket with ForgeRock Support

Getting started with ForgeRock Support

AM/OpenAM

How do I collect all the data required for troubleshooting AM/OpenAM and Policy Agents (All versions)?

How do I record troubleshooting information in AM (All versions) and OpenAM 13.x? 

How do I create a HAR file for troubleshooting AM/OpenAM (All versions)?

How do I collect JVM data for troubleshooting AM/OpenAM (All versions)?

Troubleshooting AM/OpenAM and Policy Agents 

DS/OpenDJ

How do I use the Support Extract tool in DS/OpenDJ (All versions) to capture troubleshooting information?

How do I collect JVM data for troubleshooting DS/OpenDJ (All versions)?

Troubleshooting DS/OpenDJ

IDM/OpenIDM

How do I create a HAR file for troubleshooting IDM/OpenIDM (All versions)?

How do I collect JVM data for troubleshooting IDM/OpenIDM (All versions)?

Troubleshooting IDM/OpenIDM 

IG/OpenIG

How do I collect debug logs in IG/OpenIG (All versions) for troubleshooting?

How do I collect JVM data for troubleshooting IG/OpenIG (All versions)?

Troubleshooting IG/OpenIG 


How do I check if IG/OpenIG (All versions) is up and running?

The purpose of this article is to provide a way to check if IG/OpenIG is up and running when it is behind a load balancer. This article provides a way to call a page that is similar to the AM/OpenAM isAlive.jsp page.

Checking if IG/OpenIG is up and running

Since most of what IG/OpenIG does is proxy, its health mainly depends on the health of upstream applications for which IG/OpenIG is the proxy.

The following method provides a simple way to check that IG/OpenIG is up and running by establishing that IG/OpenIG can read its configuration and return a result without depending on a downstream application. The static text and URI shown are just examples, you should use values that make sense in the environment where IG/OpenIG is deployed:  

  1. Create a simple isAlive route. The result should return a 200 status along with some static text; for example, "Server is ALIVE". These results can be used to check on the health of IG/OpenIG.
  2. Add a new route to the IG/OpenIG configuration. For example, you could create a 00-isAlive.json file in the $HOME/.openig/config/routes directory, similar to the following:
    {
      "handler": {
          "type": "StaticResponseHandler",
          "config": {
            "status": 200,
            "reason": "Found",
            "entity": "Server is ALIVE"
          }
        },
      "condition": "${request.uri.path == '/isAlive.jsp'}"
    }
    
    Notice that /openig/ is not used for the route since this is reserved for admin purposes only; instead the /isAlive.jsp URI is used in this example.
  3. Configure the load balancer to check the results from this URL, for example, by calling the following URL: 
    http://openig.example.com:8080/isAlive.jsp
Note

If you require more detailed checks, you could make use of a scriptable handler instead: Configuration Reference › Handlers › ScriptableHandler.

See Also

How do I collect debug logs in IG/OpenIG (All versions) for troubleshooting?

How do I collect JVM data for troubleshooting IG/OpenIG (All versions)?

How do I check if AM/OpenAM (All versions) is up and running?

Gateway Guide › Configuring Routers and Routes

Gateway Guide › Monitoring

Related Training

N/A

Related Issue Tracker IDs

OPENIG-1370 (OpenIG Healthcheck Template)


How do I troubleshoot high CPU utilization or Out of Memory errors on IG/OpenIG (All versions) servers?

The purpose of this article is to provide troubleshooting guidance if you are experiencing consistently high CPU utilization on the IG/OpenIG server or seeing Out of Memory errors. If CPU utilization is in the range 70-80% under load, you should definitely investigate what is causing it as performance is likely to be impacted.

Troubleshooting high CPU usage or Out of Memory errors

Both high CPU utilization and Out of Memory errors are usually experienced in conjunction with other symptoms such as servers becoming unresponsive and poor performance.

Note

On Linux®, Unix® and Solaris® systems, there is a script you can run to capture the stack traces and process information as detailed in How do I use the msnapshots script to capture information for troubleshooting IG/OpenIG (All versions)?

There are a number of different types of data that you should collect to help us troubleshoot high CPU utilization or Out of Memory errors; you should collect the following data and submit it to us when you raise the ticket to enable us to help you more quickly:

  • Debug logs.
  • Configuration directory.
  • JVM stack traces and current options.
  • Process / thread information.
  • Garbage Collector (GC) logs.
Note

It is important that you collect all the data at the point you are experiencing the issue so that the timestamps of the data collected and the issue correspond. Please notify us of the exact timestamp when high CPU / Out of Memory errors was noticed so we can focus our attention on the relevant information. 

Debug logs

Debug level debug logs provide more context for diagnosing errors but can generate large files. You should enable debug level debugging when you are experiencing an issue as described in How do I collect debug logs in IG/OpenIG (All versions) for troubleshooting?

Configuration directory

The configuration directory ($HOME/.openig/config/) contains all the configuration settings for an IG/OpenIG server instance and is useful for checking settings that may play a role in the issue.

JVM stack traces and current options

JVM stack traces must be collected before killing the affected process or restarting the server; otherwise the information relating to the affected process is lost forever, which may make it impossible to identify the root cause. In addition to collecting stack traces, you should also provide details of the current JVM settings as they can provide an opportunity for tuning, which can reduce CPU usage or Out of Memory errors.

Collecting stack traces and finding current JVM settings is described in How do I collect JVM data for troubleshooting IG/OpenIG (All versions)?

Process / thread information 

Detailed process / thread information is useful for identifying the exact thread within a process that is experiencing the high CPU. You should collect this data at the same time as the stack trace so we can look for the identified thread in the stack trace for more information.

  • On Unix® and Linux® systems, you can use the top command to output process information for all threads to a file:
    $ top -b -n 1 -H -p [pid] > top-output.txt
    replacing [pid] with the process ID of the affected process.
  • On Solaris®, you can use the prstat command to capture this information:
    $ prstat -L -p [pid]
    replacing [pid] with the process ID of the affected process.
  • On Microsoft® Windows®, you will need to use the Process Monitor.

See How do I find which thread is consuming CPU in a Java process in IG/OpenIG (All versions)? for further information on identifying the thread that is causing high CPU usage.

GC logs

GC logs also provide useful information about tuning issues that may be contributing to the high CPU usage or Out of Memory errors. Enabling GC logging is described in How do I enable Garbage Collector (GC) Logging for IG/OpenIG (All versions)?

In addition, please include any information about other symptoms you are seeing at the same time as the issue and any changes you have made to your system that may have contributed to the problem.

See Also

Troubleshooting IG/OpenIG

Best practice for JVM Tuning

Gateway Guide › Troubleshooting

Related Training

N/A

Related Issue Tracker IDs

OPENIG-1053 (Downloading large file fails)


How do I find which thread is consuming CPU in a Java process in IG/OpenIG (All versions)?

The purpose of this article is to provide assistance on identifying which thread is consuming CPU in a Java® process in IG/OpenIG. This is a useful troubleshooting technique when you are experiencing high CPU under load.

Identifying the thread

You can identify which thread is consuming CPU in a Java process as follows:

  1. Determine the process ID (PID) of the web container instance in which the affected server is running using the following command:
    $ jps -v
  2. Determine which thread in the PID identified in step 1 is consuming the CPU:
    • On Unix® and Linux® systems, you can use the top command:
      $ top -n 1 -H -p [pid]
      replacing [pid] with the process ID of the affected process.
    • On Solaris®, you can use the prstat command:
      $ prstat -L -p [pid]
      replacing [pid] with the process ID of the affected process.
    • On Microsoft® Windows®, you can use the Process Monitor.
    These commands all give an output listing all the threads in the selected process along with various details, including the CPU usage percentage. For example, the top command gives an output similar to this:
    Tasks: 152 total,   0 running, 152 sleeping,   0 stopped,   0 zombie 
    Cpu(s):  2.0%us,  1.4%sy,  0.0%ni, 94.7%id,  0.8%wa,  0.0%hi,  1.1%si,  0.0%st 
    Mem:   5008484k total,  4854428k used,   154056k free,    85624k buffers 
    Swap:  5013496k total,     6516k used,  5006980k free,  3393948k cached
    PID  USER     PR  NI  VIRT  RES  SHR S  %CPU  %MEM   TIME+  COMMAND              
    8706 user.1   20   0 2433m 561m  10m R  32.0  11.5  0:35.45 java
    8624 user.1   20   0 2433m 561m  10m S   0.0  11.5  0:00.01 java                 
    8625 user.1   20   0 2433m 561m  10m S   0.0  11.5  0:10.12 java                 
    8626 user.1   20   0 2433m 561m  10m S   0.0  11.5  0:35.60 java                 
    8627 user.1   20   0 2433m 561m  10m S   0.0  11.5  0:00.01 java                 
    8628 user.1   20   0 2433m 561m  10m S   0.0  11.5  0:00.02 java              
    In this example, we can see that thread ID 8706 is consuming 32% of the CPU.
  3. Produce a stack trace for the PID identified in step 1 using the following command:
    $ jstack [PID] > jstack-output.txt
  4. Convert the thread ID identified as problematic in step 2 to a hex value. In our example output, the thread ID decimal value 8706 converts to hex value 2202.
  5. Search the stack trace output for this hex value using grep. You are looking for a thread nid that matches this hex value:
    $ cat jstack-output.txt | grep -i 2202
    This command gives an output similar to this:
    "Concurrent Mark-Sweep GC Thread" prio=10 tid=0x00007f1448029800 nid=0x2202 runnable
    In this example, we can see that the problem is a Garbage Collector (GC) thread, which suggests that GC is not properly tuned.

See Also

How do I troubleshoot high CPU utilization or Out of Memory errors on IG/OpenIG (All versions) servers?

How do I use the msnapshots script to capture information for troubleshooting IG/OpenIG (All versions)?

How do I collect JVM data for troubleshooting IG/OpenIG (All versions)?

How do I enable Garbage Collector (GC) Logging for IG/OpenIG (All versions)?

Troubleshooting IG/OpenIG

Java Thread Dump Analyzer

Related Training

N/A

Related Issue Tracker IDs

N/A


Logging


Where can I find useful logs for troubleshooting ForgeRock products?

The purpose of this article is to provide information on finding logs across ForgeRock products (AM/OpenAM, DS/OpenDJ, IDM/OpenIDM and IG/OpenIG) for troubleshooting purposes. This article shows default log locations, although most of them can be changed.

AM/OpenAM logs

The following logs are available:

Log type Location
AM/OpenAM debug logs $HOME/[am_instance]/openam/debug
AM/OpenAM audit logs $HOME/[am_instance]/openam/log
ssoadm logs /path/to/openam-tools/[ssoadm_install_folder]/debug
Fedlet debug logs $HOME/fedlet/debug
Container logs if deployed on Apache Tomcat™ (localhost_access_log.YYYY-MM-DD.log and catalina.out) /path/to/tomcat/logs
SSL debug logs if deployed on Apache Tomcat (catalina.out) /path/to/tomcat/logs

Policy Agents logs

The following logs are available:

Log type Location
Web policy agents debug.log /path/to/policy_agent/instances/agent_n/logs/debug directory where the policy agent is installed.
Web policy agents audit.log /path/to/policy_agent/instances/agent_n/logs/audit directory where the policy agent is installed.
Web policy agents install log (installYYYYMMDDHHMMSS.log) /path/to/policy_agent/log directory where the policy agent is installed.

Web policy agents system information:

  • system_n.log (Agents 5.5 and later)
  • agent.log (Pre-Agents 5.5)
/path/to/policy_agent/log directory where the policy agent is installed.
Java agents debug log (amAgent) /path/to/policy_agent/agent_n/logs/debug directory where the policy agent is installed.
Java agents audit logs /path/to/policy_agent/agent_n/logs/audit directory where the policy agent is installed.
Java agents install logs /path/to/policy_agent/installer-logs directory where the policy agent is installed.

DS/OpenDJ logs

The following logs are available:

Log type Location
Embedded DS/OpenDJ logs (access, errors and replication) $HOME/[am_instance]/opends/logs
External DS/OpenDJ logs (access, errors and replication) /path/to/ds/logs directory where DS/OpenDJ is installed.
SSL debug logs (server.out) /path/to/ds/logs directory where DS/OpenDJ is installed

IDM/OpenIDM logs

The following logs are available:

Log type Location
IDM/OpenIDM log (openidm0.log.n) /path/to/idm/logs
IDM/OpenIDM audit logs /path/to/idm/audit
Jetty® Request logs /path/to/idm/logs
DS/OpenDJ password sync plugin /path/to/ds/logs directory where DS/OpenDJ is installed.
Active Directory® password sync plugin (idm.log) The location is specified in the logPath registry entry under the HKEY_LOCAL_MACHINE\SOFTWARE\ForgeRock\OpenIDM\PasswordSync registry key.

IG/OpenIG logs

The following logs are available:

Log type Location
IG 5 and later $HOME/.openig/logs
OpenIG 3.x and 4.x stdout (catalina.out if you are using Apache Tomcat™) or /tmp/gateway.log depending on how you have configured logging.
SAML logs $HOME/.openig/SAML/debug

See Also

How do I collect all the data required for troubleshooting AM/OpenAM and Policy Agents (All versions)?

How do I enable debug logging for troubleshooting Policy Agents (All versions)?

How do I use the Support Extract tool in DS/OpenDJ (All versions) to capture troubleshooting information?

How do I collect debug logs in IG/OpenIG (All versions) for troubleshooting?

Troubleshooting AM/OpenAM and Policy Agents

Troubleshooting DS/OpenDJ

Troubleshooting IDM/OpenIDM

Troubleshooting IG/OpenIG

Related Training

N/A

Related Issue Tracker IDs

N/A


How do I trace transactions through the audit logs for troubleshooting across ForgeRock products?

The purpose of this article is to provide information on tracing transactions through the audit logs to help with troubleshooting across ForgeRock products. This article covers an IG/OpenIG --> AM/OpenAM --> DS/OpenDJ flow to demonstrate this usage and applies to AM/OpenAM (All versions) and OpenAM 13.x, DS/OpenDJ (All versions) and IG/OpenIG (All versions).

Overview

A Trust Transaction Header system property (org.forgerock.http.TrustTransactionHeader) exists to allow the propagation of transaction IDs across ForgeRock products using the HTTP header X-ForgeRock-TransactionId. This header can also be passed to ForgeRock products from client applications so that the same transaction ID is used in client applications and ForgeRock products. For example, in flows such as Client Application --> IG/OpenIG --> AM/OpenAM --> DS/OpenDJ or Client Application --> AM/OpenAM --> DS/OpenDJ.

By default, this system property is set to false so that a malicious actor cannot flood the system with requests using the same transaction ID header to hide their tracks. Once enabled, you can trace a single transaction across multiple products in order to troubleshoot their interactions. See the following links for further information:

This article demonstrates using this HTTP header to trace a single transaction through the audit logs for an IG/OpenIG --> AM/OpenAM --> DS/OpenDJ flow and includes the same transaction in the Apache Tomcat™ access logs for a complete view of the transaction's journey.

Note

A related article exists for tracing transaction IDs through IDM/OpenIDM logs using the thread ID: How do I add Thread IDs to log statements in IDM/OpenIDM (All versions)?

Tracing transaction IDs

The following example demonstrates configuring the products to propagate transaction IDs and then verifying that they appear in the logs, including the Tomcat log:

  1. Configure amHandler in IG/OpenIG to use the ForgeRockClientHandler in place of the ClientHandler. This change ensures the X-ForgeRock-TransactionId header values are passed to AM/OpenAM. For example, this demonstration is based on making this change to the amHandler in PolicyEnforcementFilter. See Configuration Reference › PolicyEnforcementFilter for further details. 
  2. Enable audit logging in IG/OpenIG as detailed in Gateway Guide › Auditing.
  3. Configure DS/OpenDJ to trust transaction IDs sent with client application requests using dsconfig, for example:
    $ ./dsconfig set-global-configuration-prop --advanced --port 4444 --hostname ds1.example.com --bindDN "cn=Directory Manager" --bindPassword password --set trust-transaction-ids:true --trustAll --no-prompt 
  4. Configure AM/OpenAM to trust any incoming X-ForgeRock-TransactionId headers as detailed in Setup and Maintenance Guide › Configuring the Trust Transaction Header System Property.
  5. Update Tomcat's server.xml file to log the X-ForgeRock-Transactionid. You should modify the pattern to match the following example for the org.apache.catalina.valves.AccessLogValve className:
    <Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
          prefix="localhost_access_log" suffix=".txt"
          pattern="%h %l %u %t &quot;%r&quot; %s %b %{X-ForgeRock-Transactionid}i" />
    
  6. Invoke the IG/OpenIG route.
  7. Note the transaction ID and then examine the following logs to trace the progress and corresponding operations of the request - In this example, we search the logs for transaction ID "7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27" (shown in bold):
    • IG/OpenIG access.audit.json log:
      {"realm":"/","transactionId":"2f34280f-c061-423c-8e64-adc9f8e12b95-508","userId":"id=jdoe,ou=user,o=employees,ou=services,dc=openam,dc=forgerock,dc=org","client":{"ip":"127.0.0.1","port":37796},"server":{"ip":"127.0.0.1","port":8989},"http":{"request":{"secure":false,"method":"POST","queryParameters":{"_action":["validate"]},"headers":{"accept-api-version":["protocol=1.0,resource=1.1"],"host":["host1.example.com:8989"],"user-agent":["Apache-HttpAsyncClient/4.1.2 (Java/1.8.0_151)"],"x-forgerock-transactionid":["7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/0"],"x-forwarded-for":["192.0.2.0"]},"cookies":{},"path":"http://host1.example.com:8989/openam/json/sessions"}},"request":{"protocol":"CREST","operation":"ACTION","detail":{"action":"validate"}},"timestamp":"2018-05-18T14:32:38.987Z","eventName":"AM-ACCESS-OUTCOME","component":"Session","response":{"status":"SUCCESSFUL","statusCode":"","elapsedTime":11,"elapsedTimeUnits":"MILLISECONDS"},"trackingIds":["2f34280f-c061-423c-8e64-adc9f8e12b95-469"],"_id":"2f34280f-c061-423c-8e64-adc9f8e12b95-510"}
      {"realm":"/","transactionId":"2f34280f-c061-423c-8e64-adc9f8e12b95-514","userId":"id=jdoe,ou=user,o=employees,ou=services,dc=openam,dc=forgerock,dc=org","client":{"ip":"192.0.2.0","port":55437},"server":{"ip":"192.0.2.24","port":8989},"http":{"request":{"secure":false,"method":"POST","queryParameters":{"_action":["getSessionInfo"]},"headers":{"accept":["application/json, text/javascript, */*; q=0.01"],"accept-api-version":["protocol=1.0,resource=2.0"],"dnt":["1"],"host":["host1.example.com:8989"],"referer":["http://host1.example.com:8989/openam/XUI/?service=LDAP&realm=/employees&goto=http://ig1.example.com:9292/home/pep"],"user-agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10.13; rv:59.0) Gecko/20100101 Firefox/59.0"],"x-requested-with":["XMLHttpRequest"]},"cookies":{"i18next":"en-US"},"path":"http://host1.example.com:8989/openam/json/sessions"}},"request":{"protocol":"CREST","operation":"ACTION","detail":{"action":"getSessionInfo"}},"timestamp":"2018-05-18T14:32:39.009Z","eventName":"AM-ACCESS-OUTCOME","component":"Session","response":{"status":"SUCCESSFUL","statusCode":"","elapsedTime":1,"elapsedTimeUnits":"MILLISECONDS"},"trackingIds":["2f34280f-c061-423c-8e64-adc9f8e12b95-469"],"_id":"2f34280f-c061-423c-8e64-adc9f8e12b95-518"}
      {"realm":"/employees","transactionId":"7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/1","userId":"id=policyAdmin,ou=user,o=employees,ou=services,dc=openam,dc=forgerock,dc=org","timestamp":"2018-05-18T14:32:39.057Z","eventName":"AM-ACCESS-OUTCOME","component":"Authentication","response":{"status":"SUCCESSFUL","statusCode":"","elapsedTime":54,"elapsedTimeUnits":"MILLISECONDS"},"client":{"ip":"127.0.0.1","port":37797},"http":{"request":{"secure":false,"method":"POST","path":"http://host1.example.com:8989/openam/json/employees/authenticate","queryParameters":{},"headers":{"Accept-API-Version":["protocol=2.1"],"host":["host1.example.com:8989"],"user-agent":["Apache-HttpAsyncClient/4.1.2 (Java/1.8.0_151)"],"x-forgerock-transactionid":["7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/1"],"x-forwarded-for":["192.0.2.0"],"x-openam-username":["policyAdmin"]},"cookies":{}}},"trackingIds":["2f34280f-c061-423c-8e64-adc9f8e12b95-516"],"_id":"2f34280f-c061-423c-8e64-adc9f8e12b95-527"}
      {"realm":"/employees","transactionId":"2f34280f-c061-423c-8e64-adc9f8e12b95-529","userId":"id=policyAdmin,ou=user,o=employees,ou=services,dc=openam,dc=forgerock,dc=org","client":{"ip":"127.0.0.1","port":37796},"server":{"ip":"127.0.0.1","port":8989},"http":{"request":{"secure":false,"method":"POST","path":"http://host1.example.com:8989/openam/json/employees/policies","queryParameters":{"_action":["evaluate"]},"headers":{"accept-api-version":["protocol=1.0,resource=2.0"],"host":["host1.example.com:8989"],"user-agent":["Apache-HttpAsyncClient/4.1.2 (Java/1.8.0_151)"],"x-forgerock-transactionid":["7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/2"],"x-forwarded-for":["192.0.2.0"]},"cookies":{}}},"request":{"protocol":"CREST","operation":"ACTION","detail":{"action":"evaluate"}},"timestamp":"2018-05-18T14:32:39.083Z","eventName":"AM-ACCESS-OUTCOME","component":"Policy","response":{"status":"SUCCESSFUL","statusCode":"","elapsedTime":20,"elapsedTimeUnits":"MILLISECONDS","detail":[{"advices":{},"ttl":9223372036854775807,"resource":"http://igApp.example.com:8081/home/pep","actions":{"POST":true,"GET":true},"attributes":{"givenName":["Jane"],"dn":["uid=jdoe,ou=People,dc=example,dc=com"],"isMemberOf":[],"cn":["Jane Doe"]}}]},"trackingIds":["2f34280f-c061-423c-8e64-adc9f8e12b95-516"],"_id":"2f34280f-c061-423c-8e64-adc9f8e12b95-533"}
      
    • Tomcat localhost_access_log file:
      127.0.0.1 - - [18/May/2018:10:32:38 -0400] "POST /openam/json/sessions?_action=validate HTTP/1.1" 200 61 7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/0
      192.0.2.0 - - [18/May/2018:10:32:38 -0400] "GET /openam/XUI/org/forgerock/openam/ui/common/models/JSONSchema.js?v=5.5.1 HTTP/1.1" 200 12619 -
      192.0.2.0 - - [18/May/2018:10:32:38 -0400] "GET /openam/XUI/org/forgerock/openam/ui/common/models/JSONValues.js?v=5.5.1 HTTP/1.1" 200 16418 -
      192.0.2.0 - - [18/May/2018:10:32:38 -0400] "GET /openam/XUI/org/forgerock/openam/ui/admin/services/SMSServiceUtils.js?v=5.5.1 HTTP/1.1" 200 6112 -
      192.0.2.0 - - [18/May/2018:10:32:38 -0400] "GET /openam/XUI/org/forgerock/openam/ui/common/util/Promise.js?v=5.5.1 HTTP/1.1" 200 1827 -
      192.0.2.0 - - [18/May/2018:10:32:39 -0400] "GET /openam/XUI/org/forgerock/openam/ui/common/models/schemaTransforms/transformEnumTypeToString.js?v=5.5.1 HTTP/1.1" 200 838 -
      192.0.2.0 - - [18/May/2018:10:32:39 -0400] "GET /openam/XUI/org/forgerock/openam/ui/common/models/schemaTransforms/transformBooleanTypeToCheckboxFormat.js?v=5.5.1 HTTP/1.1" 200 643 -
      192.0.2.0 - - [18/May/2018:10:32:39 -0400] "GET /openam/XUI/org/forgerock/openam/ui/common/models/schemaTransforms/warnOnInferredPasswordWithoutFormat.js?v=5.5.1 HTTP/1.1" 200 999 -
      192.0.2.0 - - [18/May/2018:10:32:39 -0400] "POST /openam/json/sessions?_action=getSessionInfo HTTP/1.1" 200 297 -
      127.0.0.1 - - [18/May/2018:10:32:39 -0400] "POST /openam/json/employees/authenticate HTTP/1.1" 200 164 7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/1
      127.0.0.1 - - [18/May/2018:10:32:39 -0400] "POST /openam/json/employees/policies?_action=evaluate HTTP/1.1" 200 266 7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/2​
      
    • AM/OpenAM access.audit.json file:
      {"realm":"/","transactionId":"2f34280f-c061-423c-8e64-adc9f8e12b95-508","userId":"id=jdoe,ou=user,o=employees,ou=services,dc=openam,dc=forgerock,dc=org","client":{"ip":"127.0.0.1","port":37796},"server":{"ip":"127.0.0.1","port":8989},"http":{"request":{"secure":false,"method":"POST","queryParameters":{"_action":["validate"]},"headers":{"accept-api-version":["protocol=1.0,resource=1.1"],"host":["host1.example.com:8989"],"user-agent":["Apache-HttpAsyncClient/4.1.2 (Java/1.8.0_151)"],"x-forgerock-transactionid":["7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/0"],"x-forwarded-for":["192.0.2.0"]},"cookies":{},"path":"http://host1.example.com:8989/openam/json/sessions"}},"request":{"protocol":"CREST","operation":"ACTION","detail":{"action":"validate"}},"timestamp":"2018-05-18T14:32:38.987Z","eventName":"AM-ACCESS-OUTCOME","component":"Session","response":{"status":"SUCCESSFUL","statusCode":"","elapsedTime":11,"elapsedTimeUnits":"MILLISECONDS"},"trackingIds":["2f34280f-c061-423c-8e64-adc9f8e12b95-469"],"_id":"2f34280f-c061-423c-8e64-adc9f8e12b95-510"}
      {"realm":"/","transactionId":"2f34280f-c061-423c-8e64-adc9f8e12b95-514","userId":"id=jdoe,ou=user,o=employees,ou=services,dc=openam,dc=forgerock,dc=org","client":{"ip":"192.0.2.0","port":55437},"server":{"ip":"192.0.2.24","port":8989},"http":{"request":{"secure":false,"method":"POST","queryParameters":{"_action":["getSessionInfo"]},"headers":{"accept":["application/json, text/javascript, */*; q=0.01"],"accept-api-version":["protocol=1.0,resource=2.0"],"dnt":["1"],"host":["host1.example.com:8989"],"referer":["http://host1.example.com:8989/openam/XUI/?service=LDAP&realm=/employees&goto=http://ig1.example.com:9292/home/pep"],"user-agent":["Mozilla/5.0 (Macintosh; Intel Mac OS X 10.13; rv:59.0) Gecko/20100101 Firefox/59.0"],"x-requested-with":["XMLHttpRequest"]},"cookies":{"i18next":"en-US"},"path":"http://host1.example.com:8989/openam/json/sessions"}},"request":{"protocol":"CREST","operation":"ACTION","detail":{"action":"getSessionInfo"}},"timestamp":"2018-05-18T14:32:39.009Z","eventName":"AM-ACCESS-OUTCOME","component":"Session","response":{"status":"SUCCESSFUL","statusCode":"","elapsedTime":1,"elapsedTimeUnits":"MILLISECONDS"},"trackingIds":["2f34280f-c061-423c-8e64-adc9f8e12b95-469"],"_id":"2f34280f-c061-423c-8e64-adc9f8e12b95-518"}
      {"realm":"/employees","transactionId":"7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/1","userId":"id=policyAdmin,ou=user,o=employees,ou=services,dc=openam,dc=forgerock,dc=org","timestamp":"2018-05-18T14:32:39.057Z","eventName":"AM-ACCESS-OUTCOME","component":"Authentication","response":{"status":"SUCCESSFUL","statusCode":"","elapsedTime":54,"elapsedTimeUnits":"MILLISECONDS"},"client":{"ip":"127.0.0.1","port":37797},"http":{"request":{"secure":false,"method":"POST","path":"http://host1.example.com:8989/openam/json/employees/authenticate","queryParameters":{},"headers":{"Accept-API-Version":["protocol=2.1"],"host":["host1.example.com:8989"],"user-agent":["Apache-HttpAsyncClient/4.1.2 (Java/1.8.0_151)"],"x-forgerock-transactionid":["7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/1"],"x-forwarded-for":["192.0.2.0"],"x-openam-username":["policyAdmin"]},"cookies":{}}},"trackingIds":["2f34280f-c061-423c-8e64-adc9f8e12b95-516"],"_id":"2f34280f-c061-423c-8e64-adc9f8e12b95-527"}
      {"realm":"/employees","transactionId":"2f34280f-c061-423c-8e64-adc9f8e12b95-529","userId":"id=policyAdmin,ou=user,o=employees,ou=services,dc=openam,dc=forgerock,dc=org","client":{"ip":"127.0.0.1","port":37796},"server":{"ip":"127.0.0.1","port":8989},"http":{"request":{"secure":false,"method":"POST","path":"http://host1.example.com:8989/openam/json/employees/policies","queryParameters":{"_action":["evaluate"]},"headers":{"accept-api-version":["protocol=1.0,resource=2.0"],"host":["host1.example.com:8989"],"user-agent":["Apache-HttpAsyncClient/4.1.2 (Java/1.8.0_151)"],"x-forgerock-transactionid":["7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/2"],"x-forwarded-for":["192.0.2.0"]},"cookies":{}}},"request":{"protocol":"CREST","operation":"ACTION","detail":{"action":"evaluate"}},"timestamp":"2018-05-18T14:32:39.083Z","eventName":"AM-ACCESS-OUTCOME","component":"Policy","response":{"status":"SUCCESSFUL","statusCode":"","elapsedTime":20,"elapsedTimeUnits":"MILLISECONDS","detail":[{"advices":{},"ttl":9223372036854775807,"resource":"http://igApp.example.com:8081/home/pep","actions":{"POST":true,"GET":true},"attributes":{"givenName":["Jane"],"dn":["uid=jdoe,ou=People,dc=example,dc=com"],"isMemberOf":[],"cn":["Jane Doe"]}}]},"trackingIds":["2f34280f-c061-423c-8e64-adc9f8e12b95-516"],"_id":"2f34280f-c061-423c-8e64-adc9f8e12b95-533"}
      
    • DS/OpenDJ ldap-access.audit.json file:
      {"eventName":"DJ-LDAP","client":{"ip":"127.0.0.1","port":40459},"server":{"ip":"127.0.0.1","port":3389},"request":{"protocol":"LDAP","operation":"SEARCH","connId":20,"msgId":24,"dn":"dc=example,dc=com","scope":"sub","filter":"(uid=policyAdmin)","attrs":["dn","uid"]},"transactionId":"7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/1/0","response":{"status":"SUCCESSFUL","statusCode":"0","elapsedTime":1,"elapsedTimeUnits":"MILLISECONDS","nentries":1},"timestamp":"2018-05-18T14:32:39.018Z","_id":"7d2d88aa-26f4-4ca6-a248-0e1486292159-124403"}
      {"eventName":"DJ-LDAP","client":{"ip":"127.0.0.1","port":40460},"server":{"ip":"127.0.0.1","port":3389},"request":{"protocol":"LDAP","operation":"BIND","connId":21,"msgId":24,"version":"3","dn":"uid=policyAdmin,ou=people,dc=example,dc=com","authType":"SIMPLE"},"transactionId":"7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/1/1","response":{"status":"SUCCESSFUL","statusCode":"0","elapsedTime":1,"elapsedTimeUnits":"MILLISECONDS"},"userId":"uid=policyAdmin,ou=people,dc=example,dc=com","timestamp":"2018-05-18T14:32:39.020Z","_id":"7d2d88aa-26f4-4ca6-a248-0e1486292159-124405"}
      {"eventName":"DJ-LDAP","client":{"ip":"127.0.0.1","port":40453},"server":{"ip":"127.0.0.1","port":3389},"request":{"protocol":"LDAP","operation":"SEARCH","connId":18,"msgId":43,"dn":"uid=policyAdmin,ou=people,dc=example,dc=com","scope":"base","filter":"(objectClass=*)","attrs":["inetuserstatus"]},"transactionId":"7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/1/2","response":{"status":"SUCCESSFUL","statusCode":"0","elapsedTime":1,"elapsedTimeUnits":"MILLISECONDS","nentries":1},"timestamp":"2018-05-18T14:32:39.023Z","_id":"7d2d88aa-26f4-4ca6-a248-0e1486292159-124407"}
      {"eventName":"DJ-LDAP","client":{"ip":"127.0.0.1","port":40453},"server":{"ip":"127.0.0.1","port":3389},"request":{"protocol":"LDAP","operation":"SEARCH","connId":18,"msgId":44,"dn":"uid=policyAdmin,ou=people,dc=example,dc=com","scope":"base","filter":"(objectClass=*)","attrs":["inetuserstatus"]},"transactionId":"7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/1/3","response":{"status":"SUCCESSFUL","statusCode":"0","elapsedTime":1,"elapsedTimeUnits":"MILLISECONDS","nentries":1},"timestamp":"2018-05-18T14:32:39.025Z","_id":"7d2d88aa-26f4-4ca6-a248-0e1486292159-124409"}
      {"eventName":"DJ-LDAP","client":{"ip":"127.0.0.1","port":40453},"server":{"ip":"127.0.0.1","port":3389},"request":{"protocol":"LDAP","operation":"SEARCH","connId":18,"msgId":45,"dn":"ou=groups,dc=example,dc=com","scope":"sub","filter":"(&(objectclass=groupOfUniqueNames)(uniqueMember=uid=policyAdmin,ou=people,dc=example,dc=com))","attrs":["dn"]},"transactionId":"7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/2/0","response":{"status":"SUCCESSFUL","statusCode":"0","elapsedTime":1,"elapsedTimeUnits":"MILLISECONDS","nentries":1},"timestamp":"2018-05-18T14:32:39.070Z","_id":"7d2d88aa-26f4-4ca6-a248-0e1486292159-124411"}
      {"eventName":"DJ-LDAP","client":{"ip":"127.0.0.1","port":40453},"server":{"ip":"127.0.0.1","port":3389},"request":{"protocol":"LDAP","operation":"SEARCH","connId":18,"msgId":46,"dn":"ou=groups,dc=example,dc=com","scope":"sub","filter":"(&(objectclass=groupOfUniqueNames)(uniqueMember=uid=policyAdmin,ou=people,dc=example,dc=com))","attrs":["dn"]},"transactionId":"7db465af-c0fc-4713-b1ac-0d2c889ea1b7-27/2/3","response":{"status":"SUCCESSFUL","statusCode":"0","elapsedTime":1,"elapsedTimeUnits":"MILLISECONDS","nentries":1},"timestamp":"2018-05-18T14:32:39.079Z","_id":"7d2d88aa-26f4-4ca6-a248-0e1486292159-124413"}
      {"eventName":"DJ-LDAP","client":{"ip":"127.0.0.1","port":40272},"server":{"ip":"127.0.0.1","port":3389},"request":{"protocol":"LDAP","operation":"SEARCH","connId":16,"msgId":56,"dn":"","scope":"base","filter":"(objectClass=*)","attrs":["1.1"]},"transactionId":"0","response":{"status":"SUCCESSFUL","statusCode":"0","elapsedTime":1,"elapsedTimeUnits":"MILLISECONDS","nentries":1},"timestamp":"2018-05-18T14:32:41.824Z","_id":"7d2d88aa-26f4-4ca6-a248-0e1486292159-124415"}
      {"eventName":"DJ-LDAP","client":{"ip":"127.0.0.1","port":40273},"server":{"ip":"127.0.0.1","port":3389},"request":{"protocol":"LDAP","operation":"SEARCH","connId":17,"msgId":57,"dn":"","scope":"base","filter":"(objectClass=*)","attrs":["1.1"]},"transactionId":"0","response":{"status":"SUCCESSFUL","statusCode":"0","elapsedTime":0,"elapsedTimeUnits":"MILLISECONDS","nentries":1},"timestamp":"2018-05-18T14:32:41.879Z","_id":"7d2d88aa-26f4-4ca6-a248-0e1486292159-124417"}
      
Note

Tracing the journey of a single transaction can be very effective in locating root cause when it's not really possible to go by timestamp alone. For example, if you are experiencing delays with response times, you can now see if a specific user or group of users has any missing attributes that are expected or needs special consideration during AuthN processing of a request.

See Also

How do I configure audit logging via ssoadm in AM (All versions) and OpenAM 13.x?

How do I use the Access log to troubleshoot DS/OpenDJ (All versions)?

Troubleshooting AM/OpenAM and Policy Agents

Troubleshooting DS/OpenDJ

Troubleshooting IG/OpenIG

Related Training

N/A

Related Issue Tracker IDs

N/A


How do I collect debug logs in IG/OpenIG (All versions) for troubleshooting?

The purpose of this article is to provide information on collecting debug logs in IG/OpenIG for troubleshooting. This includes collecting message level SAML logs if you are using IG/OpenIG for SAML federation.

Overview

Logging in IG 5 has changed and is now solely based on a Logback implementation of the Simple Logging Facade for Java® (SLF4J) API. Configurations will require updating if they are based on earlier versions of the product, see IG 5 Release Notes › Important Changes to Existing Functionality for an overview of the logging and other key changes. 

This article covers collecting the following debug logs:

Collecting IG 5 and later logs

The default logging configuration of IG 5 and later is detailed in Gateway Guide › Default Logging Behavior. IG creates log entries on a per-route basis in the $HOME/.openig/logs/ directory and to standard-out at level INFO. Without any additional configuration, a log file called route-system.log is created with entries that cover the startup of IG and the loading of any routes defined in the routes configuration sub-directory.

You can enable capturing entries for a particular route by adding a capture decorator alongside any handlers of interest.

Simple example in the default route

{
  "handler": "ClientHandler",
  "capture": "all"
}

Example Logging output

09:29:49:349 | INFO  | qtp630669831-13 | o.f.o.d.c.C.c.top-level-handler | 

--- (request) id:5c4776e5-22be-4a3d-bee9-6bcc5e5af58e-44 --->

GET http://localhost:8080/examples/servlets/ HTTP/1.1
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
Accept-Encoding: gzip, deflate, sdch, br
Accept-Language: en-US;q=1,en;q=0.9,fr;q=0.8
Cache-Control: max-age=0
Connection: keep-alive
Host: localhost:7070
Upgrade-Insecure-Requests: 1
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/57.0.2987.98 Safari/537.36

09:29:49:356 | INFO  | I/O dispatcher 2 | o.f.o.d.c.C.c.top-level-handler | 

<--- (response) id:5c4776e5-22be-4a3d-bee9-6bcc5e5af58e-44 ---

HTTP/1.1 200 OK
Accept-Ranges: bytes
Content-Length: 5343
Content-Type: text/html
Date: Sun, 09 Apr 2017 21:29:49 GMT
ETag: W/"5343-1357811674000"
Last-Modified: Thu, 10 Jan 2013 09:54:34 GMT
Server: Apache-Coyote/1.1

[entity]

Capturing additional details

To change the default behavior of the CaptureDecorator, either override the default for all routes by adding a customized version in the heap of the config.json file or add an entry to the heap of a specific route, see Configuration Reference › CaptureDecorator. For example:

{
    "name": "capture",
    "type": "CaptureDecorator",
    "config": {
        "captureContext": true,
        "captureEntity": true
    }
}

To change the behavior of the Logback configuration, override the default settings by creating a new logback.xml file in the $HOME/.openig/config/ directory and adjust the logging level in one of the following places:

  • The global level:
      <root level="DEBUG">
        <appender-ref ref="SIFT"/>
        <appender-ref ref="STDOUT"/>
      </root>
    
  • For a specific component:
      <logger name="org.forgerock.openig.handler.ClientHandler" level="DEBUG"/>
    

Once you have reproduced the problem and captured the log output, you may want to revert the captureEntity and captureContext properties to false again and revert the log level to INFO to avoid filling up disk space.

Collecting OpenIG 3.x and 4.x logs

There are two log outputs you should collect for troubleshooting OpenIG: Entity and Context logs. The output from these logs is sent to one of the following depending on your logging configuration:

  • stdout (catalina.out if you are using Apache Tomcat™) - ConsoleLogSink. This is the default logging mechanism.
  • log file - FileLogSink.
Note

OpenIG 4.5 introduced a new option (Slf4jLogSink) to allow you to access all log messages from SLF4J loggers using the Logback implementation of the SLF4J API. See OpenIG 4.5 Gateway Guide › Logging Events in OpenIG and OpenIG 4.5 Configuration Reference › Slf4jLogSink — delegate log writing to SLF4J for further information. This has been replaced in IG 5 with the SLF4J class Logger. See IG 5 Release Notes › Important Changes to Existing Functionality for further information.

You can enable OpenIG to capture these log files as follows:

  1. Update the config.json file (located in the $HOME/.openig/config/ directory) and set the captureEntity and captureContext properties to true for the default CaptureDecorator:
     {
                "name": "capture",
                "type": "CaptureDecorator",
                "config": {
                    "captureEntity": true,
                    "captureContext": true
                }
     }
    
  2. Update the config.json file and set the level to DEBUG for the default ConsoleLogSink or FileLogSink depending on which one you are using:
    • ConsoleLogSink:
       {
                  "name": "LogSink",
                  "type": "ConsoleLogSink",
                  "config": {
                      "level": "DEBUG"
                  }
       }
      
    • FileLogSink:
       {
                  "name": "LogSink",
                  "type": "FileLogSink",
                  "config": {
                      "file": "/tmp/gateway.log",
                      "level": "DEBUG"
                  }
       }
      
  3. Restart OpenIG to apply these changes. The log details are output to stdout or the file you specified. 

Example log output

The following example log shows the type of information you will see in the stdout if the logs have been correctly generated:

INFO: Server startup in 5194 ms
...
------------------------------
THU JUL 07 11:21:02 EST 2016 (DEBUG) {Router}/handler
Added route '05-federate.json' defined in file '/home/suser/.openig/config/routes/05-federate.json'
...
--- (request) exchange:641186666 --->
GET ...

Once you have reproduced the problem and captured the log output, you may want to revert the captureEntity and captureContext properties to false again and revert the log level to INFO to avoid filling up disk space.

Collecting SAML logs

You can enable IG/OpenIG to capture the SAML log file (libSAML2) at message level as follows:

  1. Update the FederationConfig.properties file (located in the $HOME/.openig/SAML directory) and set these two properties as follows:
    com.iplanet.services.debug.level=message 
    com.iplanet.services.debug.directory=$HOME/.openig/SAML/debug
  2. Restart IG/OpenIG to apply these changes. The libSAML2 log file is output to the debug directory you specified.

Once you have reproduced the problem and captured the libSAML2 log file, you may want to revert the com.iplanet.services.debug.level property to error again to avoid filling up the disks where the debug logs are stored. 

See Also

OpenIG 4 Configuration Reference › Decorators › CaptureDecorator

OpenIG 4 Configuration Reference › Logging Framework

Gateway Guide › Logging Events

Gateway Guide › Troubleshooting

Related Training

N/A

Related Issue Tracker IDs

N/A


How do I generate more detailed logs to diagnose an issue in IG (All versions)?

The purpose of this article is to provide strategies for increasing the information contained in the logs when troubleshooting IG issues.

Background information

Since IG 5, log messages in IG and third-party dependencies are recorded using the Logback implementation of the Simple Logging Facade for Java® (SLF4J) API. The default configuration Logback file (logback.xml) logs to both standard-output (usually captured in container specific logs) and to IG route specific log files under the logs directory of the IG base configuration directory.

The default log level is INFO, which can provide some useful feedback when things are not working well but more than likely you will want to increase the logging level for a specific component or the amount of information being captured using the CaptureDecorator.

The Logback implementation provides flexibility for things like log rotation and filtering; these are mentioned in the IG documentation (Gateway Guide › Logging Events) and covered in detail on the Logback site. 

IG Logging Good Practice

Some good practice logging techniques include:

  • Naming all filters and handlers used in a configuration as these then appear in the logs rather than the generic names, which makes it easier to identify the path through a route in a complicated configuration or busy log file.
  • Decorate filters and handlers with the timer decorator as this can help pinpoint possible bottlenecks in the route as it generates start/stop timings in the logs for each component decorated.
  • Enable more targeted logging using the Delegate type to wrap a specific ClientHandler with capture logging or increase the logging level in the Logback logback.xml configuration file.

The last two points are covered in more detail below.

Note

When asked to provide logs by ForgeRock support, the best thing to do is just zip up the whole IG base directory (contains the config and logs directories) as this gives support the logs and the current configuration in one archive.

This article covers the following topics for generating more detailed logs:  

Targeted ClientHandler Logging

Many of the components used in IG make requests to supporting services as part of the work they do, for example, the SingleSignOnFilter making requests to AM to validate a user's single sign on session or the OAuth2ClientFilter calling out to the wellKnownEndpoint of the OAuth2 Issuer.

These requests often happen as part of processing the request that hits IG and before IG makes the request to the proxied application. They all make use of a ClientHandler (or some version of it) when making these requests and will use the default instances created by IG when it starts, unless overridden.

There are three approaches to increasing the details captured in these requests:

  1. Override the default client handler instances with something custom that includes additional logging.
    • The downside of this approach is that every time the default ClientHandler is used, this additional logging will be enabled which might overwhelm the logs; a more targeted approach is often better.
  2. Use the GlobalDecorator to decorate everything within a route with the same capture logging.
    • Similar to the first approach, this may make the logging too verbose but is a simple way to enable/disable additional logging in a single place across the whole route.
  3. Use the Delegate type to target the capture logging for a specific case.

Default client handler

Overriding the default ClientHandler (the name value is the key to overriding the default instance) and adding a capture decorator, either via the heap in the config.json or within a route json file:

    "heap": [
        {
            "name": "ClientHandler",
            "type": "ClientHandler",
            "capture": "all"
        }
    ]

GlobalDecorator

Using the globalDecorators in a route json file:

    {
        "globalDecorators": {
            "capture": "all"
        },
        "handler":

The globalDecorators approach is also a good way to introduce the timer decorator and have it enabled for all components in the route, for example:

{
        "globalDecorators": {
            "timer": true,
            "capture": "all"
        },
        "handler":

Delegate type 

Using the Delegate type to just target a specific handler case. Using this example, all the requests/responses being sent to the AM REST endpoints will be captured:

        {
            "name": "AmService1",
            "type": "AmService",
            "config": {
                "url": "https://host1.example.com/openam",
                "amHandler": {
                    "type": "Delegate",
                    "name": "AmService1Handler",
                    "config": {
                        "delegate": "ForgeRockClientHandler"
                    },
                    "capture": "all"
                }
            }
        }

Custom Capture Decorators

By default, IG provides a CaptureDecorator in the heap called capture that has captureEntity and captureContext both set to false. To enable collecting more detailed information from a handler or a filter then either the default should be overridden or a new CaptureDecorator defined.

For example, overriding the default so that any time it is used it would have this configuration:

"heap": [
    {
        "name": "capture",
        "type": "CaptureDecorator",
        "config": {
          "captureEntity": true,
          "captureContext": true
         }
    },

 or creating a new one named mycapture would be:

"heap": [
    {
        "name": "mycapture",
        "type": "CaptureDecorator",
        "config": {
          "captureEntity": true,
          "captureContext": false
         }
    },

These are then applied as required as shown in the section about targeted ClientHandler logging.

The values used for captureEntity and captureContext are going to depend on your requirements. Often setting "captureEntity": true can be really useful for seeing details being POSTed to a remote endpoint but might be too much information when the response entity is the contents of a web page so selective filtering can be of use when applying the capture decorator.

For example:

"capture": "request"

or

"mycapture": "request"

Increased IG Component Logging

There are cases where seeing some internal state might help show up an issue better than just capturing the request/responses from a ClientHandler. To see more detailed logging from the components that make up IG, one approach is to change the default root logging level from INFO to DEBUG or TRACE for all logging in the Logback logback.xml file:

  <root level="TRACE">
    <appender-ref ref="SIFT"/>
    <appender-ref ref="STDOUT"/>
  </root>

This might be good for a specific use case where a developer is looking at solving a problem on a local setup. However, in an environment where multiple users are hitting IG then the amount of logging generated could become very large so a more targeted approach might be required.

To focus the logging down to a specific sub-package or specific components, keep the root level at INFO and add entries like:

<logger name="org.forgerock.openig.openam" level="TRACE"/>

or to just get TRACE logging on a single component:

<logger name="org.forgerock.openig.openam.AmServiceHeaplet" level="TRACE"/>

Any number of these entries can be included in the logback.xml file; how many depends on the areas of interest.

Increased Apache HTTP Client Component Logging

IG makes use of the Apache™ HTTP Client libraries when making the actual HTTP requests to downstream applications so in some cases, more low-level details of the request/response might be required to understand what IG is sending to/receiving from downstream applications.

To get an idea of the components that can be looked at in this way, see Apache HTTP Logging.

For example, adding the following to the logback.xml file:

<logger name="org.apache.http.headers" level="DEBUG"/>

will generate additional logging with details about any headers in the request from IG and any headers returned in the response, for example:

GET https://accounts.google.com/.well-known/openid-configuration HTTP/1.1
Context's content as JSON:
attributes:

[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 >> GET /.well-known/openid-configuration HTTP/1.1
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 >> Host: accounts.google.com
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 >> Connection: Keep-Alive
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 >> User-Agent: Apache-HttpAsyncClient/4.1.2 (Java/1.8.0_181)
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << HTTP/1.1 200 OK
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << Accept-Ranges: none
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << Vary: Accept-Encoding
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << Content-Type: application/json
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << Access-Control-Allow-Origin: *
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << Date: Mon, 10 Sep 2018 03:57:01 GMT
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << Expires: Mon, 10 Sep 2018 04:57:01 GMT
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << Last-Modified: Wed, 05 Sep 2018 23:58:28 GMT
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << X-Content-Type-Options: nosniff
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << Server: sffe
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << X-XSS-Protection: 1; mode=block
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << Age: 916
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << Cache-Control: public, max-age=3600
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << Alt-Svc: quic=":443"; ma=2592000; v="44,43,39,35"
[I/O dispatcher 27] DEBUG org.apache.http.headers - http-outgoing-11 << Transfer-Encoding: chunked
[I/O dispatcher 27] INFO  o.f.o.d.c.C.capture.IssuerDelegate - 

Like the IG component logging examples above, the granularity of the logging can be increased or decreased by adjusting the package level used in the logger name entry and any number of these entries can be included in the logback.xml file; how many depends on the areas of interest.

Note

Depending on the Apache component being targeted and the logging level selected (DEBUG versus INFO), the amount of extra information in the logs could be quite high so not something recommended on a production system unless trying to track down a very specific issue. To get an idea of the results to expect, experiment with this on a dev/test environment first.

See Also

Troubleshooting IG/OpenIG

Configuration Reference › Decorators

Gateway Guide › Default Logging Behavior

Gateway Guide › Changing the Logging Behavior

Logback Details

Related Training

N/A

Related Issue Tracker IDs

N/A


How do I filter information included in capture logs in IG (All versions) and OpenIG 4.5?

The purpose of this article is to provide information on filtering the IG/OpenIG capture logs to determine what information is logged. Filtering allows you to hide sensitive information in the logs such as passwords.

Background Information

IG/OpenIG logs everything contained in the entity by default, which means filtering is required if you have requests or responses that contain sensitive information such as passwords.

OpenIG 4.5 introduced a new logger based on SLF4J, which provides a lot of flexibility around logging; this includes a regex pattern swapping function: replace(p){r, t}, which can be used to mask information in the logs: Logback Layouts › Replace.

Note

Using the replace(p){r, t} function will increase the logging overhead as IG/OpenIG will have to parse the entire message; you should only apply it to selective routes where you need this feature rather than to all routes.

Filtering information

You can include the replace(p){r, t} function in the pattern section of the logback.xml file in the IG/OpenIG configuration directory, which by default is $HOME/.openig/config/.

The following example demonstrates using this function to replace passwords (this example is based on the default ConsoleAppender in the logback.xml file):

  <encoder>
   <pattern>%nopex[%thread] %highlight(%-5level) %boldWhite(%logger{35}) - %replace(%message){'"X-OpenIDM-Password": ".*"', '"X-OpenIDM-Password": "xxx"'} %n%highlight(%rootException{short})
   </pattern>
  </encoder>

You can also nest replace calls, for example:

%replace(%replace(%message){'regex1', 'replacement1'}){'regex2', 'replacement2'}

You can use websites such as Online Regex Tester to test your regular expressions for any other replacement changes you want to include.

See Also

How do I collect debug logs in IG/OpenIG (All versions) for troubleshooting?

OpenIG 4.5 Release Notes › New Features

IG 5 Release Notes › Important Changes to Existing Functionality

Gateway Guide › Logging Events

Gateway Guide › Reference Logback Configuration

Related Training

N/A

Related Issue Tracker IDs

N/A


How do I create a HAR file for troubleshooting IG/OpenIG (All versions)?

The purpose of this article is to provide information on creating a HAR file (HTTP ARchive) for troubleshooting IG/OpenIG.

Overview

A HAR file is output by browser developer tools and other browser extensions. It is essentially a recording of interactions between the browser and application in JSON format; it can be very useful for troubleshooting as it can help identify where the issue is occurring.

Note

The equivalent file in Internet Explorer® 9, 10 and 11 is an XML file based on the HTTP Archive. 

Creating a HAR file

You can create a HAR file as follows:

Chrome™ browser

  1. Launch the Developer Tools in Chrome and select the Network tab.
  2. Enter the URL where you have been experiencing issues and re-create the issue. Do not open a new browser tab as Chrome records details on the tab initially shown when the Developer Tools were launched.
  3. Right-click within the Network window and select the Save as HAR with content option.

Firefox browser

  1. Launch the Developer Tools in Firefox and select the Network option.
  2. Select the Persist Logs option on the Network tab to ensure the entire request is saved, even if you are redirected.
  3. Enter the URL where you have been experiencing issues and re-create the issue. 
  4. Right-click within the Network window and select the Save All As HAR option.

Microsoft® Edge

  1. Launch the Developer Tools in Internet Explorer and select the Network tab.
  2. Click the green play button to start recording.
  3. Enter the URL where you have been experiencing issues and re-create the issue. Do not open a new browser tab as Internet Explorer records details on the tab initially shown when the Developer Tools were launched.
  4. Click the Save button to save the HAR file.

Creating an XML file (Internet Explorer 9, 10 and 11)

You can create an XML file based on the HTTP Archive format as follows:

  1. Launch the Developer Tools in Internet Explorer and select the Network tab.
  2. Click the Start Capturing button.
  3. Enter the URL where you have been experiencing issues and re-create the issue.
  4. Click the Save button and choose to save the file as XML.

See Also

Troubleshooting IG/OpenIG

Related Training

N/A

Related Issue Tracker IDs

N/A


How do I enable Garbage Collector (GC) Logging for IG/OpenIG (All versions)?

The purpose of this article is to provide information on enabling GC Logging for IG/OpenIG. It assumes that you already have a working IG/OpenIG server installed.

Enabling GC Logging

The information given here is specific to the Apache Tomcat™ web container; you should make similar changes in the configuration file specific to your web container if you use a different one.

Note

You should ensure there is enough disk space for the GC logs; if not, you should enable GC log rotation as well by including the following options when you enable GC logging: -XX:+UseGCLogFileRotation, -XX:NumberOfGCLogFiles=n, -XX:GCLogFileSize=n

On Unix® and Linux® systems:

​You should enable GC logging by specifying CATALINA_OPTS settings in the setenv.sh file (typically located in the /tomcat/bin/ directory). If this file doesn't exist, you should create it in the same directory as the catalina.sh file (also typically located in the /tomcat/bin/ directory).

To enable GC logging:

  1. Add the following line to the setenv.sh file:
    export CATALINA_OPTS="$CATALINA_OPTS -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCCause -Xloggc:[filename]"
    replacing [filename] with the path to the file that you would like to create to store the log file.
  2. Restart the web container.

Once the web container has successfully restarted, there should be a GC log file located in the directory specified in the -Xloggc: option. You can use the Universal GC Log Analyzer to analyze your GC log. This is a third-party website that we suggest can be used for analysis but is not supported by ForgeRock.

On Microsoft® Windows® systems:

​You should enable GC logging by specifying CATALINA_OPTS settings in the setenv.bat file (typically located in the /tomcat/bin/ directory). If this file doesn't exist, you should create it in the same directory as the catalina.bat file (also typically located in the /tomcat/bin/ directory).

To enable GC logging:

  1. Add the following line to the setenv.bat file:
    set CATALINA_OPTS=-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCCause -Xloggc:[filename]
    replacing [filename] with the path to the file that you would like to create to store the log file.
  2. Restart the web container.

Once the web container has successfully restarted, there should be a GC log file located in the directory specified in the -Xloggc: option. You can use the Universal GC Log Analyzer to analyze your GC log. This is a third-party website that we suggest can be used for analysis but is not supported by ForgeRock.

See Also

Best practice for JVM Tuning

How do I change the JVM heap size for IG/OpenIG (All versions)?

How do I collect JVM data for troubleshooting IG/OpenIG (All versions)?

How do I use the msnapshots script to capture information for troubleshooting IG/OpenIG (All versions)?

Setup and Maintenance Guide › Maintaining an Instance › Tuning Java Virtual Machine Settings

Related Training

N/A

Related Issue Tracker IDs

N/A


How do I collect JVM data for troubleshooting IG/OpenIG (All versions)?

The purpose of this article is to provide information on collecting JVM data for troubleshooting IG/OpenIG. JVM data (such as stack traces, heap histograms and heap dumps) can be very useful for troubleshooting issues such as a hung IG/OpenIG server, Out of Memory errors and suspected memory leaks. This data must be collected before killing the affected process or restarting the server; otherwise the information relating to the affected process is lost forever, which may make it impossible to identify the root cause.

Collecting JVM data

Note

The following utilities are all JDK utilities and are not included with the JRE; you must have the JDK installed in your production environments in order to collect this data. Additionally, you must be the owner of the identified process to be able to collect this data.

To collect JVM data, you must first determine the process ID of the hung web container instance using the following command:

$ jps -v

You can then collect the following types of data:

Stack Traces

Stack traces allow us to see what is happening with JVM threads and are sometimes referred to as thread dumps. You should collect several different stack traces (minimum of three) at roughly one minute intervals to enable us to compare them. It is recommended that you also identify the threads associated with the process ID for troubleshooting high CPU as detailed in How do I find which thread is consuming CPU in a Java process in IG/OpenIG (All versions)?

You can use the following commands to collect stack traces:

  • You can collect long listing stack traces using the jstack command:
    $ jstack -F -l [pid] > [outputfile.txt]
    replacing [pid] with the process ID of the hung container instance and [outputfile.txt] with the output file for the stack trace.
  • You can use the kill -3 command (Unix® and Linux® systems only), which consistently produces better results:
    $ kill -3 [pid]
    replacing [pid] with the process ID of the hung container instance.

The kill -3 command outputs the stack trace to the log file where the standard output is directed (typically the web container log file). The kill -3 command does not stop the running process; it will continue to run after outputting the stack trace.

You can use the Java Thread Dump Analyzer to analyze your stack traces. This is a third-party website that we suggest can be used for analysis but is not supported by ForgeRock.

Heap Histograms

Heap histograms enable us to visualize the objects in the JVM heap - we are only interested in live objects. You can collect heap histograms using the jmap command:

$ jmap -histo:live [pid]

replacing [pid] with the process ID of the hung container instance.

Caution

The jmap utility must come from the same version of JVM that the container is running.

Heap Dumps

Heap dumps allow us to see what is happening with memory at the point the heap dump is taken, which can help us to identify high memory usage issues or memory leaks. You should collect heap dumps as close in time to the stack traces as possible to enable us to compare the contents. You can collect heap dumps using the jmap command:

$ jmap -F -dump:file=[target file] [pid]

replacing [target file] with the output file for the heap dump and [pid] with the process ID of the hung container instance.

Current JVM settings

You can find the current JVM settings for the server using one of the following commands (the jinfo command is the preferred way):

  • jinfo:
    $ jinfo [pid]
    replacing [pid] with the required process ID.
  • jps:
    $ jps -v

For Unix® and Linux® systems where AM/OpenAM is running on an Apache Tomcat™ web container, you can also use: 

$ ps -ef | grep tomcat

See Also

How do I use the msnapshots script to capture information for troubleshooting IG/OpenIG (All versions)?

How do I change the JVM heap size for IG/OpenIG (All versions)?

How do I enable Garbage Collector (GC) Logging for IG/OpenIG (All versions)?

How do I collect debug logs in IG/OpenIG (All versions) for troubleshooting?

Troubleshooting IG/OpenIG

Related Training

N/A

Related Issue Tracker IDs

N/A


Performance tuning


How do I change the JVM heap size for IG/OpenIG (All versions)?

The purpose of this article is to provide information on changing the JVM heap size for IG/OpenIG. This article provides details for changing the JVM heap size on Linux®, Unix® and Windows® systems.

Changing the JVM heap size

Changing the JVM heap size can improve performance and reduce the time it takes to process HTTP requests and responses. You should try different heap sizes to see what impact it has to determine the best heap size for your setup. The information given here is specific to the Apache Tomcat™ web container; you should make similar changes in the configuration file specific to your web container if you use a different one.

Note

It is recommended that you set the minimum and maximum heap sizes to the same value for best performance. Otherwise, the JVM runs a full Garbage Collector (GC) cycle when increasing its heap, during which time it can pause ongoing operations for up to a few seconds. Generally, a smaller heap will increase the frequency at which the JVM GC executes but reduce the duration; similarly, a larger heap will reduce the frequency and increase the duration. When tuning the JVM heap, the goal is to strike a balance between frequency and duration so as to reduce the impact of the GC on the application.

On Unix® and Linux® systems:

You can set the JVM heap size by specifying CATALINA_OPTS settings in the setenv.sh file (typically located in the /tomcat/bin/ directory). If this file doesn't exist, you should create it in the same directory as the catalina.sh file (also typically located in the /tomcat/bin/ directory).

For example, to set the minimum and maximum heap sizes to 2GB, you would add the following line to the setenv.sh file and restart the web container:

export CATALINA_OPTS="$CATALINA_OPTS -Xms2048m -Xmx2048m"

On Microsoft® Windows® systems:

Providing you haven't installed Tomcat as a service, you can set the JVM heap size by specifying CATALINA_OPTS settings in the setenv.bat file (typically located in the /tomcat/bin/ directory). If this file doesn't exist, you should create it in the same directory as the catalina.bat file (also typically located in the /tomcat/bin/ directory).

For example, to set the minimum and maximum heap sizes to 2GB, you would add the following line to the setenv.bat file and restart the web container:

set CATALINA_OPTS=-Xms2048m -Xmx2048m

If you have installed Tomcat as a service on Windows, then you must use the GUI application to configure Tomcat services. This process refers to Tomcat 7, but will work for other versions by changing tomcat7w.exe in the command to match your version.

  1. Stop the Tomcat service.
  2. Navigate to \path\to\tomcat\bin\ from the command prompt:
  3. Enter the following command to display Tomcat Properties:
    tomcat7w.exe //ES//serviceName
    Where serviceName is the name of your Tomcat service.
  4. Navigate to the Java tab and complete the memory pool fields as follows:
    Initial memory pool: 2048
    Maximum memory pool: 2048
  5. Restart the Tomcat service.

Alternatively, Windows system administrators may prefer to configure these options in the registry so that they may be configured via group policy. The initial memory pool and maximum memory pool values can be configured in the JvmMS and JvmMX properties under the following registry key for Tomcat 7:

HKEY_LOCAL_MACHINE\SOFTWARE\Wow6432Node\Apache Software Foundation\Procrun 2.0\Tomcat7\Parameters\Java

See Also

Best practice for JVM Tuning

How do I enable Garbage Collector (GC) Logging for IG/OpenIG (All versions)?

How do I collect JVM data for troubleshooting IG/OpenIG (All versions)?

How do I use the msnapshots script to capture information for troubleshooting IG/OpenIG (All versions)?

Setup and Maintenance Guide › Tuning Java Virtual Machine Settings

Related Training

N/A

Related Issue Tracker IDs

N/A


Best practice for JVM Tuning

The purpose of this article is to provide best practice advice on JVM tuning ; including key symptoms, understanding heap space and GC logs. This best practice advice applies to AM/OpenAM, DS/OpenDJ, IDM/OpenIDM and IG/OpenIG. JVM tuning is not an exact science and will vary across individual environments and applications. Consistent load and stress testing of your environment will be the only true way to gauge the effect of changes made.

JVM tuning considerations

Before you begin JVM tuning, you should consider the following points:

  • Costs - depending on your environments, it may be more cost effective to add more hardware to improve performance rather than spending the time to tune.
  • Desired outcome - tuning for stability is more important in the long run than tuning for performance, although there is an overlap.
  • Ongoing problems - tuning may only delay or mask a problem temporarily if there is an underlying issue you need to resolve.
  • Memory leaks - these will always cause Garbage Collection (GC) issues regardless of tuning.

What is Java® heap and how do I know it needs tuning?

The Java heap is the amount of memory allocated to applications running in the JVM. Objects in heap memory can be shared between threads. Garbage collection (GC) refers to the automatic process of managing the runtime memory. The JVM is subject to GC pauses that vary in frequency and duration; if these pauses become more frequent and/or last longer, you will see issues (such as application pauses) which indicate that you may need to tune your Java heap. The heap is initially created when the JVM starts and is split into different spaces or generations, the key ones being Young (Eden or Nursery) and Tenured (Old):

  • The Young generation is used for new objects. A GC process (ParNew) automatically runs when it becomes full which removes unused objects and moves all objects that have lived long enough to the Tenured generation, thereby freeing up space in the Young generation for more new objects. Typically objects in the Young generation are short lived and temporary. The Young generation is small but active and GC happens frequently but with limited impact on performance.
  • The Tenured generation is used for the longer lived objects. Another GC process (CMS) runs when it becomes full to remove any unused objects. The Tenured generation is larger and less active than the Young generation but GC tends to have more impact on performance.

The following diagram illustrates the heap and also the corresponding GC options that can be set in (Java 7 and earlier):

Key symptoms that indicate you need to tune your Java heap are:

  • High CPU usage. When GC threads consume a lot of CPU, you will see spikes in overall CPU usage.
  • Application hangs. When your application appears to hang and stops responding, there are gaps in your log files or you experience general slowness when performing routine tasks, poorly tuned GC can be the cause.

The first thing to check if you experience these symptoms is your GC logs; this are easy to check and may help you identify your issue quickly.

GC Logging

There are various different GCs available; ForgeRock recommends the use of CMS (ConcurrentMMarkSweep), which is a throughput collector and tends to give the best performance as it runs concurrently with the application, meaning less pauses. You should specify this collector by setting the following JVM option:

-XX:+UseConcMarkSweepGC

You can enable GC logging as described in the following articles:

Note

Typically you can leave GC logging on without impacting your system, however, you can just enable it when you are experiencing issues.

Understanding GC Logs

These example log files come from a CMS collector, where ParNew refers to the Young generation and CMS refers to the Tenured generation. These log file examples also show typical GC logs for a system where tuning is appropriate.

ParNew section

An example GC log output for the ParNew section looks like this:

24.245: [GC24.245: [ParNew: 545344K->39439K(613440K), 0.0424360 secs] 594671K->88767K(4101632K), 0.0426850 secs] [Times: user=0.17 sys=0.00, real=0.04 secs] 
29.747: [GC29.747: [ParNew: 584783K->27488K(613440K), 0.0889130 secs] 634111K->104723K(4101632K), 0.0892180 secs] [Times: user=0.24 sys=0.01, real=0.09 secs]

Each line in this log file represents one GC and shows the following types of information for ParNew:

  • Timestamp information - if you did not set the PrintGCTimeStamps and PrintGCDateStamps options, this just shows as the number of seconds from JVM startup:
    24.245: [GC24.245:
    29.747: [GC29.747:
    This information is useful as it shows the frequency of GCs. You should be aiming for GCs to occur once every 1 to 5 seconds; if they are occurring more than once a second, you need to tune your JVM and it is likely that you will be seeing high CPU usage.
  • Young generation information:
    [ParNew: 545344K->39439K(613440K), 0.0424360 secs] 
    [ParNew: 584783K->27488K(613440K), 0.0889130 secs]
    This information shows the initial size of the Young space before doing the GC, the size after doing the GC, the total size available and the time it took to do the GC. If the time taken to do the GC is large, that is more than 0.1 seconds, then it is possible that your Young generation heap size is too big. The total size available will not grow if you set NewSize and MaxNewSize to the same value and this is what you want to see in your logs.
  • Overall heap information:
    594671K->88767K(4101632K), 0.0426850 secs]
    634111K->104723K(4101632K), 0.0892180 secs]
    This information shows initial size of the overall heap before doing the GC, the size after doing the GC and the total size available. With the second lot of figures (size after doing the GC), you can see how this incrementally grows up to the point when the GC is done and then reduces back down to a baseline figure. If you have a memory leak, you will see the baseline figure growing incrementally as it becomes increasingly full even after doing GC.
  • System information:
    [Times: user=0.17 sys=0.00, real=0.04 secs] 
    [Times: user=0.24 sys=0.01, real=0.09 secs]
    This information shows how much time was spent in user space, how much time spent in kernel or system space and what was the real impact to the user. If the user time is high, it indicates there isn't enough CPU for the number of user threads. If the system time is high, it indicates your system is swapping memory to disk which means that there isn't enough physical memory for your heap size.

CMS section

The CMS section of the log file is different to the ParNew section as it shows multiple lines for the same GC. An example GC log output for the CMS section looks like this:

40.146: [GC [1 CMS-initial-mark: 26386K(786432K)] 26404K(1048384K), 0.0074495 secs]
40.154: [CMS-concurrent-mark-start]
40.683: [CMS-concurrent-mark: 0.521/0.529 secs]
40.683: [CMS-concurrent-preclean-start]
40.701: [CMS-concurrent-preclean: 0.017/0.018 secs]
40.704: [GC40.704: [Rescan (parallel) , 0.1790103 secs]40.883: [weak refs processing, 0.0100966 secs] [1 CMS-remark: 26386K(786432K)] 52644K(1048384K), 0.1897792 secs]
40.894: [CMS-concurrent-sweep-start]
41.020: [CMS-concurrent-sweep: 0.126/0.126 secs]
41.020: [CMS-concurrent-reset-start]
41.147: [CMS-concurrent-reset: 0.127/0.127 secs]

This log shows the different phases the GC goes through. All the ones marked concurrent are happening while your application is running and therefore have little impact. The ones that don't say concurrent are stopping your application from running temporarily and therefore can have an impact. The CMS-initial-mark and CMS-remark show heap sizing details.

Note

Typically, you will see these sections intermingled, for example, some ParNews then a CMS, some more ParNews, another CMS and so on as the GC processes automatically occur to manage the heap.

Common issues shown in the GC logs and solutions

This section identifies common issues you might find in your GC logs and how you can resolve them. You can also use the Universal GC Log Analyzer to analyze your GC log. This is a third-party website that we suggest can be used for analysis but is not supported by ForgeRock.

Young generation - too small

The following log snippet shows an issue where the Young generation heap size is too small:

1.813: [GC1.813: [ParNew: 1152K­>128K(1152K), 0.0008100 secs] 16620K­->15756K(26936K), 0.0008350 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.816: [GC1.816: [ParNew: 1152K­>128K(1152K), 0.0006430 secs] 16780K­->15913K(26936K), 0.0006640 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
1.819: [GC1.819: [ParNew: 1152K­>128K(1152K), 0.0005370 secs] 16937K-­>16038K(26936K), 0.0005570 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

As you can see, there are multiple GCs occurring within a second. This means you need to increase the size of the Young generation (NewSize and MaxNewSize) and may also need to increase total heap size to compensate for this change (Xms and Xmx). Alternatively you could change the NewRatio option (this is set to 2 by default, which means the Tenured generation heap is twice as big as the Young generation heap or that the Young generation heap is a 1/3 of the size of the Tenured generation heap).

Young generation - too large / Tenured generation - too small

The following log snippet shows an issue where the Young generation heap size is too large and consequently the Tenured generation heap size is too small:

276.716: [GC (CMS Initial Mark) [1 CMS-initial-mark: 104176K(135168K)] 2758985K(6741248K), 0.8762860 secs] [Times: user=0.88 sys=0.00, real=0.88 secs] 
277.592: [CMS-concurrent-mark-start]
277.657: [CMS-concurrent-mark: 0.063/0.065 secs] [Times: user=0.12 sys=0.00, real=0.06 secs] 
277.657: [CMS-concurrent-preclean-start]
277.658: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
277.658: [CMS-concurrent-abortable-preclean-start]
277.658: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
277.658: [GC (CMS Final Remark)[YG occupancy: 2657419 K (6606080 K)]277.658: [Rescan (parallel) , 0.9815460 secs]278.639: [weak refs processing, 0.0000320 secs]278.640: [scrub string table, 0.0011700 secs] [1 CMS-remark: 104176K(135168K)] 2761595K(6741248K), 0.9828250 secs] [Times: user=7.18 sys=0.09, real=0.99 secs] 
278.641: [CMS-concurrent-sweep-start]
278.668: [CMS-concurrent-sweep: 0.026/0.027 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 
278.668: [CMS-concurrent-reset-start]
278.668: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
280.673: [GC (CMS Initial Mark) [1 CMS-initial-mark: 104079K(135168K)] 2774091K(6741248K), 0.9033730 secs] [Times: user=0.90 sys=0.00, real=0.90 secs] 
281.577: [CMS-concurrent-mark-start]
281.640: [CMS-concurrent-mark: 0.063/0.063 secs] [Times: user=0.13 sys=0.00, real=0.07 secs] 
281.640: [CMS-concurrent-preclean-start]
281.641: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
281.641: [CMS-concurrent-abortable-preclean-start]
281.641: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
281.641: [GC (CMS Final Remark)[YG occupancy: 2670011 K (6606080 K)]281.641: [Rescan (parallel) , 0.9914290 secs]282.633: [weak refs processing, 0.0000110 secs]282.633: [scrub string table, 0.0008100 secs] [1 CMS-remark: 104079K(135168K)] 2774091K(6741248K), 0.9923100 secs] [Times: user=7.14 sys=0.11, real=0.99 secs] 
282.634: [CMS-concurrent-sweep-start]
282.659: [CMS-concurrent-sweep: 0.024/0.025 secs] [Times: user=0.06 sys=0.01, real=0.02 secs] 
282.659: [CMS-concurrent-reset-start]
282.659: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

As you can see, the CMS collections are occurring too frequently, without any ParNew collections in between. This is a result of the Young generation heap size being too large so that each time a ParNew collection happens, the Tenured heap size instantly becomes full and a CMS collection runs. This could happen if you increased your Young generation heap size without increasing your total heap size. This log snippet could also happen if you have memory leaks.

CMS failure

The following log snippet shows a CMS failure (concurrent mode failure):

(concurrent mode failure): 1551948K->1548050K(1572864K), 15.1154540 secs] 1986510K->1548050K(2044736K), [CMS Perm : 78597K->78588K(524288K)], 15.4406700 secs] [Times: user=15.52 sys=0.00, real=15.44 secs] 
703240.983: [GC [1 CMS-initial-mark: 1548050K(1572864K)] 1561545K(2044736K), 0.0059690 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

This error means that the CMS collector cannot keep up with the amount of garbage being generated (the Tenured generation heap space is about 90% full) and GCs are taking longer meaning your application stops for longer periods of time. This example shows the application stopping for over 15 seconds, which will have a significant impact on performance.

You can add the following GC options to try to avoid the CMS failure:

  • -XX:CMSInitiatingOccupancyFraction=<percentage-of-tenured> 
  • -XX:+UseCMSInitiatingOccupancyOnly

You should set -XX:CMSInitiatingOccupancyFraction to 70 or 80% (instead of default ~90%) which may enable the CMS collector to keep up with the amount of garbage being generated.

Full GC

The following log snippet shows a Full GC:

25.466: [Full GC )25.466: [CMS: 68756K­>75361K(1987392K), 0.2548820 secs] 96571K­->75361K(2064064K), [CMS Perm : 61069K­>60722K(61376K)], 0.2551850 secs] [Times: user=0.25 sys=0.01, real=0.25 secs]
26.185: [Full GC (System.gc())26.185: [CMS: 75361K­>73283K(1987392K), 0.2398450 secs] 76136K-­>73283K(2064064K), [CMS Perm : 60723K­>60723K(101204K)], 0.2400120 secs] [Times: user=0.24 sys=0.00, real=0.24 secs]
27.293: [Full GC (System.gc())27.293: [CMS: 73283K­>73291K(1987392K), 0.2111960 secs] 74096K­>73291K(2064064K), [CMS Perm : 60723K­>60723K(101396K)], 0.2112730 secs] [Times: user=0.21 sys=0.00, real=0.22 secs]
68.081: [Full GC (Heap Inspection Initiated GC)68.081: [CMS: 73291K­->73187K(1987392K), 0.2172670 secs] 77634K­>73187K(2064064K), [CMS Perm : 60742K­>60742K(101396K)], 0.2174520 secs] [Times: user=0.22 sys=0.00, real=0.21 secs]

These log snippets refer to Full GCs occurring, meaning that the entire heap is being cleared (Young and Tenured); this often happens due to system processes such as RMI which performs a Full GC every hour on the hour. The PrintGCCause option is very useful to help you find out why the GC is happening (the last three lines in the log above show the additional information output by this option, making it clear which ones are system related). You can also set the DisableExplicitGC option to prevent system related Full GCs from happening.

Permanent generation 

Note

The following information does not apply to Java 8 since the Permanent generation space has been removed.

The following log snippet shows a Full GC as a result of the Permanent generation space growing (the Permanent generation space contains metadata and other data that should be permanently stored and does not typically grow):

1.241: [Full GC (Ergonomics) [PSYoungGen: 6125K­>0K(45056K)] [ParOldGen: 17659K­->20350K(20480K)] 23785K­>20350K(65536K) [PSPermGen: 13550K­->13546K(27136K)], 0.0531680 secs] [Times: user=0.25 sys=0.00, real=0.05 secs]
1.513: [Full GC (Ergonomics) [PSYoungGen: 38912K­>2783K(45056K)] [ParOldGen: 20350K­>20424K(20480K)] 59262K­>23208K(65536K) [PSPermGen: 15188K­->15188K(31744K)], 0.0992090 secs] [Times: user=0.65 sys=0.02, real=0.10 secs]

These log snippets show the Permanent generation space growing (figure in brackets after PSPermGen). You can increase the MaxPermSize option to resolve this issue.

Best practice advice on tuning

Initially, you should configure your JVM as per the recommended settings for your product (if available):

You can then tune your JVM as and when required.

You should always follow this basic process when tuning:

  1. Establish a baseline using a valid load testing process. This step is essential as it is the only way you will know if your tuning is having the desired effect.
  2. Change one thing at a time and document each change. This allows you to determine the impact of each change and revert if necessary.

Heap tuning guidelines

Although we cannot give recommended heap settings because they vary considerably between environments and applications, you should follow these guidelines when tuning:

  • You should always use the latest supported software versions.
  • You should use the CMS GC as recommended by ForgeRock.
  • Your total heap size must not exceed the amount of physical RAM available.
  • You must leave some physical RAM for other applications to run on your machine.
  • You should set Xms and Xmx to the same value for best performance. These options determine your total heap size.
  • You should set NewSize and MaxNewSize to the same value. These options determine how the heap is allocated between generations.
  • You should set the DisableExplicitGC option to prevent system related full GCs from running.
  • You must not add lots of options at once or add options you don't understand.
  • You must not copy and paste options from other applications.
  • You should use GC logs to help identify issues with your tuning.

Getting your total heap size and allocation between generations right is key; once you have these set correctly, you likely won't need to do anymore tuning.

Summary

In summary, the most important GC knobs to get right are:

  1. The collector, which should be CMS.
  2. The total heap size, where Xmx = Xms.
  3. The split between generations, using NewSize or NewRatio, where NewSize = MaxNewSize.

See Also

Java Platform, Standard Edition HotSpot Virtual Machine Garbage Collection Tuning Guide

AM/OpenAM

How do I change the JVM heap size for AM/OpenAM (All versions)?

FAQ: AM/OpenAM performance and tuning

How do I collect JVM data for troubleshooting AM/OpenAM (All versions)?

How do I diagnose a hung AM/OpenAM (All versions) server?

How do I troubleshoot high CPU utilization on AM/OpenAM (All versions) servers?

How do I find which thread is consuming CPU in a Java process in AM/OpenAM (All versions)?

How do I use the msnapshots script to capture information for troubleshooting AM/OpenAM (All versions)?

DS/OpenDJ

How do I tune DS/OpenDJ (All versions) process sizes: JVM heap and database cache?

FAQ: DS/OpenDJ performance and tuning

How do I collect JVM data for troubleshooting DS/OpenDJ (All versions)?

How do I troubleshoot high CPU utilization on DS/OpenDJ (All versions) servers?

How do I find which thread is consuming CPU in a Java process in DS/OpenDJ (All versions)?

How do I use the msnapshots script to capture information for troubleshooting DS/OpenDJ (All versions)?

IDM/OpenIDM

How do I change the JVM heap size for IDM/OpenIDM (All versions)?

FAQ: IDM/OpenIDM performance and tuning

How do I collect JVM data for troubleshooting IDM/OpenIDM (All versions)?

How do I troubleshoot high CPU utilization on IDM/OpenIDM (All versions) servers?

How do I find which thread is consuming CPU in a Java process in IDM/OpenIDM (All versions)?

How do I use the msnapshots script to capture information for troubleshooting IDM/OpenIDM (All versions)?

IG/OpenIG

How do I change the JVM heap size for IG/OpenIG (All versions)?

How do I collect JVM data for troubleshooting IG/OpenIG (All versions)?

How do I troubleshoot high CPU utilization or Out of Memory errors on IG/OpenIG (All versions) servers?

How do I find which thread is consuming CPU in a Java process in IG/OpenIG (All versions)?

How do I use the msnapshots script to capture information for troubleshooting IG/OpenIG (All versions)?

Related Training

ForgeRock Directory Services Core Concepts

Related Issue Tracker IDs

OPENAM-4414 (Apache Policy Agent does not complete cleanup / logout)

OPENIDM-1563 (Task scanner creates a new thread pool for each execution resulting in a thread leak.)


Copyright and TrademarksCopyright © 2018 ForgeRock, all rights reserved.

This content has been optimized for printing.

Loading...