------------------------------------------------------------
revno: 10421
revision-id: squid3@treenet.co.nz-20120114071941-5g6csg0cy0ho5e7q
parent: squid3@treenet.co.nz-20120110024032-c8etrkkdfc4h30v9
fixes bug(s): http://bugs.squid-cache.org/show_bug.cgi?id=3420
author: Alex Rousskov <rousskov@measurement-factory.com>
committer: Amos Jeffries <squid3@treenet.co.nz>
branch nick: SQUID_3_1
timestamp: Sat 2012-01-14 00:19:41 -0700
message:
  Bug 3420: Request body consumption races and !theConsumer exception.
  
  Also fixes endless waiting for HTTP client to send req body we no longer need.
  
  Before these changes, the client side used a single "closing" state to
  handle two different error conditions:
  
    1. We stopped receiving request body because of some error.
    2. We stopped sending response because of some error.
  
  When a "directional" error occurred, we try to keep the transaction going in
  the other direction (e.g., to give ICAP the entire request or to give HTTP
  client the entire response). However, because there was just one "closing"
  state, the code failed to correctly detect or process many corner cases,
  resulting in stuck transactions and !theConsumer assertions/exceptions due to
  races between enableAutoConsumption() and expectNoConsumption() calls.
  
  This patch replaces the "closing" state with two direction-specific "we
  stopped sending/receiving" flags.
  
  Now, when the response sending code is done, it now checks whether the
  receiving code stopped and closes the connection as needed. This is done both
  when we encounter a sending error (ClientSocketContext::initiateClose) and
  when we successfully sent the entire response to the client
  (ClientSocketContext::keepaliveNextRequest).
  
  Similarly, when the request body reading code is done, it now checks whether
  the receiving code stopped and closes the connection as needed. This is done
  both when we encounter a receiving error
  (ConnStateData::noteBodyConsumerAborted) and when we successfully receive the
  entire request body from the client (ClientSocketContext::writeComplete).
  
  TODO: This patch focuses on various error cases. We might still have problems
  when there is an early HTTP response and no errors of any kind. I marked the
  corresponding old code with an XXX.
------------------------------------------------------------
# Bazaar merge directive format 2 (Bazaar 0.90)
# revision_id: squid3@treenet.co.nz-20120114071941-5g6csg0cy0ho5e7q
# target_branch: http://bzr.squid-cache.org/bzr/squid3/branches\
#   /SQUID_3_1/
# testament_sha1: 71adfa8d85097074d14b95d813625db3a5d4dc35
# timestamp: 2012-01-14 07:54:24 +0000
# source_branch: http://bzr.squid-cache.org/bzr/squid3/branches\
#   /SQUID_3_1
# base_revision_id: squid3@treenet.co.nz-20120110024032-\
#   c8etrkkdfc4h30v9
# 
# Begin patch
=== modified file 'src/client_side.cc'
--- src/client_side.cc	2011-10-12 02:15:19 +0000
+++ src/client_side.cc	2012-01-14 07:19:41 +0000
@@ -1390,6 +1390,7 @@
      */
 }
 
