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.

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	The location of the main log file. You can configure a filename or call an external program with the syntax pipe://<external program>. Notes about configuring a custom location: The directory containing the logs must exist when starting the instance. The nevisProxy user must be able to read and write in this directory. See its username and group in the <Server> element of the navajo.xml file.
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.
BC.Tracer.LineCounter	Boolean	If 'true' then each log entry will start with a 4 digit long number that is automatically incremented. The number will reset to 0000 after 9999.

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 %o: The traceId from OpenTelemetry %u: Sets either an unique ID (%i-%p-%h-%t-%c) or the traceId of OpenTelemetry (%o) is OpenTelemetry Tracing is configured.It sets 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 "%o". 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 %o* 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.
ch.nevis.nevisproxy.LocalLogFileName	string	[Experimental] ch.nevis.nevisproxy.LocalLogFileName points to a filename where you can change the trace level based on the incoming request. The content of the file is a new-line separated list of conditions and tracegroups. You cannot use PATH_INFO inside the Condition for the property. The PATH_INFO is not yet evaluated when the local trace groups are activated. If you use PATH_INFO in this case, the error [NVST, 0020] occurs.To increase some tracelevels for an IP-range, the content of the file would look like the example below. See also the chapter Conditional parameters and pragmas for more information about conditional parameters. The level of the trace group BC.Tracer.DebugProfile.Apache can only be modified in a limited way. The log level of Apache messages that occur while nevisProxy is processing the request can be modified as specified in the file. However Apache messages that occur outside of this time frame are logged according to the main level of the trace group BC.Tracer.DebugProfile.Apache.

Condition:REMOTE_ADDR:CIDR/10.4.12.0/24/
Pragma: block-begin
BC.Tracer.DebugProfile.NavajoOp=4
BC.Tracer.DebugProfile.IsiwebOp=4
BC.Tracer.DebugProfile.IW4IdentCreaFlt=4
Pragma: block-end

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	If set to INFO (6), the global system memory is traced on a regular interval of the periodicity defined in navajo.xml. If 90% of the global memory is used, then a NOTICE is traced. If 95% of the global memory is used, then an ERROR with the error code [NVSV,0070] is traced.
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 Example of NavajoSession tracing.
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 Example of NavajoOp tracing.
BC.Tracer.DebugProfile.NavajoDump	0 - 10	Dumping the request and response between nevisproxy and the client.
BC.Tracer.DebugProfile.NavajoTimer	0 - 10	Tracing of the internal timer.
BC.Tracer.DebugProfile.NavajoHttpSess	6 - 7	Periodical tracing of session statistics (legacy session store only).
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 Example of NProxyOp tracing.
BC.Tracer.DebugProfile.Apache	0 - 10	If you enable this trace group, the content of the Apache error log is also traced in the navajo.log file. What will be traced depends on the log level set in the file navajo.xml. For example, to enable debug tracing, you have to set the following: In the navajo.xml file: Loglevel="DEBUG". In bc.properties file: BC.Tracer.DebugProfile.Apache="4" (assuming that the ThresholdBase is "5").

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.NPCountryIpFlt	0 - 10	Traces the functioning of and defines the log level for the CountryIpFilter.
BC.Tracer.DebugProfile.NPDynCfgFlt	0 - 10	Traces the functioning of and defines the log level for the DynamicConfigFilter.
BC.Tracer.DebugProfile.NPXmlFilter	0 - 10	Traces the functioning of and defines the log level for the XMLFilter.
BC.Tracer.DebugProfile.WSInspFlt	0 - 10	Traces the functioning of WebSocketInspectionFilter, and defines the log level for the WebSocketInspectionFilter.
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.
BC.Tracer.DebugProfile.NPMultiLevelStr	0 - 10	Traces the functioning of and defines the log level for the MultiLevelSessionStoreServlet. On log level INFO ("6"), this trace group traces the number of waiting sessions and the delay (in seconds) to the configured BackupServlet, in a regular interval. TheBackupServletis one of the parameters of theMultiLevelSessionStoreServlet. It defines the servlet used to back up the session information. The trace interval is configured with the parameterPeriodicityin the filenavajo.xml.If one of the configured thresholds is reached, a NOTICE message is traced (instead of an INFO). The thresholds are specified in the parameters BackupThreads.DelayThreshold and BackupThreads.QueueLengthThreshold of the MultiLevelSessionStoreServlet.".
BC.Tracer.DebugProfile.NPBackendSrv	0 - 10	Traces the functioning of and defines the log level for the BackendConnectorServlet.
BC.Tracer.DebugProfile.NPLoadBalance	0 - 10	Traces the functioning of and defines the log level for the LoadBalancerServlet.
BC.Tracer.DebugProfile.NPPerfMeter	0 - 10	Valid for all filters: If the RequestFlag NEEDS_TIME_METER is set, an INFO message of the time spent in this filter will be traced. If the RequestFlag NEEDS_TIME_METER is not set, an INFO message of the time spent in a filter will only be traced, if a request takes longer than the configured in the property BC.Tracer.DebugProfile.NPPerfMeter.InfoTimeout.
BC.Tracer.DebugProfile.NPPerfMeter.InfoTimeout	time in milliseconds	Valid for all filters, except for those filters that have the RequestFlag NEEDS_TIME_METER configured. If the time spent in a specific filter is equal or greater than the timeout configured in this property, the system will trace an INFO message on the trace group NPPerfMeter. The INFO message contains the filter name and the time spent. Setting this property helps you check which filters are slow in case you have some performance issues. Make sure to also set the trace level of NPPerfMeter to "INFO". If, for example, the filter is called MyFilter, the message will look like the below example.

