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

Name	Type	Description
BC.Tracer.ThresholdBase	0 - 10	The 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.MaxLogFileVersions	integer	The number of rotated log files that will be written. This property will be ignored if the 'BC.Tracer.LogFile' is a pipe
BC.Tracer.MaxLogFileSize	integer	The 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.LogFileAccess	Octal file mask or comma-separated list of 'onwer', 'group', and 'other'. Default: 0640	File 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.LogFileCompression	String	You 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.LogFile	String	Can be the name of a file or an external program start with pipe::/`<external program>`
BC.Tracer.Pipe.RetryInterval	Integer	Interval 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.MaxRetries	Integer	For 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.ProgName	String	The 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.LogDir	String	In 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.LogFileAppend	Boolean	If '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.LogFileReopenInterval	Integer	Interval 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.VersioningTimes	String	Interval 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.LogArchiveFormat	String	The 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.LogArchiveDir	String	Defines 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.Cipher	String	Defines 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>`	String	Defines 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".

Name	Type	Description
ch.nevis.navajo.tracing.TraceId.Format	String	Possible 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.ReconfigurationPeriod	Integer, default is 60 sec	Dynamically 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.

Name	Type	Description
BC.Tracer.DebugProfile.NavajoResource	0 - 10	Memory consumption.
BC.Tracer.DebugProfile.NavajoRequest	0 - 10	Request processing.
BC.Tracer.DebugProfile.NavajoSSL	0 - 10	SSLCache handling.
BC.Tracer.DebugProfile.NavajoCookie	0 - 10	CookieCache handling.
BC.Tracer.DebugProfile.NavajoSession	0 - 10	Session handling. For an example, see.
BC.Tracer.DebugProfile.NavajoStart	0 - 10	Tracing during booting.
BC.Tracer.DebugProfile.NavajoConfig	0 - 10	Tracing of the generated configuration file for Apache2.
BC.Tracer.DebugProfile.NavajoOp	0 - 10	Tracing processing time of the invoked filters/servlets and request/response headers. For an example, see.
BC.Tracer.DebugProfile.NavajoDump	0 - 10	Dumping the response written to the client.
BC.Tracer.DebugProfile.NavajoTimer	0 - 10	Tracing of the internal timer.
BC.Tracer.DebugProfile.NavajoHttpSess	6 - 7	Periodical tracing of session statistics.
BC.Tracer.DebugProfile.NavajoReqIO	0 - 10	Tracing of the IO operation of the request.
BC.Tracer.DebugProfile.NProxyOp	0 - 10	Single line tracing of backend and frontend calls with processing time statistics. For an example, see.
bc.security.PassPhrasePolicy	String 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.PassPhraseDialog	string 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.

Name	Type	Component
BC.Tracer.DebugProfile.NPAuthFilter	0 - 10	Traces the functioning of and defines the log level for the AuthenticationFilter.
BC.Tracer.DebugProfile.NPParamVldFlt	0 - 10	Traces the functioning of and defines the log level for the ParameterValidationFilter.
BC.Tracer.DebugProfile.NPHdrVldFlt	0 - 10	Traces the functioning of and defines the log level for the HeaderValidationFilter.
BC.Tracer.DebugProfile.NPSessionFlt	0 - 10	Traces the functioning of and defines the log level for the SessionManagementFilter.
BC.Tracer.DebugProfile.NPDynCfgFlt	0 - 10	Traces the functioning of and defines the log level for the DynamicConfigFilter.
BC.Tracer.DebugProfile.NPRdrctFrmFlt	0 - 10	Traces the functioning of and defines the log level for the RedirectFormFilter.
BC.Tracer.DebugProfile.NPXmlFilter	0 - 10	Traces the functioning of and defines the log level for the XMLFilter.
BC.Tracer.DebugProfile.NPMemLeakFlt	0 - 10	Traces the functioning of and defines the log level for the MemoryLeakFilter.
BC.Tracer.DebugProfile.NPReaperOp	0 - 10	Traces 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.NPLocalSessStr	0 - 10	Traces the functioning of and defines the log level for the LocalSessionStoreServlet.
BC.Tracer.DebugProfile.NPMySQLSessSrv	0 - 10	Traces 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.NPReqObsFlt	0 - 10	Traces 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.

