Event Logging

As part of the monitoring and diagnostic capabilities, the WebSphere® Application Server Liberty generates events at various components of Java Platform, Enterprise Edition to track the requests. The eventLogging-1.0 feature logs such events when the application requests are running. Using this feature, the user can track the requests that are running in the WebSphere Application Server Liberty. Each request is associated with a unique correlator called the request ID and the context information that helps the user to understand the request-specific data.

The event logging feature is controlled through the server configuration. The feature is configured in the server.xml file.

The following sample log shows the end-to-end event logs for the AAY6TalVDTO_AAAAAAAAAAK request ID and TradeWeb context:

[12/15/14 18:24:29:528 IST] 0000002e EventLogging		I BEGIN requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.servlet.service # contextInfo=TradeWeb | TradeScenarioServlet
[12/15/14 18:24:29:531 IST] 0000002e EventLogging		I BEGIN requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.servlet.service # contextInfo=TradeWeb | TradeAppServlet
[12/15/14 18:24:29:532 IST] 0000002e EventLogging		I BEGIN requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.servlet.service # contextInfo=TradeWeb | /quote.jsp
[12/15/14 18:24:29:533 IST] 0000002e EventLogging		I BEGIN requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.servlet.service # contextInfo=TradeWeb | /displayQuote.jsp
[12/15/14 18:24:29:534 IST] 0000002e EventLogging		I BEGIN requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.datasource.psExecuteQuery # contextInfo=jdbc/TradeDataSource | select * from quoteejb q where q.symbol=?
[12/15/14 18:24:29:547 IST] 0000002e EventLogging		I END requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.datasource.psExecuteQuery # contextInfo=jdbc/TradeDataSource | select * from quoteejb q where q.symbol=? # duration=12.537ms
[12/15/14 18:24:29:556 IST] 0000002e EventLogging		I END requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.servlet.service # contextInfo=TradeWeb | /displayQuote.jsp # duration=22.171ms
[12/15/14 18:24:29:671 IST] 0000002e EventLogging		I BEGIN requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.servlet.service # contextInfo=TradeWeb | /displayQuote.jsp
[12/15/14 18:24:29:672 IST] 0000002e EventLogging		I BEGIN requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.datasource.psExecuteQuery # contextInfo=jdbc/TradeDataSource | select * from quoteejb q where q.symbol=?
[12/15/14 18:24:29:677 IST] 0000002e EventLogging		I END requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.datasource.psExecuteQuery # contextInfo=jdbc/TradeDataSource | select * from quoteejb q where q.symbol=? # duration=4.968ms
[12/15/14 18:24:29:684 IST] 0000002e EventLogging		I END requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.servlet.service # contextInfo=TradeWeb | /displayQuote.jsp # duration=12.569ms
[12/15/14 18:24:29:685 IST] 0000002e EventLogging		I END requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.servlet.service # contextInfo=TradeWeb | /quote.jsp # duration=152.752ms
[12/15/14 18:24:29:686 IST] 0000002e EventLogging		I END requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.servlet.service # contextInfo=TradeWeb | TradeAppServlet # duration=154.616ms
[12/15/14 18:24:29:687 IST] 0000002e EventLogging		I END requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.servlet.service # contextInfo=TradeWeb | TradeScenarioServlet # duration=158.283ms

The request begins at the BEGIN websphere.servlet.service "contextInfo=TradeWeb | TradeScenarioServlet" event (refer to the first line in the sample code) and ends at END websphere.servlet.service "contextInfo=TradeWeb | TradeScenarioServlet" (refer to the last line in the sample code). The total time that is taken by this request is also displayed at the end (which is 158.283 ms in the sample code).

You can look at the child requests by looking at the BEGIN and END of the main request. You can also find the time that is taken by each of the child request.

For best performance, you might use binary logging when event logging is enabled. The eventType, contextInfo, and requestID attributes from the event log entries are stored as log record extensions. You can use those log record extensions to filter the logs with the binaryLog command.

Parsing the event log entries in the messages.log file

The event logs capture the information of the events in the following format:

[Log mode] [Request Identifier] # [Event Type] # [Context Information] # [Duration] (optional)

In this example:

Log mode indicates whether the log was recorded at the entry to the event or the exit from the event. BEGIN refers to the entry to the event and END refers to the exit from the event.
Request identifier is a unique string that is assigned to each request. This can be used for filtering events that belong to a particular request. Example: requestId=AAY6TalVDTO_AAAAAAAAAAK .
Event type provides information about the event source and can be any of the supported event types as given in the following table. The event type can be used for filtering events of a specific type. Example: eventType=websphere.servlet.service.
Context information of the event provides details relevant to the event type. The information varies depending on the event type. Context information can contain multiple sections and are separated by | (space|space). Examples of the context information for various event types are given in the following table.
Duration indicates the time that is taken by the event. The duration appears only in the exit event entries. See the following example: duration=158.283ms
Except the log mode, which is separated by a space, all other log attributes are separated by # (space#space). For example,
```
[12/15/14 18:24:29:687 IST] 0000002e EventLogging	I END requestID=AAY6TalVDTO_AAAAAAAAAAK # eventType=websphere.servlet.service # contextInfo=TradeWeb | TradeScenarioServlet # duration=158.283ms
```

The following table lists the event types that are supported by event logging:

Table 1. Supported event types along with the relevant context information
Component	Event types	Context information	Example
Servlet	websphere.servlet.destroy websphere.servlet.service	[Application Name] \| [Servlet Name] \| [Path Information] \| [Query String]	`contextInfo=TradeWeb \| /displayQuote.jsp`
Session	websphere.session.dbSessionDestroyedByTimeout, websphere.session.dbSessionDestroyed websphere.session.sessionAccessed websphere.session.sessionCreated websphere.session.sessionDestroyedByTimeout websphere.session.sessionDestroyed websphere.session.sessionLiveCountDec websphere.session.sessionLiveCountInc websphere.session.sessionReleased websphere.session.getAttribute websphere.session.setAttribute	[Session Id] [Session Id] \| [Session Attribute Name]	`contextInfo=EuitabHZUOD7J2u01HDdAG0` `contextInfo=EuitabHZUOD7J2u01HDdAG0 \| userID`
JDBC	websphere.datasource.execute websphere.datasource.executeQuery websphere.datasource.executeUpdate websphere.datasource.psExecute websphere.datasource.psExecuteQuery websphere.datasource.psExecuteUpdate websphere.datasource.rsCancelRowUpdates websphere.datasource.rsDeleteRow websphere.datasource.rsInsertRow websphere.datasource.rsUpdateRow	[Jndi Name Of Data Source] \| [SQL Query]	`contextInfo=jdbc/TradeDataSource \| select * from quoteejb q where q.symbol=?`