Логирование

Этот раздел перенесён из документации Camunda 7 и в дальнейшем будет доработан с учётом особенностей OpenBPM Engine

Эта страница предоставляет информацию о логировании в Camunda.

SLF4J

Большинство модулей Camunda, включая движок Camunda, используют slf4j в качестве "фасада" для логировани. Это позволяет пользователям перенаправлять выходные данные для логирования в логирующий "бэкенд" по своему выбору, например, logback или log4j.

Предварительно сконфигурированное логирование с разделенныи=м движком управления процессами

При установке Camunda в качестве разделенного (shared) движка управления процессами на сервере приложений логирование в Camunda является предварительно сконфигурированным.

На всех серверах приложений кроме Wildfly логирование предварительно конфигурируется с использованием моста slf4j-jdk14. Это означает, что Camunda эффективно перенаправляет все свое логирование на Java Util Logging. Как SLF4J API, так и мост slf4j-jdk14 доступны в разделенном classpath, что означает, что они доступны в classpath всех приложений, задеплоенных на этих серверах.

На Wildfly логирование направляется в логирующую инфраструктуру JBoss. По умолчанию SLF4J API недоступен в classpath кастомизированных приложений.

Добавление логирующего бэкенда для использования его как встроенной функции

При использовании модулей Camunda Maven в кастомизированном приложении только slf4j API подтягивается транзитивно. Если вы не предоставляете никакого бэкенда, никакого логирования не произойдет.

Далее мы предлагаем два альтернативных примера настройки логирования. См. документацию по SLF4J, чтобы узнать больше подробностей о добавлении бэкенда для логирования.

Пример с использованием Java Util Logging

Если у вас нет особых предпочтений по бэкенду логирования, самая простая опция — это перенаправить логирование в Java Util Logging, добавив следующую Maven-зависимость:

<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>slf4j-jdk14</artifactId>
  <version>1.7.26</version>
</dependency>

Пример с использованием Logback

Для более тонких настроек логирования мы рекомендуем использовать Logback. Чтобы это сделать, необходимы следующие шаги:

Добавить зависимость logback:

<dependency>
  <groupId>ch.qos.logback</groupId>
  <artifactId>logback-classic</artifactId>
  <version>1.1.2</version>
</dependency>

Добавить файл с именем logback.xml. Пример конфигурации:

<configuration>

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <!-- encoders are assigned the type
         ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>

  <!-- openbpm engine -->
  <logger name="io.openbpm" level="info" />

  <!-- common dependencies -->
  <logger name="org.apache.ibatis" level="info" />
  <logger name="javax.activation" level="info" />
  <logger name="org.springframework" level="info" />

  <root level="debug">
    <appender-ref ref="STDOUT" />
  </root>

</configuration>

Также убедитесь в том, что mybatis используют SLF4J в качестве логера через добавление

LogFactory.useSlf4jLogging();

где-то в пределах вашего конфигурационного кода.

Контекст данных процесса

Чтобы предоставить детали текущего контекста выполнения для вхождений лога, мы кстанавливаем данные, специфичные для выполнения процесса, в Mapped Diagnostic Context (MDC).

Данные процесса хранятся в MDC в течение всего времени выполнения и удаляются оттуда после успешного выхода из контекста выполгнения. В случае, если выполнение привело к появлению исключений, данные хранятся в MDC до тех пор, пока вызывающий контекст, то есть JobExecutor или окружающие его команды не закончат с его логированием.

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

Чтобы получить доступ к MDC данным, вам необходимо подкорректировать паттерн логирования в вашей конфигурации логирования. Пример с использованием Logback мог бы выглядеть вот так:

<configuration>
  ...

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} context:[%X] - %msg%n</pattern>
    </encoder>
  </appender>

  ...
</configuration>

Если добавить context:[%X] к вашей конфигурации, то все значения, находящиеся в MDC в то время, когда формируется новое вхождение лога, будут отображаться. См. руководство по вашему фреймворку логирования, чтобы узнать больше информации по доступу к MDC, например, документацию по Logback.

Категории логирования

Движок управления процессами

Движок управления процессами логирует следующие категории

Логер Описание

io.openbpm.bpm.application

Логирует детали задеплоенного процессного приложения на движке

io.openbpm.bpm.container

Логирует операции с контекнером на движке

