Skip to main content
Version: 3.14.x.x LTS

Debugging

For troubleshooting, you can get more detailed information by increasing the log levels. The following type of tracings are available:

  • Apache tracing
  • Servlet container tracing
  • nevisProxy tracing
  • Isiweb tracing
  • SSL tracing

To adjust the tracing of the servlet container, you have to edit the bc.properties file. For further information on how to proceed, see the chapter Configuration of server instances in Server handling.

General tracing properties​

NameTypeDescription
BC.Tracer.ThresholdBase0 - 10The threshold base for all trace groups. It is strongly recommended that you set the threshold base to severity level "5" (Notice) at the least. By doing so, recommended settings, deprecated notices and other useful information appear in the logs.
BC.Tracer.MaxLogFileVersionsintegerThe number of rotated log files that will be written. This property will be ignored if the 'BC.Tracer.LogFile' is a pipe
BC.Tracer.MaxLogFileSizeintegerThe maximum size of a log file. This property will be ignored if the 'BC.Tracer.LogFile' is a pipe
BC.Tracer.TimeFormat( ctime | detailed | time0 )The time format traced in the log file.
BC.Tracer.LogFileAccessOctal file mask or comma-separated list of 'onwer', 'group', and 'other'. Default: 0640File mask that determines the log file permissions (e.g., default 0640 is -rw-r-----). Note: Read and write flags for user are always set, regardless of the actual file mask used. If the comma-separated list is used, the corresponding write-bit will be added. This property will be ignored if the 'BC.Tracer.LogFile' is a pipe.
BC.Tracer.LogFileCompressionStringYou may specify a program or script which shall be used to compress rotated files, e.g. /usr/bin/gzipThis property will be ignored if the 'BC.Tracer.LogFile' is a pipe
BC.Tracer.LogFileStringCan be the name of a file or an external program start with pipe::/<external program>
BC.Tracer.Pipe.RetryIntervalIntegerInterval in milliseconds for piped log files only (BC.Tracer.LogFile=pipe::/<external program>). The timeout in milliseconds if the external program needs to be restarted. During that time no requests will be processed. Default: 0 (no interval).
BC.Tracer.Pipe.MaxRetriesIntegerFor piped log files only (BC.Tracer.LogFile=pipe::/<external program>). The number of maximal retries to start the external program (if it needs to be restarted). During restart no requests will be processed. If after 'BC.Tracer.Pipe.MaxRetries' the external program can still not be started, you may lose some log information.Default: 0 (no interval, continue to attempt restarts without pausing in between).
BC.Tracer.ProgNameStringThe program name that appears on each line of the log file, just after the date. If not defined, the nevisProxy version will be logged. For example: 2019 02 01 11:53:37.600 3.14.0.0 IW4Esau4Co 30371.140514241705728 5-NOTICE: Esauth4ConnectorServlet_1_0::pollTerminatedSessions: (NevisAuthConnector)
BC.Tracer.LogDirStringIn which directory to save the log files. This property will be ignored if 'BC.Tracer.LogFile' is either a pipe or an absolute filename.
BC.Tracer.LogFileAppendBooleanIf 'true', then the log will be added to the existing file (if any), otherwise a new file will be created (and the old one removed). This property will be ignored if the 'BC.Tracer.LogFile' is a pipe.
BC.Tracer.LogFileReopenIntervalIntegerInterval in seconds. If during this time nothing is logged, the logfile will be closed and reopened again on the next log-entry. This property will be ignored if the 'BC.Tracer.LogFile' is a pipe.
BC.Tracer.VersioningTimesStringInterval on which a logfile will be rotated. The format is the same like crontab: <minutes> <hours> <days> <months> <weekdays>. The time and date fields and allowed values are the following:
  • minute 0-59
  • hour 0-23
  • day of month 1-31
  • month 1-12
  • day of week 0-6
A field may be an asterisk (*), which always stands for "first-last". This property will be ignored if the 'BC.Tracer.LogFile' is a pipe or if a BC.Tracer.MaxLogFileSize is set.
BC.Tracer.LogArchiveFormatStringThe format of the archived logfile (after rotation). Legal specifiers are:
  • %Y (4-digit year)
  • %y (last two digits of year [00..99])
  • %m (month [01..12])
  • %d (day of month [01..31])
  • %H (hour [00..23])
  • %M (minute [00..59])
  • %f (filename without extension)
