]> git.ipfire.org Git - thirdparty/squid.git/commitdiff
Properly track (and mark) truncated store entries (#909)
authorEduard Bagdasaryan <eduard.bagdasaryan@measurement-factory.com>
Sat, 9 Oct 2021 21:31:53 +0000 (21:31 +0000)
committerSquid Anubis <squid-anubis@squid-cache.org>
Sun, 10 Oct 2021 00:21:15 +0000 (00:21 +0000)
## Responses with truncated bodies

Squid used an error-prone approach to identifying truncated responses:
The response is treated as whole[^1] unless somebody remembers to mark
it as truncated. This dangerous default naturally resulted in bugs where
truncated responses are treated as complete under various conditions.

This change reverses that approach: Responses not explicitly marked as
whole are treated as truncated. This change affects all Squid-server
FwsState-dispatched communications: HTTP, FTP, Gopher, and WHOIS. It
also affects responses received from the adaptation services.

Squid still tries to deliver responses with truncated bodies to clients
in most cases (no changes are expected/intended in that area).

[^1]: A better word to describe a "whole" response would be "complete",
    but several key Squid APIs use "complete" to mean "no more content
    is coming", misleading developers into thinking that a "completed"
    response has all the expected bytes and may be cached/shared/etc.

## Related access-logging improvements

Transactions that failed due to origin server or peer timeout (a common
source of truncation) are now logged with a _TIMEOUT %Ss suffix and
ERR_READ_TIMEOUT/WITH_SRV %err_code/%err_detail.

Transactions prematurely canceled by Squid during client-Squid
communication (usually due to various timeouts) now have WITH_CLT
default %err_detail. This detail helps distinguish otherwise
similarly-logged problems that may happen when talking to the client or
to the origin server/peer.

## Other

FwdState now (indirectly) complete()s truncated entries _after_
releasing/adjusting them so that invokeHandlers() and others do not get
a dangerous glimpse at a seemingly OK entry before its release().

14 files changed:
src/FwdState.cc
src/FwdState.h
src/Store.h
src/client_side.cc
src/client_side_request.cc
src/client_side_request.h
src/clients/Client.cc
src/clients/Client.h
src/clients/FtpGateway.cc
src/clients/FtpRelay.cc
src/gopher.cc
src/http.cc
src/store.cc
src/whois.cc

index f68538b45bcebd42cf25e13f7e400038bfa85d76..a9b3200a1084274dcc1ce26cf869ea4ae4d046c2 100644 (file)
@@ -150,7 +150,8 @@ FwdState::FwdState(const Comm::ConnectionPointer &client, StoreEntry * e, HttpRe
     start_t(squid_curtime),
     n_tries(0),
     destinations(new ResolvedPeers()),
-    pconnRace(raceImpossible)
+    pconnRace(raceImpossible),
+    storedWholeReply_(nullptr)
 {
     debugs(17, 2, "Forwarding client request " << client << ", url=" << e->url());
     HTTPMSGLOCK(request);
@@ -255,6 +256,23 @@ FwdState::selectPeerForIntercepted()
 }
 #endif
 
+/// updates ALE when we finalize the transaction error (if any)
+void
+FwdState::updateAleWithFinalError()
+{
+    if (!err || !al)
+        return;
+
+    LogTagsErrors lte;
+    lte.timedout = (err->xerrno == ETIMEDOUT || err->type == ERR_READ_TIMEOUT);
+    al->cache.code.err.update(lte);
+    if (!err->detail) {
+        static const auto d = MakeNamedErrorDetail("WITH_SERVER");
+        err->detailError(d);
+    }
+    al->updateError(Error(err->type, err->detail));
+}
+
 void
 FwdState::completed()
 {
@@ -279,20 +297,26 @@ FwdState::completed()
 
     if (entry->store_status == STORE_PENDING) {
         if (entry->isEmpty()) {
+            assert(!storedWholeReply_);
             if (!err) // we quit (e.g., fd closed) before an error or content
                 fail(new ErrorState(ERR_READ_ERROR, Http::scBadGateway, request, al));
             assert(err);
+            updateAleWithFinalError();
             errorAppendEntry(entry, err);
             err = NULL;
 #if USE_OPENSSL
             if (request->flags.sslPeek && request->clientConnectionManager.valid()) {
                 CallJobHere1(17, 4, request->clientConnectionManager, ConnStateData,
                              ConnStateData::httpsPeeked, ConnStateData::PinnedIdleContext(Comm::ConnectionPointer(nullptr), request));
+                // no flags.dont_retry: completed() is a post-reforward() act
             }
 #endif
         } else {
-            entry->complete();
-            entry->releaseRequest();
+            updateAleWithFinalError(); // if any
+            if (storedWholeReply_)
+                entry->completeSuccessfully(storedWholeReply_);
+            else
+                entry->completeTruncated("FwdState default");
         }
     }
 
@@ -549,6 +573,7 @@ FwdState::complete()
         serverConn = nullptr;
         destinationReceipt = nullptr;
 
+        storedWholeReply_ = nullptr;
         entry->reset();
 
         useDestinations();
@@ -558,10 +583,8 @@ FwdState::complete()
             debugs(17, 3, "server FD " << serverConnection()->fd << " not re-forwarding status " << replyStatus);
         else
             debugs(17, 3, "server (FD closed) not re-forwarding status " << replyStatus);
-        entry->complete();
 
-        if (!Comm::IsConnOpen(serverConn))
-            completed();
+        completed();
 
         stopAndDestroy("forwarding completed");
     }
@@ -573,6 +596,18 @@ FwdState::usingDestination() const
     return encryptionWait || peerWait || Comm::IsConnOpen(serverConn);
 }
 
+void
+FwdState::markStoredReplyAsWhole(const char * const whyWeAreSure)
+{
+    debugs(17, 5, whyWeAreSure << " for " << *entry);
+
+    // the caller wrote everything to Store, but Store may silently abort writes
+    if (EBIT_TEST(entry->flags, ENTRY_ABORTED))
+        return;
+
+    storedWholeReply_ = whyWeAreSure;
+}
+
 void
 FwdState::noteDestination(Comm::ConnectionPointer path)
 {
@@ -1010,6 +1045,8 @@ FwdState::connectedToPeer(Security::EncryptorAnswer &answer)
         // [in ways that may affect logging?]. Consider informing
         // ConnStateData about our tunnel or otherwise unifying tunnel
         // establishment [side effects].
+        flags.dont_retry = true; // TunnelStateData took forwarding control
+        entry->abort();
         complete(); // destroys us
         return;
     } else if (!Comm::IsConnOpen(answer.conn) || fd_table[answer.conn->fd].closing()) {
@@ -1203,9 +1240,12 @@ FwdState::dispatch()
 
 #if USE_OPENSSL
     if (request->flags.sslPeek) {
+        // we were just asked to peek at the server, and we did that
         CallJobHere1(17, 4, request->clientConnectionManager, ConnStateData,
                      ConnStateData::httpsPeeked, ConnStateData::PinnedIdleContext(serverConnection(), request));
         unregister(serverConn); // async call owns it now
+        flags.dont_retry = true; // we gave up forwarding control
+        entry->abort();
         complete(); // destroys us
         return;
     }
index d4d607664fbcace4920d1c679ac995d9ee20cd5f..20d8cfe017025cb52f385e0d7ab2906301fcb718 100644 (file)
@@ -78,6 +78,11 @@ public:
     void unregister(Comm::ConnectionPointer &conn);
     void unregister(int fd);
     void complete();
+
+    /// Mark reply as written to Store in its entirety, including the header and
+    /// any body. If the reply has a body, the entire body has to be stored.
+    void markStoredReplyAsWhole(const char *whyWeAreSure);
+
     void handleUnregisteredServerEnd();
     int reforward();
     bool reforwardableStatus(const Http::StatusCode s) const;
@@ -159,6 +164,8 @@ private:
     void notifyConnOpener();
     void reactToZeroSizeObject();
 
+    void updateAleWithFinalError();
+
 public:
     StoreEntry *entry;
     HttpRequest *request;
@@ -200,6 +207,10 @@ private:
     /// possible pconn race states
     typedef enum { raceImpossible, racePossible, raceHappened } PconnRace;
     PconnRace pconnRace; ///< current pconn race state
+
+    /// Whether the entire reply (including any body) was written to Store.
+    /// The string literal value is only used for debugging.
+    const char *storedWholeReply_;
 };
 
 class acl_tos;
index 16520001c2ddcba4db18095eb4eac7c5dbca9179..5f19842d9c854f328c1025e8d2288f7febab09fc 100644 (file)
@@ -67,9 +67,18 @@ public:
     bool isEmpty() const { return mem().endOffset() == 0; }
     bool isAccepting() const;
     size_t bytesWanted(Range<size_t> const aRange, bool ignoreDelayPool = false) const;
-    /// flags [truncated or too big] entry with ENTRY_BAD_LENGTH and releases it
-    void lengthWentBad(const char *reason);
+
+    /// Signals that the entire response has been stored and no more append()
+    /// calls should be expected; cf. completeTruncated().
+    void completeSuccessfully(const char *whyWeAreSureWeStoredTheWholeReply);
+
+    /// Signals that a partial response (if any) has been stored but no more
+    /// append() calls should be expected; cf. completeSuccessfully().
+    void completeTruncated(const char *whyWeConsiderTheReplyTruncated);
+
+    /// \deprecated use either completeSuccessfully() or completeTruncated() instead
     void complete();
+
     store_client_t storeClientType() const;
     /// \returns a malloc()ed buffer containing a length-long packed swap header
     const char *getSerialisedMetaData(size_t &length) const;
@@ -308,6 +317,9 @@ private:
     StoreEntry *adjustVary();
     const cache_key *calcPublicKey(const KeyScope keyScope);
 
+    /// flags [truncated or too big] entry with ENTRY_BAD_LENGTH and releases it
+    void lengthWentBad(const char *reason);
+
     static MemAllocator *pool;
 
     unsigned short lock_count;      /* Assume < 65536! */
index bb5e087e7d4272fc470a4abab5bca550126add07..9f14323b3e27c1c467371f149599cb19dd03ba45 100644 (file)
@@ -3993,8 +3993,16 @@ ConnStateData::unpinConnection(const bool andClose)
 }
 
 void