io.openbpm.bpm.engine.bpmn.behavior

Логирует операции, связанные с активностями BPMN

io.openbpm.bpm.engine.bpmn.parser

Логирует события, произошедшие во время парсинга BPMN моделей

io.openbpm.bpm.engine.cfg

Логирует детали инициализации в конфигурации движка управления процессами

io.openbpm.bpm.engine.cmd

Логирует начало и конец всех команд, выполняемых движком

io.openbpm.bpm.engine.cmmn.behavior

Логирует исключения, которые выбрасываются во время выполнения CMMN по присине несовместимого CMMN поведения

io.openbpm.bpm.engine.cmmn.operation

Логирует исключения во время выполнения CMMN операций

io.openbpm.bpm.engine.cmmn.transformer

Логирует операции CMMN трансформера, выполняемые движком

io.openbpm.bpm.engine.context

Логи контекстов команд, включая атомарные операции и BPMN стэк трейсы во время выполнений

Вы можете переопределить уровень лога (по умолчанию DEBUG) ждя BPMN стэк трейсов, см. раздел Параметры уровня логирования.

io.openbpm.bpm.engine.core

Логирует операции ядра движка, например, выполнение атомарных операций

io.openbpm.bpm.engine.dmn

Логирует исключения, которые выбрасываются во время оценки решений

io.openbpm.bpm.dmn.feel

Логирует события, кторые происходят во время оценки решений с помощью движка JUEL FEEL

io.openbpm.bpm.dmn.feel.scala

Логирует события, которые происходят во время оценки решений при помощи движка Scala FEEL

io.openbpm.feel.FeelEngine

Логирует события, которые происходят во время оценки выражений с помощью движка Scala FEEL

io.openbpm.bpm.engine.externaltask

Логер для внешних задач

io.openbpm.bpm.engine.identity

Логер IdentityService, например, логирует информацию о том, заблокирован ли пользователь

io.openbpm.bpm.engine.incident

Логирует детали обработки инцидента

io.openbpm.bpm.engine.jobexecutor

Логирует операции, выполняемые job executor-ом, такие как получение джобы

io.openbpm.bpm.engine.metrics

Логирует детали метрик движка

io.openbpm.bpm.engine.migration

Логирует исключения, которые выбрасываются во время миграции процесса

io.openbpm.bpm.engine.persistence

Логирует идентификации всех сущностей, которые движок вставляет/удаляет/обновляет в базе данных

io.openbpm.bpm.engine.plugin.admin

Логирует детали авторизации для администраторов, если подключен плагин AdministratorAuthorizationPlugin

io.openbpm.bpm.engine.pvm

Логирует операции Process Virtual Machine (PVM), например, вход/выход из активности, создание/удаление области видимости

io.openbpm.bpm.engine.rest.exception

Логирует исключения, выброшенные внутри REST API

io.openbpm.bpm.engine.script

Логирует детали обработки скриптов, например, оценку, компиляцию.

io.openbpm.bpm.engine.security

Логирует исключения, которые выбрасываются во время хэширования пароля

io.openbpm.bpm.engine.test

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

io.openbpm.bpm.engine.tx

Логирует детали транзакций, например, коммиты и откаты

io.openbpm.bpm.engine.util

Логирует операции утилит движка6 такие как парсинг XML, считывание стрима, проблемы с загрузкой классов, парсинг интервалов/продолжительности и т.д.

io.openbpm.bpm.webapp

Логирует события, происходящие в Camunda web apps (Cockpit, Tasklist и Admin), такие, как вход и выход из системы, инициируемое пользователем, а также информация по времени валидации кеша.

По умолчанию вывод движка содержит логи с уровнями ERROR, WARNING и INFO. Чтобы разрешить более подробное логирование информации, например, ддля целей отладки, сконфигурируйте уровень логирования DEBUG или TRACE.

ВНИМАНИЕ!: Вывод логеров может поменяться в более новых версиях Camunda.

ВНИМАНИЕ!: В Tomcat логирование управляется java.util.logging через реализацию Tomcat JULI. Заметьте, что уровни логирования DEBUG and TRACE в этом окружении называются FINE и FINEST.

Когда использовать логеры движка?

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

Команды базы данных

