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 e4df4b54d5b4f480006fe15970143ed6cb50e510..6ca8b0f0864aa7a923163224a8f8c3ec5900f73b 100644 (file)
--- 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 f1a2fb4124577b548bb503c8e157a91feda35bbe..d92cacaff83dd40ae37579b7108719087fb93cc1 100644 (file)
--- 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 59282567f7b9af4b19abbd063db40abad4de0508..141305249de08e81255ec00cbf405b90b7757bf3 100644 (file)
--- 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 6fef97a26ceea9bf7a28934563078cf86450436e..7baffe364997dbf96dd9cf76610fef97d5831b21 100644 (file)
--- 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 e2a0e91d3ced80268be71178bccdb0ae6db46a48..8f67337b91463116aed186b696958fba64bb75fd 100644 (file)
--- 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());