Name	Type	Component
BC.Tracer.DebugProfile.IsiwebOp	0 - 10	The IsiwebOp trace group is used for trouble shooting for content providers (times, response status code, etc). For an example, see.
BC.Tracer.DebugProfile.EsauthProvider	0 - 10	This trace group is used for provider tracing.
BC.Tracer.DebugProfile.IW4HttpConnSrv	0 - 10	Traces the functioning of and defines the log level for the HttpConnectorServlet.
BC.Tracer.DebugProfile.IW4HttpsConnSrv	0 - 10	Traces the functioning of and defines the log level for the HttpsConnectorServlet.
BC.Tracer.DebugProfile.IW4Esau4ConnSrv	0 - 10	Traces the functioning of and defines the log level for the Esauth4ConnectorServlet.
BC.Tracer.DebugProfile.IW4MqSrv	0 - 10	Traces the functioning of and defines the log level for the MQServlet.
BC.Tracer.DebugProfile.IW4UserStatSrv	0 - 10	Traces the functioning of and defines the log level for the UserStatusServlet.
BC.Tracer.DebugProfile.IW4, defaultSrv	0 - 10	Traces the functioning of and defines the log level for the DefaultServlet.
BC.Tracer.DebugProfile.IW4LogRenSrv	0 - 10	Traces the functioning of and defines the log level for the LoginRendererServlet.
BC.Tracer.DebugProfile.IW4AuditFlt	0 - 10	Traces the functioning of and defines the log level for the AuditFilter.
BC.Tracer.DebugProfile.IW4CacheFlt	0 - 10	Traces the functioning of and defines the log level for the CacheFilter.
BC.Tracer.DebugProfile.IW4CharSetFlt	0 - 10	Traces the functioning of and defines the log level for the CharsetFilter.
BC.Tracer.DebugProfile.IW4CltTrackFlt	0 - 10	Traces the functioning of and defines the log level for the ClientTrackingFilter.
BC.Tracer.DebugProfile.IW4CookieFlt	0 - 10	Traces the functioning of and defines the log level for the CookieCacheFilter.
BC.Tracer.DebugProfile.IW4CSRFFlt	0 - 10	Traces the functioning of and defines the log level for the CSRFFilter.
BC.Tracer.DebugProfile.IW4DeflateFlt	0 - 10	Traces the functioning of and defines the log level for the DeflateFilter.
BC.Tracer.DebugProfile.IW4DelegateFlt	0 - 10	Traces the functioning of and defines the log level for the DelegationFilter.
BC.Tracer.DebugProfile.IW4DumpFlt	0 - 10	Traces the functioning of and defines the log level for the DumpFilter.
BC.Tracer.DebugProfile.IW4EncryptFlt	0 - 10	Traces the functioning of and defines the log level for the EncryptionFilter.
BC.Tracer.DebugProfile.IW4UrlEncrypt	0 - 10	Traces all URLs encryption/decryption (by the EncryptionFilter) on INFO-Level ("6").
BC.Tracer.DebugProfile.IW4ErrorFlt	0 - 10	Traces the functioning of and defines the log level for the ErrorFilter.
BC.Tracer.DebugProfile.IW4FakeLoginFlt	0 - 10	Traces the functioning of and defines the log level for the FakeLoginFilter.
BC.Tracer.DebugProfile.IW4FltMappFlt	0 - 10	Traces the functioning of and defines the log level for the FilterMappingFilter.
BC.Tracer.DebugProfile.IW4HdrDlgFlt	0 - 10	Traces the functioning of and defines the log level for the HeaderDelegationFilter.
BC.Tracer.DebugProfile.IW4ICAPFlt	0 - 10	Traces the functioning of and defines the log level for the ICAPFilter.
BC.Tracer.DebugProfile.IW4IdentCreaFlt	0 - 10	Traces the functioning of and defines the log level for the IdentityCreationFilter.
BC.Tracer.DebugProfile.IW4InflateFlt	0 – 10	Traces the functioning of and defines the log level for the InflateFilter.
BC.Tracer.DebugProfile.IW4ValidFlt	0 - 10	Traces the functioning of and defines the log level for the InputValidationFilter.
BC.Tracer.DebugProfile.IW4JsonFlt	0 - 10	Traces the functioning of and defines the log level for the JsonFilter.
BC.Tracer.DebugProfile.IW4LuaFlt	0 - 10	Traces the functioning of and defines the log level for the LuaFilter.
BC.Tracer.DebugProfile.LuaNevisLib	0 - 10	LuaNevisLib: The interface between the Lua filter and the core of the proxy.
BC.Tracer.DebugProfile.IW4MaintFlt	0 - 10	Traces the functioning of and defines the log level for the MaintenanceFilter.
BC.Tracer.DebugProfile.IW4ParamFlt	0 - 10	Traces the functioning of and defines the log level for the ParameterFilter.
BC.Tracer.DebugProfile.IW4QmrFlt	0 - 10	Traces the functioning of and defines the log level for the QumramFilter.
BC.Tracer.DebugProfile.IW4RewriteFlt	0 - 10	Traces the functioning of and defines the log level for the RewriteFilter.
BC.Tracer.DebugProfile.IW4SamlErrFlt	0 - 10	Traces the functioning of and defines the log level for the SAMLErrorFilter.
BC.Tracer.DebugProfile.IW4SAMLFlt	0 - 10	Traces the functioning of and defines the log level for the SAMLProviderFilter.
BC.Tracer.DebugProfile.IW4SecRoleFlt	0 - 10	Traces the functioning of and defines the log level for the SecurityRoleFilter.
BC.Tracer.DebugProfile.IW4SessionFlt	0 - 10	Traces the functioning of and defines the log level for the SessionFilter.
BC.Tracer.DebugProfile.IW4ResSessFlt	0 - 10	Traces the functioning of and defines the log level for the SessionResourceFilter.
BC.Tracer.DebugProfile.IW4SoapFlt	0 - 10	Traces the functioning of and defines the log level for the SoapFilter.
BC.Tracer.DebugProfile.IW4UnbluFlt	0 - 10	Traces the functioning of and defines the log level for the UnbluFilter.
BC.Tracer.DebugProfile.IW4VirtSessFlt	0 - 10	Traces the functioning of and defines the log level for the VirtualSessionFilter.
BC.Tracer.DebugProfile.IW4SessionLst	0 - 10	Traces the functioning of and defines the log level for the SessionListener.
BC.Tracer.DebugProfile.IW4HtmlRewrite	0 - 10	Traces the functioning of and defines the log level for the HttpConnectorServlet and HttpsConnectorServlet.
BC.Tracer.DebugProfile.IW4LuaUrlEnc	0 - 10	Traces the functioning of and defines the log level for the UrlEncryptionFilter.
BC.Tracer.DebugProfile.IW4WebSocketSrv	0 - 10	Traces the functioning of and defines the log level for the WebSocketServlet.
BC.Tracer.DebugProfile.IW4XMLValidFlt	0 - 10	Traces the functioning of and defines the log level for the XMLValidationFilter.
BC.Tracer.DebugProfile.IW4ResSessFlt	0 - 10	Traces the functioning of and defines the log level for the SessionResourceFilter.
BC.Tracer.DebugProfile.IW4LogFlt	0 - 10	Traces the functioning of and defines the log level for the LoggerFilter.
BC.Tracer.DebugProfile.IW4ModsecFlt	0 - 10	Traces the functioning of and defines the log level for the ModsecurityFilter.

