From 6e20d77a76193562113631fb3d03f6bd0f17878a Mon Sep 17 00:00:00 2001 From: Eduard Bagdasaryan Date: Sat, 9 Oct 2021 21:31:53 +0000 Subject: [PATCH] Bug 5187: Properly track (and mark) truncated store entries (#909) 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. 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. 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(). --- src/FwdState.cc | 52 +++++++++++++++++++++++++++++++++----- src/FwdState.h | 11 ++++++++ src/Store.h | 16 ++++++++++-- src/client_side.cc | 10 +++++++- src/client_side_request.cc | 15 ++++++++++- src/client_side_request.h | 3 +++ src/clients/Client.cc | 34 ++++++++++++++++++++++++- src/clients/Client.h | 7 +++++ src/clients/FtpGateway.cc | 1 + src/clients/FtpRelay.cc | 8 +++++- src/gopher.cc | 14 ++++++++++ src/http.cc | 16 ++++++++++-- src/store.cc | 18 +++++++++++-- src/whois.cc | 3 +++ 14 files changed, 192 insertions(+), 16 deletions(-) diff --git a/src/FwdState.cc b/src/FwdState.cc index 5f297d2257e..bf15f4e26f5 100644 --- a/src/FwdState.cc +++ b/src/FwdState.cc @@ -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); @@ -259,6 +260,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() { @@ -283,20 +301,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"); } } @@ -543,6 +567,7 @@ FwdState::complete() if (Comm::IsConnOpen(serverConn)) unregister(serverConn); + storedWholeReply_ = nullptr; entry->reset(); useDestinations(); @@ -552,15 +577,25 @@ 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"); } } +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) { @@ -979,6 +1014,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()) { @@ -1173,9 +1210,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; } diff --git a/src/FwdState.h b/src/FwdState.h index eda01fb6746..01cc4ebda0f 100644 --- a/src/FwdState.h +++ b/src/FwdState.h @@ -79,6 +79,11 @@ class FwdState: public RefCountable, public PeerSelectionInitiator 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; @@ -160,6 +165,8 @@ class FwdState: public RefCountable, public PeerSelectionInitiator void notifyConnOpener(); + void updateAleWithFinalError(); + public: StoreEntry *entry; HttpRequest *request; @@ -197,6 +204,10 @@ class FwdState: public RefCountable, public PeerSelectionInitiator /// 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_; }; void getOutgoingAddress(HttpRequest * request, const Comm::ConnectionPointer &conn); diff --git a/src/Store.h b/src/Store.h index 0066befbb97..26b55a9031a 100644 --- a/src/Store.h +++ b/src/Store.h @@ -67,9 +67,18 @@ class StoreEntry : public hash_link, public Packable bool isEmpty() const { return mem().endOffset() == 0; } bool isAccepting() const; size_t bytesWanted(Range 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; @@ -311,6 +320,9 @@ class StoreEntry : public hash_link, public Packable 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! */ diff --git a/src/client_side.cc b/src/client_side.cc index 77a44598f61..7ae6e04af0a 100644 --- a/src/client_side.cc +++ b/src/client_side.cc @@ -4001,8 +4001,16 @@ ConnStateData::unpinConnection(const bool andClose) } void -ConnStateData::terminateAll(const Error &error, const LogTagsErrors <e) +ConnStateData::terminateAll(const Error &rawError, const LogTagsErrors <e) { + 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()) { diff --git a/src/client_side_request.cc b/src/client_side_request.cc index 86b48420b5c..9b35d2d95f4 100644 --- a/src/client_side_request.cc +++ b/src/client_side_request.cc @@ -162,6 +162,7 @@ ClientHttpRequest::ClientHttpRequest(ConnStateData * aConn) : , sslBumpNeed_(Ssl::bumpEnd) #endif #if USE_ADAPTATION + , receivedWholeAdaptedReply(false) , request_satisfaction_mode(false) , request_satisfaction_offset(0) #endif @@ -2124,6 +2125,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(); @@ -2137,7 +2143,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 diff --git a/src/client_side_request.h b/src/client_side_request.h index d5a8453833e..871014b7c92 100644 --- a/src/client_side_request.h +++ b/src/client_side_request.h @@ -239,6 +239,9 @@ class ClientHttpRequest CbcPointer virginHeadSource; BodyPipe::Pointer adaptedBodySource; + /// noteBodyProductionEnded() was called + bool receivedWholeAdaptedReply; + bool request_satisfaction_mode; int64_t request_satisfaction_offset; #endif diff --git a/src/clients/Client.cc b/src/clients/Client.cc index 96b0fad5090..52db3ee2ffd 100644 --- a/src/clients/Client.cc +++ b/src/clients/Client.cc @@ -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 } diff --git a/src/clients/Client.h b/src/clients/Client.h index e9d1c3389ec..d19cbe9aed7 100644 --- a/src/clients/Client.h +++ b/src/clients/Client.h @@ -81,6 +81,10 @@ class Client: 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 @@ class Client: bool adaptationAccessCheckPending = false; bool startedAdaptation = false; + + /// handleAdaptedBodyProductionEnded() was called + bool receivedWholeAdaptedReply = false; #endif bool receivedWholeRequestBody = false; ///< handleRequestBodyProductionEnded called diff --git a/src/clients/FtpGateway.cc b/src/clients/FtpGateway.cc index bd1665ea75c..4e6f85d4909 100644 --- a/src/clients/FtpGateway.cc +++ b/src/clients/FtpGateway.cc @@ -2281,6 +2281,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"); diff --git a/src/clients/FtpRelay.cc b/src/clients/FtpRelay.cc index 13056db48e4..b69ac6a25da 100644 --- a/src/clients/FtpRelay.cc +++ b/src/clients/FtpRelay.cc @@ -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"); } diff --git a/src/gopher.cc b/src/gopher.cc index f1cfb2f77aa..3012ae03c33 100644 --- a/src/gopher.cc +++ b/src/gopher.cc @@ -87,6 +87,7 @@ class GopherStateData HTML_header_added(0), HTML_pre(0), type_id(GOPHER_FILE /* '0' */), + overflowed(false), cso_recno(0), len(0), buf(NULL), @@ -117,8 +118,15 @@ class GopherStateData 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; @@ -444,6 +452,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 */ @@ -810,6 +819,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 { @@ -968,6 +981,7 @@ gopherStart(FwdState * fwd) } gopherToHTML(gopherState, (char *) NULL, 0); + fwd->markStoredReplyAsWhole("gopher instant internal request satisfaction"); fwd->complete(); return; } diff --git a/src/http.cc b/src/http.cc index f4e033f0760..6552df8eb45 100644 --- a/src/http.cc +++ b/src/http.cc @@ -1445,6 +1445,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 @@ -1462,6 +1475,7 @@ HttpStateData::decodeAndWriteReplyBody() if (doneParsing) { lastChunk = 1; flags.do_next_read = false; + markParsedVirginReplyAsWhole("http parsed last-chunk"); } return true; } @@ -1579,8 +1593,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; diff --git a/src/store.cc b/src/store.cc index 5c112f27e88..5ac4e0d152e 100644 --- a/src/store.cc +++ b/src/store.cc @@ -755,7 +755,7 @@ StoreEntry::adjustVary() pe->startWriting(); // after timestampsSet() - pe->complete(); + pe->completeSuccessfully("wrote the entire Vary marker object"); return pe; } @@ -1055,6 +1055,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() { @@ -1748,7 +1762,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"); diff --git a/src/whois.cc b/src/whois.cc index 7b3a7cb9a5e..21225d2e160 100644 --- a/src/whois.cc +++ b/src/whois.cc @@ -169,6 +169,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();