Introduction to OpenIG (Part 4: Troubleshooting)

As transformations are dictated by the set of filters/handlers in your configuration, they are not always trivial, it's becoming very important quickly to capture the messages at different phases of the processing.

See the flow

First thing to understand when trying to debug a configuration is "where the hell are all my messages going ?" :)

This is achievable simply by activating DEBUG traces in your LogSink heap object:

When the DEBUG traces are on, you should see something like:

You'll see a new line each time an Exchanges comes into a Handler/Filter and each time it's flowing out of the element (you also get a performance measurement).

Capture the messages (requests/responses)

OpenIG provides a simple, way to see the HTTP message (being a request or a response), including both headers and (optionaly) the entity (if that's a textual content): the CaptureFilter.

Here is an output example you can obtain when you install a CaptureFilter:

Install a CaptureFilter

Being a filter, it has to be installed as part of a Chain:

It is usually best placed either as the OpenIG entry point (the first element to be invoked), that helps to see what the User-Agent sends and receives (as it's perceived by OpenIG) or just before a ClientHandler (that represents a sort of endpoint, usually your protected application).

Capture what you want

CaptureFilter is sufficient for simple capturing needs. When what you want to observe is not contained in the HTTP message, we have to use the OpenIG swiss-knife: ScriptableFilter.

This is a special filter that allows you to execute a Groovy script when traversed by an Exchange.

Here is a sample script that prints the content of the Exchange's session:

Copy this script into ~/.openig/scripts/groovy/PrintSessionFilter.groovy and configure your heap object:

Seeing the messages on wire

Sometimes, all of the previous solutions are not applicable, because you want to see the on-wire message content (as opposed to modelled by OpenIG).

For this case, the only solution is to start your OpenIG with a couple of system properties that will activate deep traces of the http client library we're using: Apache HTTP Client.

>$ bin/catalina.sh -Dorg.apache.commons.logging.Log=org.apache.commons.logging.impl.SimpleLog 
                   -Dorg.apache.commons.logging.simplelog.log.httpclient.wire=debug 
                   -Dorg.apache.commons.logging.simplelog.log.org.apache.commons.httpclient=debug 
                   run

See the HTTP Client Logging page for more informations.

Next

In the next post we'll explain how routes can speed-up your configuration preparation.

Rotating debug logs

Since OpenAM 10.0.0 it is possible to enable time based debug log rotation in order to make your log files a bit more managable. Time based as in the logs will be rotated periodically after a configurable amount of time has passed.
Now the problem with debug logs is that they get written to in the very early phase of the startup process: just think about the fact that an error can occur already while trying to connect to the configuration store. This means that to store the rotation config, we can’t actually use the service config system, as by the time those settings get loaded, files are already written. To overcome this problem, instead, you need to modify/create files in the WAR file to make these configurations accessible for startup as well.
To enable debug log rotation, you need to create/modify the WEB-INF/classes/debugconfig.properties file:

org.forgerock.openam.debug.prefix=mylogs-
org.forgerock.openam.debug.suffix=-MM.dd.yyyy-kk.mm
org.forgerock.openam.debug.rotation=

The properties in detail:

  • org.forgerock.openam.debug.prefix (optional): an arbitrary string that will be used as a filename prefix for every debug log
  • org.forgerock.openam.debug.suffix (optional): a valid Java dateformat string. Please note that if you set up rotation for every 5 minutes and you don’t include minutes in the format string, then you won’t really rotate the debug log every 5 minutes (the logs won’t get overwritten, you’ll just have one log file with all the content).
  • org.forgerock.openam.debug.rotation: rotation interval for the debug logs in minutes. If rotation interval is higher than 0, then rotation is enabled

Since this has been implemented in the shared Debug class, this also means, that you can put this properties file on ClassPath for any OpenAM component that is using the ClientSDK, so things like DAS and Java EE agents too.
Obviously after creating/modifying the properties file, you have to restart the container for the changes to take effect.