[squid-users] Squid log shows peer_response_time = 0 and status is 200

[Alex Rousskov]

On 12/30/22 12:29, Raghav P wrote:
> Thank you Alex.
> 
> We modified the log format as per your suggestion and here is the 
> relevant log entries (its been parsed) for one such log entry
> 
>    "http_method": "CONNECT",
>    "request_method_from_client": "CONNECT",
>    "request_method_to_server": "CONNECT",
>    "status": 200,
>    "vendor_action": "TCP_TUNNEL",
>    "err_code": "-",
>    "err_detail": "-",
>    "dest_status": "HIER_DIRECT",
>    "response_time": 8612,
>    "total_time_milliseconds": 8608,
>    "peer_response_time": 0,
>    "http_content_type": "-",
>    "bytes": 13071,
>    "bytes_in": 5373,
>    "bytes_out": 7698,
>    "sni": "-",
>    "X-Forwarded-For": "-"

Several use cases might result in the above combination of fields, but I 
think the following one is the most likely:

* Squid successfully opened an HTTP CONNECT tunnel to the origin server.

* The client and the origin server exchanged some data.

* The client was either the last to send data or it sent data during the 
same millisecond when Squid received the last data from the server.

In this use case, we see a clash between %<pt definition that was based 
on a basic GET request exchange (client sends TCP payload then server 
sends TCP payload) and the way HTTP CONNECT tunnels usually function 
when forwarding encrypted traffic (both sides send TCP data from time to 
time):

> [http::]<pt Peer response time in milliseconds. The timer starts
> when the last request byte is sent to the next hop
> and stops when the last response byte is received.

The above definition makes %<pt measurements useless in many CONNECT 
tunnel cases. There is even a source code comment about that: "The peer 
response time (%<pt) stopwatch is currently defined to start when we 
wrote the entire request. Thus, if we wrote something after the last 
read, report zero peer response time." In this case, "we wrote" means 
"we forwarded client bytes to the server" and "the last read" means "the 
last read from the origin server".


HTH,

Alex.


> On Fri, Dec 30, 2022 at 4:01 AM Alex Rousskov 
> <rousskov at measurement-factory.com 
> <mailto:rousskov at measurement-factory.com>> wrote:
> 
>     On 12/29/22 16:17, Raghav P wrote:
>      > We have a squid proxy configured as a forward proxy. But we see
>     that for
>      > some requests the log shows peer_response_time =0 but has status
>     is 200.
>      > At times users on their browser see this as a page not loading.
>      >
>      > As we couldn't find documentation around this. We wish to know
>     what this
>      > actually means and if this is an issue how to resolve it.
> 
>     It is difficult to say for sure what is going on without a lot more
>     details, but it is likely that Squid experienced some kind of an error
>     after receiving the beginning of a 200 OK response from the peer. I am
>     guessing that when handling certain kinds of errors, Squid may
>     forget to
>     update the transaction response time clock and log zero. It is also
>     possible, in some environments, that the transaction took less than one
>     millisecond.
> 
>     I recommend configuring Squid to log all the standard fields in "squid"
>     logformat, including %Ss (you probably log that already) and to add
>     %err_code/%err_detail fields (you probably do not log those now). Share
>     the values of those three specific fields (at least) with this mailing
>     list. In general, the more logged fields you can share, the higher are
>     the chances that somebody here will know what is going on with those
>     transactions.
> 
>     You may also want to mention whether these transactions are HTTP or
>     HTTPS, and, if HTTPS, whether your Squid has ssl_bump rules for those
>     transactions.
> 
> 
>     HTH,
> 
>     Alex.
> 
>     _______________________________________________
>     squid-users mailing list
>     squid-users at lists.squid-cache.org
>     <mailto:squid-users at lists.squid-cache.org>
>     http://lists.squid-cache.org/listinfo/squid-users
>     <http://lists.squid-cache.org/listinfo/squid-users>
>