From 1752af45113eefb03eb28dbbcdbb212800d49c8b Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Sun, 30 Jun 2024 16:56:09 -0400 Subject: [PATCH 1/3] Bug 5383: handleNegotiationResult() level-2 debugs() crash In some environments, writing a nil c-string to an std::ostream object crashes Squid. In some use cases, Security::IoResult::errorDescription may be nil. These changes handle the combination better while making higher-level reporting code simpler and safer. This change alters affected level-1 ERROR test lines a little, including removing duplicated connection information from clientNegotiateSSL() message (cache_log_message id=62). That duplication happened because Squid reporting the same Connection info automatically via CodeContext. --- src/client_side.cc | 8 ++++---- src/security/Io.cc | 13 +++++-------- src/security/PeerConnector.cc | 6 +++--- src/tests/stub_libsecurity.cc | 1 + 4 files changed, 13 insertions(+), 15 deletions(-) diff --git a/src/client_side.cc b/src/client_side.cc index 2a977e34d7e..09462b22dbb 100644 --- a/src/client_side.cc +++ b/src/client_side.cc @@ -2288,8 +2288,8 @@ clientNegotiateSSL(int fd, void *data) return; case Security::IoResult::ioError: - debugs(83, (handshakeResult.important ? Important(62) : 2), "ERROR: " << handshakeResult.errorDescription << - " while accepting a TLS connection on " << conn->clientConnection << ": " << handshakeResult.errorDetail); + debugs(83, (handshakeResult.important ? Important(62) : 2), "ERROR: Cannot accept a TLS connection" << + Debug::Extra << "problem: " << handshakeResult); // TODO: No ConnStateData::tunnelOnError() on this forward-proxy code // path because we cannot know the intended connection target? conn->updateError(ERR_SECURE_ACCEPT_FAIL, handshakeResult.errorDetail); @@ -3036,8 +3036,8 @@ ConnStateData::handleSslBumpHandshakeError(const Security::IoResult &handshakeRe } case Security::IoResult::ioError: - debugs(83, (handshakeResult.important ? DBG_IMPORTANT : 2), "ERROR: " << handshakeResult.errorDescription << - " while SslBump-accepting a TLS connection on " << clientConnection << ": " << handshakeResult.errorDetail); + debugs(83, (handshakeResult.important ? DBG_IMPORTANT : 2), "ERROR: Cannot SslBump-accept a TLS connection" << + Debug::Extra << "problem: " << handshakeResult); updateError(errCategory = ERR_SECURE_ACCEPT_FAIL, handshakeResult.errorDetail); break; diff --git a/src/security/Io.cc b/src/security/Io.cc index de5564d6355..74978583e81 100644 --- a/src/security/Io.cc +++ b/src/security/Io.cc @@ -27,7 +27,7 @@ typedef SessionPointer::element_type *ConnectionPointer; void Security::IoResult::print(std::ostream &os) const { - const char *strCat = "unknown"; + const char *strCat = nullptr; switch (category) { case ioSuccess: strCat = "success"; @@ -39,16 +39,13 @@ Security::IoResult::print(std::ostream &os) const strCat = "want-write"; break; case ioError: - strCat = "error"; + strCat = errorDescription; break; } - os << strCat; + os << (strCat ? strCat : "unknown"); - if (errorDescription) - os << ", " << errorDescription; - - if (important) - os << ", important"; + if (errorDetail) + os << Debug::Extra << "error detail: " << errorDetail; } // TODO: Replace high-level ERR_get_error() calls with ForgetErrors() calls or diff --git a/src/security/PeerConnector.cc b/src/security/PeerConnector.cc index 48fbbf45c13..76b0af1be59 100644 --- a/src/security/PeerConnector.cc +++ b/src/security/PeerConnector.cc @@ -278,9 +278,9 @@ Security::PeerConnector::handleNegotiationResult(const Security::IoResult &resul } // TODO: Honor result.important when working in a reverse proxy role? - debugs(83, 2, "ERROR: Cannot establish a TLS connection to " << serverConnection() << ':' << - Debug::Extra << "problem: " << result.errorDescription << - RawPointer("detail: ", result.errorDetail).asExtra()); + debugs(83, 2, "ERROR: Cannot establish a TLS connection" << + Debug::Extra << "problem: " << result << + Debug::Extra << "connection: " << serverConnection()); recordNegotiationDetails(); noteNegotiationError(result.errorDetail); } diff --git a/src/tests/stub_libsecurity.cc b/src/tests/stub_libsecurity.cc index 456f3122ae7..6ca3c7b972c 100644 --- a/src/tests/stub_libsecurity.cc +++ b/src/tests/stub_libsecurity.cc @@ -48,6 +48,7 @@ bool Security::HandshakeParser::parseHello(const SBuf &) STUB_RETVAL(false) #include "security/Io.h" Security::IoResult Security::Accept(Comm::Connection &) STUB_RETVAL(IoResult(IoResult::ioError)) Security::IoResult Security::Connect(Comm::Connection &) STUB_RETVAL(IoResult(IoResult::ioError)) +void Security::IoResult::print(std::ostream &) const STUB void Security::ForgetErrors() STUB #include "security/KeyData.h" From 518d13078708f60359347bafb6965b0404e66dee Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Sun, 30 Jun 2024 21:49:17 -0400 Subject: [PATCH 2/3] Differentiate debugging from level-0/1 output for admins Debugging is for developers. Things like a TLS operation outcome often end up in async call arguments and other places where admin-friendly, multiline output complicates filtering/searching. Also, if code does not care about specifics like errorDetail (after it has been collected and before it is logged), we do not want to display those details every time we debug the result inside that code. Today, the only known debugging context for Security::IoResult is Security::PeerConnector::suspendNegotiation(), but that is likely to change as we upgrade TLS callers to library-independent wrappers beyond the current Security::Accept() and Security::Connect() pair. New WithExtras() mechanism may be useful for other "debugging and level-0/1 details ought to differ" cases as well. --- src/base/IoManip.h | 18 ++++++++++++++++++ src/client_side.cc | 4 ++-- src/security/Io.cc | 19 ++++++++++++++++++- src/security/Io.h | 12 ++++++++++-- src/security/PeerConnector.cc | 2 +- src/tests/stub_libsecurity.cc | 3 ++- 6 files changed, 51 insertions(+), 7 deletions(-) diff --git a/src/base/IoManip.h b/src/base/IoManip.h index b62865d49df..e30a725dbb7 100644 --- a/src/base/IoManip.h +++ b/src/base/IoManip.h @@ -288,5 +288,23 @@ operator <<(std::ostream &os, AtMostOnce &a) { return os; } +/// Helps prints T object using object's T::printWithExtras() method. +template +class WithExtras +{ +public: + /// caller must ensure `t` lifetime extends to the last use of this class instance + explicit WithExtras(const T &t): toPrint(t) {} + const T &toPrint; +}; + +/// writes T object to the given stream using object's T::printWithExtras() method +template +inline auto & +operator <<(std::ostream &os, const WithExtras &a) { + a.toPrint.printWithExtras(os); + return os; +} + #endif /* SQUID_SRC_BASE_IOMANIP_H */ diff --git a/src/client_side.cc b/src/client_side.cc index 09462b22dbb..6a22399cea0 100644 --- a/src/client_side.cc +++ b/src/client_side.cc @@ -2289,7 +2289,7 @@ clientNegotiateSSL(int fd, void *data) case Security::IoResult::ioError: debugs(83, (handshakeResult.important ? Important(62) : 2), "ERROR: Cannot accept a TLS connection" << - Debug::Extra << "problem: " << handshakeResult); + Debug::Extra << "problem: " << WithExtras(handshakeResult)); // TODO: No ConnStateData::tunnelOnError() on this forward-proxy code // path because we cannot know the intended connection target? conn->updateError(ERR_SECURE_ACCEPT_FAIL, handshakeResult.errorDetail); @@ -3037,7 +3037,7 @@ ConnStateData::handleSslBumpHandshakeError(const Security::IoResult &handshakeRe case Security::IoResult::ioError: debugs(83, (handshakeResult.important ? DBG_IMPORTANT : 2), "ERROR: Cannot SslBump-accept a TLS connection" << - Debug::Extra << "problem: " << handshakeResult); + Debug::Extra << "problem: " << WithExtras(handshakeResult)); updateError(errCategory = ERR_SECURE_ACCEPT_FAIL, handshakeResult.errorDetail); break; diff --git a/src/security/Io.cc b/src/security/Io.cc index 74978583e81..21db8924eaa 100644 --- a/src/security/Io.cc +++ b/src/security/Io.cc @@ -24,8 +24,9 @@ typedef SessionPointer::element_type *ConnectionPointer; } // namespace Security +/// common part of printGist() and printWithExtras() void -Security::IoResult::print(std::ostream &os) const +Security::IoResult::printDescription(std::ostream &os) const { const char *strCat = nullptr; switch (category) { @@ -43,9 +44,25 @@ Security::IoResult::print(std::ostream &os) const break; } os << (strCat ? strCat : "unknown"); +} +void +Security::IoResult::printGist(std::ostream &os) const +{ + printDescription(os); + if (important) + os << ", important"; + // no errorDetail in this summary output +} + +void +Security::IoResult::printWithExtras(std::ostream &os) const +{ + printDescription(os); if (errorDetail) os << Debug::Extra << "error detail: " << errorDetail; + // this->important flag may affect caller debugs() level, but the flag + // itself is not reported to the admin explicitly } // TODO: Replace high-level ERR_get_error() calls with ForgetErrors() calls or diff --git a/src/security/Io.h b/src/security/Io.h index cb5660940d8..69c4e5ccb44 100644 --- a/src/security/Io.h +++ b/src/security/Io.h @@ -33,7 +33,12 @@ class IoResult: public RefCountable { /// convenience wrapper to detect whether more I/O is needed bool wantsIo() const { return category == ioWantRead || category == ioWantWrite; } - void print(std::ostream &os) const; + /// reports brief summary (on one line) suitable for low-level debugging + void printGist(std::ostream &) const; + + /// reports detailed summary, often using multiple Debug::Extra lines + /// suitable for level-0/1 cache.log messages + void printWithExtras(std::ostream &) const; ErrorDetailPointer errorDetail; ///< ioError case details (or nil) @@ -42,12 +47,15 @@ class IoResult: public RefCountable { /* the data members below facilitate human-friendly debugging */ const char *errorDescription = nullptr; ///< a brief description of an error bool important = false; ///< whether the error was serious/unusual + +private: + void printDescription(std::ostream &) const; }; inline std::ostream & operator <<(std::ostream &os, const IoResult &result) { - result.print(os); + result.printGist(os); return os; } diff --git a/src/security/PeerConnector.cc b/src/security/PeerConnector.cc index 76b0af1be59..ae3137d95f6 100644 --- a/src/security/PeerConnector.cc +++ b/src/security/PeerConnector.cc @@ -279,7 +279,7 @@ Security::PeerConnector::handleNegotiationResult(const Security::IoResult &resul // TODO: Honor result.important when working in a reverse proxy role? debugs(83, 2, "ERROR: Cannot establish a TLS connection" << - Debug::Extra << "problem: " << result << + Debug::Extra << "problem: " << WithExtras(result) << Debug::Extra << "connection: " << serverConnection()); recordNegotiationDetails(); noteNegotiationError(result.errorDetail); diff --git a/src/tests/stub_libsecurity.cc b/src/tests/stub_libsecurity.cc index 6ca3c7b972c..ea31d816e60 100644 --- a/src/tests/stub_libsecurity.cc +++ b/src/tests/stub_libsecurity.cc @@ -48,7 +48,8 @@ bool Security::HandshakeParser::parseHello(const SBuf &) STUB_RETVAL(false) #include "security/Io.h" Security::IoResult Security::Accept(Comm::Connection &) STUB_RETVAL(IoResult(IoResult::ioError)) Security::IoResult Security::Connect(Comm::Connection &) STUB_RETVAL(IoResult(IoResult::ioError)) -void Security::IoResult::print(std::ostream &) const STUB +void Security::IoResult::printGist(std::ostream &) const STUB +void Security::IoResult::printWithExtras(std::ostream &) const STUB void Security::ForgetErrors() STUB #include "security/KeyData.h" From 99007576232213371bbef68cbaf93957b89f30dd Mon Sep 17 00:00:00 2001 From: Alex Rousskov Date: Sun, 30 Jun 2024 22:01:29 -0400 Subject: [PATCH 3/3] fixup: Regenerated doc/debug-messages.dox --- doc/debug-messages.dox | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/doc/debug-messages.dox b/doc/debug-messages.dox index a4087a319d3..28c4be99687 100644 --- a/doc/debug-messages.dox +++ b/doc/debug-messages.dox @@ -59,7 +59,7 @@ ID Message gist 58 ERROR: ALE missing ... 59 Shutdown: Digest authentication. 60 Shutdown: Negotiate authentication. -62 ERROR: ... while accepting a TLS connection on ...: ... +62 ERROR: Cannot accept a TLS connection ...problem: ... 63 Resuming indexing cache_dir # ... from ... 64 DNS IPv4 socket created at ..., FD ... 65 WARNING: Indexer ignores a cache_dir entry: ...