I’m using HAProxy in TCP mode and I’ve a requirement to log SNI in a HTTPS requesst. To get the SNI value, I’m reading the raw socket buffer.
tcp-request inspect-delay 3s
tcp-request content capture req.ssl_sni len 100
It works, but I’ve noticed considerably high %Tw time when doing this. For perspective, without using the SNI extraction block, I see value as just 1, but with the SNI extraction block and logging, the %Tw value is as high as ~150.
I’m unable to understand why this would happen. Why is tcp inspect causing increased latency for simply waiting for a connection slot? To add to that, why is it 150x, too crazy.
Interesting piece of information that I don’t want to leave out, in my case, since this is TCP proxy, SSL termination is done by the backend.
Log without SNI extraction:-
{
"date_time": "01/Jul/2021:14:40:41.665",
"client": "127.0.0.1:36372",
"frontend": "public_tcp_https/127.0.0.1:8443",
"backend": "lx_https/ltx1-app1019.stg.domain.com/10.153.53.236:22272",
"Tw_time_queue_wait": "1",
"Tc_time_connect": "79",
"Tt_time_total": "597",
"bytes_read": "9699",
"bytes_uploaded": "445",
"ts_termination_state": "--",
"actconn/feconn/beconn/srv_conn/retries": "1/1/0/0/0",
"srv_queue/backend_queue": "0/0",
"client_rtt/rttvar/unacked/sacked/retrans/fackets/lost/reordering": "0/0/1/0/0/0/0/3",
"host/sni": "-"
}
Log with SNI extraction:-
{
"date_time": "01/Jul/2021:14:34:44.014",
"client": "127.0.0.1:59818",
"frontend": "public_tcp_https/127.0.0.1:8443",
"backend": "lx_https/ltx1-app1019.stg.domain.com/10.153.53.236:22272",
"Tw_time_queue_wait": "170",
"Tc_time_connect": "80",
"Tt_time_total": "674",
"bytes_read": "9699",
"bytes_uploaded": "445",
"ts_termination_state": "--",
"actconn/feconn/beconn/srv_conn/retries": "1/1/0/0/0",
"srv_queue/backend_queue": "0/0",
"client_rtt/rttvar/unacked/sacked/retrans/fackets/lost/reordering": "0/0/1/0/0/0/0/3",
"host/sni": "www.domain.com"
}