SKUDONET Profiling timers

When it comes to operationalising your log data, SKUDONET  provides a wide range of information related to the traffic moving between the client and the backend, in this article we will explain how to enable SKUDONET HTTP(S) profiling logging and describe each HTTP(S) profiling timer to help you understand the log fields.

SKUDONET is designed to be the critical path of your infrastructure. It works as an edge load balancer, an on-premise reverse proxy, or a WAAP system (Web application and API protection). Therefore, obtaining meaningful logs from SKUDONET is a must.

Profiling Logging provides insights about each client request and backend response. It enables extended information needed for troubleshooting and can even be used to detect early issues. Other methods include using various open-source integrations for storing log or statistical data over time like Grafana, ELK or other log analysis tools. SKUDONET HTTP(S) profile offers extended information in logs with millisecond accuracy, generating a wealth of information about traffic flowing into your infrastructure. The profiling logs give you the following advanced information about traffic timing data, traffic size, backend response time, client request time, failures in the client or server, etc.

In this post, you’ll learn how to configure and understand SKUDONET HTTP(S) profiling logging and the HTTP(S) timers it generates.

Enabling Profiling log for HTTP(S) profiles

Profiling logging is an extended property that has been available since SKUDONET v10.0.3, To enable profiling logging follow these steps:

• Click on the desired HTTP(S) profile, in the section LSLB > Farms.
• In the upper right corner enable the “ADVANCED” view.
• Enable the Log toggle (by default disabled) in the same Global tab.
• Ensure the profiling toggle is enabled as well.
• Save changes.

Understanding SKUDONET HTTP(S) timers

The HTTP(S) profile in SKUDONET works like a reverse proxy, mediating communication between the client and the server, taking decisions, and analysing traffic (if IPDS is enabled). The following diagram describes the request and response flow for a simple client HTTP request:

This request/response flow triggers the following timers in the SKUDONET HTTP(S) profile over a period of successive times:

In the following list, we describe each HTTP(S) profiling timer:

• tcc (time connection client): Time spent since the Client opens the TCP connections against the  SKUDONET HTTP(S) profile until the client receives the HTTP connection. For HTTPS traffic, it Includes time spent in the SSL handshake.
• trch (time read client headers): Time spent by the client to send request headers to the SKUDONET HTTP(S) profile.
• tcb (time connection backend): Time spent since the SKUDONET HTTP(S) profile opens the TCP connections against the backend until the SKUDONET HTTP(S) profile receives the HTTP connection. For HTTPS traffic, it Includes time spent in the SSL handshake.
• wp1 (WAF phase 1): Time spent analyzing WAF phase 1 ( request headers )
• twbh (time write backend headers): Time spent by SKUDONET HTTP(S) profile sending request headers to the backend.
• tdcb (time data client backend): Time spent by SKUDONET HTTP(S) profile copying request body data from client to backend. It includes wp2.
• wp2 (WAF phase 2): Time spent analyzing WAF phase 2 ( request body )
• trbh (time read backend headers): Time spent by the backend sending response headers to
• wp3 (WAF phase 3): Time spent analyzing WAF phase 3 ( response headers )
• twch (time write client headers): Time spent by SKUDONET HTTP(S) profile sending response headers to the client.
• tdbc (time data backend client): Time spent by SKUDONET HTTP(S) profile copying response body data from the backend to the client. It includes wp4
• wp4 (WAF phase 4): Time spent analyzing WAF phase 4 ( response body )
• ti (time idle): Time spent by SKUDONET HTTP(S) profile managing data, checking requests well-formed, checking headers, load balancing decisions, Persistence session management, logging messages, etc.
• tr (time request): Time spent by SKUDONET HTTP proxy from the connection to the backend until reading the last byte from the backend.
• tt (time total): Time spent by SKUDONET HTTP(S) profile handling the request.

As soon as the profiling is enabled for a certain HTTP(S) farm, the timer information is saved in the log file /var/log/syslog, extending any reverse proxy log information as shown below:

2024-08-05T14:21:37.574594+00:00 sva10000-1 pound: test-1, 172.16.100.49:8080 192.168.2.23 - - [05/Aug/2024:14:21:37 +0000] "GET /test/slee HTTP/1.1" 404 169 "" "curl/7.74.0" (s1 -> 172.16.100.254:80) 0.003 sec (0.088|0.020|0.287|0.008|-|0.015|0.004|0.077 2.908|3.070)(1.494|0.799|0.144|0.003)

2024-08-05T14:31:30.919413+00:00 sva10000-1 pound: test-1, 172.16.100.49:8080 192.168.2.23 - - [05/Aug/2024:14:31:30 +0000] "GET / HTTP/1.1" 200 274 "" "curl/7.74.0" (s1 -> 172.16.100.254:80) 0.003 sec (0.045|0.018|0.314|0.008|-|0.014|0.004|0.096 2.874|2.995)(1.477|0.732|0.145|0.002)

2024-08-05T14:32:06.817966+00:00 sva10000-1 pound: test-1, 172.16.100.49:8080 192.168.2.23 - - [05/Aug/2024:14:32:01 +0000] "GET /test/sleep.php?sleep=5 HTTP/1.1" 200 286 "" "curl/7.74.0" (s1 -> 172.16.100.254:80) 5.010 sec (0.047|0.018|0.241|0.009|-|5006.751|0.005|0.031 5010.358|5010.479)(1.738|1.235|0.190|-)

*timers are in milliseconds.

The timers are introduced at the end of the log line under parenthesis, and each timer name is shown in the following position:

order:
(tcc | trch | tcb | twbh | tdcb | trbh | twch | tdbc tr | tt)( wp1 | wp2 | wp3 | wp4)

So taking into consideration the previous lines of the log we can obtain the following information:

2024-08-05T14:21:37.574594+00:00 sva10000-1 pound: test-1, 172.16.100.49:8080 192.168.2.23 - - [05/Aug/2024:14:21:37 +0000] "GET /test/slee HTTP/1.1" 404 169 "" "curl/7.74.0" (s1 -> 172.16.100.254:80) 0.003 sec (0.088|0.020|0.287|0.008|-|0.015|0.004|0.077 2.908|3.070)(1.494|0.799|0.144|0.003)

There is no information in the field tdcb, as it is a GET and the GETs don’t include content in the body.

2024-08-05T14:32:06.817966+00:00 sva10000-1 pound: test-1, 172.16.100.49:8080 192.168.2.23 - - [05/Aug/2024:14:32:01 +0000] "GET /test/sleep.php?sleep=5 HTTP/1.1" 200 286 "" "curl/7.74.0" (s1 -> 172.16.100.254:80) 5.010 sec (0.047|0.018|0.241|0.009|-|5006.751|0.005|0.031 5010.358|5010.479)(1.738|1.235|0.190|-)

There is no information in the wp4 as the WAF is disabled from analysing the response body.

Additionally, the field trbh reaches 5 seconds, which means that the backend spent 5 seconds sending the entire response to the SKUDONET HTTP(S) profile.

2024-08-05T16:13:25.883623+00:00 sva10000-1 pound: test-1, s2 192.168.2.23 - - [05/Aug/2024:16:13:20 +0000] "GET /test/sleep.php?sleep=5 HTTP/1.1" 200 286 "" "curl/7.74.0" (s2 -> 172.16.100.254:80) 5.001 sec (0.092|0.019|0.270|0.010|-|5000.693|0.009|0.035 5001.102|5001.347)(-|-|-|-)

There is no information in the wp fields (WAF phases) as the WAF has been disabled for this service s2.

Profiling timers is another useful tool of SKUDONET ADC ready for troubleshooting or analysing how your entire system is working.