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

Signed-off-by: Shikugawa <[email protected]>
envoyproxy · Jan 19, 2021 · da1b0e4 · da1b0e4
1 parent deaf537
commit da1b0e4
Show file tree

Hide file tree

Showing 8 changed files with 122 additions and 2 deletions.
diff --git a/source/extensions/transport_sockets/tls/BUILD b/source/extensions/transport_sockets/tls/BUILD
@@ -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",
     ],

diff --git a/source/extensions/transport_sockets/tls/ssl_handshaker.cc b/source/extensions/transport_sockets/tls/ssl_handshaker.cc
@@ -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:

diff --git a/source/extensions/transport_sockets/tls/ssl_handshaker.h b/source/extensions/transport_sockets/tls/ssl_handshaker.h
@@ -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);

diff --git a/source/extensions/transport_sockets/tls/ssl_socket.cc b/source/extensions/transport_sockets/tls/ssl_socket.cc
@@ -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;
@@ -265,6 +267,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;

diff --git a/source/extensions/transport_sockets/tls/utility.cc b/source/extensions/transport_sockets/tls/utility.cc
@@ -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"
@@ -214,6 +215,50 @@ absl::optional<std::string> Utility::getLastCryptoError() {
   return absl::nullopt;
 }
 
+absl::string_view Utility::getErrorDescription(int err) {
+  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

diff --git a/source/extensions/transport_sockets/tls/utility.h b/source/extensions/transport_sockets/tls/utility.h
@@ -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
@@ -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

diff --git a/test/extensions/transport_sockets/tls/handshaker_test.cc b/test/extensions/transport_sockets/tls/handshaker_test.cc
@@ -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);

diff --git a/test/extensions/transport_sockets/tls/utility_test.cc b/test/extensions/transport_sockets/tls/utility_test.cc
@@ -138,6 +138,39 @@ TEST(UtilityTest, TestGetCertificationExtensionValue) {
   EXPECT_EQ("", Utility::getCertificateExtensionValue(*cert, "foo"));
 }
 
+TEST(UtilityTest, SslErrorDescriptionTest) {
+  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