Introduction

Logging is critical to identifying and understanding defects in Automation Scripts, where traditional Java debugging strategies such as attaching a remote debugger that allows stepping through code are not possible. While logging has always been available in Automation Scripts, it has evolved significantly through the Maximo versions, which makes employing a consistent logging strategy challenging. In this post we will examine the logging facilities in Maximo, the current state of logging for Automation Scripts and provide recommendations for how to consistently implement logging across versions to ensure your logging will continue to work as expected through upgrades.

Maximo Logging

Logger Names

Before we get started, a brief overview of the logging infrastructure is needed. The core of Automation Script logging is of course the Maximo logging functionality, which is configured through the Logging application and Maximo logging in turn uses Log4J.

There is a critical issue with Log4J that you should patch immediately. Stop reading this article, go read the CVE https://nvd.nist.gov/vuln/detail/CVE-2021-44228 and then the IBM remediation steps here https://www.ibm.com/blogs/psirt/an-update-on-the-apache-log4j-cve-2021-44228-vulnerability and here https://www.ibm.com/support/pages/node/6525706.

With that out of the way, Log4J uses a dot notation to separate parent and child loggers, for example the root logger for Automation Scripts is called autoscript and has the logger key of log4j.logger.maximo.script as can been seen below.

The key for the autoscript logger starts with log4j.logger, which is the root logger for everything, followed by maximo and then finally script. When we create loggers for the root logger each logger is appended to the root logger key. For example if we create a child logger of the script root logger named EXAMPLE, the logger key will be log4j.logger.maximo.script.EXAMPLE. We will revisit this later, but for now just understand that for Maximo loggers the log4j.logger portion of the log name is implicit when getting a MXLogger instance only the maximo.xxx.yyy portion is required when specifying a log name.

System.out

Despite what we are about to cover, there are times when you just can't seem to get any log to show up and the logging of last resort is System.out.println. I do not advocate using System.out ever, but for completeness and because it is sometimes useful, here we go.

Copy
// Import System
System = Java.type("java.lang.System");

System.out.println("Your message goes here");

This is an extremely blunt instrument and should only be used in desperation. There is of course no way to change the log level for this or ever mute it and these statements have a way of finding their way to production systems where they clutter the logs with statements. It is very easy to miss removing System.out statements, so these are best avoided.

service.log

The implicit service variable has provided a log() function since Maximo 7.6.0.0 and its implementation has been a source of confusion for myself and I suspect many others. The Automation Script application has a Log Level attribute and one would expect that setting that value would impact what is output to the log and to a degree that expectation is correct. Based on analysis of the behavior of the service.log() function, the implementation must be something similar to the following Java code.

Copy
import psdi.util.logging.MXLogger;
import psdi.util.logging.MXLoggerFactory;

MXLogger logger = MXLoggerFactory.getLogger("maximo.script." + scriptName);

public void log(message){
    if (scriptInfo.isLogLevelDebug()) {
      logger.debug(logMsg);
    } else {
      logger.info(logMsg);
    } 
}

As you can see the service class creates a logger in the form of maximo.script.[scriptname], so calls to log() will be under the out of the box autoscript logger configuration. Things go off the rails however in the log() function, where the script's Log Level attribute is referenced and despite allowing for DEBUG,ERROR, FATAL, INFO and WARN only actually handles DEBUG and NOT DEBUG, all NOT DEBUG statements are logged at INFO level no matter what is selected. Even more confusing is that since this is part of the autoscript logger, the debug() and info() calls will only result in a log entry if the autoscript logger's log level is set to INFO or DEBUG and the script's Log Level attribute has no effect on the actual log level.

All this is to say that the service.log() and script Log Level functionality is fundamentally broken and should be avoided.

service.log_[level]

In Maximo 7.6.1.2 a new log_[level] function was introduced, where [level] is the log level name, for example log_info, log_error, or log_debug. For these the service class still creates a logger in the form of maximo.script.[scriptname], but the separate log_[level] functions each then in turn calls the appropriate levelled method on the logger. For example calling service.log_info() will call logger.info() or service.log_debug() will call logger.debug(). This resolves the ambiguity of the previous log() function, but unfortunately is only available in later versions of Maximo.

Logger Library

Given the inconsistencies with the Maximo provided service logging functions and the fact that the service implicit variable may not be available in library scripts I have developed a library script for logging. In case you are not familiar with using library scripts, you can check out our blog post on the topic here .

Here is the script, I recommend you create a new Nashorn Automation Script named LOGGER and copy / paste the following.

Copy
Throwable = Java.type("java.lang.Throwable");

MXLoggerFactory = Java.type("psdi.util.logging.MXLoggerFactory");

var logger;

function init(scriptName) {
    logger = MXLoggerFactory.getLogger("maximo.script." + scriptName);
    return this;
}

function debug(message, throwable) {
    if (!logger) { throw new Error("Logger has not been initialized, call init(scriptName) function before calling debug()."); }
    if (throwable && throwable instanceof Throwable) {
        logger.debug(message, throwable);
    } else {
        logger.debug(message);
    }
}

function info(message, throwable) {
    if (!logger) { throw new Error("Logger has not been initialized, call init(scriptName) function before calling info()."); }
    if (throwable && throwable instanceof Throwable) {
        logger.info(message, throwable);
    } else {
        logger.info(message);
    }
}

