March 23, 2018 at 15:18Logging in Adaptivist ScriptRunner
In this article, I would like to talk about logging in the Adaptivist ScriptRunner. Logs are the main tool for developers and operating personnel to analyze emergency situations in an industrial environment. Therefore, when developing the application, we should think about what we will need when analyzing the incidents.
All examples were prepared in Jira Software 7.8.0 and Adaptivist ScriptRunner 5.3.9.
Let's assume that you came to a project that has been going on for some time, or you have already written dozens of scripts, and here comes an incident with an error.
From the logs it is clear that this is an inline script. The script is in some kind of business process in transition from id 951. Next, we must request information from the operating personnel on the transition from id 951, and even after we receive this information, we still won’t know this script is in subject to validator or post function. In addition, we understand that NPE was obtained because some kind of object was null, but we cannot imagine what kind of object it was and why it was null. We must first find this inline script, and we have problems with this.
Things are better here. We see that there is an error in the getIndexOutOfBoundsException method that was caused by the pfNPE.groovy script. We know the location of this script. But we do not know where the UtilHelper.groovy file is located. We can run a search on the file system and, most likely, find the UtilHelper file, but we also do not understand why we got an IndexOutOfBoundsException, what values the array that we selected the element had. That is, we lack the context in which the script was executed.
Here we see that an error occurred in the ScriptRunner built-in function, which creates a subtask. But we do not know this function was added to the post function, listener, or anywhere else. In addition, we again have no script execution context.
Suppose we know that our custom script sends mail to us, but how do we understand what went wrong in this custom script?
So, let's try to systematize the information displayed in the logs in order to:
I prefer to store scripts by type of object. For example, the function post will be stored in the ru / matveev / alexey / main / postfunctions directory, the listeners in the ru / matveev / alexey / main / listeners directory and so on. This will help to structure the layout of the scripts and quickly navigate the variety of scripts (there are exceptions for which this structuring is inconvenient, I'll try to talk about it in another article).
A script package determines its location in the file system. For example, for post functions, a package will be defined as follows:
This will help us determine the location of the scripts. For example, in Incident 2 we had the following entry in the logs:
From here we understand that UtilHelper is in ru / matveev.
How to determine the logger for a script in ScriptRunner can be found here . But I prefer to use SLF4J, since the log output syntax seems to me more convenient than in log4j. For example, you can log like this:
Here, during the execution of the script, the values of the variables var1 and var2 are substituted for curly brackets.
The logger for scripts that are in the file system can be defined like this:
In this case, the logger will be equal to the script package plus the file name. For example, for the pfNPE.groovy file, which has the ru.matveev.alexey.main.postfunctions package defined, the logger will look like this:
For inline scripts, you must explicitly specify the logger. To do this, you must first fill in the Note field when starting an inline script. This will allow us to accurately determine the executable script:
Next, we determine where the script would be located if it were located in the file system. In the screenshot above, we are adding a listener, so this file would be located in ru / matveev / alexey / main / listeners. Thus, our logger turns out like this:
I also add .inline to the logger in order to understand that this is an inline script and the final form of the logger is like this:
Logger allows us to:
For inline scripts, immediately after determining the logger, I log in to the script and exit the script. For example, for a listener whose Note field is defined as NPEListener, the entry and exit log lines will look like this:
For inline scripts that run in business processes, you can also specify the name of the business process, initial status, transition, and the value of the Note field. For example, like this:
In this case, the script in MyWorkflow is called, the initial status is In Progress, the transition is In Progress, the value is Note OutOfIndexBoundsPF. The encoding format of the call site can be any.
It is clear that the name of the business process or status may change, and then the information will become irrelevant. In this case, it will be possible to find the place where the script was called by transition ID.
For scripts in the file system, logging of input and output looks like this:
Logging in and out helps to understand if the script has finished work or not. You can log the inputs and outputs of functions in a script or called modules. But it is necessary to determine for yourself how necessary it is, and also to determine the level of logging.
I am logging in and out of the script with the INFO level so that I can enable the log of only the inputs and outputs from the script when I do not need the script execution context. Levels work in such a way that they log all values that are equal to the set level or higher. For example, the INFO level will log the INFO, WARN, ERROR, FATAL levels, but will not log DEBUG and TRACE.
In order for us to understand the context of script execution, we must at least pledge the values of variables. Variables are logged like this:
I log the context with the DEBUG or TRACE level.
Now let's try to rewrite the scripts that caused the incidents using the approach described above, and see how it helps us analyze these incidents.
The script that generated the error for Incident 1 looks like this:
After adding logging, the script will look like this:
In order to see the logs in the atlassian-jira.log file, go to System -> Logging and Profiling and set the INFO level for the logger ru.matveev.alexey.main.postfunctions.NPEPF.inline. After that, we will see these entries in the logs:
From the logs we see that we entered the inline NPEPF script and did not exit it, which means that the error occurred in it. In the text of the script, we see that the variable variable is not initialized.
The scripts that caused the error look like this:
pfNPE.groovy
UtilHelper.groovy
After adding logging, the scripts will look like this:
pfNPE.groovy
UtilHelper.groovy
In order for us to see the logs in the atlassian-jira.log file, we need to set the loggers to ru.matveev.alexey.main.helpers.UtilHelper and ru.matveev.alexey.main.postfunctions.pfNPE level DEBUG in System -> Logging and Profiling. After that we will see the following logs:
From the logs we understand. what scripts were called and where they are located. We see the values of all variables. You can open scripts and try to understand what went wrong. All the information we have.
Here you need to add logging for inline scripts and then we can also understand where the script is called from and in what context.
There may be several options. For example, we can know for sure the script that is executed when the executor is appointed. Then we turn on the DEBUG level for the script logger and look at the logs. If we do not know the script, then we can set the DEBUG level for all scripts (ru.matveev.alexey.main) or for a particular type of script (ru.matveev.alexey.main.listeners - only for listeners). Further, we can filter the output of logs by loggers in the program that we use to view logs, and receive information only about the logs we need. After that, we appoint an artist and watch what happens in the logs. If we have logged in scripts, then we will get all the necessary information.
This is all I would like to tell in this article. I would just like to add that there may be a desire to pledge every line of the script. No need to do this, because then the script will be difficult to understand. It must be remembered that readability of program code is as important as logging.
All examples were prepared in Jira Software 7.8.0 and Adaptivist ScriptRunner 5.3.9.
Let's assume that you came to a project that has been going on for some time, or you have already written dozens of scripts, and here comes an incident with an error.
Incident Example 1
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:
java.lang.NullPointerException: Cannot invoke method getKey() on null object
at Script1.run(Script1.groovy:4) From the logs it is clear that this is an inline script. The script is in some kind of business process in transition from id 951. Next, we must request information from the operating personnel on the transition from id 951, and even after we receive this information, we still won’t know this script is in subject to validator or post function. In addition, we understand that NPE was obtained because some kind of object was null, but we cannot imagine what kind of object it was and why it was null. We must first find this inline script, and we have problems with this.
Incident Example 2
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)Things are better here. We see that there is an error in the getIndexOutOfBoundsException method that was caused by the pfNPE.groovy script. We know the location of this script. But we do not know where the UtilHelper.groovy file is located. We can run a search on the file system and, most likely, find the UtilHelper file, but we also do not understand why we got an IndexOutOfBoundsException, what values the array that we selected the element had. That is, we lack the context in which the script was executed.
Incident Example 3
2018-03-17 16:26:25,165 http-nio-8080-exec-22 ERROR admin 986x4387x1 gj4xqt 127.0.0.1 /secure/CommentAssignIssue.jspa [c.o.s.c.jira.utils.ConditionUtils] Condition failed on issue: BP-2, built-in script:com.onresolve.scriptrunner.canned.jira.workflow.postfunctions.CreateSubTask
java.lang.NullPointerException: Cannot invoke method getClauseNames() on null object
at Script19.run(Script19.groovy:3)
2018-03-17 16:26:25,166 http-nio-8080-exec-22 ERROR admin 986x4387x1 gj4xqt 127.0.0.1 /secure/CommentAssignIssue.jspa [c.o.s.c.jira.utils.ConditionUtils] Script follows:
import com.atlassian.jira.component.ComponentAccessor
def cs = ComponentAccessor.getCustomFieldManager().getCustomFieldObjectByName("field name")
cs.getClauseNames()Here we see that an error occurred in the ScriptRunner built-in function, which creates a subtask. But we do not know this function was added to the post function, listener, or anywhere else. In addition, we again have no script execution context.
Incident Example 4
Не отправляется почта исполнителю задачи после назначения. Никаких ошибок в логах не обнаружено.Suppose we know that our custom script sends mail to us, but how do we understand what went wrong in this custom script?
So, let's try to systematize the information displayed in the logs in order to:
- quickly find the required script
- determine the context in which the script was run
- understand what goes wrong when running a script
- search for the required logs among a large number of other logs
1. It is necessary to structure all our scripts in the file system
I prefer to store scripts by type of object. For example, the function post will be stored in the ru / matveev / alexey / main / postfunctions directory, the listeners in the ru / matveev / alexey / main / listeners directory and so on. This will help to structure the layout of the scripts and quickly navigate the variety of scripts (there are exceptions for which this structuring is inconvenient, I'll try to talk about it in another article).
2. It is necessary to define the script package as the first line
A script package determines its location in the file system. For example, for post functions, a package will be defined as follows:
package ru.matveev.alexey.main.postfunctionsThis will help us determine the location of the scripts. For example, in Incident 2 we had the following entry in the logs:
at ru.matveev.UtilHelper.getIndexOutOfBoundsException(UtilHelper.groovy:13)From here we understand that UtilHelper is in ru / matveev.
3. It is necessary immediately after imports to determine the script logger
How to determine the logger for a script in ScriptRunner can be found here . But I prefer to use SLF4J, since the log output syntax seems to me more convenient than in log4j. For example, you can log like this:
log.debug("var1: {}, var2: {}", var1, var2)Here, during the execution of the script, the values of the variables var1 and var2 are substituted for curly brackets.
The logger for scripts that are in the file system can be defined like this:
def log = LoggerFactory.getLogger(this.getClass())In this case, the logger will be equal to the script package plus the file name. For example, for the pfNPE.groovy file, which has the ru.matveev.alexey.main.postfunctions package defined, the logger will look like this:
ru.matveev.alexey.main.postfunctions.pfNPEFor inline scripts, you must explicitly specify the logger. To do this, you must first fill in the Note field when starting an inline script. This will allow us to accurately determine the executable script:
Next, we determine where the script would be located if it were located in the file system. In the screenshot above, we are adding a listener, so this file would be located in ru / matveev / alexey / main / listeners. Thus, our logger turns out like this:
ru.matveev.alexey.main.listeners.NPElistenerI also add .inline to the logger in order to understand that this is an inline script and the final form of the logger is like this:
def log = LoggerFactory.getLogger("ru.matveev.alexey.main.listeners.NPElistener.inline")Logger allows us to:
- Set script logging level (you can read about logging levels here )
- Filter logs only for our script. Without this, log analysis is not possible, since Jira generates a large number of logs.
4. Log entry and exit script
For inline scripts, immediately after determining the logger, I log in to the script and exit the script. For example, for a listener whose Note field is defined as NPEListener, the entry and exit log lines will look like this:
log.info("NPElistener in")
...
log.info("NPElistener out")For inline scripts that run in business processes, you can also specify the name of the business process, initial status, transition, and the value of the Note field. For example, like this:
log.info("MyWorkflow:IN Progress:In Progress:OutOfIndexBoundsPF in")
...
log.info("MyWorkflow:IN Progress:In Progress:OutOfIndexBoundsPF out")In this case, the script in MyWorkflow is called, the initial status is In Progress, the transition is In Progress, the value is Note OutOfIndexBoundsPF. The encoding format of the call site can be any.
It is clear that the name of the business process or status may change, and then the information will become irrelevant. In this case, it will be possible to find the place where the script was called by transition ID.
For scripts in the file system, logging of input and output looks like this:
log.info("{} in", this.getClass())
...
log.info("{} out", this.getClass())Logging in and out helps to understand if the script has finished work or not. You can log the inputs and outputs of functions in a script or called modules. But it is necessary to determine for yourself how necessary it is, and also to determine the level of logging.
I am logging in and out of the script with the INFO level so that I can enable the log of only the inputs and outputs from the script when I do not need the script execution context. Levels work in such a way that they log all values that are equal to the set level or higher. For example, the INFO level will log the INFO, WARN, ERROR, FATAL levels, but will not log DEBUG and TRACE.
5. It is necessary to log the values of the variables in the script
In order for us to understand the context of script execution, we must at least pledge the values of variables. Variables are logged like this:
log.debug("index: {}", index) I log the context with the DEBUG or TRACE level.
Now let's try to rewrite the scripts that caused the incidents using the approach described above, and see how it helps us analyze these incidents.
Incident 1
The script that generated the error for Incident 1 looks like this:
import com.atlassian.jira.issue.Issue
Issue issue
issue.getKey()After adding logging, the script will look like this:
import com.atlassian.jira.issue.Issue
import org.apache.log4j.Logger
def log = Logger.getLogger("ru.matveev.alexey.main.postfunctions.NPEPF.inline")
log.info("MyWorkflow:IN Progress:In Progress:NPEPF in")
Issue issue
issue.getKey()
log.info("MyWorkflow:IN Progress:In Progress:NPEPF out")In order to see the logs in the atlassian-jira.log file, go to System -> Logging and Profiling and set the INFO level for the logger ru.matveev.alexey.main.postfunctions.NPEPF.inline. After that, we will see these entries in the logs:
2018-03-18 18:10:48,462 http-nio-8080-exec-36 INFO admin 1090x711x1 e9394m 127.0.0.1 /secure/WorkflowUIDispatcher.jspa [r.m.a.m.postfunctions.NPEPF.inline] MyWorkflow:IN Progress:In Progress:NPEPF in
2018-03-18 18:10:48,467 http-nio-8080-exec-36 ERROR admin 1090x711x1 e9394m 127.0.0.1 /secure/WorkflowUIDispatcher.jspa [c.o.s.jira.workflow.ScriptWorkflowFunction] *************************************************************************************
2018-03-18 18:10:48,468 http-nio-8080-exec-36 ERROR admin 1090x711x1 e9394m 127.0.0.1 /secure/WorkflowUIDispatcher.jspa [c.o.s.jira.workflow.ScriptWorkflowFunction] Script function failed on issue: BP-2, actionId: 951, file:
java.lang.NullPointerException: Cannot invoke method getKey() on null object
at Script16.run(Script16.groovy:7) From the logs we see that we entered the inline NPEPF script and did not exit it, which means that the error occurred in it. In the text of the script, we see that the variable variable is not initialized.
Incident 2
The scripts that caused the error look like this:
pfNPE.groovy
import ru.matveev.UtilHelper
List stringList = new ArrayList<>()
stringList.add("0")
stringList.add("1")
stringList.add("2")
UtilHelper.getRandomElement(stringList) UtilHelper.groovy
package ru.matveev
import com.atlassian.jira.issue.Issue
import java.util.Random
public class UtilHelper {
public static String getRandomElement(List value) {
Random rand = new Random()
int max = 5
def index = rand.nextInt(max);
return value.get(index)
}
} After adding logging, the scripts will look like this:
pfNPE.groovy
package ru.matveev.alexey.main.postfunctions
import ru.matveev.alexey.main.helpers.UtilHelper
import org.slf4j.LoggerFactory;
def log = LoggerFactory.getLogger(this.getClass())
log.info("pfNPE in")
List stringList = new ArrayList<>()
stringList.add("0")
stringList.add("1")
stringList.add("2")
UtilHelper.getRandomElement(stringList)
log.info("pfNPE out") UtilHelper.groovy
package ru.matveev.alexey.main.helpers
import com.atlassian.jira.issue.Issue
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 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)
}
} In order for us to see the logs in the atlassian-jira.log file, we need to set the loggers to ru.matveev.alexey.main.helpers.UtilHelper and ru.matveev.alexey.main.postfunctions.pfNPE level DEBUG in System -> Logging and Profiling. After that we will see 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)From the logs we understand. what scripts were called and where they are located. We see the values of all variables. You can open scripts and try to understand what went wrong. All the information we have.
Incident 3
Here you need to add logging for inline scripts and then we can also understand where the script is called from and in what context.
Incident 4
There may be several options. For example, we can know for sure the script that is executed when the executor is appointed. Then we turn on the DEBUG level for the script logger and look at the logs. If we do not know the script, then we can set the DEBUG level for all scripts (ru.matveev.alexey.main) or for a particular type of script (ru.matveev.alexey.main.listeners - only for listeners). Further, we can filter the output of logs by loggers in the program that we use to view logs, and receive information only about the logs we need. After that, we appoint an artist and watch what happens in the logs. If we have logged in scripts, then we will get all the necessary information.
This is all I would like to tell in this article. I would just like to add that there may be a desire to pledge every line of the script. No need to do this, because then the script will be difficult to understand. It must be remembered that readability of program code is as important as logging.