This property will be ignored if the 'BC.Tracer.LogFile' is a pipe.
BC.Tracer.LogArchiveDirStringDefines the directory where to save the archived files. If none is set, then the directory where the log file is located will be used. This property will be ignored if the BC.Tracer.LogFile is a pipe
BC.Tracer.DebugProfile.Secrets.CipherStringDefines the cipher to encrypt the sensitive data within the log. The following ciphers are supported:
  • AES: Corresponds to the OpenSSL cipher "aes-128-cbc".
  • DES: Corresponds to the OpenSSL cipher "des-cbc".
  • Blowfish: Corresponds to the OpenSSL cipher "bf-cbc".
  • DESede: Corresponds to the OpenSSL cipher "des-ede3".
  • RC4: Corresponds to the OpenSSL cipher "rc4".
The default is "AES"
BC.Tracer.DebugProfile.<tracegroup>.Secrets.Key=<key>StringDefines the key to encrypt the sensitive data for the given trace group.*If no key is set, the string "***" will be traced.* If the trace level is lower than DEBUG_LOW, a "**" will be traced. In all other cases the sensitive data will be encrypted with the given cipher (see BC.Tracer.DebugProfile.Secrets.Cipher) and the given <key>. Encrypted data can be decrypted with the openssl command below.
echo "<encrypted data>" | openssl enc -d -a -<cipher> -K `bin2hex <key>` -iv `bin2hex 0123456789ABCDEF`

The binary bin2hex is delivered with the nevisProxy package. You can find it in "/opt/nevisproxy/bin".

NameTypeDescription
ch.nevis.navajo.tracing.TraceId.FormatStringPossible values are:%i:
  • %i: Remote address
  • %p: Process identifier (PID)
  • %h: Host ID
  • %t: Timestamp
  • %c: Counter
  • %u: Sets a unique ID (%i-%p-%h-%t-%c) as well as the UNIQUE_ID variable in the Apache environment variables (apache-env)
  • %H[<name>]: Value of <name> in the request header
  • %E[<name>]: Value of <name> in the Apache environment variables (apache-env)
  • %C: The name of the connector
  • %X: The name or address of the context
The default is "%u" (to make the tracing backward compatible). If "%u" is set, theUNIQUE_ID(Apache environment variablesapache-env) adopts this value. If "%u" is not set, theUNIQUE_IDwill adopt the resulting value of the trace ID. To be sure that the ID is unique, the following values should be set:either: %u* or (at least): %p, %h, %t, and %c
ch.nevis.navajo.tracing.ReconfigurationPeriodInteger, default is 60 secDynamically checks the bc.properties file for changes and reapplies tracing configuration.

Servlet container trace group​

The servlet container trace groups adjust the verbosity of the messages regarding the Navajo container recorded in the navajo.log file. For an overview of the various log levels, see Log level below.

NameTypeDescription
BC.Tracer.DebugProfile.NavajoResource0 - 10Memory consumption.
BC.Tracer.DebugProfile.NavajoRequest0 - 10Request processing.
BC.Tracer.DebugProfile.NavajoSSL0 - 10SSLCache handling.
BC.Tracer.DebugProfile.NavajoCookie0 - 10CookieCache handling.
BC.Tracer.DebugProfile.NavajoSession0 - 10Session handling. For an example, see.
BC.Tracer.DebugProfile.NavajoStart0 - 10Tracing during booting.
BC.Tracer.DebugProfile.NavajoConfig0 - 10Tracing of the generated configuration file for Apache2.
BC.Tracer.DebugProfile.NavajoOp0 - 10Tracing processing time of the invoked filters/servlets and request/response headers. For an example, see.
BC.Tracer.DebugProfile.NavajoDump0 - 10Dumping the response written to the client.
BC.Tracer.DebugProfile.NavajoTimer0 - 10Tracing of the internal timer.
BC.Tracer.DebugProfile.NavajoHttpSess6 - 7Periodical tracing of session statistics.
BC.Tracer.DebugProfile.NavajoReqIO0 - 10Tracing of the IO operation of the request.
BC.Tracer.DebugProfile.NProxyOp0 - 10Single line tracing of backend and frontend calls with processing time statistics. For an example, see.
bc.security.PassPhrasePolicyString default is: 'pipe,env,prompt'Controls password access: pipe: Executes the command set in the propertybc.security.PassPhraseDialog(see below). env: The package uses a prefetching mechanism and passes the passphrases via env. * prompt: The passphrases are read from the controlling terminal (if possible).
bc.security.PassPhraseDialogstring default is: 'pipe://@KEYBOX_HOME@/@KEYBOX_VERSION@/bin/keystorepwget'Command to execute if the property bc.security.PassPhrasePolicy is set to "pipe".