function warn(message, throwable) {
    if (!logger) { throw new Error("Logger has not been initialized, call init(scriptName) function before calling warn()."); }
    if (throwable && throwable instanceof Throwable) {
        logger.warn(message, throwable);
    } else {
        logger.warn(message);
    }
}

function error(message, throwable) {
    if (!logger) { throw new Error("Logger has not been initialized, call init(scriptName) function before calling error()."); }
    if (throwable && throwable instanceof Throwable) {
        logger.error(message, throwable);
    } else {
        logger.error(message);
    }
}

function fatal(message, throwable) {
    if (!logger) { throw new Error("Logger has not been initialized, call init(scriptName) function before calling fatal()."); }
    if (throwable && throwable instanceof Throwable) {
        logger.fatal(message, throwable);
    } else {
        logger.fatal(message);
    }
}

Once you have created the script you can reference it with the following. The LOGGER script is invoked and then initialized with the calling script's name. The init() function returns a reference to the script object and the script functions can not be called from the script object.

Copy
Exception = Java.type("java.lang.Exception");

// invoke and initialize the logger.
var logger = service.invokeScript("LOGGER").init(service.getScriptName());

// standard log messages
logger.debug("Your debug level log message here");
logger.info("Your info level log message here");
logger.warn("Your warn level log message here");
logger.error("Your error level log message here");
logger.fatal("Your fatal level log message here");

// log message with an exception
var error = new Exception("An error message in an exception");

// invoke the error log function including the exception
logger.error("Your error level log message here", error);

Note that we are calling service.getScriptName() instead of using the scriptName implicit variable. While the documentation https://www.ibm.com/docs/en/cdfsp/7.6.1.2?topic=scripts-implicit-variables states that scriptName is available for all launch points, it is not available if you invoke the script from a direct web call such as https://hostname/maximo/oslc/script/script_name_here. Also note that the same documentation states that userinfo is available from all launch points, but it is actually userInfo.

Script Names

Script naming strategy may seem a bit off topic, but remember that the logger name is formed by appending the script name to the base script logger maximo.script and that Log4J separates the logger hierarchy using a dot notation. Using this knowledge we can name our scripts in logical groupings by separating related scripts with dots, not only for organization, but also to create a logging hierarchy. In the example below we have a number of script loggers all starting with the name EXAMPLE, with a sub group of ACTIONS and with other script loggers defined separately. The root EXAMPLE logger is set to ERROR, the EXAMPLE.ACTIONS is set to DEBUG, the EXAMPLE.ACTIONS.ACTION1 is set to ERROR, and the EXAMPLE.SAVE logger is set to INFO.

For this example, let us assume we have scripts named EXAMPLE.ACTIONS.ACTION1, EXAMPLE.ACTIONS.ACTION2, EXAMPLE.INIT and EXAMPLE.SAVE. With the log configuration above we can see that because EXAMPLE.ACTIONS is set to DEBUG, EXAMPLE.ACTIONS.ACTION2 will log debug messages by inheriting the parent logger of EXAMPLE.ACTIONS, but EXAMPLE.ACTIONS.ACTION1 will only log errors because it is explicitly set to ERROR. Likewise, EXAMPLE.SAVE will log INFO level log messages, but EXAMPLE.INIT will only log ERROR messages because no logger has been defined and it too will inherit from the EXAMPLE root logger configuration.

Log Output Format

Manual Message Prefixing

I have noticed that it is common for developers to add a prefix to the log messages, typically with the script name. This is likely for identifying which script generated the log output and to allow filtering within the log. In the least reusable form it looks something like the following.

Copy
debug("The log message");

function debug(message){
    service.log("SCRIPTNAME_HERE " + message);
}

Of course, hard coding the script name is not great and as we discussed service.log is unclear for defining log levels, so we can improve it with the following, assuming Maximo 7.6.1.2.

Copy
debug("The log message");

function debug(message){
    service.log_debug(service.getScriptName() + " " + message);
}

However, this still must be applied to each script individually and is generally an unpleasant maintenance burden.

Log4J Message Formatting

Alternatively, we can leverage the built in Log4J formatting and not have to add any custom functions and still get log messages prefixed with the script name. In the Maximo Logging application, select the Manage Appenders menu item.

From there expand the desired appender. For altering the standard SystemOut.log in WebSphere Traditional or the console.log in WebSphere Liberty select the Console appender. In the Conversion Pattern attribute add %c where you want the script name to be printed.

The %c is the logger category, more commonly referred to as the logger name, that happens to match the script's name and therefore achieves the goal of identifying and filtering log entries. Full details of all available patterns and formats is available here: https://logging.apache.org/log4j/2.x/manual/layouts.html.

Conclusion

In this post we delved into the mess that is the service.log() function and uncovered why its behavior is so unintuitive. We looked at the new service.log_[level] functions, which provide a much clearer and useful implementation of logging, but is only available in the latest versions of Maximo. We then implemented a library function to provide a consistent logging framework across all versions. Finally, we reviewed how carefully naming your Automation Scripts using a dot separated format can help group your logging into a sensible hierarchy.

Hopefully you have found this useful and if you have any questions or comments please reach out to us at [email protected]