Adding Logging to OpenIAM Groovy Scripts

If you want to provide some custom logic to an aspect of OpenIAM, the chances are you'll need a groovy script. OpenIAM comes with a large number of example groovy scripts, but I've found that it's not always obvious to what's going on. You can always println to output something, but it can be difficult to track that down. There is a better way! As OpenIAM is written on top of the Spring Framework, we can make use of Spring Framework's implementation of the Apache Commons Logging (JCL) Utility. Though this isn't actually responsible for creating your logs, it gives developers a standard set of APIs to call which pass on your log line to an underlying logger, which isn't something we need to worry about.

What is Logging?

Logging allows you to output data or messages as they happen to the operating system for later review. Generally you would log errors, events, or even general messages to help you understand what is being executed and create an audit trail. The output can be useful when trying to dive into why something went wrong and should contain useful information to tell you the journey the process took until the error occurred. Using the framework's built in logging makes it incredibly easy to output logs, we don't need to worry about the logging implementation or how the logs are saved as this is all done for us with a nice API to call. The documentation for the Log interface can be found here.

Logging can be important not just from a debugging perspective but also security. It's common practise to ship logs off of the servers that generate them into centralised logging services such as an ELK stack as it ensures the logs are stored away from the service and makes them searchable. In the event that a server is compromised the logs are still intact on an external system and can be used to audit what happened.

Log Levels

Logging implementations usually allow you to specify two things, the severity of the message that you are outputting and the severity of the message that you care about seeing. The most commonly used log levels are:

• fatal
• error
• warn
• info
• debug
• trace

These log levels go from most to least serious. Within the Spring Framework fatal is available but not used, if called, it will generate an error log level instead. Generally you set an application wide log level which determines which severity of logs will make it into the log files. The higher the log level your application is set to, the less you'll see in your logs. A log level works like a filter and will only output messages that match or are higher than the log level set for your application. When you are running a production environment, you probably only want to see logs generated from warn or above as your logs will be telling you when something is wrong. For a development environment having your log level set to info or debug will show you exactly what's going on. By default, the log level within OpenIAM is set to info on kubernetes, warn on docker and info on RPM.

Log Methods

The Apache Commons Logging (JCL) API has a matching method for each of the log levels.

• fatal(Object)
• error(Object)
• warn(Object)
• info(Object)
• debug(Object)
• trace(Object)

You can pass any object into these methods, and it will be output to the logs.

Usage:

log.debug("User Object: ${user}")
log.info("Starting to execute xyz")
log.error("Something went wrong while doing this")

Log Format

The log format used by OpenIAM is:

log.error("Something went wrong while doing this")

2023-01-10 17:05:03.917  ERROR 1 --- [   thread-10] nameOfClass     : Something went wrong while doing this

• Date and Time: Millisecond precision and easily sortable.
• Log Level: ERROR, WARN, INFO, DEBUG, or TRACE.
• Process ID.
• A --- separator to distinguish the start of actual log messages.
• Thread name: Enclosed in square brackets (may be truncated for console output).
• Logger name: This is usually the source class name (often abbreviated).
• The log message

Log Location

kubectl logs -l release=test --all-containers --max-log-requests 34 -f

docker logs --tail=0 --follow

tail -f /usr/local/openiam/logs/*

Change OpenIAM's Log Level

Kubernetes

To change the log level set for OpenIAM using Kubernetes you will need to update lines 58 and 510 within your terraform.tfvars file to the appropriate log level and redeploy. (These line number maybe different in different versions of OpenIAM)

Docker

To change the log level set for OpenIAM using Docker, you need to update the LOGGING_LEVEL variable within your env.sh file currently found on line 23, once changed you will need to restart OpenIAM.

RPM

As an EE customer using Kubernetes, I've not used the RPM version of OpenIAM! I'll find this out and update this post.

Logging within OpenIAM Groovy Script

Apache Commons Logging (JCL) can be added to any groovy script within OpenIAM.

import org.apache.commons.logging.Log
import org.apache.commons.logging.LogFactory

class LoggingExample {
    private static final Log log = LogFactory.getLog("LoggingExample")

    public void methodName() {
        log.info("methodName has been called")
    }
}

Though this isn't a script you can actually run, it shows you the bare bones needed to start logging.

In each script you want to add logging, you need to import the Apache Common Logging classes

import org.apache.commons.logging.Log
import org.apache.commons.logging.LogFactory

At the top of your class we use the LogFactory class to return a named logger.

private static final Log log = LogFactory.getLog("LoggingExample")

Rather than hardcoding a name for the logger, you can use this.class.name to get the name of the class, in my example it would result in the same name.

To output something to the log you need to call one of the log level methods. In my example, if the LoggingExample.methodName() method was called the following line would get executed.

log.info("methodName has been called")

This would output something like this to the logs

2023-01-10 17:05:03.917  INFO 1 --- [   thread-10] LoggingExample   : methodName has been called

Be careful with what you send to your logs. Using logging to output user information isn't a good idea as it may commit personal, identifiable or sensitive information such as passwords into storage. If you need to identify the user affected by an issue, use the user's ID using the getId() method to output their OpenIAM ID only.

Having a named logger allows you to filter the logs to just the output related to the named logger. In my example I could pipe my logs to grep and search for "LoggingExample". This will only show me the related log lines, e.g:

kubectl logs -l release=test --all-containers --max-log-requests 34 -f | grep "LoggingExample"

docker logs --tail=0 --follow | grep "LoggingExample"

tail -f /usr/local/openiam/logs/* | grep "LoggingExample"

Summary

As you can see, it is fairly simple to add logging to an OpenIAM Groovy Script. I would strongly advise that you make logging part of your scripts as it will help to minimise technical debt at a later date and make it much easier to troubleshoot an issue. If you want to see some working examples of how you could use logging check out one of my other posts related to OpenIAM such as Finding Users with Groovy Script in OpenIAM.