How To

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

Last updated Oct 23, 2018

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



Copyright and TrademarksCopyright © 2018 ForgeRock, all rights reserved.
Loading...