-ConnStateData::terminateAll(const Error &error, const LogTagsErrors &lte)
+ConnStateData::terminateAll(const Error &rawError, const LogTagsErrors &lte)
 {
+    auto error = rawError; // (cheap) copy so that we can detail
+    // We detail even ERR_NONE: There should be no transactions left, and
+    // detailed ERR_NONE will be unused. Otherwise, this detail helps in triage.
+    if (!error.detail) {
+        static const auto d = MakeNamedErrorDetail("WITH_CLIENT");
+        error.detail = d;
+    }
+
     debugs(33, 3, pipeline.count() << '/' << pipeline.nrequests << " after " << error);
 
     if (pipeline.empty()) {
index b9624ee4e094f7995650874813b2d64a75015d51..ae498388416cf928f3a221cacc0c8af83153315c 100644 (file)
@@ -161,6 +161,7 @@ ClientHttpRequest::ClientHttpRequest(ConnStateData * aConn) :
     , sslBumpNeed_(Ssl::bumpEnd)
 #endif
 #if USE_ADAPTATION
+    , receivedWholeAdaptedReply(false)
     , request_satisfaction_mode(false)
     , request_satisfaction_offset(0)
 #endif
@@ -2113,6 +2114,11 @@ void
 ClientHttpRequest::noteBodyProductionEnded(BodyPipe::Pointer)
 {
     assert(!virginHeadSource);
+
+    // distinguish this code path from future noteBodyProducerAborted() that
+    // would continue storing/delivering (truncated) reply if necessary (TODO)
+    receivedWholeAdaptedReply = true;
+
     // should we end request satisfaction now?
     if (adaptedBodySource != NULL && adaptedBodySource->exhausted())
         endRequestSatisfaction();
@@ -2126,7 +2132,14 @@ ClientHttpRequest::endRequestSatisfaction()
     stopConsumingFrom(adaptedBodySource);
 
     // TODO: anything else needed to end store entry formation correctly?
-    storeEntry()->complete();
+    if (receivedWholeAdaptedReply) {
+        // We received the entire reply per receivedWholeAdaptedReply.
+        // We are called when we consumed everything received (per our callers).
+        // We consume only what we store per noteMoreBodyDataAvailable().
+        storeEntry()->completeSuccessfully("received, consumed, and, hence, stored the entire REQMOD reply");
+    } else {
+        storeEntry()->completeTruncated("REQMOD request satisfaction default");
+    }
 }
 
 void
index a560561ef77b7cc7af8f52ade6f5641c6770b5ae..e2c3160e66831b1cb9586a747c3bc1ef53f4ac03 100644 (file)
@@ -240,6 +240,9 @@ private:
     CbcPointer<Adaptation::Initiate> virginHeadSource;
     BodyPipe::Pointer adaptedBodySource;
 
+    /// noteBodyProductionEnded() was called
+    bool receivedWholeAdaptedReply;
+
     bool request_satisfaction_mode;
     int64_t request_satisfaction_offset;
 #endif
index 5b1dcc2712975117f1b9cf8ca4925a9eefcf5f57..8cb6e9a27b1e8aeedc84a69e40deb7f71da5faf0 100644 (file)
@@ -155,6 +155,27 @@ Client::setFinalReply(HttpReply *rep)
     return theFinalReply;
 }
 
+void
+Client::markParsedVirginReplyAsWhole(const char *reasonWeAreSure)
+{
+    assert(reasonWeAreSure);
+    debugs(11, 3, reasonWeAreSure);
+
+    // The code storing adapted reply takes care of markStoredReplyAsWhole().
+    // We need to take care of the remaining regular network-to-store case.
+#if USE_ADAPTATION
+    if (startedAdaptation) {
+        debugs(11, 5, "adaptation handles markStoredReplyAsWhole()");
+        return;
+    }
+#endif
+
+    // Convert the "parsed whole virgin reply" event into the "stored..." event
+    // because, without adaptation, we store everything we parse: There is no
+    // buffer for parsed content; addVirginReplyBody() stores every parsed byte.
+    fwd->markStoredReplyAsWhole(reasonWeAreSure);
+}
+
 // called when no more server communication is expected; may quit
 void
 Client::serverComplete()
@@ -722,6 +743,7 @@ Client::handleAdaptedHeader(Http::Message *msg)
         assert(result);
     } else {
         // no body
+        fwd->markStoredReplyAsWhole("setFinalReply() stored header-only adapted reply");
         if (doneWithAdaptation()) // we may still be sending virgin response
             handleAdaptationCompleted();
     }