SSL tracing

Name	Type	Description
BC.Tracer.DebugProfile.OpenSSLHandshk	0 - 10	Tracing of the handshake process. Defines the severity level of the logged events.
BC.Tracer.DebugProfile.OpenSSLRecord	0 - 10	SSL record tracing. Defines the severity level of the logged events.
BC.Tracer.DebugProfile.OpenSSLStream	0 - 10	SSL stream tracing. Defines the severity level of the logged events.
bcx.net.debug.host	String, list of host-names	To 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.debug	enum: record,handshake,ssl	To 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:

Level	Severity	Description
0	EMERGENCY	Nothing works anymore.
1	ALERT	Something should be corrected immediately.
2	CRITICAL	A critical situation has occurred.
3	ERROR	Other error messages.
4	WARNING	Warning messages.
5	NOTICE	Things you should know.
6	INFO	Things of interest.
7	DEBUG_LOW	Low debug level.
8	DEBUG_MED	Medium debug level.
9	DEBUG_HIGH	High debug level (enter/leave).
10	DEBUG_MAX	Highest 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:

Abbreviation	Description	Example
<<<< '`<HTTP method> <URI>`'	Request line from the frontend	<<<<< 'GET /test/session/?session-type=default'
invS	The filter chain with the invoked servlet.	invS='/ CommonDelegationFilter) / (ErrorFilter) /test/ (RewriteFilter) >TestServlet'
sC	Returned status code.	sC='200'
bS	Number of the bytes sent.	bS='836'
dTF	Total time needed to process the frontend call.	dTF='15'
dTFrs	The time needed to read and write the data from/to the frontend.	dTFrs='1'
rmIP	IP address of the client.	rmIP='192.168.5.175'
clID	HttpSession ID (if it was accessed).	clID='S5cde8370c5d1dIrJr+ZyXwK6JSukZosY1Syz61YqY3bIO0i8y+f20wI='
trID	Transaction ID	trID='01000000-5615-7f0100-1675bb326e8-00000005'
cR	Number of concurrent requests within nevisProxy	(cR=1)
parsedRequestUri	Value 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:

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'
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
11 28 20:02:06.825 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 9-DBG_HI: >>> Accept-Encoding: gzip, deflate
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
11 28 20:02:06.826 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 8-DBG_ME: >>>>>>>>>>>>>>>>>> (filter 'TracingLuaFilter')
11 28 20:02:06.828 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 8-DBG_ME: >>>>>>>>>>>>>>>>>> (servlet 'ServletForHTT')
11 28 20:02:06.933 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 7-DBG_LO: <<<<<<<<<<<<<<<<< (remoteIP '::1' servlet 'ServletForHTT' dT='106')
11 28 20:02:06.934 isi3web NavajoOp 22037.139733629540096.01000000-5615-7f0100-1675bb326e8-00000005 7-DBG_LO: <<<<<<<<<<<<<<<<< (remoteIP '::1' filter 'TracingLuaFilter' dT='109')
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)
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:

