Bug 5383: handleNegotiationResult() level-2 debugs() crash (#1856)

Writing a nil c-string to an std::ostream object results in undefined
behavior. When Security::IoResult::errorDescription is nil, that UB
leads to crashes for some STL implementations. These changes avoid UB
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 existed because
Squid reports the same Connection info automatically via CodeContext.

New WithExtras() mechanism may be useful for other "low-level debugging
and level-0/1 details for admins ought to differ" cases as well. 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.

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: ...

src/base/IoManip.h

@@ -288,5 +288,23 @@ operator <<(std::ostream &os, AtMostOnce<T> &a) {
     return os;
 }
 
+/// Helps prints T object using object's T::printWithExtras() method.
+template <class T>
+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 <class T>
+inline auto &
+operator <<(std::ostream &os, const WithExtras<T> &a) {
+    a.toPrint.printWithExtras(os);
+    return os;
+}
+
 #endif /* SQUID_SRC_BASE_IOMANIP_H */
 

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: " << 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);
@@ -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: " << WithExtras(handshakeResult));
         updateError(errCategory = ERR_SECURE_ACCEPT_FAIL, handshakeResult.errorDetail);
         break;
 

src/security/Io.cc

@@ -24,10 +24,11 @@ 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 = "unknown";
+    const char *strCat = nullptr;
     switch (category) {
     case ioSuccess:
         strCat = "success";
@@ -39,16 +40,29 @@ Security::IoResult::print(std::ostream &os) const
         strCat = "want-write";
         break;
     case ioError:
-        strCat = "error";
+        strCat = errorDescription;
         break;
     }
-    os << strCat;
-
-    if (errorDescription)
-        os << ", " << errorDescription;
+    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

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;
 }
 

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: " << WithExtras(result) <<
+           Debug::Extra << "connection: " << serverConnection());
     recordNegotiationDetails();
     noteNegotiationError(result.errorDetail);
 }

src/tests/stub_libsecurity.cc

@@ -48,6 +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::printGist(std::ostream &) const STUB
+void Security::IoResult::printWithExtras(std::ostream &) const STUB
 void Security::ForgetErrors() STUB
 
 #include "security/KeyData.h"