2020 11 25 11:27:18.620 4.4.0 NPPerfMete 47288.140477112874752.00b8b8-16063000381708837-175fef17434 6-INFO : FilterTimeMeter_1_0::_cleanup: (MyFilter) time spent: 299 msecs

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).
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.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.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.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.IW4RewriteFlt	0 - 10	Traces the functioning of and defines the log level for the RewriteFilter.
BC.Tracer.DebugProfile.IW4SecRoleFlt	0 - 10	Traces the functioning of and defines the log level for the SecurityRoleFilter.
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.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.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

To enable SSL tracing on the backend and trace the functioning of, for example, the HttpsConnectorServlet or the BackendConnectorServlet, set the trace groups described in the following table.

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.
BC.Tracer.DebugProfile.OpenSSLCipher	0 - 10	SSL cipher tracing. Defines the severity level of the logged cipher functions.
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, ssl-key	To enable the tracing mentioned in the previous rows, Set this property (bcx.net.debug) to "record,handshake,ssl,ssl-key" or select one of these values. Additionally, set the bcx.net.debug.host property (see the previous row). If the value ssl-key is set, the TLS master keys are traced in the tracegroup BC.Tracer.DebugProfile.OpenSSLHandshk with the debug level LOW, for example: Oct 20 14:46:35 TestRunner OpenSSLHan 977751.139883295164160.test_tsl_master_key 7-DBG_LO: SSLKEY: SERVER_HANDSHAKE_TRAFFIC_SECRET 2887819562bbfafdedfed1dddc8ef91d3f3d573bdef5e0dc4af59b3d6c7c329c 8cee60e35c99ffcf4e42f132f05f706997c2241812bed97670caa2aa9339f9b070b5ae1cfc3d3dd0e650770ef3d3623d

|

To enable SSL tracing on the frontend, do this:

• Set the property Loglevel in the file navajo.xml, as follows:

Loglevel="debug ssl:trace5"

• Set the following trace group in the file bc.properties, to log the tracing to the navajo.log file as well:

BC.Tracer.DebugProfile.Apache=4

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.
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.
dTP	Total time spent in nevisProxy. Calculated by subtracting the time spent on frontend (dTFrs) and backend (dTB) from the total time (dTF).	dTP='12'

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='nevis.net:443 (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=nevis.net:443 (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='nevis.net:443' 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='nevis.net:443' 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: nevis.net
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='nevis.net:443 (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=nevis.net:443 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. That is, the length of time between the first byte received by the proxy (start), and the last byte sent back to the frontend (stop). dTF = stop - start.	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=nevis.net:443	%{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	The Session ID if it was accessed.	clID=<NULL>	%{clID}e
cookie	The value of the cookie if a cookie based SessionManagementFilter has been configured	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=""%h %l %u %t \"%r\" %>s %b \"%\{Referer\}i\" \"%\{User-Agent\}i\" %v %D triID=%\{UNIQUE_ID\}e clID=%\{clID\}e""

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://nevis.net:44300/esauth3/?login" "Mozilla/5.0 (X11; Linux i686; rv:7.0.1) Gecko/20100101 Firefox/7.0.1" nevis.net 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 there was no event
• Event=GW01,IW01,GW02: comma separated list of all events

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>