diff --git a/src/FwdState.cc b/src/FwdState.cc index f68538b45bc..a9b3200a108 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); @@ -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; } diff --git a/src/FwdState.h b/src/FwdState.h index d4d607664fb..20d8cfe0170 100644 --- a/src/FwdState.h +++ b/src/FwdState.h @@ -78,6 +78,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; @@ -159,6 +164,8 @@ class FwdState: public RefCountable, public PeerSelectionInitiator void notifyConnOpener(); void reactToZeroSizeObject(); + void updateAleWithFinalError(); + public: StoreEntry *entry; HttpRequest *request; @@ -200,6 +207,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_; }; class acl_tos; diff --git a/src/Store.h b/src/Store.h index 16520001c2d..5f19842d9c8 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; @@ -308,6 +317,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 bb5e087e7d4..9f14323b3e2 100644 --- a/src/client_side.cc +++ b/src/client_side.cc @@ -3993,8 +3993,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 b9624ee4e09..ae498388416 100644 --- a/src/client_side_request.cc +++ b/src/client_side_request.cc @@ -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 diff --git a/src/client_side_request.h b/src/client_side_request.h index a560561ef77..e2c3160e668 100644 --- a/src/client_side_request.h +++ b/src/client_side_request.h @@ -240,6 +240,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 5b1dcc27129..8cb6e9a27b1 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 504b1ea3cbf..9f62f3e76f7 100644 --- a/src/clients/FtpGateway.cc +++ b/src/clients/FtpGateway.cc @@ -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"); diff --git a/src/clients/FtpRelay.cc b/src/clients/FtpRelay.cc index da84beea549..6e7cc6071d5 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 7c0e6662527..489f9cf47e6 100644 --- a/src/gopher.cc +++ b/src/gopher.cc @@ -89,6 +89,7 @@ class GopherStateData 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 @@ 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; @@ -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; } diff --git a/src/http.cc b/src/http.cc index a669b87004a..08b573a9243 100644 --- a/src/http.cc +++ b/src/http.cc @@ -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; diff --git a/src/store.cc b/src/store.cc index 61266c2ee4d..6031f493112 100644 --- a/src/store.cc +++ b/src/store.cc @@ -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"); diff --git a/src/whois.cc b/src/whois.cc index 0fd47be5a57..eb2380fbf72 100644 --- a/src/whois.cc +++ b/src/whois.cc @@ -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();