@@ -796,6 +818,9 @@ Client::handleAdaptedBodyProductionEnded()
     if (abortOnBadEntry("entry went bad while waiting for adapted body eof"))
         return;
 
+    // distinguish this code path from handleAdaptedBodyProducerAborted()
+    receivedWholeAdaptedReply = true;
+
     // end consumption if we consumed everything
     if (adaptedBodySource != NULL && adaptedBodySource->exhausted())
         endAdaptedBodyConsumption();
@@ -806,6 +831,14 @@ void
 Client::endAdaptedBodyConsumption()
 {
     stopConsumingFrom(adaptedBodySource);
+
+    if (receivedWholeAdaptedReply) {
+        // We received the entire adapted reply per receivedWholeAdaptedReply.
+        // We are called when we consumed everything received (per our callers).
+        // We consume only what we store per handleMoreAdaptedBodyAvailable().
+        fwd->markStoredReplyAsWhole("received,consumed=>stored the entire RESPMOD reply");
+    }
+
     handleAdaptationCompleted();
 }
 
@@ -826,7 +859,6 @@ void Client::handleAdaptedBodyProducerAborted()
     if (handledEarlyAdaptationAbort())
         return;
 
-    entry->lengthWentBad("body adaptation aborted");
     handleAdaptationCompleted(); // the user should get a truncated response
 }
 
