Merge pull request #10049 from vespa-engine/vekterli/add-peer-address-logging-for-tls-errors

Add peer address logging for TLS errors

8 files changed, 52 insertions, 25 deletions

diff --git a/vespalib/src/tests/net/tls/openssl_impl/openssl_impl_test.cpp b/vespalib/src/tests/net/tls/openssl_impl/openssl_impl_test.cpp
index 8ee10deead1..78838ce2cd2 100644
--- a/vespalib/src/tests/net/tls/openssl_impl/openssl_impl_test.cpp
+++ b/vespalib/src/tests/net/tls/openssl_impl/openssl_impl_test.cpp
@@ -97,7 +97,7 @@ struct Fixture {
     static std::unique_ptr<CryptoCodec> create_openssl_codec(
             const std::shared_ptr<TlsContext>& ctx, CryptoCodec::Mode mode) {
         auto ctx_impl = std::dynamic_pointer_cast<impl::OpenSslTlsContextImpl>(ctx);
-        return std::make_unique<impl::OpenSslCryptoCodecImpl>(std::move(ctx_impl), mode);
+        return std::make_unique<impl::OpenSslCryptoCodecImpl>(std::move(ctx_impl), SocketAddress(), mode);
     }
 
     EncodeResult do_encode(CryptoCodec& codec, Output& buffer, vespalib::stringref plaintext) {
diff --git a/vespalib/src/vespa/vespalib/net/tls/crypto_codec.cpp b/vespalib/src/vespa/vespalib/net/tls/crypto_codec.cpp
index 680d6472470..c54990b3782 100644
--- a/vespalib/src/vespa/vespalib/net/tls/crypto_codec.cpp
+++ b/vespalib/src/vespa/vespalib/net/tls/crypto_codec.cpp
@@ -6,10 +6,12 @@
 
 namespace vespalib::net::tls {
 
-std::unique_ptr<CryptoCodec> CryptoCodec::create_default_codec(std::shared_ptr<TlsContext> ctx, Mode mode) {
+std::unique_ptr<CryptoCodec> CryptoCodec::create_default_codec(
+        std::shared_ptr<TlsContext> ctx, const SocketAddress& peer_address, Mode mode)
+{
     auto ctx_impl = std::dynamic_pointer_cast<impl::OpenSslTlsContextImpl>(ctx); // only takes by const ref
     assert(ctx_impl);
-    return std::make_unique<impl::OpenSslCryptoCodecImpl>(std::move(ctx_impl), mode);
+    return std::make_unique<impl::OpenSslCryptoCodecImpl>(std::move(ctx_impl), peer_address, mode);
 }
 
 }
diff --git a/vespalib/src/vespa/vespalib/net/tls/crypto_codec.h b/vespalib/src/vespa/vespalib/net/tls/crypto_codec.h
index fc5303dbc5b..5d9684461d7 100644
--- a/vespalib/src/vespa/vespalib/net/tls/crypto_codec.h
+++ b/vespalib/src/vespa/vespalib/net/tls/crypto_codec.h
@@ -1,6 +1,7 @@
 // Copyright 2018 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
 #pragma once
 
+#include <vespa/vespalib/net/socket_address.h>
 #include <memory>
 
 namespace vespalib::net::tls {
@@ -178,7 +179,9 @@ public:
      *
      * Throws CryptoException if resources cannot be allocated for the codec.
      */
-    static std::unique_ptr<CryptoCodec> create_default_codec(std::shared_ptr<TlsContext> ctx, Mode mode);
+    static std::unique_ptr<CryptoCodec> create_default_codec(std::shared_ptr<TlsContext> ctx,
+                                                             const SocketAddress& peer_address,
+                                                             Mode mode);
 };
 
 }
diff --git a/vespalib/src/vespa/vespalib/net/tls/impl/openssl_crypto_codec_impl.cpp b/vespalib/src/vespa/vespalib/net/tls/impl/openssl_crypto_codec_impl.cpp
index 3049c02b798..5315754d53a 100644
--- a/vespalib/src/vespa/vespalib/net/tls/impl/openssl_crypto_codec_impl.cpp
+++ b/vespalib/src/vespa/vespalib/net/tls/impl/openssl_crypto_codec_impl.cpp
@@ -17,7 +17,7 @@
 #include <openssl/err.h>
 #include <openssl/pem.h>
 
-#include <vespa/log/log.h>
+#include <vespa/log/bufferedlogger.h>
 LOG_SETUP(".vespalib.net.tls.openssl_crypto_codec_impl");
 
 #if (OPENSSL_VERSION_NUMBER < 0x10000000L)
@@ -159,15 +159,23 @@ vespalib::string ssl_error_from_stack() {
     return vespalib::string(buf);
 }
 
-void log_ssl_error(const char* source, int ssl_error) {
-    LOG(error, "%s returned unexpected error: %s (%s)",
-        source, ssl_error_to_str(ssl_error), ssl_error_from_stack().c_str());
+void log_ssl_error(const char* source, const SocketAddress& peer_address, int ssl_error) {
+    // Buffer the emitted log messages on the peer's IP address. This prevents a single misbehaving
+    // client from flooding our logs, while at the same time ensuring that logs for other clients
+    // aren't lost.
+    LOGBT(warning, peer_address.ip_address(),
+          "%s (with peer '%s') returned unexpected error: %s (%s)",
+          source, peer_address.spec().c_str(),
+          ssl_error_to_str(ssl_error), ssl_error_from_stack().c_str());
 }
 
 } // anon ns
 
-OpenSslCryptoCodecImpl::OpenSslCryptoCodecImpl(std::shared_ptr<OpenSslTlsContextImpl> ctx, Mode mode)
+OpenSslCryptoCodecImpl::OpenSslCryptoCodecImpl(std::shared_ptr<OpenSslTlsContextImpl> ctx,
+                                               const SocketAddress& peer_address,
+                                               Mode mode)
     : _ctx(std::move(ctx)),
+      _peer_address(peer_address),
       _ssl(::SSL_new(_ctx->native_context())),
       _mode(mode),
       _deferred_handshake_params(),
@@ -214,6 +222,10 @@ OpenSslCryptoCodecImpl::OpenSslCryptoCodecImpl(std::shared_ptr<OpenSslTlsContext
     } else {
         ::SSL_set_accept_state(_ssl.get());
     }
+    // Store self-reference that can be fished out of SSL object during certificate verification callbacks
+    if (SSL_set_app_data(_ssl.get(), this) != 1) {
+        throw CryptoException("SSL_set_app_data() failed");
+    }
 }
 
 OpenSslCryptoCodecImpl::~OpenSslCryptoCodecImpl() = default;
@@ -302,7 +314,7 @@ HandshakeResult OpenSslCryptoCodecImpl::do_handshake_and_consume_peer_input_byte
         ConnectionStatistics::get(_mode == Mode::Server).inc_tls_connections();
         return handshake_consumed_bytes_and_is_complete(static_cast<size_t>(consumed));
     } else {
-        log_ssl_error("SSL_do_handshake()", ssl_result);
+        log_ssl_error("SSL_do_handshake()", _peer_address, ssl_result);
         ConnectionStatistics::get(_mode == Mode::Server).inc_failed_tls_handshakes();
         return handshake_failed();
     }
