Fixed Write.cc:41 "!ccb->active()" assertion.

The following sequence of events triggers this assertion:
  - The server sends an 1xx control message.
  - http.cc schedules ConnStateData::sendControlMsg call.
  - Before sendControlMsg is fired, http.cc detects an error (e.g., I/O
    error or timeout) and starts writing the reply to the user.
  - The ConnStateData::sendControlMsg is fired, starts writing 1xx, and
    hits the "no concurrent writes" assertion.

We could only reproduce this sequence in the lab after changing Squid
code to trigger a timeout at the right moment, but the sequence looks
plausible. Other event sequences might result in the same outcome.

To avoid concurrent writes, Squid now drops the control message if
Http::One::Server detects that a reply is already being written. Also,
ConnStateData delays reply writing until a pending control message write
has been completed.

This is a Measurement Factory project.

diff --git a/src/HttpControlMsg.cc b/src/HttpControlMsg.cc
index 2ca06b6897cbbb8f2c5a8acf55ee7468c2bc8cb5..1efc69b7ccdcbec75b7bcc7a4811a860fee1972c 100644 (file)
--- a/src/HttpControlMsg.cc
+++ b/src/HttpControlMsg.cc
@@ -11,6 +11,15 @@
 #include "CommCalls.h"
 #include "HttpControlMsg.h"
 
+void
+HttpControlMsgSink::wroteControlMsgOK()
+{
+    if (cbControlMsgSent) {
+        ScheduleCallHere(cbControlMsgSent);
+        cbControlMsgSent = nullptr;
+    }
+}
+
 /// called when we wrote the 1xx response
 void
 HttpControlMsgSink::wroteControlMsg(const CommIoCbParams &params)
@@ -19,8 +28,7 @@ HttpControlMsgSink::wroteControlMsg(const CommIoCbParams &params)
         return;
 
     if (params.flag == Comm::OK) {
-        if (cbControlMsgSent)
-            ScheduleCallHere(cbControlMsgSent);
+        wroteControlMsgOK();
         return;
     }
 

diff --git a/src/HttpControlMsg.h b/src/HttpControlMsg.h
index 6e8d22b0bf2d3c2cf935719a32085b83ae89d393..eb51dd3e044eaf592174d7c2ed7471ab1944aa05 100644 (file)
--- a/src/HttpControlMsg.h
+++ b/src/HttpControlMsg.h
@@ -33,6 +33,8 @@ public:
     /// called to send the 1xx message and notify the Source
     virtual void sendControlMsg(HttpControlMsg msg) = 0;
 
+    virtual void wroteControlMsgOK();
+
     /// callback to handle Comm::Write completion
     void wroteControlMsg(const CommIoCbParams &);
 

diff --git a/src/client_side.cc b/src/client_side.cc
index 0ceffb48358652f1d3504b5068d061541804dd96..ce3722645921a322f02ca3c2503e128fb1fe75ff 100644 (file)
--- a/src/client_side.cc
+++ b/src/client_side.cc
@@ -814,6 +814,8 @@ clientSocketRecipient(clientStreamNode * node, ClientHttpRequest * http,
     // TODO: enforces HTTP/1 MUST on pipeline order, but is irrelevant to HTTP/2
     if (context != http->getConn()->pipeline.front())
         context->deferRecipientForLater(node, rep, receivedData);
+    else if (http->getConn()->cbControlMsgSent) // 1xx to the user is pending
+        context->deferRecipientForLater(node, rep, receivedData);
     else
         http->getConn()->handleReply(rep, receivedData);
 
@@ -3831,6 +3833,17 @@ ConnStateData::sendControlMsg(HttpControlMsg msg)
     clientConnection->close();
 }
 
+void
+ConnStateData::wroteControlMsgOK()
+{
+    HttpControlMsgSink::wroteControlMsgOK();
+
+    if (Http::StreamPointer deferredRequest = pipeline.front()) {
+        debugs(33, 3, clientConnection << ": calling PushDeferredIfNeeded after control msg wrote");
+        ClientSocketContextPushDeferredIfNeeded(deferredRequest, this);
+    }
+}
+
 /// Our close handler called by Comm when the pinned connection is closed
 void
 ConnStateData::clientPinnedConnectionClosed(const CommCloseCbParams &io)

diff --git a/src/client_side.h b/src/client_side.h
index 04610561bea24d0f36f44710f7f2e89827dac110..7d32b16596ea64c39ddb5b51d59dfa20d70cb4b1 100644 (file)
--- a/src/client_side.h
+++ b/src/client_side.h
@@ -77,6 +77,7 @@ public:
 
     /* HttpControlMsgSink API */
     virtual void sendControlMsg(HttpControlMsg);
+    virtual void wroteControlMsgOK();
 
     /// Traffic parsing
     bool clientParseRequests();

diff --git a/src/servers/Http1Server.cc b/src/servers/Http1Server.cc
index b564896c3cb3d5478c8995b1e3a7853b3e9e0802..ecdc2f12e1dc8b471336cf74200c46b2eb5c7042 100644 (file)
--- a/src/servers/Http1Server.cc
+++ b/src/servers/Http1Server.cc
@@ -309,7 +309,19 @@ Http::One::Server::handleReply(HttpReply *rep, StoreIOBuffer receivedData)
 void
 Http::One::Server::writeControlMsgAndCall(HttpReply *rep, AsyncCall::Pointer &call)
 {
-    const ClientHttpRequest *http = pipeline.front()->http;
+    Http::StreamPointer context = pipeline.front();
+    Must(context != nullptr);
+
+    // Ignore this late control message if we have started sending a 
+    // reply to the user already (e.g., after an error).
+    if (context->reply) {
+        debugs(11, 2, "drop 1xx made late by " << context->reply);
+        // but still inform the caller (so it may resume its operation)
+        ScheduleCallHere(call);
+        return;
+    }
+
+    const ClientHttpRequest *http = context->http;
 
     // apply selected clientReplyContext::buildReplyHeader() mods
     // it is not clear what headers are required for control messages