Logging
Axon.ivy uses a library called log4j to log certain events. The
logging configuration file is located in the engineDir/configuration
directory and is called log4jconfig.xml. By default log events are
written to the console and to log files. The log files are written to the
engineDir/logs
directory.
Each log message has a log level:
Log Level |
Description |
---|---|
FATAL |
This level is used to report problems that may cause the engine not to work correctly. |
ERROR |
This level is used to report problems that something has not worked as expected and may cause that the user gets an error message on the UI. |
WARN |
This level is used to report problems that have to be solved because it can lead to errors later. |
INFO |
This level is used to report that something was done. (E.g. for example a database call) |
DEBUG |
This level is used to report internal events. Most of these events are only interesting for developers. However, some of them may also be interesting for troubleshooting. |
You can control which log levels should be written to which logs. The following is configured as default:
Logging Type |
Log Level |
---|---|
Console log |
WARN |
File log |
INFO |
Windows Event Log |
FATAL |
Log Message Format
A log message looks like the following:
2018-11-20 12:23:17.910 INFO [runtimelog.LicenseOrder.LicenseOrder.db] [ivy background operation pool-thread-5] [request=call(36764.36363.0.0), session=491 (fred), task=36363, application=2, requestId=3634, executionContext=SYSTEM, pmv=LicenseOrder$LicenseOrder$1, processElement=156B16E81393F7E9-f3]
Executed database statement successfully in 2,787 milli seconds
The first entry of a log message is the exact time it was written
12:23:17.910
. Followed by the log level of the message INFO
. Next is the
log category [runtimelog.LicenseOrder.LicenseOrder.db]
. Then the name of the
thread in whichs context the log message was written follows [ivy background
operation pool-thread-5]
. The next section conains a lot of Axon.ivy context
information. For example the user session or the process model version that were
active when the log message was written. The content of the context information
can change depending on the context the log message was written. The following
context information exists:
Info |
Description |
---|---|
application |
The identifier of the current application. |
client |
The IP address and maybe the host name of the current web client. |
executionContext |
The security execution context that is used to check permissions. This can be the current session or SYSTEM if security is disabled. |
request |
Information about the current request is written to the log. |
requestId |
The identifier of the current request. Can be used to filter all messages that are written in the context of the same request. |
pmv |
The identification string of the current process model version. |
processElement |
The process element that is currently executed. |
hd |
The fully qualified name of the Html Dialog. |
session |
The current Axon.ivy session. The identifier of the session and the user name (if a user is logged in). |
task |
The identifier of the current task. |
On the next line the message that was logged follows. In case of errors a java exception stack trace may follow on the next lines.
Runtime Log
On the Axon.ivy Designer certain events of processes are logged to the runtime log view. The process designer itself can write to the runtime log using the ivy.log object. On the Axon.ivy Engine all information written to the runtime log is handled by Log4j. It is written to the console, to log files and to the Windows Event Log.
The runtime log entries are written to special log categories which names start with runtimelog followed by the application name, the process model name and the runtime log category. For example: the category name runtimelog.app.hrm.user_code represents the runtime log of the application called app, with the process model called hrm and the runtime log category user_code.
Examples:
The following xml snippet can be added to the Log4j configuration file so that
the runtime log of the process model hrm of the application app is
written to its own log file called runtimelog.app.hrm.log
:
<!-- Defines a log file called runtimelog.app.hrm.log -->
<appender name="RuntimeLog" class="org.apache.log4j.DailyRollingFileAppender">
<param name="File" value="${user.dir}/logs/runtimelog.app.hrm.log"/>
<param name="DatePattern" value="'.'yyyy-MM-dd"/>
<layout class="org.apache.log4j.IvyLog4jLayout">
<param name="DateFormat" value="HH:mm:ss"/>
</layout>
</appender>
<!-- Configures that the log category runtimelog.app.hrm has priority DEBUG and is written to the RuntimeLog file -->
<category name="runtimelog.app.hrm" class="ch.ivyteam.log.Logger">
<appender-ref ref="RuntimeLog"/>
<priority value="DEBUG"/>
</category>
Request/Performance Logging
If you want to know the time when a request was received from the Axon.ivy Engine and at what time the request processing of the engine was done, then you use the log category ch.ivyteam.ivy.webserver.internal.PerformanceLogValve
Configuration Example (log4jconfig.xml):
<!-- Configures that the log category ch.ivyteam.ivy.webserver.internal.PerformanceLogValve has priority DEBUG -->
<category name="ch.ivyteam.ivy.webserver.internal.PerformanceLogValve" class="ch.ivyteam.log.Logger">
<priority value="DEBUG"/>
</category>
The log category logs the entry of a request right after the internal web server has received it. The exit is logged after the request was processed by the web server. In the exit log message you find the duration of the request in microseconds.
The log level of the these messages is DEBUG
. Change the threshold of the
appenders to DEBUG
so that log messages with this priority are written to
the appender’s destination.
Configuration Example (log4jconfig.xml):
<appender name="FileLog" class="org.apache.log4j.DailyRollingFileAppender">
<param name="Threshold" value="DEBUG"/>
<param name="File" value="${user.dir}/logs/ivy.log"/>
<param name="DatePattern" value="'.'yyyy-MM-dd"/>
<layout class="org.apache.log4j.IvyLog4jLayout">
<param name="DateFormat" value="HH:mm:ss.SSS"/>
</layout>
</appender>
If you want to know what the Axon.ivy Engine has done between the entry and exit of the request you can use the context information requestId which you can find on every log message. A unique request identifier is assigned to every request. By filtering the log for messages with the same requestId you find out what kind of operations Axon.ivy Engine has done during the request.
Example:
10:49:40.904 DEBUG [...rformanceLogValve] [http-8081-1] [requestId=43]
Entry url=http://localhost:8080/ivy/pro/myapp/OpenEditor/13224891E742EE17/start4.ivp client=0:0:0:0:0:0:0:1 session=null httpsession=C900A5BC35251533DEB5B36E4316EE98
10:49:41.020 INFO [...nEditor.user_code] [http-8081-1] [application=2147483647, client=0:0:0:0:0:0:0:1, requestId=43, task=1, pmv=designer$OpenEditor$1, processElement=13224891E742EE17-f26-t, session=1, request=HTTP GET test.mod/start4.ivp(1.1.0.0), executionContext=1]
This is my log message
10:49:41.050 INFO [...ner.OpenEditor.db] [Process Extension Thread 1] [application=2147483647, client=0:0:0:0:0:0:0:1, requestId=43, task=1, pmv=designer$OpenEditor$1, processElement=13224891E742EE17-f29-bean, session=1, request=HTTP GET test.mod/start4.ivp(1.1.0.0), executionContext=SYSTEM]
Execute database statement SELECT * FROM IWA_ACCESSCONTROL
10:49:41.050 INFO [...ner.OpenEditor.db] [Process Extension Thread 1] [application=2147483647, client=0:0:0:0:0:0:0:1, requestId=43, task=1, pmv=designer$OpenEditor$1, processElement=13224891E742EE17-f29-bean, session=1, request=HTTP GET test.mod/start4.ivp(1.1.0.0), executionContext=SYSTEM]
Executed database statement successfully in 0 milli seconds
10:49:41.100 DEBUG [...rformanceLogValve] [http-8081-1] [requestId=43]
Exit url=http://localhost:8080/ivy/pro/myapp/OpenEditor/13224891E742EE17/start4.ivp client=0:0:0:0:0:0:0:1 session=1 httpsession=C900A5BC35251533DEB5B36E4316EE98 duration=194181 us
In the example above you see the log messages when the request with the id 43 has entered and exited the web server. There was also one user runtime log message written in the same request and one database call that has lasted 0 milliseconds. The whole request needed 19.418 ms to be processed.