Чтобы проверить команды базы данных, выполненные движком, в большинстве случаев юудет достаточно поднять уровень логеров io.openbpm.bpm.engine.persistence и io.openbpm.bpm.engine.impl.persistence.entity. На уровне DEBUG они логируют все SQL запросы с их параметрами. При установке уровня в TRACE логируются также результаты этих запросов. Отметим, что если у запроса много результатов, лог будет большим.

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

  • io.openbpm.bpm.engine.persistence

  • io.openbpm.bpm.engine.impl.persistence.entity

  • io.openbpm.bpm.engine.impl.history.event

  • io.openbpm.bpm.engine.impl.batch

  • io.openbpm.bpm.engine.impl.cmmn.entity

  • io.openbpm.bpm.engine.impl.dmn.entity.repository

  • io.openbpm.bpm.engine.history

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

25-Nov-2019 15:15:57.870 FINE [thread-1] o.c.c.l.BaseLogger.logDebug ENGINE-03006 Cache state after flush: [
  PERSISTENT GroupEntity[development]
]
25-Nov-2019 15:15:57.871 FINE [thread-1] o.c.c.l.BaseLogger.logDebug ENGINE-03009 SQL operation: 'INSERT'; Entity: 'AuthorizationEntity[id=19ac0d96-0f8e-11ea-8b01-e4a7a094a9d6]'
25-Nov-2019 15:15:57.871 FINE [thread-1] o.a.i.l.j.BaseJdbcLogger.debug ==>  Preparing: insert into ACT_RU_AUTHORIZATION ( ID_, TYPE_, GROUP_ID_, USER_ID_, RESOURCE_TYPE_, RESOURCE_ID_, PERMS_, REV_ ) values ( ?, ?, ?, ?, ?, ?, ?, 1 )
25-Nov-2019 15:15:57.872 FINE [thread-1] o.a.i.l.j.BaseJdbcLogger.debug ==> Parameters: 19ac0d96-0f8e-11ea-8b01-e4a7a094a9d6(String), 1(Integer), development(String), null, 2(Integer), development(String), 2(Integer)
25-Nov-2019 15:17:17.075 FINE [thread-2] o.a.i.l.j.BaseJdbcLogger.debug ==>  Preparing: update ACT_ID_GROUP set REV_ = ?, NAME_ = ?, TYPE_ = ? where ID_ = ? and REV_ = ?
25-Nov-2019 15:17:17.076 FINE [thread-2] o.a.i.l.j.BaseJdbcLogger.debug ==> Parameters: 2(Integer), Dev-Department(String), DEV(String), development(String), 1(Integer)

Чтобы включить логирование для определенной сущности базы данных, предоставьте пространство имен для MyBatis-маппера (все мапперы). Обычно это полное имя класса для данной сущности, например:

  • io.openbpm.bpm.engine.impl.batch.BatchEntity

  • io.openbpm.bpm.engine.impl.persistence.entity.JobEntity

  • io.openbpm.bpm.engine.impl.persistence.entity.VariableInstanceEntity

Чтобы получить больше информации, см. документацию MyBatis по логированию.

Диагностика выполнения джоб

Чтобы диагностировать поведение Job Execution, на старте переключите уровень следующих логеров в DEBUG:

  • io.openbpm.bpm.engine.impl.persistence.entity.JobEntity — логирует информацию, касающуюся непосредственно выполнения джоб

  • io.openbpm.bpm.engine.jobexecutor — другая информация по выполнению джоб, такая как получение джобы и операции по выполнению

  • io.openbpm.bpm.engine.cmd — начало/окончание команд поможет определить, с какой команды началось выполнение джобы

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