index e9d1c3389ecf1d3c5d68da7acdff9d3f3ba30c27..d19cbe9aed79340b30daa03c740277860b12c1bf 100644 (file)
@@ -81,6 +81,10 @@ public:
 public: // should be protected
     void serverComplete();     /**< call when no server communication is expected */
 
+    /// remember that the received virgin reply was parsed in its entirety,
+    /// including its body (if any)
+    void markParsedVirginReplyAsWhole(const char *reasonWeAreSure);
+
 private:
     void serverComplete2();    /**< Continuation of serverComplete */
     bool completed = false;            /**< serverComplete() has been called */
@@ -176,6 +180,9 @@ protected:
 
     bool adaptationAccessCheckPending = false;
     bool startedAdaptation = false;
+
+    /// handleAdaptedBodyProductionEnded() was called
+    bool receivedWholeAdaptedReply = false;
 #endif
     bool receivedWholeRequestBody = false; ///< handleRequestBodyProductionEnded called
 
index 504b1ea3cbf6512dad2a461c76ed921bf9e5310c..9f62f3e76f742e261b26e838dbad9987fa776ef7 100644 (file)
@@ -2233,6 +2233,7 @@ ftpReadTransferDone(Ftp::Gateway * ftpState)
             ftpState->completedListing();
             /* QUIT operation handles sending the reply to client */
         }