nevisProxy trace groups​

The nevisProxy trace groups adjust the verbosity of the messages recorded in the log file regarding specific nevisProxy filters and servlets. For an overview of the various log levels, see Log level below.

NameTypeComponent
BC.Tracer.DebugProfile.NPAuthFilter0 - 10Traces the functioning of and defines the log level for the AuthenticationFilter.
BC.Tracer.DebugProfile.NPParamVldFlt0 - 10Traces the functioning of and defines the log level for the ParameterValidationFilter.
BC.Tracer.DebugProfile.NPHdrVldFlt0 - 10Traces the functioning of and defines the log level for the HeaderValidationFilter.
BC.Tracer.DebugProfile.NPSessionFlt0 - 10Traces the functioning of and defines the log level for the SessionManagementFilter.
BC.Tracer.DebugProfile.NPDynCfgFlt0 - 10Traces the functioning of and defines the log level for the DynamicConfigFilter.
BC.Tracer.DebugProfile.NPRdrctFrmFlt0 - 10Traces the functioning of and defines the log level for the RedirectFormFilter.
BC.Tracer.DebugProfile.NPXmlFilter0 - 10Traces the functioning of and defines the log level for the XMLFilter.
BC.Tracer.DebugProfile.NPMemLeakFlt0 - 10Traces the functioning of and defines the log level for the MemoryLeakFilter.
BC.Tracer.DebugProfile.NPReaperOp0 - 10Traces the functioning of and defines the log level for the SessionManagementFilter. If set to INFO ("6"), this trace group will print out statistical information of the local store or the MySQL store used by a SessionManagementFilter.
BC.Tracer.DebugProfile.NPLocalSessStr0 - 10Traces the functioning of and defines the log level for the LocalSessionStoreServlet.
BC.Tracer.DebugProfile.NPMySQLSessSrv0 - 10Traces the functioning of and defines the log level for the MySQLSessionStoreServlet: On level INFO ("6"), this trace group traces the statistics about timed-out, removed and zombie sessions. On level DEBUG_HIGH ("9"), the trace group logs all SQL requests regarding the MySQL/MariaDB remote session store used by a SessionManagementFilter.
BC.Tracer.DebugProfile.NPReqObsFlt0 - 10Traces the functioning of and defines the log level for the RequestObserverFilter.

Isiweb trace groups​

The Isiweb trace groups adjust the verbosity of the messages recorded in the log file regarding specific nevisProxy filters and servlets. For an overview of the various log levels, see Log level below.