@@ -327,7 +339,7 @@ EncodeResult OpenSslCryptoCodecImpl::encode(const char* plaintext, size_t plaint
         // SSL_write encodes plaintext to ciphertext and writes to _output_bio
         const int consumed = ::SSL_write(_ssl.get(), plaintext, to_consume);
         if (consumed < 0) {
-            log_ssl_error("SSL_write()", ::SSL_get_error(_ssl.get(), consumed));
+            log_ssl_error("SSL_write()", _peer_address, ::SSL_get_error(_ssl.get(), consumed));
             ConnectionStatistics::get(_mode == Mode::Server).inc_broken_tls_connections();
             return encode_failed(); // TODO explicitly detect and log TLS renegotiation error (SSL_ERROR_WANT_READ)?
         } else if (consumed != to_consume) {
@@ -391,7 +403,7 @@ DecodeResult OpenSslCryptoCodecImpl::remap_ssl_read_failure_to_decode_result(int
         LOG(debug, "SSL_read() returned SSL_ERROR_ZERO_RETURN; connection has been shut down normally by the peer");
         return decode_peer_has_closed();
     default:
-        log_ssl_error("SSL_read()", ssl_error);
+        log_ssl_error("SSL_read()", _peer_address, ssl_error);
         ConnectionStatistics::get(_mode == Mode::Server).inc_broken_tls_connections();
         return decode_failed();
     }
@@ -403,7 +415,7 @@ EncodeResult OpenSslCryptoCodecImpl::half_close(char* ciphertext, size_t ciphert
     const int pending_before = BIO_pending(_output_bio);
     int ssl_result = ::SSL_shutdown(_ssl.get());
     if (ssl_result < 0) {
-        log_ssl_error("SSL_shutdown()", ::SSL_get_error(_ssl.get(), ssl_result));
+        log_ssl_error("SSL_shutdown()", _peer_address, ::SSL_get_error(_ssl.get(), ssl_result));
         return encode_failed();
     }
     const int pending_after = BIO_pending(_output_bio);
diff --git a/vespalib/src/vespa/vespalib/net/tls/impl/openssl_crypto_codec_impl.h b/vespalib/src/vespa/vespalib/net/tls/impl/openssl_crypto_codec_impl.h
index ef7e0998994..14200de449a 100644
--- a/vespalib/src/vespa/vespalib/net/tls/impl/openssl_crypto_codec_impl.h
+++ b/vespalib/src/vespa/vespalib/net/tls/impl/openssl_crypto_codec_impl.h
@@ -2,6 +2,7 @@
 #pragma once
 
 #include "openssl_typedefs.h"
+#include <vespa/vespalib/net/socket_address.h>
 #include <vespa/vespalib/net/tls/transport_security_options.h>
 #include <vespa/vespalib/net/tls/crypto_codec.h>
 #include <memory>
@@ -45,6 +46,7 @@ class OpenSslCryptoCodecImpl : public CryptoCodec {
     // The context maintains shared verification callback state, so it must be
     // kept alive explictly for at least as long as any codecs.
     std::shared_ptr<OpenSslTlsContextImpl> _ctx;
+    SocketAddress _peer_address;
     SslPtr _ssl;
     ::BIO* _input_bio;  // Owned by _ssl
     ::BIO* _output_bio; // Owned by _ssl
@@ -52,7 +54,7 @@ class OpenSslCryptoCodecImpl : public CryptoCodec {
     std::optional<DeferredHandshakeParams> _deferred_handshake_params;
     std::optional<HandshakeResult> _deferred_handshake_result;
 public:
-    OpenSslCryptoCodecImpl(std::shared_ptr<OpenSslTlsContextImpl> ctx, Mode mode);
+    OpenSslCryptoCodecImpl(std::shared_ptr<OpenSslTlsContextImpl> ctx, const SocketAddress& peer_address, Mode mode);
     ~OpenSslCryptoCodecImpl() override;
 
     /*
@@ -85,6 +87,8 @@ public:
     DecodeResult decode(const char* ciphertext, size_t ciphertext_size,
                         char* plaintext, size_t plaintext_size) noexcept override;
     EncodeResult half_close(char* ciphertext, size_t ciphertext_size) noexcept override;
+
+    const SocketAddress& peer_address() const noexcept { return _peer_address; }
 private:
     HandshakeResult do_handshake_and_consume_peer_input_bytes() noexcept;
     DecodeResult drain_and_produce_plaintext_from_ssl(char* plaintext, size_t plaintext_size) noexcept;
diff --git a/vespalib/src/vespa/vespalib/net/tls/impl/openssl_tls_context_impl.cpp b/vespalib/src/vespa/vespalib/net/tls/impl/openssl_tls_context_impl.cpp
index c87dc1d2148..98675ec6b0b 100644
--- a/vespalib/src/vespa/vespalib/net/tls/impl/openssl_tls_context_impl.cpp
+++ b/vespalib/src/vespa/vespalib/net/tls/impl/openssl_tls_context_impl.cpp
@@ -2,6 +2,7 @@
 #include "iana_cipher_map.h"
 #include "openssl_typedefs.h"
 #include "openssl_tls_context_impl.h"
+#include "openssl_crypto_codec_impl.h"
 #include <vespa/vespalib/net/tls/crypto_exception.h>
 #include <vespa/vespalib/net/tls/statistics.h>
 #include <vespa/vespalib/net/tls/transport_security_options.h>
@@ -17,7 +18,7 @@
 #include <openssl/asn1.h>
 #include <openssl/pem.h>
 
-#include <vespa/log/log.h>
+#include <vespa/log/bufferedlogger.h>
 LOG_SETUP(".vespalib.net.tls.openssl_tls_context_impl");
 
 #if (OPENSSL_VERSION_NUMBER < 0x10000000L)
@@ -402,8 +403,6 @@ bool fill_certificate_subject_alternate_names(::X509* cert, PeerCredentials& cre
 
 } // anon ns
 
-// TODO if/when we want to move per-connection peer credentials into the crypto codec/socket
-// itself, we probably need to set the verification callback (data) on _SSL_, not _SSL_CTX_..!
 // Note: we try to be as conservative as possible. If anything looks out of place, we fail
 // secure by denying the connection.
 //
@@ -426,19 +425,22 @@ int OpenSslTlsContextImpl::verify_cb_wrapper(int preverified_ok, ::X509_STORE_CT
     void* data = ::X509_STORE_CTX_get_ex_data(store_ctx, ::SSL_get_ex_data_X509_STORE_CTX_idx());
     LOG_ASSERT(data != nullptr);
     auto* ssl = static_cast<::SSL*>(data);
+    data = SSL_get_app_data(ssl);
+    LOG_ASSERT(data != nullptr);
+    auto* codec_impl = static_cast<OpenSslCryptoCodecImpl*>(data);
     const ::SSL_CTX* ssl_ctx = ::SSL_get_SSL_CTX(ssl);
     LOG_ASSERT(ssl_ctx != nullptr);
     auto* self = static_cast<OpenSslTlsContextImpl*>(SSL_CTX_get_app_data(ssl_ctx));
     LOG_ASSERT(self != nullptr);
 
-    if (self->verify_trusted_certificate(store_ctx)) {
+    if (self->verify_trusted_certificate(store_ctx, codec_impl->peer_address())) {
         return 1;
     }
     ConnectionStatistics::get(SSL_in_accept_init(ssl) != 0).inc_invalid_peer_credentials();
     return 0;
 }
 
-bool OpenSslTlsContextImpl::verify_trusted_certificate(::X509_STORE_CTX* store_ctx) {
+bool OpenSslTlsContextImpl::verify_trusted_certificate(::X509_STORE_CTX* store_ctx, const SocketAddress& peer_address) {
     const auto authz_mode = authorization_mode();
     // TODO consider if we want to fill in peer credentials even if authorization is disabled
     if (authz_mode == AuthorizationMode::Disable) {
@@ -459,13 +461,16 @@ bool OpenSslTlsContextImpl::verify_trusted_certificate(::X509_STORE_CTX* store_c
     try {
         const bool verified_by_cb = _cert_verify_callback->verify(creds);
         if (!verified_by_cb) {
-            // TODO we should print the peer's remote address too, but that information is
-            // not currently available to us here.
-            LOG(warning, "Certificate verification failed for %s", to_string(creds).c_str());
+            // Buffer warnings on peer IP address to avoid log flooding.
+            LOGBT(warning, peer_address.ip_address(),
+                  "Certificate verification of peer '%s' failed with %s",
+                  peer_address.spec().c_str(), to_string(creds).c_str());
             return (authz_mode != AuthorizationMode::Enforce);
         }
     } catch (std::exception& e) {
-        LOG(error, "Got exception during certificate verification callback: %s", e.what());
+        LOGBT(error, peer_address.ip_address(),
+              "Got exception during certificate verification callback for peer '%s': %s",
+              peer_address.spec().c_str(), e.what());
         return false;
     } // we don't expect any non-std::exception derived exceptions, so let them terminate the process.
     return true;
diff --git a/vespalib/src/vespa/vespalib/net/tls/impl/openssl_tls_context_impl.h b/vespalib/src/vespa/vespalib/net/tls/impl/openssl_tls_context_impl.h
index 31814dad8ba..c519b1ae874 100644
--- a/vespalib/src/vespa/vespalib/net/tls/impl/openssl_tls_context_impl.h
+++ b/vespalib/src/vespa/vespalib/net/tls/impl/openssl_tls_context_impl.h
@@ -2,6 +2,7 @@
 #pragma once
 
 #include "openssl_typedefs.h"
+#include <vespa/vespalib/net/socket_address.h>
 #include <vespa/vespalib/net/tls/tls_context.h>
 #include <vespa/vespalib/net/tls/transport_security_options.h>
 #include <vespa/vespalib/net/tls/certificate_verification_callback.h>
@@ -46,7 +47,7 @@ private:
     void set_ssl_ctx_self_reference();
     void set_accepted_cipher_suites(const std::vector<vespalib::string>& ciphers);
 
-    bool verify_trusted_certificate(::X509_STORE_CTX* store_ctx);
+    bool verify_trusted_certificate(::X509_STORE_CTX* store_ctx, const SocketAddress& peer_address);
 
     static int verify_cb_wrapper(int preverified_ok, ::X509_STORE_CTX* store_ctx);
 };
diff --git a/vespalib/src/vespa/vespalib/net/tls/tls_crypto_engine.cpp b/vespalib/src/vespa/vespalib/net/tls/tls_crypto_engine.cpp
index 7d0d3287965..58d99cc7108 100644
--- a/vespalib/src/vespa/vespalib/net/tls/tls_crypto_engine.cpp
+++ b/vespalib/src/vespa/vespalib/net/tls/tls_crypto_engine.cpp
@@ -15,7 +15,7 @@ std::unique_ptr<TlsCryptoSocket>
 TlsCryptoEngine::create_tls_crypto_socket(SocketHandle socket, bool is_server)
 {
     auto mode = is_server ? net::tls::CryptoCodec::Mode::Server : net::tls::CryptoCodec::Mode::Client;
-    auto codec = net::tls::CryptoCodec::create_default_codec(_tls_ctx, mode);
+    auto codec = net::tls::CryptoCodec::create_default_codec(_tls_ctx, SocketAddress::peer_address(socket.get()), mode);
     return std::make_unique<net::tls::CryptoCodecAdapter>(std::move(socket), std::move(codec));
 }