Skip to main content
Version: 8.2411.x.x RR

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.
dTPTotal 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:

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=nevis.net:443 (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='nevis.net:443' trId='01000000-5615-7f0100-1675bb326e8-00000005'

The maximum log level 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
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. 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
reqBRequest line to the backend.reqB="GET /htt/ HTTP/1.1"%{reqB}e
adrBThe address and port of the backend.adrB=nevis.net:443%{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
clIDThe Session ID if it was accessed.clID=<NULL>%{clID}e
cookieThe base64 encoded SHA256 value of the cookie if a cookie based SessionManagementFilter has been configuredcookie=<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. 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://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