В этой статье я хотел бы поговорить о логировании в Adaptivist ScriptRunner. Логи являются основным инструментом разработчиков и экспулатирующего персонала для анализа нештатных ситуаций в промышленной среде. Поэтому при разработке приложения мы должны подумать о том, что нам будет необходимо при анализе возникающих инцидентов.



Все примеры были подготовлены в Jira Software 7.8.0 и Adaptivist ScriptRunner 5.3.9.

Давайте предположим, что вы пришли на проект, который уже идет некоторое время, или же вы уже написали несколько десятков скриптов, и вот к вам приходит инцидент c ошибкой.

Пример Инцидента 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: <inline script>
java.lang.NullPointerException: Cannot invoke method getKey() on null object
    at Script1.run(Script1.groovy:4)

Из логов понятно, что это инлайн скрипт. Скрипт находится в каком-то бизнес процессе в переходе с ид 951. Далее мы должны запросить у эксплуатирующего персонала информацию о переходе с ид 951, и даже после того, как мы получим эту информацию, мы все равно не будем знать, этот скрипт находится в условии, валидаторе или пост функции. Кроме того мы понимаем, что NPE было получено потому, что какой-то объект был null, но мы не представляем, какой это объект и почему он был null. Мы должны сначала найти этот инлайн скрипт, а с этим у нас проблемы.

Пример Инцидента 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)

Здесь дела обстоят лучше. Мы видим, что ошибка в методе getIndexOutOfBoundsException, который был вызван скриптом pfNPE.groovy. Мы знаем местоположение данного скрипта. Но мы не знаем, где находится файл UtilHelper.groovy. Мы можем запустить поиск по файловой системе и, скорее всего, найдем файл UtilHelper, но мы также не понимаем, почему мы получили IndexOutOfBoundsException, какие значения были у массива, у которого мы выбирали элемент. То есть нам не хватает контекста, в котором выполнялся скрипт.

Пример Инцидента 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()

Здесь мы видим, что ошибка произошла во встроенной функции ScriptRunner, которая создает подзадачу. Но мы не знаем эта функция была добавлена в пост функцию, листенер или еще куда-нибудь. Кроме того у нас опять нет контекста выполнения скрипта.

Пример Инцидента 4

Не отправляется почта исполнителю задачи после назначения. Никаких ошибок в логах не обнаружено.

Допустим, мы знаем, что у нас оправляет почту наш кастомный скрипт, но как понять, что пошло не так в этом кастомном скрипте?

Итак, давайте попробуем систематизировать информацию, выдаваемую в логи, для того, чтобы:

• быстро находить требуемый скрипт
• определять контекст, в котором выполнялся скрипт
• понимать, что идет не так при выполнении скрипта
• искать требуемые нам логи среди большого количества других логов

1. Необходимо структурировать все наши скрипты в файловой системе

Я предпочитаю хранить скрипты по типу объекта. Например, пост функции будут храниться в директории ru/matveev/alexey/main/postfunctions, листенеры — в ru/matveev/alexey/main/listeners и так далее. Это поможет структурировать расположение скриптов и быстрее ориентироваться в многообразии скриптов (есть исключения, для которых данное структурирование неудобно, попробую об этом рассказать в другой статье).

2. Необходимо первой строкой определять пакет скрипта

Пакет скрипта определяет его местоположением в файловой системе. Например, для пост функций пакет будет определяться следующим образом:

package ru.matveev.alexey.main.postfunctions

Это нам поможет определять расположение скриптов. Например, у нас в Инциденте 2 в логах была вот такая запись:

   at ru.matveev.UtilHelper.getIndexOutOfBoundsException(UtilHelper.groovy:13)

Отсюда мы понимаем, что UtilHelper находится в ru/matveev.

3. Необходимо сразу после импортов определить логер скрипта

Как определить логер для скрипта в ScriptRunner можно найти здесь. Но я предпочитаю использовать SLF4J, так как синтаксис вывода логов мне кажется более удобным, чем в log4j. Например, логировать можно вот так:

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

Здесь в процессе выполнения скрипта, вместо фигурных скобок подставляются значения переменных var1 и var2.

Логер для скриптов, которые находятся в файловой системе, можно определять вот так:

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

В этом случае логер будет равен пакету скрипта плюс имя файла. Например, для файла pfNPE.groovy, у которого определен пакет ru.matveev.alexey.main.postfunctions, логер будет выглядеть вот так:

ru.matveev.alexey.main.postfunctions.pfNPE

Для инлайн скриптов необходимо явно указывать логер. Для этого сначала нужно обязательно заполнить поле Note при заведении инлайн скрипта. Это нам позволит точно определить исполняемый скрипт:



Далее мы определяем, где бы находился скрипт, если бы он размещался в файловой системе. На скриншоте выше мы добавляем листенер, поэтому этот файл рамещался бы в ru/matveev/alexey/main/listeners. Таким образом наш логер получается вот таким:

ru.matveev.alexey.main.listeners.NPElistener

Еще я добавляю .inline к логеру для того, чтобы понимать, что это инлайн скрипт и окончательный вид логера вот такой:

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

