Logging

In order to successfully run an Axon Ivy Engine, you need to be prepared in case of errors or even failures. Therefore mission critical events are logged. Each event has a level:

FATAL systems runs partially or not at all
ERROR something is not working properly
WARNING warning which can lead someday to an error
INFO neutral message
DEBUG/TRACE low-level events, needed for troubleshooting

Axon Ivy comes with a sophisticated default log configuration which logs all warning, error and fatal events in the logs directory of the Axon Ivy Engine. The log files will be rotated and compressed every day.

Keep in mind that an unfavorable log configuration can lead to failures. For example, if the root log level is set to DEBUG, so many logs are written that the engine has no more resources for other tasks.

Customization

The logging configuration can be fully customized to your needs. For example, you can change the log level of a logger so that the log events are logged in a log file. Therefore you need to know that Axon Ivy uses Log4j 2 for logging and comes with a built-in default configuration which can be customized by providing a configuration in [engineDir]/configuration/log4j2.xml. The custom configuration will be merged with the default configuration automatically on the fly.

Runtime Log

The Runtime Log is a well-known designer feature and disabled by default in the Axon Ivy Engine to prevent a flood of log messages, which can decrease performance and filling the disk. But you can set the log level of a specific runtime logger and bring them even to another file to get the logs also on the Axon Ivy Engine.

The name of the runtime logger has a well defined format:

runtimelog.[app name].[process model name].[category]

Example:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
  <!-- custom appender for the Runtime Log which will log in file logs/runtime.log -->
  <Appenders>
    <RollingRandomAccessFile name="RuntimeLog" fileName="logs/runtime.log" filePattern="logs/runtime-%d{MM-dd-yyyy}.log.gz" ignoreExceptions="false">
      <PatternLayout pattern="${pattern}" />
      <TimeBasedTriggeringPolicy />
    </RollingRandomAccessFile>
  </Appenders>

   <Loggers>
    <!-- example to log runtime logs of application 'myapp' and process model 'hrm' -->
    <!-- will only pass logs to the appender with RuntimeLog -->
    <Logger name="runtimelog.myapp.hrm" level="debug" includeLocation="false" additivity="false">
      <AppenderRef ref="RuntimeLog" />
    </Logger>
  </Loggers>
</Configuration>

All available categories [category] are defined in the RuntimeLogCategory. Write them in lower case e.g. <Logger name="runtimelog.myapp.hrm.rest_client">.

Request Tracing

If you experience poor performance, you can trace the individual requests to the Axon Ivy Engine by setting the level of the request performance logger in [engineDir]/configuration/log4j2.xml:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
   <Loggers>
    <!-- logs the start and the end of a request -->
    <Logger name="ch.ivyteam.ivy.performance.request" level="all" />
  </Loggers>
</Configuration>

This will make a log when the request was received by the internal web server and when the request was processed with the time spent for processing.

A unique request identifier requestId is assigned to every request. This can be used to find out what the Axon Ivy Engine did while processing the request.

Example:

[2020-09-15 11:17:29.621][DEBUG][ch.ivyteam.ivy.performance.request][http-nio-8080-exec-10]{requestId=61}
Entry url=http://localhost:8080/system/ client=127.0.0.1 session=4 httpsession=71902C0036745F320CAAD55AFA85A281
[2020-09-15 11:17:29.630][DEBUG][ch.ivyteam.ivy.db][http-nio-8080-exec-10]{requestId=61, client=127.0.0.1, executionContext=SYSTEM}
Execute database statement SELECT * FROM IWA_ACCESSCONTROL 
[2020-09-15 11:17:29.630][DEBUG][ch.ivyteam.ivy.db][http-nio-8080-exec-10]{requestId=61, client=127.0.0.1, executionContext=SYSTEM}
Executed database statement successfully in 0 milli seconds 
[2020-09-15 11:17:29.637][DEBUG][ch.ivyteam.ivy.performance.request][http-nio-8080-exec-10]{requestId=61}
Exit url=http://localhost:8080/system/ client=127.0.0.1 session=4 httpsession=71902C0036745F320CAAD55AFA85A281 took 16ms

The example above shows the log messages when the request with id 61 has entered and exited the web server. During the request a database SELECT statement was executed. The whole request was processed in 16 ms.

Request Tracing Tools

If you use an external tracing tool that propagates a trace id as HTTP header then the trace id is used as requestId instead of the internally generated identifier. This allows you to aggregate log entries from different systems using the requestId. Axon Ivy Engine supports the following HTTP headers:

HTTP Header	Tool/Standard
traceparent	W3C Trace Context
uber-trace-id	Jaeger
b3	Zipkin
X-B3-TraceId	Zipkin
X-Amzn-Trace-Id	Amazon X-Ray
ot-tracer-traceid	Open Tracing

For a deeper integration with a tracing tool have a look at our Jaeger Tracing (Jaeger and OpenTelemetry) example.

Log format

A single event can be found as a log entry in the format [datetime][level][logger name][thread name]{context infos} followed by the message itself like:

[2020-09-15 11:19:30.351][DEBUG][ch.ivyteam.ivy.performance.classgraph][http-nio-8080-exec-10]{application=system, client=127.0.0.1, executionContext=SYSTEM, pmv=system$engine-cockpit$1, request=, requestId=79, session=1}
Annotation scanning for javax.faces.validator.FacesValidator in engine-cockpit-.iar.zip took 20ms