25-Nov-2019 15:45:27.613 INFO [main] o.c.c.l.BaseLogger.logInfo ENGINE-14014 Starting up the JobExecutor[io.openbpm.bpm.engine.impl.jobexecutor.RuntimeContainerJobExecutor].
25-Nov-2019 15:45:27.615 INFO [Thread-6] o.c.c.l.BaseLogger.logInfo ENGINE-14018 JobExecutor[io.openbpm.bpm.engine.impl.jobexecutor.RuntimeContainerJobExecutor] starting to acquire jobs
25-Nov-2019 15:45:27.619 FINE [Thread-6] o.c.c.l.BaseLogger.logDebug ENGINE-13005 Starting command -------------------- AcquireJobsCmd ----------------------
25-Nov-2019 15:45:27.620 FINE [Thread-6] o.c.c.l.BaseLogger.logDebug ENGINE-13009 opening new command context
25-Nov-2019 15:45:27.689 FINE [Thread-6] o.a.i.l.j.BaseJdbcLogger.debug ==>  Preparing: select RES.ID_, RES.REV_, RES.DUEDATE_, RES.PROCESS_INSTANCE_ID_, RES.EXCLUSIVE_ from ACT_RU_JOB RES where (RES.RETRIES_ > 0) and ( RES.DUEDATE_ is null or RES.DUEDATE_ <= ? ) and (RES.LOCK_OWNER_ is null or RES.LOCK_EXP_TIME_ < ?) and RES.SUSPENSION_STATE_ = 1 and (RES.DEPLOYMENT_ID_ is null ) and ( ( RES.EXCLUSIVE_ = 1 and not exists( select J2.ID_ from ACT_RU_JOB J2 where J2.PROCESS_INSTANCE_ID_ = RES.PROCESS_INSTANCE_ID_ -- from the same proc. inst. and (J2.EXCLUSIVE_ = 1) -- also exclusive and (J2.LOCK_OWNER_ is not null and J2.LOCK_EXP_TIME_ >= ?) -- in progress ) ) or RES.EXCLUSIVE_ = 0 ) LIMIT ? OFFSET ?
25-Nov-2019 15:45:27.692 FINE [Thread-6] o.a.i.l.j.BaseJdbcLogger.debug ==> Parameters: 2019-11-25 15:45:27.621(Timestamp), 2019-11-25 15:45:27.621(Timestamp), 2019-11-25 15:45:27.621(Timestamp), 3(Integer), 0(Integer)
25-Nov-2019 15:45:27.693 FINE [Thread-6] o.a.i.l.j.BaseJdbcLogger.debug <==      Total: 1
25-Nov-2019 15:45:27.695 FINE [Thread-6] o.c.c.l.BaseLogger.logDebug ENGINE-13011 closing existing command context
25-Nov-2019 15:45:27.699 FINE [Thread-6] o.a.i.l.j.BaseJdbcLogger.debug ==>  Preparing: update ACT_RU_JOB SET REV_ = ?, LOCK_EXP_TIME_ = ?, LOCK_OWNER_ = ?, DUEDATE_ = ?, PROCESS_INSTANCE_ID_ = ?, EXCLUSIVE_ = ? where ID_= ? and REV_ = ?
25-Nov-2019 15:45:27.703 FINE [Thread-6] o.a.i.l.j.BaseJdbcLogger.debug ==> Parameters: 90(Integer), 2019-11-25 15:50:27.695(Timestamp), 62eae13f-c636-4a21-a80e-c82fc028a959(String), 2019-11-25 00:01:00.0(Timestamp), null, true(Boolean), 9e1a4275-0c41-11ea-8035-e4a7a094a9d6(String), 89(Integer)
25-Nov-2019 15:45:27.706 FINE [Thread-6] o.c.c.l.BaseLogger.logDebug ENGINE-13006 Finishing command -------------------- AcquireJobsCmd ----------------------

Узнайте больше о диагностике Job Executor в это блог-посте — The Job Executor: What Is Going on in My Process Engine?.

Диагностика Deadlock-ов

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

  • io.openbpm.bpm.engine.persistence — persistence логер будет логировать идентичности всех сущностей движка, чтобы определить, какие ресурсы вызывают deadlock

  • io.openbpm.bpm.engine.cmd — командный вывод поможет определить скоуп вовлеченных в ситуацию транзакций, которые вызывают deadlock

Когда проблема появляется для специфической сущности (например, VariableInstance), подумайте о том, чтобы подключить логирование также и конкретно для cэтой сущности (io.openbpm.bpm.engine.impl.persistence.entity.VariableInstanceEntity). Тогда вывод будет включать все вхождения от этих сущностей, чтобы можно было посмотреть на произошедшие изменения.

Далее приведен пример трейсов, которые будет содержать лог-файл сервера при поднятии уровня для этих логеров.

