From e7a9b7a8025ef4ecfca5e656760107cf369dd172 Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Fri, 6 Jan 2023 20:32:17 +0000 Subject: [PATCH] Log the number of request sending attempts (#541) Squid retries certain request forwarding failures. When the problem is persistent, and there are many peers (or the origin server has many IPs), many retries are possible. Absence of Squid-server transaction log hides these retries from admins. The new logformat code helps discover and triage problems, especially when Squid retries many times. --- src/AccessLogEntry.h | 6 ++++++ src/FwdState.cc | 22 +++++++++++++++++++--- src/FwdState.h | 1 + src/cf.data.pre | 12 +++++++++++- src/format/ByteCode.h | 1 + src/format/Format.cc | 5 +++++ src/format/Token.cc | 1 + src/tunnel.cc | 21 ++++++++++++++++++--- 8 files changed, 62 insertions(+), 7 deletions(-) diff --git a/src/AccessLogEntry.h b/src/AccessLogEntry.h index 28b0c58ae9..18a4a6a268 100644 --- a/src/AccessLogEntry.h +++ b/src/AccessLogEntry.h @@ -200,6 +200,12 @@ public: /// key=value pairs returned from URL rewrite/redirect helper NotePairs::Pointer notes; + /// The total number of finished attempts to establish a connection. + /// Excludes discarded HappyConnOpener attempts. Includes failed + /// HappyConnOpener attempts and [always successful] persistent connection + /// reuse. See %request_attempts. + int requestAttempts = 0; + /// see ConnStateData::proxyProtocolHeader_ ProxyProtocol::HeaderPointer proxyProtocolHeader; diff --git a/src/FwdState.cc b/src/FwdState.cc index 495666854b..c1afa28595 100644 --- a/src/FwdState.cc +++ b/src/FwdState.cc @@ -847,8 +847,7 @@ FwdState::noteConnection(HappyConnOpener::Answer &answer) transportWait.finish(); - Must(n_tries <= answer.n_tries); // n_tries cannot decrease - n_tries = answer.n_tries; + updateAttempts(answer.n_tries); ErrorState *error = nullptr; if ((error = answer.error.get())) { @@ -1095,6 +1094,22 @@ FwdState::syncHierNote(const Comm::ConnectionPointer &server, const char *host) al->hier.resetPeerNotes(server, host); } +/// sets n_tries to the given value (while keeping ALE, if any, in sync) +void +FwdState::updateAttempts(const int newValue) +{ + Assure(n_tries <= newValue); // n_tries cannot decrease + + // Squid probably creates at most one FwdState/TunnelStateData object per + // ALE, but, unlike an assignment would, this increment logic works even if + // Squid uses multiple such objects for a given ALE in some esoteric cases. + if (al) + al->requestAttempts += (newValue - n_tries); + + n_tries = newValue; + debugs(17, 5, n_tries); +} + /** * Called after forwarding path selection (via peer select) has taken place * and whenever forwarding needs to attempt a new connection (routing failover). @@ -1158,7 +1173,8 @@ FwdState::usePinned() return; } - ++n_tries; + updateAttempts(n_tries + 1); + request->flags.pinned = true; assert(connManager); diff --git a/src/FwdState.h b/src/FwdState.h index ca1ad75e3c..e9a907d36e 100644 --- a/src/FwdState.h +++ b/src/FwdState.h @@ -152,6 +152,7 @@ private: /// whether we have used up all permitted forwarding attempts bool exhaustedTries() const; + void updateAttempts(int); /// \returns the time left for this connection to become connected or 1 second if it is less than one second left time_t connectingTimeout(const Comm::ConnectionPointer &conn) const; diff --git a/src/cf.data.pre b/src/cf.data.pre index 5f4b24784d..f63929dba2 100644 --- a/src/cf.data.pre +++ b/src/cf.data.pre @@ -4085,7 +4085,7 @@ DOC_START * unfinished Happy Eyeballs connection attempts (prevented by setting happy_eyeballs_connect_limit to 0) - See also: forward_timeout and connect_retries. + See also: forward_timeout, connect_retries, and %request_attempts. DOC_END COMMENT_START @@ -4941,6 +4941,16 @@ DOC_START Ss Squid request status (TCP_MISS etc) Sh Squid hierarchy status (DEFAULT_PARENT etc) + [http::]request_attempts Number of request forwarding attempts + + See forward_max_tries documentation that details what Squid counts + as a forwarding attempt. Pure cache hits log zero, but cache hits + that triggered HTTP cache revalidation log the number of attempts + made when sending an internal revalidation request. DNS, ICMP, + ICP, HTCP, ESI, ICAP, eCAP, helper, and other secondary requests + sent by Squid as a part of a master transaction do not increment + the counter logged for the received request. + SSL-related format codes: ssl::bump_mode SslBump decision for the transaction: diff --git a/src/format/ByteCode.h b/src/format/ByteCode.h index d65c785ffd..ff05b44e0b 100644 --- a/src/format/ByteCode.h +++ b/src/format/ByteCode.h @@ -173,6 +173,7 @@ typedef enum { LFT_SQUID_ERROR, LFT_SQUID_ERROR_DETAIL, LFT_SQUID_HIERARCHY, + LFT_SQUID_REQUEST_ATTEMPTS, LFT_MIME_TYPE, LFT_TAG, diff --git a/src/format/Format.cc b/src/format/Format.cc index 5bbba9c8c3..96e8a2a5bb 100644 --- a/src/format/Format.cc +++ b/src/format/Format.cc @@ -1017,6 +1017,11 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS out = hier_code_str[al->hier.code]; break; + case LFT_SQUID_REQUEST_ATTEMPTS: + outint = al->requestAttempts; + doint = 1; + break; + case LFT_MIME_TYPE: out = al->http.content_type; break; diff --git a/src/format/Token.cc b/src/format/Token.cc index 6b826dcc70..b5cbc4dd49 100644 --- a/src/format/Token.cc +++ b/src/format/Token.cc @@ -147,6 +147,7 @@ static TokenTableEntry TokenTableMisc[] = { TokenTableEntry(">handshake", LFT_CLIENT_HANDSHAKE), TokenTableEntry("err_code", LFT_SQUID_ERROR ), TokenTableEntry("err_detail", LFT_SQUID_ERROR_DETAIL ), + TokenTableEntry("request_attempts", LFT_SQUID_REQUEST_ATTEMPTS), TokenTableEntry("note", LFT_NOTE ), TokenTableEntry("credentials", LFT_CREDENTIALS), TokenTableEntry("master_xaction", LFT_MASTER_XACTION), diff --git a/src/tunnel.cc b/src/tunnel.cc index 4b202ce643..22ad8ba325 100644 --- a/src/tunnel.cc +++ b/src/tunnel.cc @@ -265,6 +265,7 @@ private: void cancelStep(const char *reason); bool exhaustedTries() const; + void updateAttempts(int); public: bool keepGoingAfterRead(size_t len, Comm::Flag errcode, int xerrno, Connection &from, Connection &to); @@ -490,6 +491,21 @@ TunnelStateData::syncHierNote(const Comm::ConnectionPointer &conn, const char *o al->hier.resetPeerNotes(conn, origin); } +/// sets n_tries to the given value (while keeping ALE in sync) +void +TunnelStateData::updateAttempts(const int newValue) +{ + Assure(n_tries <= newValue); // n_tries cannot decrease + + // Squid probably creates at most one FwdState/TunnelStateData object per + // ALE, but, unlike an assignment would, this increment logic works even if + // Squid uses multiple such objects for a given ALE in some esoteric cases. + al->requestAttempts += (newValue - n_tries); + + n_tries = newValue; + debugs(26, 5, n_tries); +} + int TunnelStateData::Connection::debugLevelForError(int const xerrno) const { @@ -1052,8 +1068,7 @@ TunnelStateData::noteConnection(HappyConnOpener::Answer &answer) { transportWait.finish(); - Assure(n_tries <= answer.n_tries); // n_tries cannot decrease - n_tries = answer.n_tries; + updateAttempts(answer.n_tries); ErrorState *error = nullptr; if ((error = answer.error.get())) { @@ -1412,7 +1427,7 @@ TunnelStateData::usePinned() const auto serverConn = ConnStateData::BorrowPinnedConnection(request.getRaw(), al); debugs(26, 7, "pinned peer connection: " << serverConn); - ++n_tries; + updateAttempts(n_tries + 1); // Set HttpRequest pinned related flags for consistency even if // they are not really used by tunnel.cc code. -- 2.47.2