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

Jump to bottom

tls: improve TLS handshake/read/write error log #14600

Merged
merged 7 commits into from
Jan 19, 2021
Merged

tls: improve TLS handshake/read/write error log #14600

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
910396d
ssl: improve TLS handshake/read/write error log
Shikugawa Jan 8, 2021
622c900
fix spell
Shikugawa Jan 8, 2021
d83fc4d
allow logs without fips
Shikugawa Jan 9, 2021
08dea59
add generic get error interface
Shikugawa Jan 9, 2021
eb3b529
fix test
Shikugawa Jan 9, 2021
b41e655
add test
Shikugawa Jan 9, 2021
53f7810
review
Shikugawa Jan 15, 2021
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
1 change: 1 addition & 0 deletions source/extensions/transport_sockets/tls/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -177,6 +177,7 @@ envoy_cc_library(
],
deps = [
"//source/common/common:assert_lib",
"//source/common/common:empty_string",
"//source/common/common:utility_lib",
"//source/common/network:address_lib",
],
Expand Down
2 changes: 2 additions & 0 deletions source/extensions/transport_sockets/tls/ssl_handshaker.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -233,6 +233,8 @@ Network::PostIoAction SslHandshakerImpl::doHandshake() {
: PostIoAction::Close;
} else {
int err = SSL_get_error(ssl(), rc);
ENVOY_CONN_LOG(trace, "ssl error occurred while read: {}", handshake_callbacks_->connection(),
Utility::getErrorDescription(err));
switch (err) {
case SSL_ERROR_WANT_READ:
case SSL_ERROR_WANT_WRITE:
Expand Down
4 changes: 3 additions & 1 deletion source/extensions/transport_sockets/tls/ssl_handshaker.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -37,7 +37,9 @@ class SslExtendedSocketInfoImpl : public Envoy::Ssl::SslExtendedSocketInfo {
Envoy::Ssl::ClientValidationStatus::NotValidated};
};

class SslHandshakerImpl : public Ssl::ConnectionInfo, public Ssl::Handshaker {
class SslHandshakerImpl : public Ssl::ConnectionInfo,
public Ssl::Handshaker,
protected Logger::Loggable<Logger::Id::connection> {
public:
SslHandshakerImpl(bssl::UniquePtr<SSL> ssl, int ssl_extended_socket_info_index,
Ssl::HandshakeCallbacks* handshake_callbacks);
Expand Down
4 changes: 4 additions & 0 deletions source/extensions/transport_sockets/tls/ssl_socket.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -137,6 +137,8 @@ Network::IoResult SslSocket::doRead(Buffer::Instance& read_buffer) {
if (result.error_.has_value()) {
keep_reading = false;
int err = SSL_get_error(rawSsl(), result.error_.value());
ENVOY_CONN_LOG(trace, "ssl error occurred while read: {}", callbacks_->connection(),
Utility::getErrorDescription(err));
switch (err) {
case SSL_ERROR_WANT_READ:
break;
Expand Down Expand Up @@ -263,6 +265,8 @@ Network::IoResult SslSocket::doWrite(Buffer::Instance& write_buffer, bool end_st
bytes_to_write = std::min(write_buffer.length(), static_cast<uint64_t>(16384));
} else {
int err = SSL_get_error(rawSsl(), rc);
ENVOY_CONN_LOG(trace, "ssl error occurred while write: {}", callbacks_->connection(),
Utility::getErrorDescription(err));
switch (err) {
case SSL_ERROR_WANT_WRITE:
bytes_to_retry_ = bytes_to_write;
Expand Down
45 changes: 45 additions & 0 deletions source/extensions/transport_sockets/tls/utility.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
#include "extensions/transport_sockets/tls/utility.h"

#include "common/common/assert.h"
#include "common/common/empty_string.h"
#include "common/network/address_impl.h"

#include "absl/strings/str_join.h"
Expand Down Expand Up @@ -214,6 +215,50 @@ absl::optional<std::string> Utility::getLastCryptoError() {
return absl::nullopt;
}

absl::string_view Utility::getErrorDescription(int err) {
Copy link
Member

Choose a reason for hiding this comment

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

Drive by: It seems like this is a function that could be provided by BoringSSL? cc @PiotrSikora @davidben @ggreenway

Copy link
Contributor

Choose a reason for hiding this comment

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

It is. SSL_error_description :-)

Copy link
Member

Choose a reason for hiding this comment

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

OK, thanks. @Shikugawa can you please do a follow up PR to swap this out?

Copy link
Member Author

Choose a reason for hiding this comment

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

@davidben @mattklein123 I found a problem that SSL_error_description can't be utilized when BORINGSSL_FIPS. I didn't survey about this issue but considered this approach would be no problem and more performant with string_view.

Copy link
Contributor

Choose a reason for hiding this comment

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

That function isn't gated on FIPS mode in BoringSSL. I'm guessing Envoy pins to a much much older version in some build configurations? I'm not sure what you all's policy on that is. @PiotrSikora? SSL_error_description was added way back in August of 2019.

If callers want to support a range of versions, our usual recommendation is to add preprocessor checks on BORINGSSL_API_VERSION, so that you can still call into newer functions when they're available, and then to retire the old paths when no longer needed. In particular, SSL_error_description will pick up new values when we add them. So that may be an option.

Copy link
Contributor

Choose a reason for hiding this comment

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

@davidben BoringSSL-FIPS builds are pinned to the latest FIPS-validated version for Linux x86-64, which per crypto/fipsmodule/FIPS.md is fips-20190808, tagged ~2 weeks before SSL_error_description was added.

Copy link
Member

Choose a reason for hiding this comment

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

OK @Shikugawa can you possibly add a TODO so thast when we bump the FIPS version we can remove this function?

Copy link
Member Author

Choose a reason for hiding this comment

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

Sure

switch (err) {
case SSL_ERROR_NONE:
return SSL_ERROR_NONE_MESSAGE;
case SSL_ERROR_SSL:
return SSL_ERROR_SSL_MESSAGE;
case SSL_ERROR_WANT_READ:
return SSL_ERROR_WANT_READ_MESSAGE;
case SSL_ERROR_WANT_WRITE:
return SSL_ERROR_WANT_WRITE_MESSAGE;
case SSL_ERROR_WANT_X509_LOOKUP:
return SSL_ERROR_WANT_X509_LOOPUP_MESSAGE;
case SSL_ERROR_SYSCALL:
return SSL_ERROR_SYSCALL_MESSAGE;
case SSL_ERROR_ZERO_RETURN:
return SSL_ERROR_ZERO_RETURN_MESSAGE;
case SSL_ERROR_WANT_CONNECT:
return SSL_ERROR_WANT_CONNECT_MESSAGE;
case SSL_ERROR_WANT_ACCEPT:
return SSL_ERROR_WANT_ACCEPT_MESSAGE;
case SSL_ERROR_WANT_CHANNEL_ID_LOOKUP:
return SSL_ERROR_WANT_CHANNEL_ID_LOOKUP_MESSAGE;
case SSL_ERROR_PENDING_SESSION:
return SSL_ERROR_PENDING_SESSION_MESSAGE;
case SSL_ERROR_PENDING_CERTIFICATE:
return SSL_ERROR_PENDING_CERTIFICATE_MESSAGE;
case SSL_ERROR_WANT_PRIVATE_KEY_OPERATION:
return SSL_ERROR_WANT_PRIVATE_KEY_OPERATION_MESSAGE;
case SSL_ERROR_PENDING_TICKET:
return SSL_ERROR_PENDING_TICKET_MESSAGE;
case SSL_ERROR_EARLY_DATA_REJECTED:
return SSL_ERROR_EARLY_DATA_REJECTED_MESSAGE;
case SSL_ERROR_WANT_CERTIFICATE_VERIFY:
return SSL_ERROR_WANT_CERTIFICATE_VERIFY_MESSAGE;
case SSL_ERROR_HANDOFF:
return SSL_ERROR_HANDOFF_MESSAGE;
case SSL_ERROR_HANDBACK:
return SSL_ERROR_HANDBACK_MESSAGE;
default:
ENVOY_BUG(false, "Unknown BoringSSL error had occurred");
return SSL_ERROR_UNKNOWN_ERROR_MESSAGE;
}
}

} // namespace Tls
} // namespace TransportSockets
} // namespace Extensions
Expand Down
30 changes: 30 additions & 0 deletions source/extensions/transport_sockets/tls/utility.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,29 @@ namespace TransportSockets {
namespace Tls {
namespace Utility {

static constexpr absl::string_view SSL_ERROR_NONE_MESSAGE = "NONE";
static constexpr absl::string_view SSL_ERROR_SSL_MESSAGE = "SSL";
static constexpr absl::string_view SSL_ERROR_WANT_READ_MESSAGE = "WANT_READ";
static constexpr absl::string_view SSL_ERROR_WANT_WRITE_MESSAGE = "WANT_WRITE";
static constexpr absl::string_view SSL_ERROR_WANT_X509_LOOPUP_MESSAGE = "WANT_X509_LOOKUP";
static constexpr absl::string_view SSL_ERROR_SYSCALL_MESSAGE = "SYSCALL";
static constexpr absl::string_view SSL_ERROR_ZERO_RETURN_MESSAGE = "ZERO_RETURN";
static constexpr absl::string_view SSL_ERROR_WANT_CONNECT_MESSAGE = "WANT_CONNECT";
static constexpr absl::string_view SSL_ERROR_WANT_ACCEPT_MESSAGE = "WANT_ACCEPT";
static constexpr absl::string_view SSL_ERROR_WANT_CHANNEL_ID_LOOKUP_MESSAGE =
"WANT_CHANNEL_ID_LOOKUP";
static constexpr absl::string_view SSL_ERROR_PENDING_SESSION_MESSAGE = "PENDING_SESSION";
static constexpr absl::string_view SSL_ERROR_PENDING_CERTIFICATE_MESSAGE = "PENDING_CERTIFICATE";
static constexpr absl::string_view SSL_ERROR_WANT_PRIVATE_KEY_OPERATION_MESSAGE =
"WANT_PRIVATE_KEY_OPERATION";
static constexpr absl::string_view SSL_ERROR_PENDING_TICKET_MESSAGE = "PENDING_TICKET";
static constexpr absl::string_view SSL_ERROR_EARLY_DATA_REJECTED_MESSAGE = "EARLY_DATA_REJECTED";
static constexpr absl::string_view SSL_ERROR_WANT_CERTIFICATE_VERIFY_MESSAGE =
"WANT_CERTIFICATE_VERIFY";
static constexpr absl::string_view SSL_ERROR_HANDOFF_MESSAGE = "HANDOFF";
static constexpr absl::string_view SSL_ERROR_HANDBACK_MESSAGE = "HANDBACK";
static constexpr absl::string_view SSL_ERROR_UNKNOWN_ERROR_MESSAGE = "UNKNOWN_ERROR";

/**
* Retrieves the serial number of a certificate.
* @param cert the certificate
Expand Down Expand Up @@ -89,6 +112,13 @@ SystemTime getExpirationTime(const X509& cert);
*/
absl::optional<std::string> getLastCryptoError();

/**
* Returns error string corresponding error code derived from OpenSSL.
* @param err error code
* @return string message corresponding error code.
*/
absl::string_view getErrorDescription(int err);

} // namespace Utility
} // namespace Tls
} // namespace TransportSockets
Expand Down
5 changes: 4 additions & 1 deletion test/extensions/transport_sockets/tls/handshaker_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -153,7 +153,10 @@ TEST_F(HandshakerTest, ErrorCbOnAbnormalOperation) {
BIO* bio = BIO_new(BIO_s_socket());
SSL_set_bio(client_ssl_.get(), bio, bio);

StrictMock<MockHandshakeCallbacks> handshake_callbacks;
NiceMock<MockHandshakeCallbacks> handshake_callbacks;
NiceMock<Network::MockConnection> mock_connection;

ON_CALL(handshake_callbacks, connection).WillByDefault(ReturnRef(mock_connection));
EXPECT_CALL(handshake_callbacks, onFailure);

SslHandshakerImpl handshaker(std::move(server_ssl_), 0, &handshake_callbacks);
Expand Down
33 changes: 33 additions & 0 deletions test/extensions/transport_sockets/tls/utility_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -138,6 +138,39 @@ TEST(UtilityTest, TestGetCertificationExtensionValue) {
EXPECT_EQ("", Utility::getCertificateExtensionValue(*cert, "foo"));
}

TEST(UtilityTest, SslErrorDescriptionTest) {
Copy link
Contributor

Choose a reason for hiding this comment

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

I don't feel like this test adds much value. Was it needed just to keep coverage up?

Copy link
Member Author

Choose a reason for hiding this comment

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

Yes. It is needed for test coverage.

const std::vector<std::pair<int, std::string>> test_set = {
{0, "NONE"},
{1, "SSL"},
{2, "WANT_READ"},
{3, "WANT_WRITE"},
{4, "WANT_X509_LOOKUP"},
{5, "SYSCALL"},
{6, "ZERO_RETURN"},
{7, "WANT_CONNECT"},
{8, "WANT_ACCEPT"},
{9, "WANT_CHANNEL_ID_LOOKUP"},
{11, "PENDING_SESSION"},
{12, "PENDING_CERTIFICATE"},
{13, "WANT_PRIVATE_KEY_OPERATION"},
{14, "PENDING_TICKET"},
{15, "EARLY_DATA_REJECTED"},
{16, "WANT_CERTIFICATE_VERIFY"},
{17, "HANDOFF"},
{18, "HANDBACK"},
};

for (const auto& test_data : test_set) {
EXPECT_EQ(test_data.second, Utility::getErrorDescription(test_data.first));
}

#if defined(NDEBUG)
EXPECT_EQ(Utility::getErrorDescription(19), "UNKNOWN_ERROR");
#else
EXPECT_DEATH(Utility::getErrorDescription(19), "Unknown BoringSSL error had occurred");
#endif
}

} // namespace
} // namespace Tls
} // namespace TransportSockets
Expand Down