Bug 5279: FwdState.cc:279: "!storedWholeReply_" assertion (#2052)

This assertion may be triggered when RESPMOD adaptation is aborted
(e.g., when an essential ICAP service is down, or when it sends an ICAP
response status code unsupported by Squid).

Ftp::Relay::forwardReply() calls markParsedVirginReplyAsWhole() before
adaptOrFinalizeReply(). Thus, at that markParsedVirginReplyAsWhole()
call time, startedAdaptation remained false, markStoredReplyAsWhole()
was called, and storedWholeReply_ became true. If Squid then decided to
start adaptation, but that adaptation had failed, FwdState::completed()
detected a mismatch between true storedWholeReply_ and a still-empty
STORE_PENDING StoreEntry. This bug was added in 2021 commit ba3fe8d.

Squid does not write virgin response to Store while adaptation_access
check is pending or after RESPMOD adaptation has started. Code that does
not write to Store must not make storedWholeReply_ true. On the other
hand, after adaptation_access is denied, and Squid finishes storing all
virgin response bytes, Squid needs to know whether storedWholeReply_
should be set (i.e. whether Squid has received the whole virgin reply
and called markParsedVirginReplyAsWhole()). This fix adds
Client::markedParsedVirginReplyAsWhole to remember the latter event.

Author: eduard-bagdasaryan

src/clients/Client.cc

@@ -159,20 +159,7 @@ 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);
+    markedParsedVirginReplyAsWhole = reasonWeAreSure;
 }
 
 // called when no more server communication is expected; may quit
@@ -230,6 +217,24 @@ Client::completeForwarding()
 {
     debugs(11,5, "completing forwarding for "  << fwd);
     assert(fwd != nullptr);
+
+    auto storedWholeReply = markedParsedVirginReplyAsWhole;
+#if USE_ADAPTATION
+    // This precondition is necessary for its two implications:
+    // * We cannot be waiting to decide whether to adapt this response. Thus,
+    //   the startedAdaptation check below correctly detects all adaptation
+    //   cases (i.e. it does not miss adaptationAccessCheckPending ones).
+    // * We cannot be waiting to consume/store received adapted response bytes.
+    //   Thus, receivedWholeAdaptedReply implies that we stored everything.
+    Assure(doneWithAdaptation());
+
+    if (startedAdaptation)
+        storedWholeReply = receivedWholeAdaptedReply ? "receivedWholeAdaptedReply" : nullptr;
+#endif
+
+    if (storedWholeReply)
+        fwd->markStoredReplyAsWhole(storedWholeReply);
+
     doneWithFwd = "completeForwarding()";
     fwd->complete();
 }
@@ -738,9 +743,11 @@ Client::handleAdaptedHeader(Http::Message *msg)
         // assume that ICAP does not auto-consume on failures
         const bool result = adaptedBodySource->setConsumerIfNotLate(this);
         assert(result);
+        checkAdaptationWithBodyCompletion();
     } else {
         // no body
-        fwd->markStoredReplyAsWhole("setFinalReply() stored header-only adapted reply");
+        Assure(!adaptedReplyAborted);
+        receivedWholeAdaptedReply = true;
         if (doneWithAdaptation()) // we may still be sending virgin response
             handleAdaptationCompleted();
     }
@@ -757,8 +764,7 @@ Client::resumeBodyStorage()
 
     handleMoreAdaptedBodyAvailable();
 
-    if (adaptedBodySource != nullptr && adaptedBodySource->exhausted())
-        endAdaptedBodyConsumption();
+    checkAdaptationWithBodyCompletion();
 }
 
 // more adapted response body is available
@@ -815,28 +821,36 @@ Client::handleAdaptedBodyProductionEnded()
     if (abortOnBadEntry("entry went bad while waiting for adapted body eof"))
         return;
 
-    // distinguish this code path from handleAdaptedBodyProducerAborted()
+    Assure(!adaptedReplyAborted);
     receivedWholeAdaptedReply = true;
 