Abbreviation	Description	Example
<==== '`<HTTP method> <URI> <Protocol>`'	The request line from the frontend.	<==== 'GET /htt/ HTTP/1.1' invS='ServletForHTT'
invS	The name of the invoked servlet.	invS='ServletForHTT'
inetA	The inet address of the content provider (important in case of load balancing).	inetA=`adnlt730-vm2.dyn.adnovum.ch:11071 (127.0.0.1)`
trID	Transaction ID.	trId='01000000-5615-7f0100-1675bb326e8-00000005'
sC	Returned status code.	sC='200'
dTB	Total time needed to process the backend call (including establishing the connection, sending the request, and reading the response).	dTB='103'
dTcB	The time needed to establish the connection (incl. TLS handshake).	dTcB='0'
dTsB	The time needed to send the request to the backend (HTTP header and optional body) in milliseconds.	dTsB='1'
dTr1B	The time needed to read the HTTP headers of the response from the backend.	dTr1B='102'
dTr2B	The time needed to read the HTTP body of the response from the backend.	dTr1B='0'
usrID	The 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:

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'
12 06 10:54:34.509 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 8-DBG_ME: ==> Host: adnlt730-vm2.dyn.adnovum.ch
12 06 10:54:34.509 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 8-DBG_ME: ==> Connection: close
12 06 10:54:34.509 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 8-DBG_ME: ==> Upgrade-Insecure-Requests: 1
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
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
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
12 06 10:54:34.509 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 8-DBG_ME: ==> Accept-Encoding: gzip, deflate
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>'
12 06 10:54:34.515 isi3web IsiwebOp 24053.140715453273856.01000000-5df5-7f0100-16782f0bd87-00000002 8-DBG_ME: <== Content-Type: text/html
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

Abbreviation	Description	Example	Apache environment variable
reqF	Request line from the frontend.	reqF="GET /htt/ HTTP/1.1"	%r
reqDecF	Decrypted request URI (NULL if no URL encryption is used).	reqDecF=`<NULL>`	%{reqDecF}e
ipF	IP of the frontend.	ipF=::1	%a
sCF	Status code of the frontend.	sCF=200	%>s
bSF	Bytes sent to frontend	bSF=199	%B or %b
dTF	Total time needed to process the frontend call.	dTF=110	%{dTF}e
reqB	Request line to the backend.	reqB="GET /htt/ HTTP/1.1"	%{reqB}e
adrB	The address and port of the backend.	`adrB=adnlt730-vm2.dyn.adnovum.ch:11071`	%{adrB}e
ipB	IP of the backend.	ipB=127.0.0.1	%{ipB}e
sCB	Status code of the response from the backend.	sCB=200	%{sCB}e
dTB	Total 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
dTcB	Time needed to establish the connection with the backend (incl. TLS handshake).	dTcB=0	%{dTcB}e
dTsB	The time needed to send the request to the backend (HTTP header and optional body) in milliseconds.	dTsB=1	%{dTsB}e
dTr1B	Time needed to read the HTTP headers of the response from the backend.	dTr1B=102	%{dTr1B}e
dTr2B	Time needed to read the HTTP body of the response from the backend.	dTr2B=0	%{dTr2B}e
dTFrs	The time needed to read and write the data from/to the frontend.	dTFrs=1	%{dTFrs}e
invS	The filter chain with the invoked servlet.	invS=/htt/* (TracingLuaFilter) >ServletForHTT	%{invS}e
cR	Number of concurrent request within nevisProxy	cR=1	%{cR}e
usrID	ID of the authenticated user	usrID=`<NULL>`	%{usrID}e
Event	List of events triggered by the request, see the table nevisProxy Events	Event=`<NULL>`	%{Event}e
clID	HttpSession ID if it was accessed.	clID=`<NULL>`	%{clID}e
cookie	Value of the Navajo cookie	cookie=`<NULL>`	%{cookie}e
sslID	TLS/SSL session ID	sslID=`<NULL>`	%{sslID}e
trID	Transaction ID	trId='01000000-5615-7f0100-1675bb326e8-00000005'	%{UNIQUE_ID}e
parsedRequestUri	Value 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>

Debugging

General tracing properties​

Servlet container trace group​

nevisProxy trace groups​

Isiweb trace groups​

SSL tracing​

Tracing examples​

Example of NavajoOp tracing​

Example of IsiwebOp tracing​

Example of NProxyOp tracing​

Example of Apache tracing​

Propagate client and transaction identifier​