NameTypeComponent
BC.Tracer.DebugProfile.IsiwebOp0 - 10The IsiwebOp trace group is used for trouble shooting for content providers (times, response status code, etc). For an example, see.
BC.Tracer.DebugProfile.EsauthProvider0 - 10This trace group is used for provider tracing.
BC.Tracer.DebugProfile.IW4HttpConnSrv0 - 10Traces the functioning of and defines the log level for the HttpConnectorServlet.
BC.Tracer.DebugProfile.IW4HttpsConnSrv0 - 10Traces the functioning of and defines the log level for the HttpsConnectorServlet.
BC.Tracer.DebugProfile.IW4Esau4ConnSrv0 - 10Traces the functioning of and defines the log level for the Esauth4ConnectorServlet.
BC.Tracer.DebugProfile.IW4MqSrv0 - 10Traces the functioning of and defines the log level for the MQServlet.
BC.Tracer.DebugProfile.IW4UserStatSrv0 - 10Traces the functioning of and defines the log level for the UserStatusServlet.
BC.Tracer.DebugProfile.IW4, defaultSrv0 - 10Traces the functioning of and defines the log level for the DefaultServlet.
BC.Tracer.DebugProfile.IW4LogRenSrv0 - 10Traces the functioning of and defines the log level for the LoginRendererServlet.
BC.Tracer.DebugProfile.IW4AuditFlt0 - 10Traces the functioning of and defines the log level for the AuditFilter.
BC.Tracer.DebugProfile.IW4CacheFlt0 - 10Traces the functioning of and defines the log level for the CacheFilter.
BC.Tracer.DebugProfile.IW4CharSetFlt0 - 10Traces the functioning of and defines the log level for the CharsetFilter.
BC.Tracer.DebugProfile.IW4CltTrackFlt0 - 10Traces the functioning of and defines the log level for the ClientTrackingFilter.
BC.Tracer.DebugProfile.IW4CookieFlt0 - 10Traces the functioning of and defines the log level for the CookieCacheFilter.
BC.Tracer.DebugProfile.IW4CSRFFlt0 - 10Traces the functioning of and defines the log level for the CSRFFilter.
BC.Tracer.DebugProfile.IW4DeflateFlt0 - 10Traces the functioning of and defines the log level for the DeflateFilter.
BC.Tracer.DebugProfile.IW4DelegateFlt0 - 10Traces the functioning of and defines the log level for the DelegationFilter.
BC.Tracer.DebugProfile.IW4DumpFlt0 - 10Traces the functioning of and defines the log level for the DumpFilter.
BC.Tracer.DebugProfile.IW4EncryptFlt0 - 10Traces the functioning of and defines the log level for the EncryptionFilter.
BC.Tracer.DebugProfile.IW4UrlEncrypt0 - 10Traces all URLs encryption/decryption (by the EncryptionFilter) on INFO-Level ("6").
BC.Tracer.DebugProfile.IW4ErrorFlt0 - 10Traces the functioning of and defines the log level for the ErrorFilter.
BC.Tracer.DebugProfile.IW4FakeLoginFlt0 - 10Traces the functioning of and defines the log level for the FakeLoginFilter.
BC.Tracer.DebugProfile.IW4FltMappFlt0 - 10Traces the functioning of and defines the log level for the FilterMappingFilter.
BC.Tracer.DebugProfile.IW4HdrDlgFlt0 - 10Traces the functioning of and defines the log level for the HeaderDelegationFilter.
BC.Tracer.DebugProfile.IW4ICAPFlt0 - 10Traces the functioning of and defines the log level for the ICAPFilter.
BC.Tracer.DebugProfile.IW4IdentCreaFlt0 - 10Traces the functioning of and defines the log level for the IdentityCreationFilter.
BC.Tracer.DebugProfile.IW4InflateFlt0 – 10Traces the functioning of and defines the log level for the InflateFilter.
BC.Tracer.DebugProfile.IW4ValidFlt0 - 10Traces the functioning of and defines the log level for the InputValidationFilter.
BC.Tracer.DebugProfile.IW4JsonFlt0 - 10Traces the functioning of and defines the log level for the JsonFilter.
BC.Tracer.DebugProfile.IW4LuaFlt0 - 10Traces the functioning of and defines the log level for the LuaFilter.
BC.Tracer.DebugProfile.LuaNevisLib0 - 10LuaNevisLib: The interface between the Lua filter and the core of the proxy.
BC.Tracer.DebugProfile.IW4MaintFlt0 - 10Traces the functioning of and defines the log level for the MaintenanceFilter.
BC.Tracer.DebugProfile.IW4ParamFlt0 - 10Traces the functioning of and defines the log level for the ParameterFilter.
BC.Tracer.DebugProfile.IW4QmrFlt0 - 10Traces the functioning of and defines the log level for the QumramFilter.
BC.Tracer.DebugProfile.IW4RewriteFlt0 - 10Traces the functioning of and defines the log level for the RewriteFilter.
BC.Tracer.DebugProfile.IW4SamlErrFlt0 - 10Traces the functioning of and defines the log level for the SAMLErrorFilter.
BC.Tracer.DebugProfile.IW4SAMLFlt0 - 10Traces the functioning of and defines the log level for the SAMLProviderFilter.
BC.Tracer.DebugProfile.IW4SecRoleFlt0 - 10Traces the functioning of and defines the log level for the SecurityRoleFilter.
BC.Tracer.DebugProfile.IW4SessionFlt0 - 10Traces the functioning of and defines the log level for the SessionFilter.
BC.Tracer.DebugProfile.IW4ResSessFlt0 - 10Traces the functioning of and defines the log level for the SessionResourceFilter.
BC.Tracer.DebugProfile.IW4SoapFlt0 - 10Traces the functioning of and defines the log level for the SoapFilter.
BC.Tracer.DebugProfile.IW4UnbluFlt0 - 10Traces the functioning of and defines the log level for the UnbluFilter.
BC.Tracer.DebugProfile.IW4VirtSessFlt0 - 10Traces the functioning of and defines the log level for the VirtualSessionFilter.
BC.Tracer.DebugProfile.IW4SessionLst0 - 10Traces the functioning of and defines the log level for the SessionListener.
BC.Tracer.DebugProfile.IW4HtmlRewrite0 - 10Traces the functioning of and defines the log level for the HttpConnectorServlet and HttpsConnectorServlet.
BC.Tracer.DebugProfile.IW4LuaUrlEnc0 - 10Traces the functioning of and defines the log level for the UrlEncryptionFilter.
BC.Tracer.DebugProfile.IW4WebSocketSrv0 - 10Traces the functioning of and defines the log level for the WebSocketServlet.
BC.Tracer.DebugProfile.IW4XMLValidFlt0 - 10Traces the functioning of and defines the log level for the XMLValidationFilter.
BC.Tracer.DebugProfile.IW4ResSessFlt0 - 10Traces the functioning of and defines the log level for the SessionResourceFilter.
BC.Tracer.DebugProfile.IW4LogFlt0 - 10Traces the functioning of and defines the log level for the LoggerFilter.
BC.Tracer.DebugProfile.IW4ModsecFlt0 - 10Traces the functioning of and defines the log level for the ModsecurityFilter.