+        ftpState->markParsedVirginReplyAsWhole("ftpReadTransferDone code 226 or 250");
         ftpSendQuit(ftpState);
     } else {            /* != 226 */
         debugs(9, DBG_IMPORTANT, HERE << "Got code " << code << " after reading data");
index da84beea54998f4c7a828a9ac22b68fe66a051f5..6e7cc6071d52d77c139084646ff3a767492020fe 100644 (file)
@@ -386,6 +386,7 @@ Ftp::Relay::forwardReply()
     reply->sources |= Http::Message::srcFtp;
 
     setVirginReply(reply);
+    markParsedVirginReplyAsWhole("Ftp::Relay::handleControlReply() does not forward partial replies");
     adaptOrFinalizeReply();
 
     serverComplete();
@@ -719,7 +720,12 @@ Ftp::Relay::readTransferDoneReply()
 {
     debugs(9, 3, status());
 
-    if (ctrl.replycode != 226 && ctrl.replycode != 250) {
+    // RFC 959 says that code 226 may indicate a successful response to a file
+    // transfer and file abort commands, but since we do not send abort
+    // commands, let's assume it was a successful file transfer.
+    if (ctrl.replycode == 226 || ctrl.replycode == 250) {
+        markParsedVirginReplyAsWhole("Ftp::Relay::readTransferDoneReply() code 226 or 250");
+    } else {
         debugs(9, DBG_IMPORTANT, "got FTP code " << ctrl.replycode <<
                " after reading response data");
     }
index 7c0e666252739c0cd2177c969b1a017e48c4ac04..489f9cf47e66d240078c77cf735b9a9ed3f08199 100644 (file)
@@ -89,6 +89,7 @@ public:
         HTML_header_added(0),
         HTML_pre(0),
         type_id(GOPHER_FILE /* '0' */),
+        overflowed(false),
         cso_recno(0),
         len(0),
         buf(NULL),
@@ -116,8 +117,15 @@ public:
     int HTML_pre;
     char type_id;
     char request[MAX_URL];
+
+    /// some received bytes ignored due to internal buffer capacity limits
+    bool overflowed;
+
     int cso_recno;
+
+    /// the number of not-yet-parsed Gopher line bytes in this->buf
     int len;
+
     char *buf;          /* pts to a 4k page */
     Comm::ConnectionPointer serverConn;
     FwdState::Pointer fwd;
@@ -431,6 +439,7 @@ gopherToHTML(GopherStateData * gopherState, char *inbuf, int len)
         if (gopherState->len + llen >= TEMP_BUF_SIZE) {
             debugs(10, DBG_IMPORTANT, "GopherHTML: Buffer overflow. Lost some data on URL: " << entry->url()  );
             llen = TEMP_BUF_SIZE - gopherState->len - 1;
+            gopherState->overflowed = true; // may already be true
         }
         if (!lpos) {
             /* there is no complete line in inbuf */
@@ -804,6 +813,10 @@ gopherReadReply(const Comm::ConnectionPointer &conn, char *buf, size_t len, Comm
 
         entry->timestampsSet();
         entry->flush();
+
+        if (!gopherState->len && !gopherState->overflowed)
+            gopherState->fwd->markStoredReplyAsWhole("gopher EOF after receiving/storing some bytes");
+
         gopherState->fwd->complete();
         gopherState->serverConn->close();
     } else {
@@ -962,6 +975,7 @@ gopherStart(FwdState * fwd)
         }
 
         gopherToHTML(gopherState, (char *) NULL, 0);
+        fwd->markStoredReplyAsWhole("gopher instant internal request satisfaction");
         fwd->complete();
         return;
     }
index a669b87004aaf892b85743fd99fe2673eef42e47..08b573a924319cf1c78c30aa52f648ff71256b0f 100644 (file)
@@ -1419,6 +1419,19 @@ HttpStateData::writeReplyBody()
     int len = inBuf.length();
     addVirginReplyBody(data, len);
     inBuf.consume(len);
+
+    // after addVirginReplyBody() wrote (when not adapting) everything we have
+    // received to Store, check whether we have received/parsed the entire reply
+    int64_t clen = -1;
+    const char *parsedWhole = nullptr;
+    if (!virginReply()->expectingBody(request->method, clen))
+        parsedWhole = "http parsed header-only reply";
+    else if (clen >= 0 && clen == payloadSeen - payloadTruncated)
+        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);
 }
 
 bool
@@ -1436,6 +1449,7 @@ HttpStateData::decodeAndWriteReplyBody()
         if (doneParsing) {
             lastChunk = 1;
             flags.do_next_read = false;
+            markParsedVirginReplyAsWhole("http parsed last-chunk");
         }
         return true;
     }
