Logging in Adaptivist ScriptRunner
In this article, I would like to talk about logging in Adaptivist ScriptRunner. Logs are the main tool for developers and operators to analyze abnormal situations in an industrial environment. Therefore, when developing an application, we should think about what we will need when analyzing the incidents that occur.
All examples were prepared in Jira Software 7.8.0 and Adaptivist ScriptRunner 5.3.9.
Let's assume that you have come to a project that has already been going on for some time, or you have already written several dozen scripts, and now an incident with an error comes to you.
')
From logs it is clear that this is an inline script. The script is in some business process in transition from ID 951. Next, we need to ask the operating personnel for information on switching from ID 951, and even after we receive this information, we still will not know, this script is in provided validator or post function. In addition, we understand that the NPE was received because an object was null, but we do not know what object it is and why it was null. We must first find this inline script, and with this we have problems.
Here things are better. We see that there is an error in the getIndexOutOfBoundsException method, which was caused by the pfNPE.groovy script. We know the location of this script. But we do not know where the file UtilHelper.groovy. We can run a file system search and, most likely, find the UtilHelper file, but we also do not understand why we received an IndexOutOfBoundsException, what values the array from which we selected the element had. That is, we lack the context in which the script was executed.
Here we see that the error occurred in the built-in function ScriptRunner, which creates a subtask. But we do not know this function has been added to the post function, listener or somewhere else. In addition, we again have no script execution context.
Suppose we know that our custom script is sending mail to us, but how to understand what went wrong in this custom script?
So, let's try to systematize the information issued in the logs in order to:
I prefer to store scripts by object type. For example, the post functions will be stored in the directory ru / matveev / alexey / main / postfunctions, the listeners will be stored in ru / matveev / alexey / main / listeners, and so on. This will help to structure the location of the scripts and more quickly navigate the variety of scripts (there are exceptions for which this structuring is inconvenient, I will try to tell about it in another article).
The script package determines its location in the file system. For example, for post functions, the 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 define a logger for a script in ScriptRunner can be found here . But I prefer to use SLF4J, since the syntax of log output seems to me more convenient than in log4j. For example, you can log like this:
Here, during the script execution, instead of curly brackets, the values of the variables var1 and var2 are substituted.
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 would look like this:
For inline scripts, you must explicitly specify the logger. To do this, you must first fill in the Note field when setting up an inline script. This will allow us to accurately determine the executable script:
Next, we determine where the script would be if it were located in the file system. In the screenshot above, we add a listener, so this file would be placed in ru / matveev / alexey / main / listeners. Thus, our logger is obtained like this:
I also add .inline to the logger in order to understand that this is an inline script and the final look of the logger is this:
Logger allows us to:
For inline scripts, immediately after determining the logger, I log in the script entry and exit. For example, for a listener whose Note field is defined as an NPEListener, the input and output logging lines will look like this:
For inline scripts that run in a business process, 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 is called in MyWorkflow, 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 a place to call the script on the transition ID
For scripts in the file system, input and output logging looks like this:
Logging the input and output helps to understand whether the script is finished or not. You can log the inputs and outputs of functions in a script or called modules. But it is necessary to determine it yourself, as far as necessary, and also to determine the level of logging.
I log in and out of the script with the INFO level in order to enable the log only of the inputs and outputs from the script when I do not need the context of the script execution. Levels work in such a way that they log all values that are equal to the specified level or higher. For example, the INFO level will log 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 log the values of variables. The variables are logged like this:
I am logging context with DEBUG or TRACE.
Now let's try to rewrite the scripts that caused the incidents, using the approach outlined above, and see how this 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 in the logs such records:
From the logs we see that we entered the NPEPF inline script and did not exit it, which means the error occurred in it. In the text of the script, we see that the variable issue is not initialized.
The scripts that caused the error look like this:
pfNPE.groovy
Utilhelper.groovy
After adding logging, the scripts will be like this:
pfNPE.groovy
Utilhelper.groovy
In order for us to see the logs in the atlassian-jira.log file, you need to install the loggers ru.matveev.alexey.main.helpers.UtilHelper and ru.matveev.alexey.main.postfunctions.pfNPE DEBUG level 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. 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 will also be able to understand where the script is called from and in what context.
There may be several options. For example, we can know exactly the script that is executed when assigning an artist. Then we enable 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 separate type of scripts (ru.matveev.alexey.main.listeners - only for listeners). Next, we can set the filtering of the log output by the loggers in the program that we use to view the logs, and receive information only about the logs we need. After that, we assign an artist and see what happens in the logs. If we have logged in scripts, we will get all the necessary information.
This is all that I would like to tell in this article. I would just like to add that you may want to log each line of the script. No need to do this, because then the script will be difficult to understand. It must be remembered that the readability of the 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 have come to a project that has already been going on for some time, or you have already written several dozen scripts, and now an incident with an error comes to you.
')
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 [cosjira.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) From logs it is clear that this is an inline script. The script is in some business process in transition from ID 951. Next, we need to ask the operating personnel for information on switching from ID 951, and even after we receive this information, we still will not know, this script is in provided validator or post function. In addition, we understand that the NPE was received because an object was null, but we do not know what object it is and why it was null. We must first find this inline script, and with this we have problems.
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 [cosjira.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) Here things are better. We see that there is an error in the getIndexOutOfBoundsException method, which was caused by the pfNPE.groovy script. We know the location of this script. But we do not know where the file UtilHelper.groovy. We can run a file system search and, most likely, find the UtilHelper file, but we also do not understand why we received an IndexOutOfBoundsException, what values the array from which 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 [coscjira.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 [coscjira.utils.ConditionUtils] Script follows: import com.atlassian.jira.component.ComponentAccessor def cs = ComponentAccessor.getCustomFieldManager().getCustomFieldObjectByName("field name") cs.getClauseNames() Here we see that the error occurred in the built-in function ScriptRunner, which creates a subtask. But we do not know this function has been added to the post function, listener or somewhere else. In addition, we again have no script execution context.
Sample Incident 4
. . Suppose we know that our custom script is sending mail to us, but how to understand what went wrong in this custom script?
So, let's try to systematize the information issued in the logs in order to:
- quickly find the required script
- determine the context in which the script was executed
- understand what goes wrong when executing the script
- look for the logs we need 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 object type. For example, the post functions will be stored in the directory ru / matveev / alexey / main / postfunctions, the listeners will be stored in ru / matveev / alexey / main / listeners, and so on. This will help to structure the location of the scripts and more quickly navigate the variety of scripts (there are exceptions for which this structuring is inconvenient, I will try to tell about it in another article).
2. It is necessary to define the script package in the first line.
The script package determines its location in the file system. For example, for post functions, the package will be defined as follows:
package ru.matveev.alexey.main.postfunctions This 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 the import to determine the script script.
How to define a logger for a script in ScriptRunner can be found here . But I prefer to use SLF4J, since the syntax of log output seems to me more convenient than in log4j. For example, you can log like this:
log.debug("var1: {}, var2: {}", var1, var2) Here, during the script execution, instead of curly brackets, the values of the variables var1 and var2 are substituted.
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 would look like this:
ru.matveev.alexey.main.postfunctions.pfNPE For inline scripts, you must explicitly specify the logger. To do this, you must first fill in the Note field when setting up an inline script. This will allow us to accurately determine the executable script:
Next, we determine where the script would be if it were located in the file system. In the screenshot above, we add a listener, so this file would be placed in ru / matveev / alexey / main / listeners. Thus, our logger is obtained like this:
ru.matveev.alexey.main.listeners.NPElistener I also add .inline to the logger in order to understand that this is an inline script and the final look of the logger is this:
def log = LoggerFactory.getLogger("ru.matveev.alexey.main.listeners.NPElistener.inline") Logger allows us to:
- Set the script logging level (you can read about logging levels here )
- Filter logs only for our script. Without this, log analysis is impossible, 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 the script entry and exit. For example, for a listener whose Note field is defined as an NPEListener, the input and output logging lines will look like this:
log.info("NPElistener in") ... log.info("NPElistener out") For inline scripts that run in a business process, 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 is called in MyWorkflow, 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 a place to call the script on the transition ID
For scripts in the file system, input and output logging looks like this:
log.info("{} in", this.getClass()) ... log.info("{} out", this.getClass()) Logging the input and output helps to understand whether the script is finished or not. You can log the inputs and outputs of functions in a script or called modules. But it is necessary to determine it yourself, as far as necessary, and also to determine the level of logging.
I log in and out of the script with the INFO level in order to enable the log only of the inputs and outputs from the script when I do not need the context of the script execution. Levels work in such a way that they log all values that are equal to the specified level or higher. For example, the INFO level will log INFO, WARN, ERROR, FATAL levels, but will not log DEBUG and TRACE.
5. It is necessary to log the values of variables in the script
In order for us to understand the context of script execution, we must at least log the values of variables. The variables are logged like this:
log.debug("index: {}", index) I am logging context with DEBUG or TRACE.
Now let's try to rewrite the scripts that caused the incidents, using the approach outlined above, and see how this 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 in the logs such records:
2018-03-18 18:10:48,462 http-nio-8080-exec-36 INFO admin 1090x711x1 e9394m 127.0.0.1 /secure/WorkflowUIDispatcher.jspa [rmampostfunctions.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 [cosjira.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 [cosjira.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 Script16.run(Script16.groovy:7) From the logs we see that we entered the NPEPF inline script and did not exit it, which means the error occurred in it. In the text of the script, we see that the variable issue is not initialized.
Incident 2
The scripts that caused the error look like this:
pfNPE.groovy
import ru.matveev.UtilHelper List<String> 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<String> value) { Random rand = new Random() int max = 5 def index = rand.nextInt(max); return value.get(index) } } After adding logging, the scripts will be 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<String> 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<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) } } In order for us to see the logs in the atlassian-jira.log file, you need to install the loggers ru.matveev.alexey.main.helpers.UtilHelper and ru.matveev.alexey.main.postfunctions.pfNPE DEBUG level 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 [rmamain.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 [rmamain.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 [rmamain.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 [cosjira.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 [cosjira.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. 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 will also be able to understand where the script is called from and in what context.
Incident 4
There may be several options. For example, we can know exactly the script that is executed when assigning an artist. Then we enable 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 separate type of scripts (ru.matveev.alexey.main.listeners - only for listeners). Next, we can set the filtering of the log output by the loggers in the program that we use to view the logs, and receive information only about the logs we need. After that, we assign an artist and see what happens in the logs. If we have logged in scripts, we will get all the necessary information.
This is all that I would like to tell in this article. I would just like to add that you may want to log each line of the script. No need to do this, because then the script will be difficult to understand. It must be remembered that the readability of the program code is as important as logging.
Source: https://habr.com/ru/post/351412/
All Articles