squid icon indicating copy to clipboard operation
squid copied to clipboard

Fixed and redefined total peering time (%<tt)

Open rousskov opened this issue 1 month ago • 4 comments

This change adjusts %[http::]<tt definition to include peer selection stage (with any relevant DNS lookups). That stage runs in parallel with connection establishment attempts, so excluding portions of that stage made interpreting logged delays more difficult (and code more complex).

Also documented how cache refresh (TCP_REFRESH_MODIFIED) affects %<tt. Fetching a new version of the stale object creates a second FwdState object, effectively repeating peer selection activities and request forwarding attempts. %<tt includes the time spent by those activities.

The following three bugs were fixed (at least):

  • Squid logged dash %<tt values for pinned connections (e.g., connections bumped at SslBump step 2 or 3) because Squid did not call HierarchyLogEntry::startPeerClock() for pinned connections.

  • Logged %<tt values for connections spliced at SslBump step 2 or 3 included TCP connection establishment time and TLS Server Hello fetching time (if any) but were missing the rest of Squid-peer communication (i.e. when Squid was tunneling bytes to and from the peer) because Squid stopped counting after calling switchToTunnel().

  • Squid logged dash %<tt values for external_acl_type and most other directives that support logformat codes because ALE::hier data member is unset until access logging, when prepareLogWithRequestDetails() copies HttpRequest::hier to ALE. This is a short-term fix. A proper one deserves a dedicated change (that should also address similar concerns for other HierarchyLogEntry-derived %codes).

rousskov avatar Jun 01 '24 00:06 rousskov