@@ -1553,8 +1567,6 @@ HttpStateData::processReplyBody()
 
         case COMPLETE_NONPERSISTENT_MSG:
             debugs(11, 5, "processReplyBody: COMPLETE_NONPERSISTENT_MSG from " << serverConnection);
-            if (flags.chunked && !lastChunk)
-                entry->lengthWentBad("missing last-chunk");
 
             serverComplete();
             return;
index 61266c2ee4d36f7951b641dfd4b2bb579e681a25..6031f4931120763648bba239b84505ddbb6b57cf 100644 (file)
@@ -745,7 +745,7 @@ StoreEntry::adjustVary()
 
         pe->startWriting(); // after timestampsSet()
 
-        pe->complete();
+        pe->completeSuccessfully("wrote the entire Vary marker object");
 
         return pe;
     }
@@ -1030,6 +1030,20 @@ StoreEntry::lengthWentBad(const char *reason)
     releaseRequest();
 }
 
+void
+StoreEntry::completeSuccessfully(const char * const whyWeAreSure)
+{
+    debugs(20, 3, whyWeAreSure << "; " << *this);
+    complete();
+}
+
+void
+StoreEntry::completeTruncated(const char * const truncationReason)
+{
+    lengthWentBad(truncationReason);
+    complete();
+}
+
 void
 StoreEntry::complete()
 {
@@ -1703,7 +1717,7 @@ StoreEntry::storeErrorResponse(HttpReply *reply)
     buffer();
     replaceHttpReply(HttpReplyPointer(reply));
     flush();
-    complete();
+    completeSuccessfully("replaceHttpReply() stored the entire error");
     negativeCache();
     releaseRequest(false); // if it is safe to negatively cache, sharing is OK
     unlock("StoreEntry::storeErrorResponse");
index 0fd47be5a57e987da3a02196e7db16bd94844509..eb2380fbf7256734c5dcf62bd413b9b24ae82685 100644 (file)
@@ -170,6 +170,9 @@ WhoisState::readReply(const Comm::ConnectionPointer &conn, char *aBuffer, size_t
     if (!entry->makePublic())
         entry->makePrivate(true);
 
+    if (dataWritten) // treat zero-length responses as incomplete
+        fwd->markStoredReplyAsWhole("whois received/stored the entire response");
+
     fwd->complete();
     debugs(75, 3, "whoisReadReply: Done: " << entry->url());
     conn->close();