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
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.
${sys:xserver.logdirectory}
as placeholder for the xServer logging directory and ${sys:processId}
as placeholder for the actual process (xserver or modules m0001, m0002, ...).
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn" monitorInterval="60">
...
</Configuration>
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. |
profileA 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. |
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.
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 for core.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.
Synopsis: Configuration steps to have HTTP request headers logged to a certain logfile :
core.logging.selectedRequestHeaders
in conf/xserver.conf
to make them available for logging.%X
for the context map to the conversion pattern of the logfile appender in conf/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:
%X
(cf. Log4j documentation).accept
is equal to Accept
.conf/xserver.conf
and conf/logging.xml
.conf/logging.xml
.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
.
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
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.