Monitoring

A log message looks like the following:

10:19:14.173 INFO [ch.ivyteam.ivy.richdialog.exec.internal.panel.RichDialogPanelImpl] [http-8082-4] [application=0, client=127.0.0.1, task=4, pmv=System$Administration$1, session=4, request=Ulc over HTTP POST 115D746C75FAF428/start1.ivp, executionContext=SYSTEM] 
  Can not restore UI state. No user is logged in.

The first entry of a log message is the exact time it was written (10:19:14.173). Followed by the log level of the message (INFO). Next is the log category ([ch.ivyteam.ivy.richdialog.exec.internal.panel.RichDialogPanelImpl]). Then the name of the thread in whichs context the log message was written follows ([http-8082-4]). 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:

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.

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.

<!-- 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>

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 following log category:

ch.ivyteam.ivy.webserver.internal.PerformanceLogValve

Configuration Example (configuration/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 (configuration/log4jconfig.xml):

<appender name="FileLog" class="org.apache.log4j.DailyRollingFileAppender">
  <param name="Threshold" value="DEBUG"/>
  <param name="File" value="${user.dir}/logs/ch.ivyteam.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:8081/ivy/pro/designer/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:8081/ivy/pro/designer/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.

It is possible to log ULC communication and status messages both on client and server side. Both a default log level and a log level per known Ivy user can be configured, as well as a log file path/name where the log of an ULC session should be stored permanently.

To configure ULC logging, the files configuration/jnlpconfig.any and configuration/ulclogconfig.any within the Axon.ivy Engine installation folder must be edited. The former one controls the client-side logging, the latter one the server-side logging. The log configurations are similar in both cases and edited with Anything notation.

To modify the client logging properties locate the following section in jnlpconfig.any:

...
                    
/log-level  {
    /user-specific {
        /johndoe  FINER
    }    
    /default  WARNING
    /log-to-file   "C:/temp/xpertivy_ulc_client.log"
}    
...

To modify the server logging properties locate the following section in ulclogconfig.any:

{
    /user-specific {
        /johndoe  FINER
    }
    /default  WARNING
    /log-to-file  "xpertivy_ulc_server.log"
} 

To enable user-specific logging on server side and/or client side, enter the known name of the Ivy user (or AD user) to log for in the /user-specific section, followed by a valid log level (one of SEVERE, WARNING, INFO, FINE, FINER, FINEST) just as specified in the example configurations with the user johndoe. Use double quotes around the Ivy user name if it contains special (i.e. non-ASCII) characters or white space.

To set the default log level (which will be used for all sessions) set the log level for the key /default.

Finally, to enable logging to a file, enter a filename in double quotes for the key /log-to-file as shown above. If the /log-to-file slot is omitted altogether or if it's value is a *, then no logfile will be created.

On an Axon.ivy Engine it is possible to dump out performance statistic informations, periodically into a CSV formatted file. This allows to analyse the performance of the engine and to detect long running and performance intensive process elements and processes. The file contains detailed informations of each executed process element since the last dump.

After activation the informations are collected and written to the log-directory of the Axon.ivy Engine installation. The file contains the following name: performance_statistic_jjjj-mm-tt_hh-mm-tt.csv (e.g. performance_statistic_2011-03-15_09-21-05.csv)

All configurations are administered by the following System Properties:

All time values are in milliseconds. The execution of some process elements are separated in two categories internal and external.

For each executed process element one entry in the view is created. See the table below which information is available.

If the Axon.ivy Engine is running under another user or on a remote host than the monitoring tool, then JMX remote access has to be activated. Remote access is protected by a user name and password of an Axon.ivy Engine Administrator, so all Axon.ivy Engine Administrator have access.

On Windows uncommenting the following line in an ivy launch control file *.ilc (See chapter Windows Program Launcher Configuration) to activate remote access:

ivy.management.port=9003

On other operating systems the below options must be added to the launch configuration script of the engine (AxonIvyEngine.conf):

-Dcom.sun.management.jmxremote.port=9003 
-Dcom.sun.management.jmxremote.login.config=jmx
-Djava.security.auth.login.config=configuration/jaas.config
-Dcom.sun.management.jmxremote.ssl=false
-Djava.rmi.server.hostname=<IP of the machine>

Some monitoring tools can auto discover running JMX servers in the network. If so the user does not have to know the server host and JMX IP port. Instead he can simple click on the auto discovered server.

Axon.ivy Engine supports auto discovery by default if JMX is activated on Windows. However, you can disable this feature by uncommenting the following line in the *.ilc file::

ivy.management.autodiscovery=false

On other operating systems the following option must be set to the launch configuration script of the engine (AxonIvyEngine.conf) to activate it:

-Dcom.sun.management.jmxremote.autodiscovery=true

The Axon.ivy Engine provides performance and management information by a set of MBeans. These allow to monitor the Axon.ivy Engine. Most monitoring tools provide a user interface to browse the available MBeans. MBeans are mostly shown in a tree which is built with the information provided in the names of MBeans.

Figure 7.1. MBeans Tree of Axon.ivy shown in MBeans Plugin of VisualVM

The names of MBeans provided by Axon.ivy are structured so that the name contains the Application, Process Model, Process Model Version or Environment where this is reasonable.

The name and description of a MBean can be found in its meta information (see the Metadata tab in the MBeans tab of VisualVM). MBeans provide information through attributes and operations. The description of the attributes and operations can also be found in its meta information (see too the tool tips in the Attributes and Operations tab of the MBeans tab of VisualVM).

In addition to the MBeans provided by Axon.ivy some third party libraries included in Axon.ivy provide their own MBeans. One of them is Apache Tomcat that is used as internal web server. Its MBeans provide information about the handling of HTTP requests like request count, errors, execution time, sessions, etc. Moreover, the Java virtual machine also provides some MBeans that provide information about the used memory (Java heap), CPU usage, uptime, etc.

Below a not complete list of provided information:

In the delivery of Axon.ivy we provide a dedicated plugin for VisualVM that allows you to monitor some of the technical aspects of an Axon.ivy Engine or Designer. For example you can observe the current transactions on the System Database, whether you violate the licence or how many requests are running at an Axon.ivy Engine at any given time. And in the same tool you can still observe the heap or CPU usage or create thread dumps.

The plugin itself should be mostly self explanatory. It consists of multiple tabs for the different aspects. Most of the tabs contain a number of charts that always have a similar structure: