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.