Fix and improve debugging of tunneled TCP connections (#2291)

When a to-client write failed, TunnelStateData::writeClientDone()
debugging said "from-client read failed".

TunnelStateData::keepGoingAfterRead() debugging did not differentiate
two key cases: zero-size read and Squid-initiated closure of the other
end of the tunnel. That "other end" was called "client", but it could be
the "server" end. Related `if` statements logic was difficult to follow.

TunnelStateData::Connection state was difficult to reconstruct when
debugging long-lived tunnels. These debugging enhancements were
instrumental in tunnel closure problems triage, but those problems
deserve dedicated fixes.

Debugging improvements aside, no functionality changes are expected.

diff --git a/src/tunnel.cc b/src/tunnel.cc
index 15029c4c66f4b06b674092076ffa2f88da953929..aeef742e41be0db1f29f87f61030842672fc028e 100644 (file)
--- a/src/tunnel.cc
+++ b/src/tunnel.cc
@@ -131,10 +131,7 @@ public:
     {
 
     public:
-        Connection() : len (0), buf ((char *)xmalloc(SQUID_TCP_SO_RCVBUF)), size_ptr(nullptr), delayedLoops(0),
-            dirty(false),
-            readPending(nullptr), readPendingFunc(nullptr) {}
-
+        explicit Connection(const char *aSide);
         ~Connection();
 
         /// initiates Comm::Connection ownership, including closure monitoring
@@ -144,6 +141,9 @@ public:
         /// reacts to the external closure of our connection
         void noteClosure();
 
+        /// reacts to a successful zero-size read(2)
+        void noteEof();
+
         int bytesWanted(int lower=0, int upper = INT_MAX) const;
         void bytesIn(int const &);
 #if USE_DELAY_POOLS
@@ -158,6 +158,11 @@ public:
         /// writes 'b' buffer, setting the 'writer' member to 'callback'.
         void write(const char *b, int size, AsyncCall::Pointer &callback, FREE * free_func);
         int len;
+
+        /// The role of the agent we are communicating with.
+        /// This string literal is only used for debugging.
+        const char * const side;
+
         char *buf;
         AsyncCall::Pointer writer; ///< pending Comm::Write callback
         uint64_t *size_ptr;      /* pointer to size in an ConnStateData for logging */
@@ -167,6 +172,8 @@ public:
 
         bool dirty; ///< whether write() has been called (at least once)
 
+        bool receivedEof = false; ///< whether read() has returned zero bytes
+
         // XXX: make these an AsyncCall when event API can handle them
         TunnelStateData *readPending;
         EVH *readPendingFunc;
@@ -214,7 +221,7 @@ public:
     /// Measures time spent on selecting and communicating with peers.
     PeeringActivityTimer peeringTimer;
 
-    void copyRead(Connection &from, IOCB *completion);
+    void copyRead(Connection &from, Connection &to, IOCB *completion);
 
     /// continue to set up connection to a peer, going async for SSL peers
     void connectToPeer(const Comm::ConnectionPointer &);
@@ -300,6 +307,35 @@ static CTCB tunnelTimeout;
 static EVH tunnelDelayedClientRead;
 static EVH tunnelDelayedServerRead;
 
+static std::ostream &
+operator <<(std::ostream &os, const TunnelStateData::Connection &c)
+{
+    os << '{';
+    os << c.side;
+
+    if (c.conn)
+        os << ' ' << c.conn->id;
+
+    if (c.len)
+        os << " buf=" << c.len;
+
+    if (c.writer)
+        os << " writing";
+    else if (!c.dirty)
+        os << " clean";
+
+    if (c.delayedLoops)
+        os << " delayedLoops=" << c.delayedLoops;
+    if (c.readPending)
+        os << " delaying";
+
+    if (c.receivedEof)
+        os << " rEOF";
+
+    os << '}';
+    return os;
+}
+
 /// TunnelStateData::serverClosed() wrapper
 static void
 tunnelServerClosed(const CommCloseCbParams &params)
@@ -351,7 +387,7 @@ TunnelStateData::finishWritingAndDelete(Connection &remainingConnection)
     // move will unnecessary delay deleteThis().
 
     if (remainingConnection.writer) {
-        debugs(26, 5, "waiting to finish writing to " << remainingConnection.conn);
+        debugs(26, 5, "waiting to finish writing to " << remainingConnection);
         // the write completion callback must close its remainingConnection
         // after noticing that the other connection is gone
         return;
@@ -400,6 +436,8 @@ guaranteedRequest(const ClientHttpRequest * const cr)
 }
 
 TunnelStateData::TunnelStateData(ClientHttpRequest *clientRequest) :
+    client("client"),
+    server("server"),
     startTime(squid_curtime),
     destinations(new ResolvedPeers()),
     destinationsFound(false),
@@ -441,6 +479,18 @@ TunnelStateData::~TunnelStateData()
     delete savedError;
 }
 
+TunnelStateData::Connection::Connection(const char * const aSide):
+    len(0),
+    side(aSide),
+    buf(static_cast<char *>(xmalloc(SQUID_TCP_SO_RCVBUF))),
+    size_ptr(nullptr),
+    delayedLoops(0),
+    dirty(false),
+    readPending(nullptr),
+    readPendingFunc(nullptr)
+{
+}
+
 TunnelStateData::Connection::~Connection()
 {
     if (readPending)
@@ -583,7 +633,7 @@ TunnelStateData::ReadServer(const Comm::ConnectionPointer &c, char *buf, size_t
 void
 TunnelStateData::readServer(char *, size_t len, Comm::Flag errcode, int xerrno)
 {
-    debugs(26, 3, server.conn << ", read " << len << " bytes, err=" << errcode);
+    debugs(26, 3, server << ", read " << len << " bytes, err=" << errcode);
     server.delayedLoops=0;
 
     /*
@@ -608,7 +658,7 @@ TunnelStateData::readServer(char *, size_t len, Comm::Flag errcode, int xerrno)
 void
 TunnelStateData::Connection::error(int const xerrno)
 {
-    debugs(50, debugLevelForError(xerrno), conn << ": read/write failure: " << xstrerr(xerrno));
+    debugs(50, debugLevelForError(xerrno), *this << ": read/write failure: " << xstrerr(xerrno));
 
     if (!ignoreErrno(xerrno))
         conn->close();
@@ -627,7 +677,7 @@ TunnelStateData::ReadClient(const Comm::ConnectionPointer &, char *buf, size_t l
 void
 TunnelStateData::readClient(char *, size_t len, Comm::Flag errcode, int xerrno)
 {
-    debugs(26, 3, client.conn << ", read " << len << " bytes, err=" << errcode);
+    debugs(26, 3, client << ", read " << len << " bytes, err=" << errcode);
     client.delayedLoops=0;
 
     /*
@@ -652,7 +702,7 @@ TunnelStateData::readClient(char *, size_t len, Comm::Flag errcode, int xerrno)
 bool
 TunnelStateData::keepGoingAfterRead(size_t len, Comm::Flag errcode, int xerrno, Connection &from, Connection &to)
 {
-    debugs(26, 3, "from={" << from.conn << "}, to={" << to.conn << "}");
+    debugs(26, 3, "from=" << from << "; writing to=" << to);
 
     /* I think this is to prevent free-while-in-a-callback behaviour
      * - RBC 20030229
@@ -675,21 +725,36 @@ TunnelStateData::keepGoingAfterRead(size_t len, Comm::Flag errcode, int xerrno,
         commSetConnTimeout(to.conn, Config.Timeout.read, timeoutCall);
     }
 
-    if (errcode)
+    if (errcode) {
         from.error (xerrno);
-    else if (len == 0 || !Comm::IsConnOpen(to.conn)) {
-        debugs(26, 3, "Nothing to write or client gone. Terminate the tunnel.");
+        return false;
+    }
+
+    if (len == 0) {
+        debugs(26, 3, "closing " << from << " after a zero-byte read");
         from.conn->close();
 
         /* Only close the remote end if we've finished queueing data to it */
         if (from.len == 0 && Comm::IsConnOpen(to.conn) ) {
             to.conn->close();
         }
-    } else if (cbdataReferenceValid(this)) {
-        return true;
+        return false;
+    }
+
+    // Stop reading from source if the destination is gone. This both increases
+    // `from` chances to realize what happened at the `to` end and terminates an
+    // otherwise potentially infinite stream of incoming `from` bytes.
+    if (!Comm::IsConnOpen(to.conn)) {
+        debugs(26, 3, "closing " << from << " because " << to << " is gone");
+        from.conn->close();
+        return false;
     }
 
-    return false;
+    if (!cbdataReferenceValid(this))
+        return false;
+
+    Assure(len > 0);
+    return true;
 }
 
 void
@@ -715,7 +780,7 @@ TunnelStateData::WriteServerDone(const Comm::ConnectionPointer &, char *buf, siz
 void
 TunnelStateData::writeServerDone(char *, size_t len, Comm::Flag flag, int xerrno)
 {
-    debugs(26, 3, server.conn << ", " << len << " bytes written, flag=" << flag);
+    debugs(26, 3, server << ", " << len << " bytes written, flag=" << flag);
 
     if (flag == Comm::ERR_CLOSING)
         return;
@@ -790,6 +855,7 @@ template <typename Method>
 void
 TunnelStateData::Connection::initConnection(const Comm::ConnectionPointer &aConn, Method method, const char *name, TunnelStateData *tunnelState)
 {
+    debugs(26, 3, *this << " uses " << aConn);
     Must(!Comm::IsConnOpen(conn));
     Must(!closer);
     Must(Comm::IsConnOpen(aConn));
@@ -801,23 +867,30 @@ TunnelStateData::Connection::initConnection(const Comm::ConnectionPointer &aConn
 void
 TunnelStateData::Connection::noteClosure()
 {
-    debugs(26, 3, conn);
+    debugs(26, 3, *this);
     conn = nullptr;
     closer = nullptr;
     writer = nullptr; // may already be nil
 }
 
+void
+TunnelStateData::Connection::noteEof()
+{
+    debugs(26, 3, "from " << *this);
+    receivedEof = true;
+}
+
 void
 TunnelStateData::writeClientDone(char *, size_t len, Comm::Flag flag, int xerrno)
 {
-    debugs(26, 3, client.conn << ", " << len << " bytes written, flag=" << flag);
+    debugs(26, 3, client << ", " << len << " bytes written, flag=" << flag);
 
     if (flag == Comm::ERR_CLOSING)
         return;
 
     /* Error? */
     if (flag != Comm::OK) {
-        debugs(26, 4, "from-client read failed: " << xerrno);
+        debugs(26, 4, "to-client write failed: " << xerrno);
         client.error(xerrno); // may call comm_close
         return;
     }
@@ -887,7 +960,7 @@ tunnelDelayedClientRead(void *data)
     tunnel->client.readPending = nullptr;
     static uint64_t counter=0;
     debugs(26, 7, "Client read(2) delayed " << ++counter << " times");
-    tunnel->copyRead(tunnel->client, TunnelStateData::ReadClient);
+    tunnel->copyRead(tunnel->client, tunnel->server, TunnelStateData::ReadClient);
     CodeContext::Reset(savedContext);
 }
 
@@ -903,13 +976,15 @@ tunnelDelayedServerRead(void *data)
     tunnel->server.readPending = nullptr;
     static uint64_t counter=0;
     debugs(26, 7, "Server read(2) delayed " << ++counter << " times");
-    tunnel->copyRead(tunnel->server, TunnelStateData::ReadServer);
+    tunnel->copyRead(tunnel->server, tunnel->client, TunnelStateData::ReadServer);
     CodeContext::Reset(savedContext);
 }
 
 void
-TunnelStateData::copyRead(Connection &from, IOCB *completion)
+TunnelStateData::copyRead(Connection &from, Connection &to, IOCB * const completion)
 {
+    debugs(26, 5, "from=" << from << "; writing to=" << to);
+
     assert(from.len == 0);
     // If only the minimum permitted read size is going to be attempted
     // then we schedule an event to try again in a few I/O cycles.
@@ -933,6 +1008,7 @@ void
 TunnelStateData::copyClientBytes()
 {
     if (preReadClientData.length()) {
+        debugs(26, 7, "pre-read bytes: " << preReadClientData.length());
         size_t copyBytes = preReadClientData.length() > SQUID_TCP_SO_RCVBUF ? SQUID_TCP_SO_RCVBUF : preReadClientData.length();
         memcpy(client.buf, preReadClientData.rawContent(), copyBytes);
         preReadClientData.consume(copyBytes);
@@ -940,13 +1016,14 @@ TunnelStateData::copyClientBytes()
         if (keepGoingAfterRead(copyBytes, Comm::OK, 0, client, server))
             copy(copyBytes, client, server, TunnelStateData::WriteServerDone);
     } else
-        copyRead(client, ReadClient);
+        copyRead(client, server, ReadClient);
 }
 
 void
 TunnelStateData::copyServerBytes()
 {
     if (preReadServerData.length()) {
+        debugs(26, 7, "pre-read bytes: " << preReadServerData.length());
         size_t copyBytes = preReadServerData.length() > SQUID_TCP_SO_RCVBUF ? SQUID_TCP_SO_RCVBUF : preReadServerData.length();
         memcpy(server.buf, preReadServerData.rawContent(), copyBytes);
         preReadServerData.consume(copyBytes);
@@ -954,7 +1031,7 @@ TunnelStateData::copyServerBytes()
         if (keepGoingAfterRead(copyBytes, Comm::OK, 0, server, client))
             copy(copyBytes, server, client, TunnelStateData::WriteClientDone);
     } else
-        copyRead(server, ReadServer);
+        copyRead(server, client, ReadServer);
 }
 
 /**
@@ -1003,7 +1080,7 @@ static void
 tunnelConnectedWriteDone(const Comm::ConnectionPointer &conn, char *, size_t len, Comm::Flag flag, int, void *data)
 {
     TunnelStateData *tunnelState = (TunnelStateData *)data;
-    debugs(26, 3, conn << ", flag=" << flag);
+    debugs(26, 3, tunnelState->client << ", flag=" << flag);
     tunnelState->client.writer = nullptr;
 
     if (flag != Comm::OK) {