-    // end consumption if we consumed everything
-    if (adaptedBodySource != nullptr && adaptedBodySource->exhausted())
-        endAdaptedBodyConsumption();
-    // else resumeBodyStorage() will eventually consume the rest
+    checkAdaptationWithBodyCompletion();
 }
 
 void
-Client::endAdaptedBodyConsumption()
+Client::checkAdaptationWithBodyCompletion()
 {
-    stopConsumingFrom(adaptedBodySource);
+    if (!adaptedBodySource) {
+        debugs(11, 7, "not consuming; " << startedAdaptation);
+        return;
+    }
+
+    if (!receivedWholeAdaptedReply && !adaptedReplyAborted) {
+        // wait for noteBodyProductionEnded() or noteBodyProducerAborted()
+        // because completeForwarding() needs to know whether we receivedWholeAdaptedReply
+        debugs(11, 7, "waiting for adapted body production ending");
+        return;
+    }
 
-    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");
+    if (!adaptedBodySource->exhausted()) {
+        debugs(11, 5, "waiting to consume the remainder of the adapted body from " << adaptedBodySource->status());
+        return; // resumeBodyStorage() should eventually consume the rest
     }
 
-    handleAdaptationCompleted();
+    stopConsumingFrom(adaptedBodySource);
+
+    if (doneWithAdaptation()) // we may still be sending virgin response
+        handleAdaptationCompleted();
 }
 
 // premature end of the adapted response body
@@ -845,18 +859,18 @@ void Client::handleAdaptedBodyProducerAborted()
     if (abortOnBadEntry("entry went bad while waiting for the now-aborted adapted body"))
         return;
 
+    Assure(!receivedWholeAdaptedReply);
+    adaptedReplyAborted = true;
     Must(adaptedBodySource != nullptr);
     if (!adaptedBodySource->exhausted()) {
         debugs(11,5, "waiting to consume the remainder of the aborted adapted body");
         return; // resumeBodyStorage() should eventually consume the rest
     }
 
-    stopConsumingFrom(adaptedBodySource);
-
     if (handledEarlyAdaptationAbort())
         return;
 
-    handleAdaptationCompleted(); // the user should get a truncated response
+    checkAdaptationWithBodyCompletion(); // the user should get a truncated response
 }
 
 // common part of noteAdaptationAnswer and handleAdaptedBodyProductionEnded

src/clients/Client.h

@@ -141,8 +141,11 @@ class Client:
 
     /// called by StoreEntry when it has more buffer space available
     void resumeBodyStorage();
-    /// called when the entire adapted response body is consumed
-    void endAdaptedBodyConsumption();
+
+    /// Reacts to adaptedBodySource-related changes. May end adapted body
+    /// consumption, adaptation as a whole, or forwarding. Safe to call multiple
+    /// times, including calls made after the end of adaptation.
+    void checkAdaptationWithBodyCompletion();
 #endif
 
 protected:
@@ -189,14 +192,22 @@ class Client:
     bool adaptationAccessCheckPending = false;
     bool startedAdaptation = false;
 
-    /// handleAdaptedBodyProductionEnded() was called
+    /// Whether the entire adapted response (including bodyless responses) has
+    /// been successfully produced. A successful end of body production does not
+    /// imply that we have consumed all of the produced body bytes.
     bool receivedWholeAdaptedReply = false;
+
+    bool adaptedReplyAborted = false; ///< handleAdaptedBodyProducerAborted() has been called
 #endif
     bool receivedWholeRequestBody = false; ///< handleRequestBodyProductionEnded called
 
     /// whether we are waiting for MemObject::delayRead() to call us back
     bool waitingForDelayAwareReadChance = false;
 
+    /// markParsedVirginReplyAsWhole() parameter (if that method was called) or nil;
+    /// points to a string literal which is used only for debugging
+    const char *markedParsedVirginReplyAsWhole = nullptr;
+
     /// whether we should not be talking to FwdState; XXX: clear fwd instead
     /// points to a string literal which is used only for debugging
     const char *doneWithFwd = nullptr;