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.

diff --git a/src/AccessLogEntry.h b/src/AccessLogEntry.h
index 28b0c58ae92f0b2951c71bb0a412b5f44011e39e..18a4a6a2688e2b74be2aa08c97330f6bf901fd05 100644 (file)
--- 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 495666854be6dd99ba16c3e18ac46ad5207b6c5d..c1afa285952564e86ccb5e102f19c3ed7db2d593 100644 (file)
--- 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 ca1ad75e3c2b7b45d8968e50608bad4a5796c625..e9a907d36e9d9182eedd22e32ec26c859daedc49 100644 (file)
--- 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 5f4b24784d0547a04f2b40d3c5cb2b1118b641bb..f63929dba214e7f1d49ae4ea41cd44727da65f98 100644 (file)
--- 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 d65c785ffd9588817301c1bcdc959db847017628..ff05b44e0b1d981d4ab2b707f5ed7400398e30d0 100644 (file)
--- 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 5bbba9c8c37aeacca28710658a0cc1015c7113b2..96e8a2a5bb6f48c3e8d8da959129f129f29c46d8 100644 (file)
--- 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 6b826dcc70818069b5f17c442ca79d1afe17537a..b5cbc4dd49b0aef47f683cc100a419049b45a29f 100644 (file)
--- 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 4b202ce64393dad704d40d3be1f8d865e4d2fd40..22ad8ba32596739cbd9591fbe16f633e604cdea6 100644 (file)
--- 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.