Logging
Logging Directory
Related file: conf/wrapper.conf,
All xServer logging configurations use a central logging directory. The default directory setting is defined by an environment variable in the wrapper.conf (cf. Default Environment Settings).
set.default.XSERVER2_LOG_DIRECTORY=./logs
Logging Configuration
Related files: conf/logging.xml, conf/logging-module.xml
The PTV xServer uses the log4j2-Framework for logging purposes.
Logging behavior is controlled by the configuration files conf/logging.xml
and conf/logging-module.xml
. These files contain the logging parameters for the server and the modules.
- File name: Typically you will want to use a rolling file appender that stores logs to a specified file name. The file name can be specified using
${sys:xserver.logdirectory}
as placeholder for the xServer logging directory and${sys:processId}
as placeholder for the actual process (xserver or modules m0001, m0002, ...). - Logging Interval:The logging configuration can be changed at runtime. These changes are checked and applied every 60 seconds.
To change this interval adjust the value of the setting monitorInterval:
<?xml version="1.0" encoding="UTF-8"?> <Configuration status="warn" monitorInterval="60"> ... </Configuration>
Predefined Logs
Request statistics log
Related file: ${sys:xserver.logdirectory}/request.statistics.log
By default PTV xServer logs statistic information on each request to the file ${sys:xserver.logdirectory}/request.statistics.log
. Per request one row is written with semicolon-separated values (CSV).
Header name | Content |
---|---|
timestamp |
The arrival time of a request. Example: |
id |
A server-provided ID for this request. Example: |
client host |
The IP of the client for this request. Example: |
user |
The user name when using http authentication. Default: |
port |
The port of the service used. Example: |
clusterId |
An ID for the server that can be assigned in |
service |
The service name and operation used in this request. Example: |
success |
Boolean value indication of the successfulness of this request. Example: |
log1 |
User logging slot, configurable with the caller context object. Useful to distinguish tenants or offices, test requests and so on. |
log2 |
User logging slot. |
log3 |
User logging slot. |
profile A profile is a collection of parameters used to configure the request. Full profiles consist of a number of specialized sub-profiles like the VehicleProfile which describes the properties of a vehicle. |
Profile name from the RequestBase. |
pool instance |
An ID for the concrete instance in the process pool. Example: |
module queueing |
Time that the request had to wait for a free backend module, in ms. |
module time |
Time spent in the backend module, the net computation time, in ms. |
total outer |
Total time for the request handling, in ms. |
use-cases |
Special use information, depending on service. Example: |
errorType |
Exception type, if applicable and available. |
errorMsg |
Exception message, if applicable and available. |
Server and module logs
The server process logs to the file ${sys:xserver.logdirectory}/xserver.log
. Each backend process logs to its own file named ${sys:xserver.logdirectory}/m0001.log
, ${sys:xserver.logdirectory}/m0002.log
and so on.
Request and response logging
To configure which requests and responses are to be logged, set core.logging.logRequests
or core.logging.logResponses
in conf/xserver.conf
to one of the following values:
true
All requests / responses are logged.exceptional
Only requests / responses which caused an exception are logged. Requests which are rejected or could not be validated against the WSDL / WADL are never logged.fatal
Only request which caused a fatal exception such as an internal error or a module restart are logged. This value is not a valid option forcore.logging.logResponses
.false
Requests / responses are not logged at all.
To log requests and responses to a different log file uncomment the RollingFile appender named RequestLog and the Logger RequestLogging in the configuration conf/logging.xml
. The requests and responses will then be written to the file ${sys:xserver.logdirectory}/requests.log
.
By default only exceptional requests and no responses are logged.
How to extend logging for HTTP request headers
Synopsis: Configuration steps to have HTTP request headers logged to a certain logfile :
- Add all HTTP request header names as comma-separated list to
core.logging.selectedRequestHeaders
inconf/xserver.conf
to make them available for logging. - Add the conversion specifier
%X
for the context map to the conversion pattern of the logfile appender inconf/logging.xml
Example: Log HTTP headers Accept
and traceparent
to ${sys:xserver.logdirectory}/request.statistics.log
:
conf/xserver.conf
:"core.logging.selectedRequestHeaders" : [ "accept", "traceparent" ]
conf/logging.xml
:<RollingFile fileName="${sys:xserver.logdirectory}/request-statistics.log" filePattern="${sys:xserver.logdirectory}/archive/request-statistics-%d{MM-dd-yyyy}.log.gz" name="RequestStatisticsLog"> <Policies> <TimeBasedTriggeringPolicy/> </Policies> <!-- Notice: Additional pattern provided here to assure that the column names are logged in an appropriate way. This works as the line with the column headers is logged with the marker 'LOG_HEADERS'. --> <PatternLayout> <MarkerPatternSelector defaultPattern="%d;%m;%X%n"> <PatternMatch key="LOG_HEADERS" pattern="%d;%m;http-headers%n"/> </MarkerPatternSelector> </PatternLayout> </RollingFile>
Additional information:
- HTTP header names can be used as keys for the context map to filter the output with the conversion specifier
%X
(cf. Log4j documentation). - HTTP header names are by specification case-insensitive, thus
accept
is equal toAccept
. - The notation of an HTTP header name should not differ between
conf/xserver.conf
andconf/logging.xml
. - The logging of HTTP headers can be applied to any logfile appender that is defined in
conf/logging.xml
. - To preserve the structure of the logfiles some characters like ';' etc. are by default converted to a replacement before they are logged.
Scripting logs
For scripting there's also a separate log file called ${sys:xserver.logdirectory}/scripting.log
. To enable scripting logs uncomment the RollingFile appender named ScriptingLog and the Logger ScriptingLogger in the configuration conf/logging.xml
.
Log Analysis
Performance Analysis
There are two ways of analyzing performance. The first one is to take a look at the module-specific access statistics. The statistics can be reset online to monitor a certain period of time.
The second way is to monitor the request time stamps in the log files. The dashboard comes with a function for exporting request time stamps into CSV format. This function requires adequate log settings:
-
file logging must be used
-
the log level for the RequestTimes category must be set to INFO
Analyzing Module Restarts
There are different types of restarts. The logfile contains information on each type which is necessary to see the reason of the restart.
When restarting all modules from the management console the following lines occur in the logfile.
2016-06-30 16:02:35,748;INFO;com.ptvgroup.xserver.runtime.Dispatcher$RollingRestarter;Rolling restart of all 1 module instances initiated.
2016-06-30 16:02:35,748;INFO;com.ptvgroup.xserver.runtime.Dispatcher$RollingRestarter;Rolling restart of module instance m0001.
2016-06-30 16:02:35,748;INFO;com.ptvgroup.xserver.runtime.ModuleAgent;Restarting module m0001 due to rolling restart.
2016-06-30 16:02:35,797;ERROR;com.ptvgroup.xserver.runtime.ModuleInstanceProcessWrapper;Module instance m0001 shutting down with exit code 1.
2016-06-30 16:02:35,797;INFO;com.ptvgroup.xserver.runtime.ProcessDestroyer;Process m0001, pid= 23160 destroyed, exit value 1.
2016-06-30 16:02:35,798;INFO;com.ptvgroup.xserver.runtime.ModuleInstanceProcessWrapper;Starting module instance m0001 in external process...
2016-06-30 16:02:40,391;INFO;com.ptvgroup.xserver.runtime.ModuleInstanceProcessWrapper;Module instance m0001 is up and running.
2016-06-30 16:02:40,891;INFO;com.ptvgroup.xserver.runtime.Dispatcher$RollingRestarter;Successful rolling restart of module instance m0001.
2016-06-30 16:02:40,892;INFO;com.ptvgroup.xserver.runtime.Dispatcher$RollingRestarter;Rolling restart finished.
When restarting the complete server by shutting down and starting again the following lines occur in the logfile. The exit code is 1.
2016-01-22 16:15:27,427;ERROR;com.ptvgroup.xserver.runtime.ModuleInstanceProcessWrapper;
Module instance m0001 shutting down with exit code 1.
2016-01-22 16:15:42,864;INFO;com.ptvgroup.xserver.runtime.ModuleInstanceProcessWrapper;
Starting module instance m0001 in external process...
2016-01-22 16:15:43,778;INFO;com.ptvgroup.xserver.runtime.ModuleInstanceProcessWrapper;
Module instance m0001 is up and running.
When the module crashes the statistics log ${sys:xserver.logdirectory}/request-statistics.log
shows the service operation called, indicates non-success with false
, and states Error communicating with backend module
. The exit code is arbitrary, very often the logs directory contains a file hs_err_pid<pid>.log
.
2016-06-30 16:08:54,131;32873119-cc55-4650-a9f9-c4ee5a960f32;0:0:0:0:0:0:0:1;unknown;50000;unknown-cluster;XCrash.exit;false;-;-;-;default;m0001;0;435;1615;null;com.ptvgroup.xserver.exceptions.FatalFault;Error communicating with backend module..
If a module does not respond to server pings for more than 5 seconds (can be configured with backendPingTimeout
in xserver.conf
) the framework assumes that the module hangs and tries to destroy the process. Here is what the log prints in this case:
2016-01-23 16:06:36,876;ERROR;com.ptvgroup.xserver.runtime.ModuleInstanceProcessWrapper;
Module instance m0001 did not answer ping for 5001 milliseconds.
2016-01-23 16:06:36,876;INFO;com.ptvgroup.xserver.runtime.XServer2Dispatcher;
Agent m0001 seems to be broken. Destroying process.
When a request exceeds the module timeout while it is running (see key moduleTimeout
in the xserver.conf
) the framework logs that the request has expired and that it is trying to delete the request. In addition the statistics log ${sys:xserver.logdirectory}/request-statistics.log
shows the service operation called, indicates non-success with false and does not contain an error message. The exit code is 0.
2016-06-30 16:14:37,779;INFO;com.ptvgroup.xserver.runtime.ModuleAgent;Request 6a972129-7cc4-4800-b82c-1971b3022113 is expired, trying to delete request.
2016-06-30 16:14:37,779;INFO;com.ptvgroup.xserver.runtime.ModuleAgent;Delete requested for 6a972129-7cc4-4800-b82c-1971b3022113.
2016-06-30 16:14:43,199;INFO;com.ptvgroup.xserver.runtime.ModuleInstanceProcessWrapper;Module instance m0001 shutting down with exit code 0.