Bug 4156: comm.cc "!commHasHalfClosedMonitor(fd)" assertion (#1443)

This bug is specific to "half_closed_clients on" configurations.

    assertion failed: ... "isOpen(fd) && !commHasHalfClosedMonitor(fd)"
    location: comm.cc:1583 in commStartHalfClosedMonitor()

Squid asserts because Server schedules comm_read() after receiving EOF:
That extra read results in another EOF notification, and an attempt to
start monitoring an already monitored half-closed connection.

Upon detecting a potentially half-closed connection,
Server::doClientRead() should clear flags.readMore to prevent Server
from scheduling another comm_read(), but it does not and cannot do that
(without significant refactoring) because

* Server does not have access to flags.readMore
* flags.readMore hack is used for more than just "read more"

We worked around the above limitation by re-detecting half-closed
conditions and clearing flags.readMore after clientParseRequests(). That
fixed the bug but further increased poor code duplication across
ConnStateData::afterClientRead() and ConnStateData::kick() methods. We
then refactored by merging and moving that duplicated code into
clientParseRequests() and renamed that method to make backports safer.

diff --git a/src/client_side.cc b/src/client_side.cc
index e62bcf0fc7de4f2e7b89cffe4772fedc5c9a1278..bd9cf6a7d5f6680c52f80c3074531ec635210fa0 100644 (file)
--- a/src/client_side.cc
+++ b/src/client_side.cc
@@ -932,7 +932,7 @@ ConnStateData::kick()
      * 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.
+     * If we are still receiving, then parseRequests() 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).
      *
@@ -952,28 +952,12 @@ ConnStateData::kick()
      * 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.
-     *
-     \par
-     * This needs to fall through - if we're unlucky and parse the _last_ request
-     * from our read buffer we may never re-register for another client read.
      */
 
-    if (clientParseRequests()) {
-        debugs(33, 3, clientConnection << ": parsed next request from buffer");
-    }
+    parseRequests();
 
-    /** \par
-     * Either we need to kick-start another read or, if we have
-     * a half-closed connection, kill it after the last request.
-     * This saves waiting for half-closed connections to finished being
-     * half-closed _AND_ then, sometimes, spending "Timeout" time in
-     * the keepalive "Waiting for next request" state.
-     */
-    if (commIsHalfClosed(clientConnection->fd) && pipeline.empty()) {
-        debugs(33, 3, "half-closed client with no pending requests, closing");
-        clientConnection->close();
+    if (!isOpen())
         return;
-    }
 
     /** \par
      * At this point we either have a parsed request (which we've
@@ -1882,16 +1866,11 @@ ConnStateData::receivedFirstByte()
     resetReadTimeout(Config.Timeout.request);
 }
 
-/**
- * Attempt to parse one or more requests from the input buffer.
- * Returns true after completing parsing of at least one request [header]. That
- * includes cases where parsing ended with an error (e.g., a huge request).
- */
-bool
-ConnStateData::clientParseRequests()
+/// Attempt to parse one or more requests from the input buffer.
+/// May close the connection.
+void
+ConnStateData::parseRequests()
 {
-    bool parsed_req = false;
-
     debugs(33, 5, clientConnection << ": attempting to parse");
 
     // Loop while we have read bytes that are not needed for producing the body
@@ -1936,8 +1915,6 @@ ConnStateData::clientParseRequests()
 
             processParsedRequest(context);
 
-            parsed_req = true; // XXX: do we really need to parse everything right NOW ?
-
             if (context->mayUseConnection()) {
                 debugs(33, 3, "Not parsing new requests, as this request may need the connection");
                 break;
@@ -1950,8 +1927,19 @@ ConnStateData::clientParseRequests()
         }
     }
 
-    /* XXX where to 'finish' the parsing pass? */
-    return parsed_req;
+    debugs(33, 7, "buffered leftovers: " << inBuf.length());
+
+    if (isOpen() && commIsHalfClosed(clientConnection->fd)) {
+        if (pipeline.empty()) {
+            // we processed what we could parse, and no more data is coming
+            debugs(33, 5, "closing half-closed without parsed requests: " << clientConnection);
+            clientConnection->close();
+        } else {
+            // we parsed what we could, and no more data is coming
+            debugs(33, 5, "monitoring half-closed while processing parsed requests: " << clientConnection);
+            flags.readMore = false; // may already be false
+        }
+    }
 }
 
 void
@@ -1968,18 +1956,7 @@ ConnStateData::afterClientRead()
     if (pipeline.empty())
         fd_note(clientConnection->fd, "Reading next request");
 
-    if (!clientParseRequests()) {
-        if (!isOpen())
-            return;
-        // We may get here if the client half-closed after sending a partial
-        // request. See doClientRead() and shouldCloseOnEof().
-        // XXX: This partially duplicates ConnStateData::kick().
-        if (pipeline.empty() && commIsHalfClosed(clientConnection->fd)) {
-            debugs(33, 5, clientConnection << ": half-closed connection, no completed request parsed, connection closing.");
-            clientConnection->close();
-            return;
-        }
-    }
+    parseRequests();
 
     if (!isOpen())
         return;
@@ -3767,7 +3744,7 @@ ConnStateData::notePinnedConnectionBecameIdle(PinnedIdleContext pic)
     startPinnedConnectionMonitoring();
 
     if (pipeline.empty())
-        kick(); // in case clientParseRequests() was blocked by a busy pic.connection
+        kick(); // in case parseRequests() was blocked by a busy pic.connection
 }
 
 /// Forward future client requests using the given server connection.

diff --git a/src/client_side.h b/src/client_side.h
index e37ab27da1a275a0b97eba1706f350646960e383..9f36d864c2cd42d640c65e27225cc216c6f99454 100644 (file)
--- a/src/client_side.h
+++ b/src/client_side.h
@@ -98,7 +98,6 @@ public:
     void doneWithControlMsg() override;
 
     /// Traffic parsing
-    bool clientParseRequests();
     void readNextRequest();
 
     /// try to make progress on a transaction or read more I/O
@@ -443,6 +442,7 @@ private:
 
     void checkLogging();
 
+    void parseRequests();
     void clientAfterReadingRequests();
     bool concurrentRequestQueueFilled() const;
 

diff --git a/src/tests/stub_client_side.cc b/src/tests/stub_client_side.cc
index 8c160e56340e7253dcd65d9c66c6dbeaee027cca..f49d5dceeede72ce21fd2429e04c7555662a1d4a 100644 (file)
--- a/src/tests/stub_client_side.cc
+++ b/src/tests/stub_client_side.cc
@@ -14,7 +14,7 @@
 #include "tests/STUB.h"
 
 #include "client_side.h"
-bool ConnStateData::clientParseRequests() STUB_RETVAL(false)
+void ConnStateData::parseRequests() STUB
 void ConnStateData::readNextRequest() STUB
 bool ConnStateData::isOpen() const STUB_RETVAL(false)
 void ConnStateData::kick() STUB