Tracing examples
The following examples illustrate the functioning of some trace groups. Each trace line is built in the following way with the default configuration:
<date> <nevisproxy_version> <trace_group> <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:
2024 11 19 16:32:23.849 8.2505.0.0 NavajoOp 22037.139733629540096.2006d991bc853619bdd6b1cad7a82dc8.198f0ba83ebe5cf0 6-INFO : <<<<< 'GET /test/session/?session-type=default' invS='/(DelegationFilter) / (ErrorFilter) /test/ (RewriteFilter), /test/ (TestRewriteFilter) / (RootRewriteFilter) / (HeaderDelegationFilter)>TestServlet' sC='200' bS='836' dTF='15' dTFrs='1' rmIP='192.168.5.175' Event='SC01' clID='S5cde8370c5d1dIrJr+ZyXwK6JSukZosY1Syz61YqY3bIO0i8y+f20wI=' trID='2006d991bc853619bdd6b1cad7a82dc8.198f0ba83ebe5cf0' (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='/ DelegationFilter) / (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' |
| Event | List of events | Event='SC01' |
| clID | HttpSession ID (if it was accessed). | clID='S5cde8370c5d1dIrJr+ZyXwK6JSukZosY1Syz61YqY3bIO0i8y+f20wI=' |
| trID | Transaction ID | trID='2006d991bc853619bdd6b1cad7a82dc8.198f0ba83ebe5cf0' |
| 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:
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 7-DBG_LO: >>>>> 'GET /htt/<NULL>' rmIP='127.0.0.1' trID='d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410'
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: >>> Upgrade-Insecure-Requests: 1
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: >>> Sec-Fetch-Site: none
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: >>> User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:128.0) Gecko/20100101 Firefox/128.0
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: >>> Accept-Language: en-US,en;q=0.5
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: >>> Sec-Fetch-Mode: navigate
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: >>> Sec-Fetch-Dest: document
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: >>> traceparent: 00-d108a5b87874779b9b9d182b7e3f7627-cc65233656c9e410-00
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: >>> Accept-Encoding: gzip, deflate, br, zstd
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: >>> Connection: keep-alive
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: >>> Host: localhost
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: >>> Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/png,image/svg+xml,*/*;q=0.8
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: >>> Priority: u=0, i
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: >>> Sec-Fetch-User: ?1
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 8-DBG_ME: >>>>>>>>>>>>>>>>>> (filter 'ErrorFilter')
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 8-DBG_ME: >>>>>>>>>>>>>>>>>> (filter 'CookieBasedSessionManagementFilter')
2024 11 19 16:44:58.125 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 8-DBG_ME: >>>>>>>>>>>>>>>>>> (filter 'Forwarded-For')
2024 11 19 16:44:58.126 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 8-DBG_ME: >>>>>>>>>>>>>>>>>> (servlet 'HTTBackend')
2024 11 19 16:44:58.127 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 7-DBG_LO: <<<<<<<<<<<<<<<<< (remoteIP '127.0.0.1' servlet 'HTTBackend' dT='1')
2024 11 19 16:44:58.127 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 7-DBG_LO: <<<<<<<<<<<<<<<<< (remoteIP '127.0.0.1' filter 'Forwarded-For' dT='2')
2024 11 19 16:44:58.127 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 7-DBG_LO: <<<<<<<<<<<<<<<<< (remoteIP '127.0.0.1' filter 'CookieBasedSessionManagementFilter' dT='2')
2024 11 19 16:44:58.128 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 7-DBG_LO: <<<<<<<<<<<<<<<<< (remoteIP '127.0.0.1' filter 'ErrorFilter' dT='3')
2024 11 19 16:44:58.128 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 6-INFO : <<<<< 'GET /htt/' invS='/* (ErrorFilter) /* (CookieBasedSessionManagementFilter) /* (Forwarded-For) >HTTBackend' sC='200' bS='218' dTF='4' dTFrs='0' rmIP='127.0.0.1' Event='SC01' clID='05faa8c03700AcCDXgJUpWcFHfhH9nIFSgWL4ApaNptDJyJYM6GIeQAB0X' trID='d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410' (cR=1)' dTP='3'
2024 11 19 16:44:58.128 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: <<< Set-Cookie: NPSession=0608a8c03700pjBlwRGlNj0jlGcB6WDQLYnUyktubMIhzx2jMerWwlAQYg; Path=/; Secure; HttpOnly
2024 11 19 16:44:58.128 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: <<< Content-Length: 218
2024 11 19 16:44:58.128 8.2505.0.0 NavajoOp 67080.139738663999040.d108a5b87874779b9b9d182b7e3f7627.cc65233656c9e410 9-DBG_HI: <<< Content-Type: text/html
Example of IsiwebOp tracing
The IsiwebOp trace group is used for troubleshooting content providers. Response line from the content provider:
2024 11 19 16:47:47.744 8.2505.0.0 IsiwebOp 67837.139637645129280.2b9b7099fbdfffb5b0e594b0e9ab64fc.ea816af8da411fb0 6-INFO : <==== 'GET /htt/ HTTP/1.1' invS='HTTBackend' inetA='localhost:8080 (127.0.0.1)' trId='2b9b7099fbdfffb5b0e594b0e9ab64fc.ea816af8da411fb0' sC='200' dTB='1' dTcB='0' dTsB='0' dTr1B='1' 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 | The name of the invoked servlet. | invS='HTTBackend' |
| inetA | The inet address of the content provider (important in case of load balancing). | inetA='localhost:8080 (127.0.0.1)' |
| trID | Transaction ID. | trId='2b9b7099fbdfffb5b0e594b0e9ab64fc.ea816af8da411fb0' |
| 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>' |
On log level "7", the IsiwebOp also traces the outgoing request to the content provider, including such information as the request line and the inet address of the backend:
2024 11 19 16:55:00.925 8.2505.0.0 IsiwebOp 67837.139637562521152.a15a5bee560d95ecfc01a83959f71d6c.42c93a1e29f8e532 7-DBG_LO: ====> 'GET /htt/ HTTP/1.1' invS='HTTBackend' inetA='localhost:8080' trId='a15a5bee560d95ecfc01a83959f71d6c.42c93a1e29f8e532'
The maximum log level will also trace the headers between the content provider and the proxy:
2024 11 19 16:59:33.649 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 7-DBG_LO: ====> 'GET /htt/ HTTP/1.1' invS='HTTBackend' inetA='localhost:8080' trId='a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771'
2024 11 19 16:59:33.649 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: ==> Upgrade-Insecure-Requests: 1
2024 11 19 16:59:33.649 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: ==> Sec-Fetch-Site: none
2024 11 19 16:59:33.649 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: ==> User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:128.0) Gecko/20100101 Firefox/128.0
2024 11 19 16:59:33.649 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: ==> Accept-Language: en-US,en;q=0.5
2024 11 19 16:59:33.649 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: ==> Sec-Fetch-Mode: navigate
2024 11 19 16:59:33.649 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: ==> Sec-Fetch-Dest: document
2024 11 19 16:59:33.649 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: ==> Connection: Keep-Alive
2024 11 19 16:59:33.649 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: ==> Accept-Encoding: gzip, deflate, br, zstd
2024 11 19 16:59:33.649 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: ==> traceparent: 00-a830107c479bb7c402f27a8fe3567a3f-0291264c19a02771-00
2024 11 19 16:59:33.649 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: ==> Host: localhost:8080
2024 11 19 16:59:33.649 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: ==> Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/png,image/svg+xml,*/*;q=0.8
2024 11 19 16:59:33.649 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: ==> Sec-Fetch-User: ?1
2024 11 19 16:59:33.649 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: ==> Priority: u=0, i
2024 11 19 16:59:33.650 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 6-INFO : <==== 'GET /htt/ HTTP/1.1' invS='HTTBackend' inetA='localhost:8080 (127.0.0.1)' trId='a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771' sC='200' dTB='1' dTcB='1' dTsB='0' dTr1B='0' dTr2B='0' usrID='<NULL>'
2024 11 19 16:59:33.650 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: <== Content-Type: text/html
2024 11 19 16:59:33.650 8.2505.0.0 IsiwebOp 69497.140410337670720.a830107c479bb7c402f27a8fe3567a3f.0291264c19a02771 8-DBG_ME: <== Content-Length: 218
Example of NProxyOp tracing
The NProxyOp trace group provides information about frontend and backend calls on one single line:
2024 11 19 17:02:33.620 8.2505.0.0 NProxyOp 69497.140409928934976.2ac23da564ee1064a78780901ce6ff4e.e2a2d5496c39aade 6-INFO : reqF="GET /htt/ HTTP/1.1" reqDecF=<NULL> ipF=127.0.0.1 sCF=200 bSF=218 dTF=3 reqB="GET /htt/ HTTP/1.1" adrB=localhost:8080 ipB=127.0.0.1 sCB=200 dTB=0 dTcB=0 dTsB=0 dTr1B=0 dTr2B=0 dTFrs=0 invS=/* (ErrorFilter) /* (CookieBasedSessionManagementFilter) /* (Forwarded-For) >HTTBackend cR=1 usrID=<NULL> Event=<NULL> clID=0f6ba8c03700PF05Mi8arij5OIEM22k6WAlgWjzwRHyvujnZ3ksFeuADML cookie=<NULL> sslID=<NULL> trID=2ac23da564ee1064a78780901ce6ff4e.e2a2d5496c39aade
| 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=127.0.0.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: 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=localhost:8080 | %{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=/* (ErrorFilter) /* (CookieBasedSessionManagementFilter) /* (Forwarded-For) >HTTBackend | %{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 | 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=2ac23da564ee1064a78780901ce6ff4e.e2a2d5496c39aade | %{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 trID=%\{UNIQUE_ID\}e clID=%\{clID\}e""
Produces the following trace event:
10.30.212.29 - - [19/Nov/2024:17:02:33 +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 trID=2ac23da564ee1064a78780901ce6ff4e.e2a2d5496c39aade 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