From: Eduard Bagdasaryan <eduard.bagdasaryan@measurement-factory.com>
Date: Sat, 28 Jan 2023 09:36:56 +0000 (+0000)
Subject: Fix logging of responses truncated by premature EOF (#1244)
X-Git-Tag: SQUID_6_0_1~29
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=21f90159029aeb05fca55a6f48f120afb5f2b705;p=thirdparty%2Fsquid.git

Fix logging of responses truncated by premature EOF (#1244)

When a transaction failed due to a premature EOF while receiving an HTTP
response, %Ss logformat code was missing the ABORTED suffix (e.g.,
logging TCP_MISS instead of TCP_MISS_ABORTED). When premature EOF
truncated the header, the default "squid" access log format contained a
502 sent status code (%>Hs), hinting at the problem. When the body was
truncated, even that weak hint was usually absent because the actual
status code returned by the server (usually 200) was usually logged.

Similarly, %err_code/%err_detail logformat codes for HTTP responses with
truncated by a premature EOF bodies carried no information. Now they
expand to ERR_READ_ERROR/SRV_PREMATURE_EOF in those cases.

No changes to requests truncated by Squid-server read timeouts. They
were and are still logged with TIMEDOUT %Ss suffix and
ERR_READ_TIMEOUT/WITH_SERVER %err_code/%err_detail.

Also adjusted WHOIS to mark zero-length responses with
ERR_ZERO_SIZE_OBJECT instead of default ERR_READ_ERROR. This affects
forwarded WHOIS transactions and AS number queries generated during
(re)configuration.
---

diff --git a/doc/release-notes/release-6.sgml b/doc/release-notes/release-6.sgml
index e4df4b54d5..6ca8b0f086 100644
--- a/doc/release-notes/release-6.sgml
+++ b/doc/release-notes/release-6.sgml
@@ -114,7 +114,17 @@ This section gives an account of those changes in three categories:
 <sect1>Changes to existing options<label id="modifiedoptions">
 <p>
 <descrip>
-	<p>There have been no options changed.
+	<tag>logformat</tag>
+	<p>More logged <em>Ss</em> code values may contain an <em>_ABORTED</em>
+	suffix because Squid now adds that suffix in more cases where a TCP
+	Squid-to-server connection was closed prematurely (e.g., an EOF in the
+	middle of a chunked HTTP response body transfer). In general, tools
+	processing <em>Ss</em> code values should treat each value as an
+	underscore-delimited list of tags rather than an enumeration of a few
+	hard-coded values.
+
+	<p>This change affects all <em>Ss</em> code uses, not just those specific to
+	the <em>logformat</em> directive.
 
 </descrip>
 </p>
diff --git a/src/FwdState.cc b/src/FwdState.cc
index f1a2fb4124..d92cacaff8 100644
--- a/src/FwdState.cc
+++ b/src/FwdState.cc
@@ -241,7 +241,10 @@ FwdState::updateAleWithFinalError()
         return;
 
     LogTagsErrors lte;
-    lte.timedout = (err->xerrno == ETIMEDOUT || err->type == ERR_READ_TIMEOUT);
+    if (err->xerrno == ETIMEDOUT || err->type == ERR_READ_TIMEOUT)
+        lte.timedout = true;
+    else if (err->type != ERR_NONE)
+        lte.aborted = true;
     al->cache.code.err.update(lte);
     if (!err->detail) {
         static const auto d = MakeNamedErrorDetail("WITH_SERVER");
diff --git a/src/http.cc b/src/http.cc
index 59282567f7..141305249d 100644
--- a/src/http.cc
+++ b/src/http.cc
@@ -1393,6 +1393,16 @@ HttpStateData::truncateVirginBody()
     }
 }
 
+/// called on a premature EOF discovered when reading response body
+void
+HttpStateData::markPrematureReplyBodyEofFailure()
+{
+    const auto err = new ErrorState(ERR_READ_ERROR, Http::scBadGateway, fwd->request, fwd->al);
+    static const auto d = MakeNamedErrorDetail("SRV_PREMATURE_EOF");
+    err->detailError(d);
+    fwd->fail(err);
+}
+
 /**
  * Call this when there is data from the origin server
  * which should be sent to either StoreEntry, or to ICAP...
@@ -1416,8 +1426,11 @@ HttpStateData::writeReplyBody()
         parsedWhole = "http parsed Content-Length body bytes";
     else if (clen < 0 && eof)
         parsedWhole = "http parsed body ending with expected/required EOF";
+
     if (parsedWhole)
         markParsedVirginReplyAsWhole(parsedWhole);
+    else if (eof)
+        markPrematureReplyBodyEofFailure();
 }
 
 bool
@@ -1436,6 +1449,8 @@ HttpStateData::decodeAndWriteReplyBody()
             lastChunk = 1;
             flags.do_next_read = false;
             markParsedVirginReplyAsWhole("http parsed last-chunk");
+        } else if (eof) {
+            markPrematureReplyBodyEofFailure();
         }
         return true;
     }
diff --git a/src/http.h b/src/http.h
index 6fef97a26c..7baffe3649 100644
--- a/src/http.h
+++ b/src/http.h
@@ -140,6 +140,7 @@ private:
     void sendComplete();
     void httpStateConnClosed(const CommCloseCbParams &params);
     void httpTimeout(const CommTimeoutCbParams &params);
+    void markPrematureReplyBodyEofFailure();
 
     mb_size_t buildRequestPrefix(MemBuf * mb);
     void forwardUpgrade(HttpHeader&);
diff --git a/src/whois.cc b/src/whois.cc
index e2a0e91d3c..8f67337b91 100644
--- a/src/whois.cc
+++ b/src/whois.cc
@@ -172,6 +172,8 @@ WhoisState::readReply(const Comm::ConnectionPointer &conn, char *aBuffer, size_t
 
     if (dataWritten) // treat zero-length responses as incomplete
         fwd->markStoredReplyAsWhole("whois received/stored the entire response");
+    else
+        fwd->fail(new ErrorState(ERR_ZERO_SIZE_OBJECT, Http::scBadGateway, fwd->request, fwd->al));
 
     fwd->complete();
     debugs(75, 3, "whoisReadReply: Done: " << entry->url());