Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
wants to merge 3 commits into from
Closed

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
1752af4
Bug 5383: handleNegotiationResult() level-2 debugs() crash
rousskov Jun 30, 2024
518d130
Differentiate debugging from level-0/1 output for admins
rousskov Jul 1, 2024
9900757
fixup: Regenerated doc/debug-messages.dox
rousskov Jul 1, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion doc/debug-messages.dox
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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: ...
Expand Down
18 changes: 18 additions & 0 deletions src/base/IoManip.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 */

8 changes: 4 additions & 4 deletions src/client_side.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more. 

- ERROR: failure while accepting a TLS connection on conn41 local=127.0.0.1:21443 remote=127.0.0.1:55000 FD 25 flags=1: SQUID_TLS_ERR_ACCEPT+TLS_LIB_ERR=A00009C+TLS_IO_ERR=1
-     connection: conn41 local=127.0.0.1:21443 remote=127.0.0.1:55000 FD 25 flags=1
+ ERROR: Cannot accept a TLS connection
+     problem: failure
+     error detail: SQUID_TLS_ERR_ACCEPT+TLS_LIB_ERR=A00009C+TLS_IO_ERR=1
+     connection: conn40 local=127.0.0.1:21443 remote=127.0.0.1:54910 FD 20 flags=1

Client-to-Squid connection is still reported here (via CodeContext) even though it is not visible in new code. That is likely to (automatically) change as we start allocating or preserving master transaction context earlier, but current PR reporting is OK.

// path because we cannot know the intended connection target?
conn->updateError(ERR_SECURE_ACCEPT_FAIL, handshakeResult.errorDetail);
Expand Down Expand Up @@ -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);
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more. 

- ERROR: failure while SslBump-accepting a TLS connection on conn35 local=127.0.0.1:3130 remote=127.0.0.1:53250 FD 20 flags=1: SQUID_TLS_ERR_ACCEPT+TLS_LIB_ERR=A00018A+TLS_IO_ERR=1
-     current master transaction: master53
+ ERROR: Cannot SslBump-accept a TLS connection
+     problem: failure
+     error detail: SQUID_TLS_ERR_ACCEPT+TLS_LIB_ERR=A00018A+TLS_IO_ERR=1
+     current master transaction: master54

No client-to-Squid connection reporting here because we do have a master transaction in this context. Admins are supposed to correlate that with their access.log entries if they need more information. We are using the same transaction/context-based approach for other level-0/1 messages as well.

break;

Expand Down
28 changes: 21 additions & 7 deletions src/security/Io.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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";
Expand All @@ -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
Expand Down
12 changes: 10 additions & 2 deletions src/security/Io.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)

Expand All @@ -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;
}

Expand Down
6 changes: 3 additions & 3 deletions src/security/PeerConnector.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 <<
yadij marked this conversation as resolved.
Show resolved Hide resolved
RawPointer("detail: ", result.errorDetail).asExtra());
debugs(83, 2, "ERROR: Cannot establish a TLS connection" <<
Debug::Extra << "problem: " << WithExtras(result) <<
Debug::Extra << "connection: " << serverConnection());
recordNegotiationDetails();
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The above debugs() is where the reported bug was triggered, but all three debugs() have similar dangerous/buggy code.

- 83,2| PeerConnector.cc(281) handleNegotiationResult: ERROR: Cannot establish a TLS connection to conn38 local=127.0.0.1:35992 remote=127.0.0.1:443 HIER_DIRECT FD 22 flags=1:
-     problem: failure
-     detail: SQUID_TLS_ERR_CONNECT+TLS_LIB_ERR=A000410+TLS_IO_ERR=1
+ 83,2| PeerConnector.cc(281) handleNegotiationResult: ERROR: Cannot establish a TLS connection
+     problem: failure
+     error detail: SQUID_TLS_ERR_CONNECT+TLS_LIB_ERR=A000410+TLS_IO_ERR=1
+     connection: conn38 local=127.0.0.1:58424 remote=127.0.0.1:443 HIER_DIRECT FD 22 flags=1

We do want to report Squid-to-peer connection in such contexts because, unlike the client-to-Squid connection discussed elsewhere in this review, there may be multiple Squid-to-peer connections per master transaction and our access.log records do not record their details.

Please note that this is a level-2 message in current code. There is a corresponding TODO to upgrade "important" messages to level-1, and the message is already formatted as a level-0/1 message, so I used WithExtras() here.

noteNegotiationError(result.errorDetail);
}
Expand Down
2 changes: 2 additions & 0 deletions src/tests/stub_libsecurity.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down