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
<rouss...@measurement-factory.com
<mailto:rouss...@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@lists.squid-cache.org
<mailto:squid-users@lists.squid-cache.org>
http://lists.squid-cache.org/listinfo/squid-users
<http://lists.squid-cache.org/listinfo/squid-users>
_______________________________________________
squid-users mailing list
squid-users@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-users