Логер позволяет нам:

• Устанавливать уровень логирования скрипта(про уровни логирования можно почитать здесь)
• Фильтровать логи только для нашего скрипта. Без этого анализ логов невозможен, так как Jira генерирует большое количество логов.

4. Логировать вход и выход из скрипта

Для инлайн скриптов сразу после определения логера я логирую вход в скрипт и выход из скрипта. Например, для листенера, у которого поле Note определено как NPEListener, строки логирования входа и выхода будут выглядеть вот так:

log.info("NPElistener in")
...
log.info("NPElistener out")

Для инлайн скриптов, которые выполняются в бизнес процессах, можно указывать еще название бизнес процесса, начальный статус, переход и значение поля Note. Например, вот так:

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

В этом случае вызывается скрипт в MyWorkflow, начальный статус In Progress, переход In Progress, значение Note OutOfIndexBoundsPF. Формат кодирования места вызова может быть любой.

Понятно, что название бизнес процесса или статуса может поменяться, и тогда информация станет неактуальной. В этом случае можно будет найти место вызова скрипта по ид перехода.

Для скриптов в файловой системе логирование входа и выхода выглядит вот так:

log.info("{} in", this.getClass())
...
log.info("{} out", this.getClass())

Логирование входа и выхода помогает понять, закончил ли скрипт работу или нет. Можно логировать входы и выходы из функций в скрипте или вызываемых модулях. Но это нужно определить самому, насколько это необходимо, а также определить уровень логирования.

Я логирую вход и выход из скрипта с уровнем INFO для того, чтобы можно было бы включить лог только входов и выходов из скрипта, когда мне не нужен контекст выполнения скрипта. Уровни работают таким образом, что они логируют все значения, которые равны установленному уровню или выше. Например, уровень INFO будет логировать уровни INFO, WARN, ERROR,FATAL, но не будет логировать DEBUG и TRACE.

5. Необходимо логировать значения переменных в скрипте

Для того, чтобы нам понимать контекст выполнения скрипта, мы должны как минимум залогировать значения переменных. Логирование переменных происходит вот так:

 log.debug("index: {}", index) 

Я логирую контекст уровнем DEBUG или TRACE.

Теперь давайте попробуем переписать скрипты, которые вызвали инциденты, используя подход, приведенный выше, и посмотрим, насколько это нам поможет анализировать эти инциденты.

Инцидент 1

Скрипт, который выдавал ошибку для Инцидента 1 выглядит вот так:

import com.atlassian.jira.issue.Issue

Issue issue
issue.getKey()

После добавления логирования скрипт будет выглядеть вот так:

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")

Для того, чтобы увидеть логи в файле atlassian-jira.log нужно зайти в System -> Logging and Profiling и установить уровень INFO для логера ru.matveev.alexey.main.postfunctions.NPEPF.inline. После этого мы увидим в логах вот такие записи:

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: <inline script>
java.lang.NullPointerException: Cannot invoke method getKey() on null object
	at Script16.run(Script16.groovy:7)

Из логов мы видим, что мы вошли в инлайн скрипт NPEPF и не вышли из него, а значит ошибка произошла именно в нем. В тексте скрипта мы видим, что переменная issue не инициализирована.

Инцидент 2

Скрипты, которые вызывали ошибку выглядят вот так:

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)
   }
}

После добавления логирования скрипты будут вот такими:

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)
   }
}

Для того, чтобы мы увидели логи в файле atlassian-jira.log необходимо установить логерам ru.matveev.alexey.main.helpers.UtilHelper и ru.matveev.alexey.main.postfunctions.pfNPE уровень DEBUG в System -> Logging and Profiling. После этого мы увидим следующие логи:

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)

Из логов мы понимаем. какие скрипты вызывались и где они находятся. Мы видим значения всех переменных. Можно открывать скрипты и пытаться понять, что пошло не так. Вся информация у нас есть.

Инцидент 3

Здесь нужно добавить логирование для инлайн скриптов и тогда мы тоже сможем понять, откуда вызывается скрипт и в каком контексте.

Инцидент 4

Здесь может быть несколько вариантов. Например, мы можем точно знать скрипт, который выполняется при назначении исполнителя. Тогда мы включаем DEBUG уровень для логера скрипта и смотрим логи. Если мы не знаем скрипт, то мы можем установить DEBUG уровень для всех скриптов (ru.matveev.alexey.main) или для отдельного типа скриптов (ru.matveev.alexey.main.listeners — только для листенеров). Дальше мы можем установить фильтрацию вывода логов по логерам в программе, которую мы используем для просмотра логов, и получать информацию только о необходимых нам логах. После этого мы назначаем исполнителя и смотрим, что происходит в логах. Если мы внесли логирование в скрипты, то мы получим всю необходимую информацию.

Это все, что я хотел бы рассказать в этой статье. Хотел бы только добавить, что может возникнуть желание залогировать каждую строчку скрипта. Не нужно этого делать, так как тогда скрипт будет сложен для понимания. Необходимо помнить, что читабельность программного кода также важна, как и логирование.