access log: add CONNECTION_TERMINATION_DETAILS operator

docs/root/configuration/http/http_filters/rbac_filter.rst

@@ -12,8 +12,9 @@ and shadow mode, shadow mode won't effect real users, it is used to test that a
 work before rolling out to production.
 
 When a request is denied, the :ref:`RESPONSE_CODE_DETAILS<config_access_log_format_response_code_details>`
-will include the name of the matched policy that caused the deny ("none" if none matched), this helps
-to distinguish the deny from Envoy RBAC filter and the upstream backend.
+will include the name of the matched policy that caused the deny in the format of `rbac_access_denied_matched_policy[policy_name]`
+(policy_name will be `none` if no policy matched), this helps to distinguish the deny from Envoy RBAC
+filter and the upstream backend.
 
 * :ref:`v3 API reference <envoy_v3_api_msg_extensions.filters.http.rbac.v3.RBAC>`
 * This filter should be configured with the name *envoy.filters.http.rbac*.

docs/root/configuration/listeners/network_filters/rbac_filter.rst

@@ -10,6 +10,11 @@ block-list (DENY) set of policies based on properties of the connection (IPs, po
 This filter also supports policy in both enforcement and shadow modes. Shadow mode won't effect real
 users, it is used to test that a new set of policies work before rolling out to production.
 
+When a request is denied, the :ref:`CONNECTION_TERMINATION_DETAILS<config_access_log_format_connection_termination_details>`
+will include the name of the matched policy that caused the deny in the format of `rbac_access_denied_matched_policy[policy_name]`
+(policy_name will be `none` if no policy matched), this helps to distinguish the deny from Envoy
+RBAC filter and the upstream backend.
+
 * :ref:`v3 API reference <envoy_v3_api_msg_extensions.filters.network.rbac.v3.RBAC>`
 * This filter should be configured with the name *envoy.filters.network.rbac*.
 

docs/root/configuration/observability/access_log/usage.rst

@@ -202,6 +202,13 @@ The following command operators are supported:
   TCP
     Not implemented ("-")
 
+.. _config_access_log_format_connection_termination_details:
+
+%CONNECTION_TERMINATION_DETAILS%
+  HTTP and TCP
+    Connection termination details may provide additional information about why the connection was
+    terminated by Envoy for L4 reasons.
+
 %BYTES_SENT%
   HTTP
     Body bytes sent. For WebSocket connection it will also include response header bytes.

docs/root/version_history/current.rst

@@ -82,6 +82,7 @@ New Features
 ------------
 * access log: added a :ref:`dynamic metadata filter<envoy_v3_api_msg_config.accesslog.v3.MetadataFilter>` for access logs, which filters whether to log based on matching dynamic metadata.
 * access log: added support for :ref:`%DOWNSTREAM_PEER_FINGERPRINT_1% <config_access_log_format_response_flags>` as a response flag.
+* access log: added support for :ref:`%CONNECTION_TERMINATION_DETAILS% <config_access_log_format_connection_termination_details>` as a log command operator about why the connection is terminated by Envoy.
 * access log: added support for nested objects in :ref:`JSON logging mode <config_access_log_format_dictionaries>`.
 * access log: added :ref:`omit_empty_values<envoy_v3_api_field_config.core.v3.SubstitutionFormatString.omit_empty_values>` option to omit unset value from formatted log.
 * admin: added :ref:`circuit breakers settings <envoy_v3_api_msg_config.cluster.v3.CircuitBreakers>` information to GET /clusters?format=json :ref:`cluster status <envoy_v3_api_msg_admin.v3.ClusterStatus>`.

include/envoy/stream_info/stream_info.h

@@ -236,6 +236,12 @@ class StreamInfo {
    */
   virtual void setResponseCodeDetails(absl::string_view rc_details) PURE;
 
+  /**
+   * @param connection_termination_details the termination details string to set for this
+   * connection.
+   */
+  virtual void setConnectionTerminationDetails(std::string connection_termination_details) PURE;
+
   /**
    * @param response_flags the response_flags to intersect with.
    * @return true if the intersection of the response_flags argument and the currently set response
@@ -287,6 +293,11 @@ class StreamInfo {
    */
   virtual const absl::optional<std::string>& responseCodeDetails() const PURE;
 
+  /**
+   * @return the termination details of the connection.
+   */
+  virtual const absl::optional<std::string>& connectionTerminationDetails() const PURE;
+
   /**
    * @return the time that the first byte of the request was received.
    */

source/common/formatter/substitution_formatter.cc

@@ -617,6 +617,11 @@ StreamInfoFormatter::StreamInfoFormatter(const std::string& field_name) {
         [](const StreamInfo::StreamInfo& stream_info) {
           return stream_info.responseCodeDetails();
         });
+  } else if (field_name == "CONNECTION_TERMINATION_DETAILS") {
+    field_extractor_ = std::make_unique<StreamInfoStringFieldExtractor>(
+        [](const StreamInfo::StreamInfo& stream_info) {
+          return stream_info.connectionTerminationDetails();
+        });
   } else if (field_name == "BYTES_SENT") {
     field_extractor_ = std::make_unique<StreamInfoUInt64FieldExtractor>(
         [](const StreamInfo::StreamInfo& stream_info) { return stream_info.bytesSent(); });

source/common/stream_info/stream_info_impl.h

@@ -121,6 +121,14 @@ struct StreamInfoImpl : public StreamInfo {
     response_code_details_.emplace(rc_details);
   }
 
+  const absl::optional<std::string>& connectionTerminationDetails() const override {
+    return connection_termination_details_;
+  }
+
+  void setConnectionTerminationDetails(std::string connection_termination_details) override {
+    connection_termination_details_.emplace(connection_termination_details);
+  }
+
   void addBytesSent(uint64_t bytes_sent) override { bytes_sent_ += bytes_sent; }
 
   uint64_t bytesSent() const override { return bytes_sent_; }
@@ -284,6 +292,7 @@ struct StreamInfoImpl : public StreamInfo {
   absl::optional<Http::Protocol> protocol_;
   absl::optional<uint32_t> response_code_;
   absl::optional<std::string> response_code_details_;
+  absl::optional<std::string> connection_termination_details_;
   uint64_t response_flags_{};
   Upstream::HostDescriptionConstSharedPtr upstream_host_{};
   bool health_check_request_{};

source/extensions/filters/network/rbac/rbac_filter.cc

@@ -39,27 +39,35 @@ Network::FilterStatus RoleBasedAccessControlFilter::onData(Buffer::Instance&, bo
                 : "none",
             callbacks_->connection().streamInfo().dynamicMetadata().DebugString());
 
+  std::string log_policy_id = "none";
   // When the enforcement type is continuous always do the RBAC checks. If it is a one time check,
   // run the check once and skip it for subsequent onData calls.
   if (config_->enforcementType() ==
       envoy::extensions::filters::network::rbac::v3::RBAC::CONTINUOUS) {
-    shadow_engine_result_ = checkEngine(Filters::Common::RBAC::EnforcementMode::Shadow);
-    engine_result_ = checkEngine(Filters::Common::RBAC::EnforcementMode::Enforced);
+    shadow_engine_result_ =
+        checkEngine(Filters::Common::RBAC::EnforcementMode::Shadow).engine_result_;
+    auto result = checkEngine(Filters::Common::RBAC::EnforcementMode::Enforced);
+    engine_result_ = result.engine_result_;
+    log_policy_id = result.connection_termination_details_;
   } else {
     if (shadow_engine_result_ == Unknown) {
       // TODO(quanlin): Pass the shadow engine results to other filters.
-      shadow_engine_result_ = checkEngine(Filters::Common::RBAC::EnforcementMode::Shadow);
+      shadow_engine_result_ =
+          checkEngine(Filters::Common::RBAC::EnforcementMode::Shadow).engine_result_;
     }
 
     if (engine_result_ == Unknown) {
-      engine_result_ = checkEngine(Filters::Common::RBAC::EnforcementMode::Enforced);
+      auto result = checkEngine(Filters::Common::RBAC::EnforcementMode::Enforced);
+      engine_result_ = result.engine_result_;
+      log_policy_id = result.connection_termination_details_;
     }
   }
 
   if (engine_result_ == Allow) {
     return Network::FilterStatus::Continue;
   } else if (engine_result_ == Deny) {
-    // TODO(yangminzhu): Set the corresponding response detail once supported in network filter.
+    callbacks_->connection().streamInfo().setConnectionTerminationDetails(
+        Filters::Common::RBAC::responseDetail(log_policy_id));
     callbacks_->connection().close(Network::ConnectionCloseType::NoFlush);
     return Network::FilterStatus::StopIteration;
   }
@@ -81,8 +89,7 @@ void RoleBasedAccessControlFilter::setDynamicMetadata(std::string shadow_engine_
   callbacks_->connection().streamInfo().setDynamicMetadata(NetworkFilterNames::get().Rbac, metrics);
 }
 
-EngineResult
-RoleBasedAccessControlFilter::checkEngine(Filters::Common::RBAC::EnforcementMode mode) {
+Result RoleBasedAccessControlFilter::checkEngine(Filters::Common::RBAC::EnforcementMode mode) {
   const auto engine = config_->engine(mode);
   std::string effective_policy_id;
   if (engine != nullptr) {
@@ -101,7 +108,7 @@ RoleBasedAccessControlFilter::checkEngine(Filters::Common::RBAC::EnforcementMode
         ENVOY_LOG(debug, "enforced allowed, matched policy {}", log_policy_id);
         config_->stats().allowed_.inc();
       }
-      return Allow;
+      return Result{Allow, effective_policy_id};
     } else {
       if (mode == Filters::Common::RBAC::EnforcementMode::Shadow) {
         ENVOY_LOG(debug, "shadow denied, matched policy {}", log_policy_id);
@@ -113,10 +120,10 @@ RoleBasedAccessControlFilter::checkEngine(Filters::Common::RBAC::EnforcementMode
         ENVOY_LOG(debug, "enforced denied, matched policy {}", log_policy_id);
         config_->stats().denied_.inc();
       }
-      return Deny;
+      return Result{Deny, log_policy_id};
     }
   }
-  return None;
+  return Result{None, "none"};
 }
 
 } // namespace RBACFilter

source/extensions/filters/network/rbac/rbac_filter.h

@@ -17,6 +17,11 @@ namespace RBACFilter {
 
 enum EngineResult { Unknown, None, Allow, Deny };
 
+struct Result {
+  EngineResult engine_result_;
+  std::string connection_termination_details_;
+};
+
 /**
  * Configuration for the RBAC network filter.
  */
@@ -74,7 +79,7 @@ class RoleBasedAccessControlFilter : public Network::ReadFilter,
   EngineResult engine_result_{Unknown};
   EngineResult shadow_engine_result_{Unknown};
 
-  EngineResult checkEngine(Filters::Common::RBAC::EnforcementMode mode);
+  Result checkEngine(Filters::Common::RBAC::EnforcementMode mode);
 };
 
 } // namespace RBACFilter

test/common/formatter/substitution_formatter_test.cc

@@ -274,6 +274,30 @@ TEST(SubstitutionFormatterTest, streamInfoFormatter) {
                 ProtoEq(ValueUtil::stringValue("via_upstream")));
   }
 
+  {
+    StreamInfoFormatter termination_details_format("CONNECTION_TERMINATION_DETAILS");
+    absl::optional<std::string> details;
+    EXPECT_CALL(stream_info, connectionTerminationDetails()).WillRepeatedly(ReturnRef(details));
+    EXPECT_EQ(absl::nullopt,
+              termination_details_format.format(request_headers, response_headers,
+                                                response_trailers, stream_info, body));
+    EXPECT_THAT(termination_details_format.formatValue(request_headers, response_headers,
+                                                       response_trailers, stream_info, body),
+                ProtoEq(ValueUtil::nullValue()));
+  }
+
+  {
+    StreamInfoFormatter termination_details_format("CONNECTION_TERMINATION_DETAILS");
+    absl::optional<std::string> details{"access_denied"};
+    EXPECT_CALL(stream_info, connectionTerminationDetails()).WillRepeatedly(ReturnRef(details));
+    EXPECT_EQ("access_denied",
+              termination_details_format.format(request_headers, response_headers,
+                                                response_trailers, stream_info, body));
+    EXPECT_THAT(termination_details_format.formatValue(request_headers, response_headers,
+                                                       response_trailers, stream_info, body),
+                ProtoEq(ValueUtil::stringValue("access_denied")));
+  }
+
   {
     StreamInfoFormatter bytes_sent_format("BYTES_SENT");
     EXPECT_CALL(stream_info, bytesSent()).WillRepeatedly(Return(1));

test/common/stream_info/stream_info_impl_test.cc

@@ -153,6 +153,11 @@ TEST_F(StreamInfoImplTest, MiscSettersAndGetters) {
     ASSERT_TRUE(stream_info.responseCodeDetails().has_value());
     EXPECT_EQ(ResponseCodeDetails::get().ViaUpstream, stream_info.responseCodeDetails().value());
 
+    EXPECT_FALSE(stream_info.connectionTerminationDetails().has_value());
+    stream_info.setConnectionTerminationDetails("access_denied");
+    ASSERT_TRUE(stream_info.connectionTerminationDetails().has_value());
+    EXPECT_EQ("access_denied", stream_info.connectionTerminationDetails().value());
+
     EXPECT_EQ(nullptr, stream_info.upstreamHost());
     Upstream::HostDescriptionConstSharedPtr host(new NiceMock<Upstream::MockHostDescription>());
     stream_info.onUpstreamHostSelected(host);

test/common/stream_info/test_util.h

@@ -41,6 +41,12 @@ class TestStreamInfo : public StreamInfo::StreamInfo {
   void setResponseCodeDetails(absl::string_view rc_details) override {
     response_code_details_.emplace(rc_details);
   }
+  const absl::optional<std::string>& connectionTerminationDetails() const override {
+    return connection_termination_details_;
+  }
+  void setConnectionTerminationDetails(std::string details) override {
+    connection_termination_details_.emplace(details);
+  }
   void addBytesSent(uint64_t) override { NOT_IMPLEMENTED_GCOVR_EXCL_LINE; }
   uint64_t bytesSent() const override { return 2; }
   bool intersectResponseFlags(uint64_t response_flags) const override {
@@ -247,6 +253,7 @@ class TestStreamInfo : public StreamInfo::StreamInfo {
   absl::optional<Http::Protocol> protocol_{Http::Protocol::Http11};
   absl::optional<uint32_t> response_code_;
   absl::optional<std::string> response_code_details_;
+  absl::optional<std::string> connection_termination_details_;
   uint64_t response_flags_{};
   Upstream::HostDescriptionConstSharedPtr upstream_host_{};
   bool health_check_request_{};

test/extensions/filters/network/rbac/integration_test.cc

@@ -131,6 +131,33 @@ name: rbac
   EXPECT_EQ(0U, test_server_->counter("tcp.rbac.shadow_denied")->value());
 }
 
+TEST_P(RoleBasedAccessControlNetworkFilterIntegrationTest, DeniedWithDenyAction) {
+  useListenerAccessLog("%CONNECTION_TERMINATION_DETAILS%");
+  initializeFilter(R"EOF(
+name: rbac
+typed_config:
+  "@type": type.googleapis.com/envoy.config.filter.network.rbac.v2.RBAC
+  stat_prefix: tcp.
+  rules:
+    action: DENY
+    policies:
+      "deny all":
+        permissions:
+          - any: true
+        principals:
+          - any: true
+)EOF");
+  IntegrationTcpClientPtr tcp_client = makeTcpConnection(lookupPort("listener_0"));
+  ASSERT_TRUE(tcp_client->write("hello", false, false));
+  tcp_client->waitForDisconnect();
+
+  EXPECT_EQ(0U, test_server_->counter("tcp.rbac.allowed")->value());
+  EXPECT_EQ(1U, test_server_->counter("tcp.rbac.denied")->value());
+  // Note the whitespace in the policy id is replaced by '_'.
+  EXPECT_THAT(waitForAccessLog(listener_access_log_name_),
+              testing::HasSubstr("rbac_access_denied_matched_policy[deny_all]"));
+}
+
 } // namespace RBAC
 } // namespace NetworkFilters
 } // namespace Extensions

test/mocks/stream_info/mocks.cc

@@ -27,6 +27,9 @@ MockStreamInfo::MockStreamInfo()
   ON_CALL(*this, setResponseCodeDetails(_)).WillByDefault(Invoke([this](absl::string_view details) {
     response_code_details_ = std::string(details);
   }));
+  ON_CALL(*this, setConnectionTerminationDetails(_))
+      .WillByDefault(
+          Invoke([this](std::string details) { connection_termination_details_ = details; }));
   ON_CALL(*this, startTime()).WillByDefault(ReturnPointee(&start_time_));
   ON_CALL(*this, startTimeMonotonic()).WillByDefault(ReturnPointee(&start_time_monotonic_));
   ON_CALL(*this, lastDownstreamRxByteReceived())
@@ -89,6 +92,8 @@ MockStreamInfo::MockStreamInfo()
   ON_CALL(*this, protocol()).WillByDefault(ReturnPointee(&protocol_));
   ON_CALL(*this, responseCode()).WillByDefault(ReturnPointee(&response_code_));
   ON_CALL(*this, responseCodeDetails()).WillByDefault(ReturnPointee(&response_code_details_));
+  ON_CALL(*this, connectionTerminationDetails())
+      .WillByDefault(ReturnPointee(&connection_termination_details_));
   ON_CALL(*this, addBytesReceived(_)).WillByDefault(Invoke([this](uint64_t bytes_received) {
     bytes_received_ += bytes_received;
   }));

test/mocks/stream_info/mocks.h

@@ -22,6 +22,7 @@ class MockStreamInfo : public StreamInfo {
   // StreamInfo::StreamInfo
   MOCK_METHOD(void, setResponseFlag, (ResponseFlag response_flag));
   MOCK_METHOD(void, setResponseCodeDetails, (absl::string_view));
+  MOCK_METHOD(void, setConnectionTerminationDetails, (std::string));
   MOCK_METHOD(bool, intersectResponseFlags, (uint64_t), (const));
   MOCK_METHOD(void, onUpstreamHostSelected, (Upstream::HostDescriptionConstSharedPtr host));
   MOCK_METHOD(SystemTime, startTime, (), (const));
@@ -51,6 +52,7 @@ class MockStreamInfo : public StreamInfo {
   MOCK_METHOD(void, protocol, (Http::Protocol protocol));
   MOCK_METHOD(absl::optional<uint32_t>, responseCode, (), (const));
   MOCK_METHOD(const absl::optional<std::string>&, responseCodeDetails, (), (const));
+  MOCK_METHOD(const absl::optional<std::string>&, connectionTerminationDetails, (), (const));
   MOCK_METHOD(void, addBytesSent, (uint64_t));
   MOCK_METHOD(uint64_t, bytesSent, (), (const));
   MOCK_METHOD(bool, hasResponseFlag, (ResponseFlag), (const));
@@ -115,6 +117,7 @@ class MockStreamInfo : public StreamInfo {
   absl::optional<Http::Protocol> protocol_;
   absl::optional<uint32_t> response_code_;
   absl::optional<std::string> response_code_details_;
+  absl::optional<std::string> connection_termination_details_;
   uint64_t response_flags_{};
   envoy::config::core::v3::Metadata metadata_;
   FilterStateSharedPtr upstream_filter_state_;