+/// called when we have successfully finished writing the response
 void
 ClientSocketContext::keepaliveNextRequest()
 {
@@ -1406,6 +1407,26 @@
     }
 
     /** \par
+     * We are done with the response, and we are either still receiving request
+     * body (early response!) or have already stopped receiving anything.
+     *
+     * If we are still receiving, then clientParseRequest() below will fail.
+     * (XXX: but then we will call readNextRequest() which may succeed and
+     * execute a smuggled request as we are not done with the current request).
+     *
+     * If we stopped because we got everything, then try the next request.
+     *
+     * If we stopped receiving because of an error, then close now to avoid
+     * getting stuck and to prevent accidental request smuggling.
+     */
+
+    if (const char *reason = conn->stoppedReceiving()) {
+        debugs(33, 3, HERE << "closing for earlier request error: " << reason);
+        comm_close(conn->fd);
+        return;
+    }
+
+    /** \par
      * Attempt to parse a request from the request buffer.
      * If we've been fed a pipelined request it may already
      * be in our read buffer.
@@ -1634,44 +1655,36 @@
     comm_close(fd());
 }
 
-/** Called to initiate (and possibly complete) closing of the context.
- * The underlying socket may be already closed */
+/// called when we encounter a response-related error
 void
 ClientSocketContext::initiateClose(const char *reason)
 {
-    debugs(33, 5, HERE << "initiateClose: closing for " << reason);
-
-    if (http != NULL) {
-        ConnStateData * conn = http->getConn();
-
-        if (conn != NULL) {
-            if (const int64_t expecting = conn->bodySizeLeft()) {
-                debugs(33, 5, HERE << "ClientSocketContext::initiateClose: " <<
-                       "closing, but first " << conn << " needs to read " <<
-                       expecting << " request body bytes with " <<
-                       conn->in.notYetUsed << " notYetUsed");
-
-                if (conn->closing()) {
-                    debugs(33, 2, HERE << "avoiding double-closing " << conn);
-                    return;
-                }
-
-                /*
-                * XXX We assume the reply fits in the TCP transmit
-                * window.  If not the connection may stall while sending
-                * the reply (before reaching here) if the client does not
-                * try to read the response while sending the request body.
-                * As of yet we have not received any complaints indicating
-                * this may be an issue.
-                */
-                conn->startClosing(reason);
-
-                return;
-            }
+    http->getConn()->stopSending(reason); // closes ASAP
+}
+
+void
+ConnStateData::stopSending(const char *error)
+{
+    debugs(33, 4, HERE << "sending error (FD " << fd << "): " << error <<
+           "; old receiving error: " <<
+           (stoppedReceiving() ? stoppedReceiving_ : "none"));
+
+    if (const char *oldError = stoppedSending()) {
+        debugs(33, 3, HERE << "already stopped sending: " << oldError);
+        return; // nothing has changed as far as this connection is concerned
+    }
+
+    stoppedSending_ = error;
+
+    if (!stoppedReceiving()) {
+        if (const int64_t expecting = bodySizeLeft()) {
+            debugs(33, 5, HERE << "must still read " << expecting <<
+                   " request body bytes with " << in.notYetUsed << " unused");
+            return; // wait for the request receiver to finish reading
         }
     }
 
-    doClose();
+    comm_close(fd);
 }
 
 void
@@ -2928,16 +2941,11 @@
     if (!bodyPipe) {
         debugs(33,5, HERE << "produced entire request body for FD " << fd);
 
-        if (closing()) {
+        if (const char *reason = stoppedSending()) {
             /* we've finished reading like good clients,
              * now do the close that initiateClose initiated.
-             *
-             * XXX: do we have to close? why not check keepalive et.
-             *
-             * XXX: To support chunked requests safely, we need to handle
-             * the case of an endless request. This if-statement does not,
-             * because mayNeedMoreData is true if request size is not known.
              */
+            debugs(33, 3, HERE << "closing for earlier sending error: " << reason);
             comm_close(fd);
             return false;
         }
@@ -2952,7 +2960,7 @@
         return;
 
     // too late to read more body
-    if (!isOpen() || closing())
+    if (!isOpen() || stoppedReceiving())
         return;
 
     readSomeData();
@@ -2961,8 +2969,11 @@
 void
 ConnStateData::noteBodyConsumerAborted(BodyPipe::Pointer )
 {
-    if (!closing())
-        startClosing("body consumer aborted");
+    // request reader may get stuck waiting for space if nobody consumes body
+    if (bodyPipe != NULL)
+        bodyPipe->enableAutoConsumption();
+
+    stopReceiving("virgin request body consumer aborted"); // closes ASAP
 }
 
 /** general lifetime handler for HTTP requests */
@@ -3755,7 +3766,9 @@
 
 CBDATA_CLASS_INIT(ConnStateData);
 
-ConnStateData::ConnStateData() :AsyncJob("ConnStateData"), transparent_ (false), closing_ (false), switchedToHttps_(false)
+ConnStateData::ConnStateData() :AsyncJob("ConnStateData"), transparent_ (false),
+    switchedToHttps_(false),
+    stoppedSending_(NULL), stoppedReceiving_(NULL)
 {
     pinning.fd = -1;
     pinning.pinned = false;
@@ -3798,33 +3811,24 @@
     return bodyPipe;
 }
 
-bool
-ConnStateData::closing() const
-{
-    return closing_;
-}
-
-/**
- * Called by ClientSocketContext to give the connection a chance to read
- * the entire body before closing the socket.
- */
 void
-ConnStateData::startClosing(const char *reason)
+ConnStateData::stopReceiving(const char *error)
 {
-    debugs(33, 5, HERE << "startClosing " << this << " for " << reason);
-    assert(!closing());
-    closing_ = true;
-
-    assert(bodyPipe != NULL);
-    assert(bodySizeLeft() > 0);
-
-    // We do not have to abort the body pipeline because we are going to
-    // read the entire body anyway.
-    // Perhaps an ICAP server wants to log the complete request.
-
-    // If a consumer abort have caused this closing, we may get stuck
-    // as nobody is consuming our data. Allow auto-consumption.
-    bodyPipe->enableAutoConsumption();
+    debugs(33, 4, HERE << "receiving error (FD " << fd << "): " << error <<
+           "; old sending error: " <<
+           (stoppedSending() ? stoppedSending_ : "none"));
+
+    if (const char *oldError = stoppedReceiving()) {
+        debugs(33, 3, HERE << "already stopped receiving: " << oldError);
+        return; // nothing has changed as far as this connection is concerned
+    }
+
+    stoppedReceiving_ = error;
+
+    if (const char *sendError = stoppedSending()) {
+        debugs(33, 3, HERE << "closing because also stopped sending: " << sendError);
+        comm_close(fd);
+    }
 }
 
 void

=== modified file 'src/client_side.h'
--- src/client_side.h	2011-10-11 02:04:19 +0000
+++ src/client_side.h	2012-01-14 07:19:41 +0000
@@ -214,8 +214,15 @@
     bool reading() const;
     void stopReading(); ///< cancels comm_read if it is scheduled
 
-    bool closing() const;
-    void startClosing(const char *reason);
+    /// true if we stopped receiving the request
+    const char *stoppedReceiving() const { return stoppedReceiving_; }
+    /// true if we stopped sending the response
+    const char *stoppedSending() const { return stoppedSending_; }
+    /// note request receiving error and close as soon as we write the response
+    void stopReceiving(const char *error);
+    /// note response sending error and close as soon as we read the request
+    void stopSending(const char *error);
+
     void expectNoForwarding(); ///< cleans up virgin request [body] forwarding state
 
     BodyPipe::Pointer expectRequestBody(int64_t size);
@@ -293,9 +300,14 @@
 private:
     CBDATA_CLASS2(ConnStateData);
     bool transparent_;
-    bool closing_;
 
     bool switchedToHttps_;
+
+    /// the reason why we no longer write the response or nil
+    const char *stoppedSending_;
+    /// the reason why we no longer read the request or nil
+    const char *stoppedReceiving_;
+
     String sslHostName; ///< Host name for SSL certificate generation
     AsyncCall::Pointer reader; ///< set when we are reading
     BodyPipe::Pointer bodyPipe; // set when we are reading request body

