Logging in ScriptRunner

[#1]

In this article I would like to talk about logging information about a ScriptRunner script execution. This information must be used later for identifying the cause of the errors in the script .

I tested all code in Jira 7.8.0 and ScriptRunner 5.3.9.

Suppose, that you have come to a project, which began some time before, or you have already written tens of scripts and now you can see errors in the atlassian-jira.log file.

For example, what can you say about this error?

2018-03-17 11:43:04,891 http-nio-8080-exec-17 ERROR admin 703x1504x1 16n2j3n 127.0.0.1 /secure/WorkflowUIDispatcher.jspa [c.o.s.jira.workflow.ScriptWorkflowFunction] Script function failed on issue: BP-2, actionId: 951, file: <inline script>
java.lang.NullPointerException: Cannot invoke method getKey() on null object
    at Script1.run(Script1.groovy:4)

It is an inline script. It was executed on a transition with actionId 951.  A getKey() method was executed on some object and the object was null. Ok. Now we have to find the script. Where to find it? We have first to identify, what actionId 951 is and even after we identified it, we still do not know, if the script is in a condition, validator or post function. Moreover we do not know, why the object was null. We have no info on it.

Or let's say we have this error:

2018-03-17 17:07:31,325 http-nio-8080-exec-22 ERROR admin 1027x4968x1 gj4xqt 127.0.0.1 /secure/WorkflowUIDispatcher.jspa [c.o.s.jira.workflow.ScriptWorkflowFunction] Script function failed on issue: BP-2, actionId: 961, file: ru/matveev/alexey/main/postfunctions/pfNPE.groovy
java.lang.IndexOutOfBoundsException: Index: 0, Size: 0
    at java_util_List$get$6.call(Unknown Source)
    at ru.matveev.UtilHelper.getIndexOutOfBoundsException(UtilHelper.groovy:13)
    at ru.matveev.UtilHelper$getIndexOutOfBoundsException.call(Unknown Source)
    at ru.matveev.alexey.main.postfunctions.pfNPE.run(pfNPE.groovy:10)

This one looks better. We know that the error was thrown in the ru.matveev.UtilHelper.getIndexOutOfBoundsException method, which was called by pfNPE.groovy and we even know, where the pfNPE file is in the file system. But we still do not know, where to find the ru.matveev.UtilHelper file. And we still do now know, why the IndexOutOfBOundsException was thrown. Ok. Let's see first the pfNPE.groovy file:

package ru.matveev.alexey.main.postfunctions
import ru.matveev.UtilHelper

List<String> stringList = new ArrayList<>()
UtilHelper.getIndexOutOfBoundsException(stringList)

Looking at the file we still can not understand, where to look for the UtilHelper file.

I think we need to do something with our scripts to make them talk to us and to other people in our project.

1. We need to define the folder structure of our script repository.

I prefer to have its own folder for each ScriptRunner object type. For example, post functions will be in the ru/matveev/alexey/main/postfunctions folder, listeners will be in the ru/matveev/alexey/main/listeners and so on. It will let us categorize our scripts and find required scripts easier (though there are exceptions to this rule. I am planning to talk about it in another article).

2. We need to provide the package for each script, according to its path.

For example, for our pfNPE.groovy we provided:

package ru.matveev.alexey.main.postfunctions

 It means that our file is placed in the ru/matveev/alexey/main/postfunctions folder. And it also means, that the UtilHelper.groovy file is placed in the  ru/matveev folder.

3. We need to define a Logger in our scripts.

You can find how to define a logger in ScriptRunner here. But I prefer to use the slf4j. I like the syntaxis. You can write to a log like this:

log.debug("var1: {}, var2: {}", var1, var2)

The logger will let us later to turn on/off debugging info from our scripts. For a script in a file system we can use this.getClass() to define the logger. For example, for the pfNPE.groovy file the logger would be like this:

def log = LoggerFactory.getLogger(this.getClass())

 For an inline script, first of all, I always fill the Note field:

Then when I set a logger, I define, what the script is and where it would be placed, if the script was saved in the file system. In the screenshot above, the inline script is a listener, that is why the logger would be like this (I added ".inline" to the end, so that I know, that the script is inline):

def log = LoggerFactory.getLogger("ru.matveev.alexey.main.listeners.NPElistener.inline")

 4. At the beginning of the script set a log, that the script started, and at the end of the script set a log, that the script has ended.

It is not a must for a script in the file system, but it is a must for an inline script. For an inline script, if it is a condition, validator or post function script, I also provide the workflow name, initial status, transition name and the Note. For example, like this:

log.info("MyWorkflow:IN Progress:In Progress:OutOfIndexBoundsPF in")
....
log.info("MyWorkflow:IN Progress:In Progress:OutOfIndexBoundsPF out")

Here is an example of an inline script:

import org.slf4j.LoggerFactory;
def log = LoggerFactory.getLogger("ru.matveev.alexey.main.postfunctions.OutOfIndexBoundsPF.inline")
log.info("MyWorkflow:IN Progress:In Progress:OutOfIndexBoundsPF in")
List<String> stringList = new ArrayList<>()
def key = stringList.get(0)
log.info("MyWorkflow:IN Progress:In Progress:OutOfIndexBoundsPF out")

I need to turn on the INFO level for my ru.matveev.alexey.main.postfunctions.OutOfIndexBoundsPF.inline logger in System -> Logging and Profiling. Then my logs will look like this:

2018-03-17 15:32:36,888 http-nio-8080-exec-9 INFO admin 932x3626x1 sxyxed 127.0.0.1 /secure/WorkflowUIDispatcher.jspa [r.m.a.m.postfunctions.OutOfIndexBoundsPF.inline] MyWorkflow:IN Progress:In Progress:OutOfIndexBoundsPF in
2018-03-17 15:32:36,895 http-nio-8080-exec-9 ERROR admin 932x3626x1 sxyxed 127.0.0.1 /secure/WorkflowUIDispatcher.jspa [c.o.s.jira.workflow.ScriptWorkflowFunction] *************************************************************************************
2018-03-17 15:32:36,896 http-nio-8080-exec-9 ERROR admin 932x3626x1 sxyxed 127.0.0.1 /secure/WorkflowUIDispatcher.jspa [c.o.s.jira.workflow.ScriptWorkflowFunction] Script function failed on issue: BP-2, actionId: 951, file: <inline script>
java.lang.IndexOutOfBoundsException: Index: 0, Size: 0
    at java_util_List$get$6.call(Unknown Source)
    at Script17.run(Script17.groovy:5)

Now I know that the error was in MyWorkflow:IN Progress:In Progress:OutOfIndexBoundsPF, because I entered the script but I did not leave it.

I usually put the in and out messages for scripts in the file system as well. I provide only the script name. It would be like this:

log.info("pfNPE in")
...

log.info("pfNPE out")

5. Provide debug messages with the values of variables.

Let's see the contents of the UtilHelper.groovy file:

package ru.matveev.alexey.main.helpers

import java.util.Random  

public class UtilHelper {
   public static String getRandomElement(List<String> value) {
      Random rand = new Random()  
      int max = 5
      def index = rand.nextInt(max);   
      return value.get(index)
   }
}

I think it is a good idea to log all input variables to a method and values of all variables in the method. That is why let's rewrite our file like this:

package ru.matveev.alexey.main.helpers

import java.util.Random
import org.slf4j.LoggerFactory;

public class UtilHelper {

   private static final LOG = LoggerFactory.getLogger("ru.matveev.alexey.main.helpers.UtilHelper")  

   public static String getRandomElement(List<String> value) {
      LOG.debug("getRandomElement in. value: {}", value)
      Random rand = new Random()  
      int max = 5
      def index = rand.nextInt(max);  
      LOG.debug("index: {}", index) 
      return value.get(index)
   }
}

We need to set the DEBUG level for the ru.matveev.alexey.main.helpers.UtilHelper in the System -> Logging and Profiling. After that we will have the following logs:

2018-03-17 18:54:00,664 http-nio-8080-exec-2 INFO admin 1134x121x1 pr8c2n 127.0.0.1 /secure/WorkflowUIDispatcher.jspa [r.m.a.main.postfunctions.pfNPE] pfNPE in
2018-03-17 18:54:00,687 http-nio-8080-exec-2 DEBUG admin 1134x121x1 pr8c2n 127.0.0.1 /secure/WorkflowUIDispatcher.jspa [r.m.a.main.helpers.UtilHelper] getRandomElement in. value: [0, 1, 2]
2018-03-17 18:54:00,687 http-nio-8080-exec-2 DEBUG admin 1134x121x1 pr8c2n 127.0.0.1 /secure/WorkflowUIDispatcher.jspa [r.m.a.main.helpers.UtilHelper] index: 4
2018-03-17 18:54:00,693 http-nio-8080-exec-2 ERROR admin 1134x121x1 pr8c2n 127.0.0.1 /secure/WorkflowUIDispatcher.jspa [c.o.s.jira.workflow.ScriptWorkflowFunction] *************************************************************************************
2018-03-17 18:54:00,694 http-nio-8080-exec-2 ERROR admin 1134x121x1 pr8c2n 127.0.0.1 /secure/WorkflowUIDispatcher.jspa [c.o.s.jira.workflow.ScriptWorkflowFunction] Script function failed on issue: BP-2, actionId: 961, file: ru/matveev/alexey/main/postfunctions/pfNPE.groovy
java.lang.IndexOutOfBoundsException: Index: 4, Size: 3
    at java_util_List$get$1.call(Unknown Source)
    at ru.matveev.alexey.main.helpers.UtilHelper.getRandomElement(UtilHelper.groovy:25)
    at ru.matveev.alexey.main.helpers.UtilHelper$getRandomElement.call(Unknown Source)
    at ru.matveev.alexey.main.postfunctions.pfNPE.run(pfNPE.groovy:12)

Now we can see that we entered the pfNPE file. Then we entered the getRandomElement method in UtilHelper. We can see the value of the value variable. We can see the value of the index variable and now we understand, why we have the error. We also know, where to find all necessary scripts.

 I would like to add, that there are two types of errors: errors, which are visible in the logs (all kinds of exceptions) and errors, which are not visible. The second type of errors is more tricky, because the user just tells you, that the flow of your program goes wrong. For example, if a user is assigned to an issue, the user must receive a email. But the user does not receive it. You look in the logs and you can see no errors. And now you have to define, what goes wrong. In this case you turn on debugging and try to see, what is wrong. If you structured your folders and defined loggers, then you can turn on the debug mode for one script or for a category of your scripts or for all your scripts. For all your scripts you would just set the DEBUG log level for the ru.matveev.alexey.main package. While you are trying to find what went wrong,  the logging of variable values will not be enough. You would want to know in what conditions you entered and what blocks of the program were executed. You can, of course, put the log statements after each program flow actions, but in the end your code would become unreadable. That is why, you should put the log statements wisely. Do not forget that the readability of your code is as important as logging.

[Matt Doar]

Very useful, thank you