From: Alex Rousskov Date: Sun, 2 Nov 2025 13:48:19 +0000 (+0000) Subject: Fix and improve debugging of tunneled TCP connections (#2291) X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=bb464adee8b3ff058a204f927010d43a14c45121;p=thirdparty%2Fsquid.git 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 15029c4c66..aeef742e41 100644 --- 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 ¶ms) @@ -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(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 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) {