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 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 base64 encoded SHA256 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. 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 eventEvent=GW01,IW01,GW02: comma separated list of all events