SSL tracing​

NameTypeDescription
BC.Tracer.DebugProfile.OpenSSLHandshk0 - 10Tracing of the handshake process. Defines the severity level of the logged events.
BC.Tracer.DebugProfile.OpenSSLRecord0 - 10SSL record tracing. Defines the severity level of the logged events.
BC.Tracer.DebugProfile.OpenSSLStream0 - 10SSL stream tracing. Defines the severity level of the logged events.
bcx.net.debug.hostString, list of host-namesTo enable the tracing mentioned in the previous rows, Set this property (bcx.net.debug.host) to "all" or specify a list of hostnames. Additionally, set the bcx.net.debug property (see the following row).
bcx.net.debugenum: record,handshake,sslTo enable the tracing mentioned in the previous rows, Set this property (bcx.net.debug) to "record,handshake,ssl" or select one of these values. Additionally, set the bcx.net.debug.host property (see the previous row).

Log level

The following table shows the mapping between the level set in the trace groups and the severity printed into the log file:

LevelSeverityDescription
0EMERGENCYNothing works anymore.
1ALERTSomething should be corrected immediately.
2CRITICALA critical situation has occurred.
3ERROROther error messages.
4WARNINGWarning messages.
5NOTICEThings you should know.
6INFOThings of interest.
7DEBUG_LOWLow debug level.
8DEBUG_MEDMedium debug level.
9DEBUG_HIGHHigh debug level (enter/leave).
10DEBUG_MAXHighest debug level.

Tracing examples​

The following examples illustrate the functioning of some trace groups. Each trace line is built in the following way:

<date> isi3web <TraceGroup> <process id>.<thread id>.<transaction id> <trace level>: <trace msg>

Example of NavajoOp tracing​

In the following example, the constructed filter chain and the invoked servlet are traced by the trace group NavajoOp with trace level "INFO". This is realized with the following trace line:

2018 01 27 14:55:00.369 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 6-INFO :    <<<<< 'GET /test/session/?session-type=default' invS='/(CommonDelegationFilter) / (ErrorFilter) /test/ (RewriteFilter), /test/ (TestRewriteFilter) / (RootRewriteFilter) / (HeaderDelegationFilter)>TestServlet' sC='200' bS='836' dTF='15' dTFrs='1' rmIP='192.168.5.175' clID='S5cde8370c5d1dIrJr+ZyXwK6JSukZosY1Syz61YqY3bIO0i8y+f20wI=' trID='01000000-5615-7f0100-1675bb326e8-00000005' (cR=1)

The next table explains the abbreviations used in the previous NavajoOP tracing example:

AbbreviationDescriptionExample
<<<< '<HTTP method> <URI>'Request line from the frontend<<<<< 'GET /test/session/?session-type=default'
invSThe filter chain with the invoked servlet.invS='/ CommonDelegationFilter) / (ErrorFilter) /test/ (RewriteFilter) >TestServlet'
sCReturned status code.sC='200'
bSNumber of the bytes sent.bS='836'
dTFTotal time needed to process the frontend call.dTF='15'
dTFrsThe time needed to read and write the data from/to the frontend.dTFrs='1'
rmIPIP address of the client.rmIP='192.168.5.175'
clIDHttpSession ID (if it was accessed).clID='S5cde8370c5d1dIrJr+ZyXwK6JSukZosY1Syz61YqY3bIO0i8y+f20wI='
trIDTransaction IDtrID='01000000-5615-7f0100-1675bb326e8-00000005'
cRNumber of concurrent requests within nevisProxy(cR=1)
parsedRequestUriValue of the parsed request URI without the query. This value is only added if it differs from the unparsed request URI.

You can log more information by further increasing the log level of the NavajoOp trace group. For example, log level "7" will also log the invoked filters and servlets, together with the corresponding processing time. The maximum log level will also log the incoming and outgoing HTTP headers of the request and the response, as you can see in the following tracing sample:

2018 11 28 20:02:06.825 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 7-DBG_LO: >>>>> 'GET /htt/' rmIP='::1' trID='01000000-5615-7f0100-1675bb326e8-00000005'
2018 11 28 20:02:06.825 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 9-DBG_HI: >>> Cookie: __utma=111872281.168812658.1523368527.1523368527.1523368527.1
2018 11 28 20:02:06.825 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 9-DBG_HI: >>> Accept-Encoding: gzip, deflate
2018 11 28 20:02:06.825 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 9-DBG_HI: >>> User-Agent: Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0
2018 11 28 20:02:06.826 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 8-DBG_ME: >>>>>>>>>>>>>>>>>> (filter 'TracingLuaFilter')
2018 11 28 20:02:06.828 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 8-DBG_ME: >>>>>>>>>>>>>>>>>> (servlet 'ServletForHTT')
2018 11 28 20:02:06.933 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 7-DBG_LO: <<<<<<<<<<<<<<<<< (remoteIP '::1' servlet 'ServletForHTT' dT='106')
2018 11 28 20:02:06.934 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 7-DBG_LO: <<<<<<<<<<<<<<<<< (remoteIP '::1' filter 'TracingLuaFilter' dT='109')
2018 11 28 20:02:06.935 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 6-INFO : <<<<< 'GET /htt/' invS='/htt/* (TracingLuaFilter) >ServletForHTT' sC='200' bS='199' dTF='110 dTFrs='1' rmIP='::1' clID='<NULL>' trID='01000000-5615-7f0100-1675bb326e8-00000005' (cR=1)
2018 11 28 20:02:06.935 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 9-DBG_HI: <<< Content-Type: text/html

Example of IsiwebOp tracing​

The IsiwebOp trace group is used for troubleshooting content providers. See the example below:

2018 11 28 20:02:06.933 isi3web IsiwebOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 6-INFO : <==== 'GET /htt/ HTTP/1.1' invS='ServletForHTT' inetA='adnlt730-vm2.dyn.adnovum.ch:11071 (127.0.0.1)' trId='01000000-5615-7f0100-1675bb326e8-00000005' sC='200' dTB='103' dTcB='0' dTsB='1' dTr1B='102' dTr2B='0' usrID='<NULL>'

The next table explains the abbreviations used in the previous IsiwebOP tracing example:

AbbreviationDescriptionExample
<==== '<HTTP method> <URI> <Protocol>'The request line from the frontend.<==== 'GET /htt/ HTTP/1.1' invS='ServletForHTT'
invSThe name of the invoked servlet.invS='ServletForHTT'
inetAThe inet address of the content provider (important in case of load balancing).inetA=adnlt730-vm2.dyn.adnovum.ch:11071 (127.0.0.1)
trIDTransaction ID.trId='01000000-5615-7f0100-1675bb326e8-00000005'
sCReturned status code.sC='200'
dTBTotal time needed to process the backend call (including establishing the connection, sending the request, and reading the response).dTB='103'
dTcBThe time needed to establish the connection (incl. TLS handshake).dTcB='0'
dTsBThe time needed to send the request to the backend (HTTP header and optional body) in milliseconds.dTsB='1'
dTr1BThe time needed to read the HTTP headers of the response from the backend.dTr1B='102'
dTr2BThe time needed to read the HTTP body of the response from the backend.dTr1B='0'
usrIDThe ID of the authenticated user.usrID='<NULL>'

Note that with log level "7", the IsiwebOp also traces the outgoing request for the content provider (including such information as the request line or inet address of the backend):

2018 11 28 20:02:06.829 isi3web IsiwebOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 7-DBG_LO: ====> 'GET /htt/ HTTP/1.1' invS='ServletForHTT' inetA='adnlt730-vm2.dyn.adnovum.ch:11071' trId='01000000-5615-7f0100-1675bb326e8-00000005'

The maximum log level ("9") will also trace the headers between the content provider and the proxy:

2018 12 06 10:54:34.509 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 7-DBG_LO: ====> 'GET /htt/ HTTP/1.1' invS='ServletForHTT' inetA='adnlt730-vm2.dyn.adnovum.ch:11071' trId='01000000-5df5-7f0100-16782f0bd87-00000002'
2018 12 06 10:54:34.509 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 8-DBG_ME: ==> Host: adnlt730-vm2.dyn.adnovum.ch
2018 12 06 10:54:34.509 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 8-DBG_ME: ==> Connection: close
2018 12 06 10:54:34.509 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 8-DBG_ME: ==> Upgrade-Insecure-Requests: 1
2018 12 06 10:54:34.509 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 8-DBG_ME: ==> Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
2018 12 06 10:54:34.509 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 8-DBG_ME: ==> Accept-Language: en-GB,en;q=0.5
2018 12 06 10:54:34.509 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 8-DBG_ME: ==> User-Agent: Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0
2018 12 06 10:54:34.509 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 8-DBG_ME: ==> Accept-Encoding: gzip, deflate
2018 12 06 10:54:34.514 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 6-INFO : <==== 'GET /htt/ HTTP/1.1' invS='ServletForHTT' inetA='adnlt730-vm2.dyn.adnovum.ch:11071 (127.0.0.1)' trId='01000000-5df5-7f0100-16782f0bd87-00000002' sC='200' dTB='3' dTcB='1' dTsB='1' dTr1B='1' dTr2B='0' usrID='<NULL>'
2018 12 06 10:54:34.515 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 8-DBG_ME: <== Content-Type: text/html
2018 12 06 10:54:34.515 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 8-DBG_ME: <== Content-Length: 91

Example of NProxyOp tracing​

The NProxyOp trace group provides information about frontend and backend calls on one single line:

2018 11 28 20:02:06.935 isi3web NProxyOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 6-INFO : reqF="GET /htt/ HTTP/1.1" reqDecF=<NULL> ipF=::1 sCF=200 bSF=199 dTF=110 reqB="GET /htt/ HTTP/1.1" adrB=adnlt730-vm2.dyn.adnovum.ch:11071 ipB=127.0.0.1 sCB=200 dTB=103 dTcB=0 dTsB=1 dTr1B=102 dTr2B=0 dTFrs=1 invS=/htt/* (TracingLuaFilter) >ServletForHTT cR=1 usrID=<NULL> Event=<NULL> clID=<NULL> cookie=<NULL> sslID=<NULL> trID=01000000-5615-7f0100-1675bb326e8-00000005
AbbreviationDescriptionExampleApache environment variable
reqFRequest line from the frontend.reqF="GET /htt/ HTTP/1.1"%r
reqDecFDecrypted request URI (NULL if no URL encryption is used).reqDecF=<NULL>%{reqDecF}e
ipFIP of the frontend.ipF=::1%a
sCFStatus code of the frontend.sCF=200%>s
bSFBytes sent to frontendbSF=199%B or %b
dTFTotal time needed to process the frontend call.dTF=110%{dTF}e
reqBRequest line to the backend.reqB="GET /htt/ HTTP/1.1"%{reqB}e
adrBThe address and port of the backend.adrB=adnlt730-vm2.dyn.adnovum.ch:11071%{adrB}e
ipBIP of the backend.ipB=127.0.0.1%{ipB}e
sCBStatus code of the response from the backend.sCB=200%{sCB}e
dTBTotal time needed to process the backend call (includes the time needed for establishing the connection, sending the request, and reading the response from the backend).dTB=103%{dTB}e
dTcBTime needed to establish the connection with the backend (incl. TLS handshake).dTcB=0%{dTcB}e
dTsBThe time needed to send the request to the backend (HTTP header and optional body) in milliseconds.dTsB=1%{dTsB}e
dTr1BTime needed to read the HTTP headers of the response from the backend.dTr1B=102%{dTr1B}e
dTr2BTime needed to read the HTTP body of the response from the backend.dTr2B=0%{dTr2B}e
dTFrsThe time needed to read and write the data from/to the frontend.dTFrs=1%{dTFrs}e
invSThe filter chain with the invoked servlet.invS=/htt/* (TracingLuaFilter) >ServletForHTT%{invS}e
cRNumber of concurrent request within nevisProxycR=1%{cR}e
usrIDID of the authenticated userusrID=<NULL>%{usrID}e
EventList of events triggered by the request, see the table nevisProxy EventsEvent=<NULL>%{Event}e
clIDHttpSession ID if it was accessed.clID=<NULL>%{clID}e
cookieValue of the Navajo cookiecookie=<NULL>%{cookie}e
sslIDTLS/SSL session IDsslID=<NULL>%{sslID}e
trIDTransaction IDtrId='01000000-5615-7f0100-1675bb326e8-00000005'%{UNIQUE_ID}e
parsedRequestUriValue of the parsed request URI without the query. The value is only added if it differs from the unparsed request URI.%{parsedRequestUri}e

Example of Apache tracing​

Apache traces an access log file. For each request, a single line is traced to describe the request. In addition to all common configurable Apache features, additional information from nevisProxy can be configured (see the table. For example:

LogFormat="&quot;%h %l %u %t \&quot;%r\&quot; %>s %b \&quot;%\{Referer\}i\&quot; \&quot;%\{User-Agent\}i\&quot; %v %D triID=%\{UNIQUE_ID\}e clID=%\{clID\}e&quot;"

Produces the following trace event:

10.30.212.29 - - \[09/Nov/2011:13:02:29 +0100\] "GET /css/styles.css HTTP/1.1" 200 3547 "https://adnwsbe09.be.adnovum.ch:44300/esauth3/?login" "Mozilla/5.0 (X11; Linux i686; rv:7.0.1) Gecko/20100101 Firefox/7.0.1" adnwsbe09.be.adnovum.ch 34358 triID=0a1ed41d-4324-1e0a1dd4-133883539b2-00000005 clID=43131e0a1dd4Uvp4sHE2BknMd2AIkwHvbXzMOkRkrLfPYugGLbtsLtg

We highly recommend that you include the transaction ID and the client ID in this configuration. This allows an easy correlation of both the Navajo and the Apache log files.

Also propagate the events to the apache-env. The events have the following format:

  • <NULL>: if no event
  • Comma separated list: a comma separated list of all events. Example: Event=GW01,IW01,GW02

Propagate client and transaction identifier​

It is always useful to propagate the IP address of the client as well as the transaction id (also called trID or transferID), which identifies a HTTP request, to the application servers to be logged on those servers too. This allows correlation of events within the log files of all involved servers. The propagation of this information may be implemented by forwarding the necessary data within HTTP request headers. The "clientID" represents the user's session identifier allowing tracking all requests performed during a user's session. A DelegationFilter may be used to add the necessary request headers.

Example configuration:

<filter>
 <filter-name>Forwarded-For</filter-name>
 <filter-class>ch::nevis::isiweb4::filter::delegation::DelegationFilter</filter-class>

 <init-param>
  <param-name>Delegate</param-name>
  <param-value>
   ENV:REMOTE_ADDR:X-Forwarded-For
   ENV:UNIQUE_ID:transferId
   ENV:bcx.servlet.session.HttpSessionId:clientId
  </param-value>
 </init-param>
</filter>