accesslog: report on listener filter errors (#12935)

emit logs in case listener filter reject or timeout incoming connections. Moved the stream info ownership to the active TCP socket. There are three cases that have to be handled separately: ownership transfer to TCP connection (how it works today), deferred deletion of TCP socket (via unlinking), direct deletion of TCP socket

Fixes: #12809

Signed-off-by: Kuat Yessenov <kuat@google.com>

source/server/connection_handler_impl.cc

@@ -17,6 +17,15 @@
 namespace Envoy {
 namespace Server {
 
+namespace {
+void emitLogs(Network::ListenerConfig& config, StreamInfo::StreamInfo& stream_info) {
+  stream_info.onRequestComplete();
+  for (const auto& access_log : config.accessLogs()) {
+    access_log->log(nullptr, nullptr, nullptr, stream_info);
+  }
+}
+} // namespace
+
 ConnectionHandlerImpl::ConnectionHandlerImpl(Event::Dispatcher& dispatcher)
     : dispatcher_(dispatcher), per_handler_stat_prefix_(dispatcher.name() + "."),
       disable_listeners_(false) {}
@@ -245,6 +254,10 @@ void ConnectionHandlerImpl::ActiveTcpSocket::unlink() {
   if (removed->timer_ != nullptr) {
     removed->timer_->disableTimer();
   }
+  // Emit logs if a connection is not established.
+  if (!connected_) {
+    emitLogs(*listener_.config_, *stream_info_);
+  }
   listener_.parent_.dispatcher_.deferredDelete(std::move(removed));
 }
 
@@ -289,10 +302,12 @@ void ConnectionHandlerImpl::ActiveTcpSocket::continueFilterChain(bool success) {
 
 void ConnectionHandlerImpl::ActiveTcpSocket::setDynamicMetadata(const std::string& name,
                                                                 const ProtobufWkt::Struct& value) {
-  (*metadata_.mutable_filter_metadata())[name].MergeFrom(value);
+  stream_info_->setDynamicMetadata(name, value);
 }
 
 void ConnectionHandlerImpl::ActiveTcpSocket::newConnection() {
+  connected_ = true;
+
   // Check if the socket may need to be redirected to another listener.
   ActiveTcpListenerOptRef new_listener;
 
@@ -323,7 +338,7 @@ void ConnectionHandlerImpl::ActiveTcpSocket::newConnection() {
     // Particularly the assigned events need to reset before assigning new events in the follow up.
     accept_filters_.clear();
     // Create a new connection on this listener.
-    listener_.newConnection(std::move(socket_), dynamicMetadata());
+    listener_.newConnection(std::move(socket_), std::move(stream_info_));
   }
 }
 
@@ -363,32 +378,16 @@ void ConnectionHandlerImpl::ActiveTcpListener::onAcceptWorker(
   if (active_socket->iter_ != active_socket->accept_filters_.end()) {
     active_socket->startTimer();
     LinkedList::moveIntoListBack(std::move(active_socket), sockets_);
+  } else {
+    // If active_socket is about to be destructed, emit logs if a connection is not created.
+    if (!active_socket->connected_) {
+      emitLogs(*config_, *active_socket->stream_info_);
+    }
   }
 }
 
-namespace {
-void emitLogs(Network::ListenerConfig& config, StreamInfo::StreamInfo& stream_info) {
-  stream_info.onRequestComplete();
-  for (const auto& access_log : config.accessLogs()) {
-    access_log->log(nullptr, nullptr, nullptr, stream_info);
-  }
-}
-} // namespace
-
 void ConnectionHandlerImpl::ActiveTcpListener::newConnection(
-    Network::ConnectionSocketPtr&& socket,
-    const envoy::config::core::v3::Metadata& dynamic_metadata) {
-  auto stream_info = std::make_unique<StreamInfo::StreamInfoImpl>(
-      parent_.dispatcher_.timeSource(), StreamInfo::FilterState::LifeSpan::Connection);
-  stream_info->setDownstreamLocalAddress(socket->localAddress());
-  stream_info->setDownstreamRemoteAddress(socket->remoteAddress());
-  stream_info->setDownstreamDirectRemoteAddress(socket->directRemoteAddress());
-
-  // merge from the given dynamic metadata if it's not empty
-  if (dynamic_metadata.filter_metadata_size() > 0) {
-    stream_info->dynamicMetadata().MergeFrom(dynamic_metadata);
-  }
-
+    Network::ConnectionSocketPtr&& socket, std::unique_ptr<StreamInfo::StreamInfo> stream_info) {
   // Find matching filter chain.
   const auto filter_chain = config_->filterChainManager().findFilterChain(*socket);
   if (filter_chain == nullptr) {

source/server/connection_handler_impl.h

@@ -16,10 +16,10 @@
 #include "envoy/server/listener_manager.h"
 #include "envoy/stats/scope.h"
 #include "envoy/stats/timespan.h"
-#include "envoy/stream_info/stream_info.h"
 
 #include "common/common/linked_object.h"
 #include "common/common/non_copyable.h"
+#include "common/stream_info/stream_info_impl.h"
 
 #include "spdlog/spdlog.h"
 
@@ -156,7 +156,7 @@ class ConnectionHandlerImpl : public Network::ConnectionHandler,
      * Create a new connection from a socket accepted by the listener.
      */
     void newConnection(Network::ConnectionSocketPtr&& socket,
-                       const envoy::config::core::v3::Metadata& dynamic_metadata);
+                       std::unique_ptr<StreamInfo::StreamInfo> stream_info);
 
     /**
      * Return the active connections container attached with the given filter chain.
@@ -243,8 +243,13 @@ class ConnectionHandlerImpl : public Network::ConnectionHandler,
                     bool hand_off_restored_destination_connections)
         : listener_(listener), socket_(std::move(socket)),
           hand_off_restored_destination_connections_(hand_off_restored_destination_connections),
-          iter_(accept_filters_.end()) {
+          iter_(accept_filters_.end()), stream_info_(std::make_unique<StreamInfo::StreamInfoImpl>(
+                                            listener_.parent_.dispatcher_.timeSource(),
+                                            StreamInfo::FilterState::LifeSpan::Connection)) {
       listener_.stats_.downstream_pre_cx_active_.inc();
+      stream_info_->setDownstreamLocalAddress(socket_->localAddress());
+      stream_info_->setDownstreamRemoteAddress(socket_->remoteAddress());
+      stream_info_->setDownstreamDirectRemoteAddress(socket_->directRemoteAddress());
     }
     ~ActiveTcpSocket() override {
       accept_filters_.clear();
@@ -308,16 +313,21 @@ class ConnectionHandlerImpl : public Network::ConnectionHandler,
     Event::Dispatcher& dispatcher() override { return listener_.parent_.dispatcher_; }
     void continueFilterChain(bool success) override;
     void setDynamicMetadata(const std::string& name, const ProtobufWkt::Struct& value) override;
-    envoy::config::core::v3::Metadata& dynamicMetadata() override { return metadata_; };
-    const envoy::config::core::v3::Metadata& dynamicMetadata() const override { return metadata_; };
+    envoy::config::core::v3::Metadata& dynamicMetadata() override {
+      return stream_info_->dynamicMetadata();
+    };
+    const envoy::config::core::v3::Metadata& dynamicMetadata() const override {
+      return stream_info_->dynamicMetadata();
+    };
 
     ActiveTcpListener& listener_;
     Network::ConnectionSocketPtr socket_;
     const bool hand_off_restored_destination_connections_;
     std::list<ListenerFilterWrapperPtr> accept_filters_;
     std::list<ListenerFilterWrapperPtr>::iterator iter_;
     Event::TimerPtr timer_;
-    envoy::config::core::v3::Metadata metadata_{};
+    std::unique_ptr<StreamInfo::StreamInfo> stream_info_;
+    bool connected_{false};
   };
 
   using ActiveTcpListenerOptRef = absl::optional<std::reference_wrapper<ActiveTcpListener>>;

test/integration/listener_filter_integration_test.cc

@@ -63,6 +63,7 @@ class ListenerFilterIntegrationTest : public testing::TestWithParam<Network::Add
       *alpn = "envoyalpn";
     });
     config_helper_.addSslConfig();
+    useListenerAccessLog("%RESPONSE_CODE_DETAILS%");
     BaseIntegrationTest::initialize();
 
     context_manager_ =
@@ -109,11 +110,14 @@ class ListenerFilterIntegrationTest : public testing::TestWithParam<Network::Add
 TEST_P(ListenerFilterIntegrationTest, AllListenerFiltersAreEnabledByDefault) {
   setupConnections(/*listener_filter_disabled=*/false, /*expect_connection_open=*/true);
   ssl_client_->close(Network::ConnectionCloseType::NoFlush);
+  EXPECT_THAT(waitForAccessLog(listener_access_log_name_), testing::Eq("-"));
 }
 
 // The tls_inspector is disabled. The ALPN won't be sniffed out and no filter chain is matched.
 TEST_P(ListenerFilterIntegrationTest, DisabledTlsInspectorFailsFilterChainFind) {
   setupConnections(/*listener_filter_disabled=*/true, /*expect_connection_open=*/false);
+  EXPECT_THAT(waitForAccessLog(listener_access_log_name_),
+              testing::Eq(StreamInfo::ResponseCodeDetails::get().FilterChainNotFound));
 }
 
 INSTANTIATE_TEST_SUITE_P(IpVersions, ListenerFilterIntegrationTest,

test/server/BUILD

@@ -79,6 +79,7 @@ envoy_cc_test(
         "//source/common/stats:stats_lib",
         "//source/server:active_raw_udp_listener_config",
         "//source/server:connection_handler_lib",
+        "//test/mocks/access_log:access_log_mocks",
         "//test/mocks/api:api_mocks",
         "//test/mocks/network:network_mocks",
         "//test/test_common:network_utility_lib",