How To
ForgeRock Identity Platform
Does not apply to Identity Cloud

How do I add Thread IDs to log statements in IDM 5.x and 6?

Last updated Apr 8, 2021

The purpose of this article is to provide information on adding thread IDs to log statements, including how to correlate thread IDs with transaction IDs for tracing transactions through standard audit and openidm0.log.0 logs. This information can help with troubleshooting and tracking performance issues.


Overview

IDM uses java.util logging, which allows you to extend logging using custom handlers, formatters etc.

  • For IDM 6.5 and later, the threadID is included in log messages by default. If you upgrade to IDM 6.5, you will need to enable this feature as detailed in the release notes: Release Notes › Adding Thread IDs to Log Messages.
  • For pre-IDM 6.5, you can use the examples in this article, which demonstrate how you can use a custom log formatter to extend java.util.logging.SimpleFormatter to include thread IDs in log statements.
Note

These examples are intended to show you what is possible; they are not recommendations from ForgeRock nor are they supported. It is your responsibility to verify that they are suitable for your needs.

Adding thread IDs to log statements

  1. Write a custom log formatter using Java® that includes the thread ID. For example: package org.forgerock.idm.sample; import java.util.logging.LogRecord; public class ThreadIdFormatter extends java.util.logging.SimpleFormatter {   public String format(LogRecord record) {         String formatted = super.format(record);         return "ThreadID=" + Thread.currentThread().getId() + " ThreadName=" + Thread.currentThread().getName() + " - " + formatted;     } }
  2. Compile and package this log formatter into a jar file, for example: $ mkdir classes $ javac -d classes ThreadIdFormatter.java $ cd classes $ jar cvf ../thread-id-formatter.jar org
  3. Shutdown the IDM instance. $ cd /path/to/idm $ ./shutdown.sh
  4. Copy the packaged jar file to the /path/to/idm/bin directory, for example: $ cp thread-id-formatter.jar /path/to/idm/bin
  5. Delete the felix cache: $ cd /path/to/idm $ rm -rf felix-cache/*
  6. Update the logging.properties file (located in the /path/to/idm/conf directory) to include this log formatter and comment out the SimpleFormatter, for example: # java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter java.util.logging.FileHandler.formatter = org.forgerock.idm.sample.ThreadIdFormatter
  7. Update the logging.properties file to include the following new line, which includes milliseconds in the log times: java.util.logging.SimpleFormatter.format = %1$tb %1$td, %1$tY %1$tl:%1$tM:%1$tS.%1$tL %1$Tp %2$s%n%4$s: %5$s%6$s%n
  8. Start the IDM server: $ cd /path/to/idm $ ./startup.sh

This will add thread IDs to all log statements, for example:

ThreadId : 156 - /openidm/managed/user/?_queryFilter=true - ThreadName : qtp440289386-156 - May 02, 2020 11:07:44.387 AM org.forgerock.openidm.repo.jdbc.impl.GenericQueryResultMapper mapQueryToObjectFINEST: Query result for queryId: null type: managed/user converted obj: {mail=jdoe@example.com, sn=doe, givenName=john, userName=jdoe, accountStatus=active, effectiveRoles=[], effectiveAssignments=[], _id=546dfe6d-7c7b-4a00-abe7-f1b4d8d1e5ee, _rev=0}

Correlating transaction IDs with thread IDs

If you have configured the audit logs to include the transactionId per Integrator's Guide › Configuring the Audit Service, you can use this log formatter in conjunction with the logging scripts used in router.json (located in the /path/to/idm/conf directory) to match transaction IDs with thread IDs.

For example, you could add a block similar to the following to router.json:

  {       "pattern": ".*",       "onRequest": {         "type": "text/javascript",         "source": "logger.debug(\"ONREQUEST \" + request.method + \" \" + request.resourcePath + \" xact=\" + context.transactionId.transactionId.value);"       },       "onResponse": {         "type": "text/javascript",         "source": "logger.debug(\"ONRESPONSE \" + request.method + \" \" + request.resourcePath + \" xact=\" + context.transactionId.transactionId.value);"        },       "onFailure": {         "type": "text/javascript",         "source": "logger.debug(\"ONFAILURE \" + request.method + \" \" + request.resourcePath + \" xact=\" + context.transactionId.transactionId.value);"       }     }

This change adds thread IDs to all log statements for these scripts; when FINE logging is enabled, the transaction IDs are shown as well, which allows you to correlate thread IDs with transaction IDs. For example:

FINE: ONREQUEST read info/version xact=db061a02-fe76-4c34-b99c-ac8839ea763d-60 ThreadId=616 ThreadName=qtp405829296-616 - /openidm/info/version - May 02, 2020 11:15:12.593 AM org.forgerock.openidm.filter.ScriptedFilter evaluateOnResponse

From this example, you can see that thread ID 616 correlates to transaction ID db061a02-fe76-4c34-b99c-ac8839ea763d-60. This information can then be used to trace transactions through the standard IDM log using the thread ID.

See Also

How do I add logging to JavaScript files in IDM (All versions)?

How do I add logging to Groovy scripts in IDM (All versions)?

Customizing Java Log Format to use SimpleFormatter fails in IDM (All versions)

FAQ: IDM performance and tuning

Troubleshooting IDM

Integrator's Guide › Configuring Server Logs

Related Training

N/A

Related Issue Tracker IDs

OPENIDM-9783 (Include thread id in all logging statements)


Copyright and Trademarks Copyright © 2021 ForgeRock, all rights reserved.