25-Nov-2019 16:00:50.675 FINE [thread-1] o.c.c.l.BaseLogger.logDebug ENGINE-13005 Starting command -------------------- RemoveExecutionVariablesCmd ----------------------
25-Nov-2019 16:00:50.676 FINE [thread-1] o.c.c.l.BaseLogger.logDebug ENGINE-13009 opening new command context
25-Nov-2019 16:00:50.718 FINE [thread-1] o.c.c.l.BaseLogger.logDebug ENGINE-03006 Cache state after flush: [
  PERSISTENT VariableInstanceEntity[0ec1ab1d-0f8d-11ea-8b01-e4a7a094a9d6]
  PERSISTENT ProcessDefinitionEntity[invoice:2:ae69d3b4-0c41-11ea-a8eb-e4a7a094a9d6]
  PERSISTENT HistoricVariableUpdateEventEntity[5eba854e-0f94-11ea-92d9-e4a7a094a9d6]
  PERSISTENT ExecutionEntity[0ec04b8b-0f8d-11ea-8b01-e4a7a094a9d6]
  PERSISTENT UserOperationLogEntryEventEntity[5ebb6faf-0f94-11ea-92d9-e4a7a094a9d6]
  PERSISTENT HistoricVariableInstanceEntity[ddea4bef-0f93-11ea-b2ca-e4a7a094a9d6]
]
25-Nov-2019 16:00:50.722 FINE [thread-1] o.c.c.l.BaseLogger.logDebug ENGINE-03008 Flush Summary: [
  INSERT UserOperationLogEntryEventEntity[5ebb6faf-0f94-11ea-92d9-e4a7a094a9d6]
  INSERT HistoricVariableUpdateEventEntity[5eba854e-0f94-11ea-92d9-e4a7a094a9d6]
  DELETE VariableInstanceEntity[ddea4bef-0f93-11ea-b2ca-e4a7a094a9d6]
  UPDATE HistoricVariableInstanceEntity[ddea4bef-0f93-11ea-b2ca-e4a7a094a9d6]
]
25-Nov-2019 16:00:50.725 FINE [thread-1] o.c.c.l.BaseLogger.logDebug ENGINE-03009 SQL operation: 'INSERT'; Entity: 'HistoricVariableUpdateEventEntity[id=5eba854e-0f94-11ea-92d9-e4a7a094a9d6]'
25-Nov-2019 16:00:50.726 FINE [thread-1] o.c.c.l.BaseLogger.logDebug ENGINE-03009 SQL operation: 'DELETE'; Entity: 'VariableInstanceEntity[id=ddea4bef-0f93-11ea-b2ca-e4a7a094a9d6]'
25-Nov-2019 16:00:50.727 FINE [thread-1] o.a.i.l.j.BaseJdbcLogger.debug ==>  Preparing: delete from ACT_RU_VARIABLE where ID_ = ? and REV_ = ?
25-Nov-2019 16:00:50.728 FINE [thread-1] o.a.i.l.j.BaseJdbcLogger.debug ==> Parameters: ddea4bef-0f93-11ea-b2ca-e4a7a094a9d6(String), 2(Integer)
25-Nov-2019 16:00:50.730 FINE [thread-1] o.c.c.l.BaseLogger.logDebug ENGINE-03009 SQL operation: 'UPDATE'; Entity: 'HistoricVariableInstanceEntity[id=ddea4bef-0f93-11ea-b2ca-e4a7a094a9d6]'
25-Nov-2019 16:00:50.737 FINE [thread-1] o.c.c.l.BaseLogger.logDebug ENGINE-13006 Finishing command -------------------- RemoveExecutionVariablesCmd ----------------------

Этот фрагмент содержит начало и конец RemoveExecutionVariablesCmd, flush summary операции и команды базы данных для экземпляра переменной.

Легаси: Java Util Logging

Некоторые модули Camunda все еще используют Java Util Logging напрямую. Использование Java Util Logging в этих модулях считается deprecated, и в будущих релизах будет постепенно проведена миграция на slf4j.

Список модулей, все еще использующих Java Util Logging:

  • camunda-ejb-service

  • camunda-ejb-client

  • camunda-jobexecutor-ra

  • camunda-jobexecutor-rar

  • camunda-engine-cdi

  • camunda-engine-spring

  • camunda-engine-rest

  • Подсистемы Wildfly

Лицензия и атрибуция

Эта документация была создана на базе материала "Camunda 7 Docs" от Camunda, находится под лицензией Creative Commons Attribution-ShareAlike 3.0 Unported License .

Оригинал документации: https://docs.camunda.org