ext_authz: add logging options

api/envoy/extensions/filters/http/ext_authz/v3/ext_authz.proto

@@ -30,7 +30,7 @@ option (udpa.annotations.file_status).package_version_status = ACTIVE;
 // External Authorization :ref:`configuration overview <config_http_filters_ext_authz>`.
 // [#extension: envoy.filters.http.ext_authz]
 
-// [#next-free-field: 29]
+// [#next-free-field: 30]
 message ExtAuthz {
   option (udpa.annotations.versioning).previous_message_type =
       "envoy.config.filter.http.ext_authz.v3.ExtAuthz";
@@ -296,6 +296,17 @@ message ExtAuthz {
   // added to StreamInfo's filter state under the namespace corresponding to the ext_authz filter
   // name.
   google.protobuf.Struct filter_metadata = 28;
+
+  // When set to true, the filter will emit per-stream stats for access logging. The filter state
+  // key will be the same as the filter name.
+  //
+  // If using Envoy GRPC, emits latency, bytes sent / received, upstream info, and upstream cluster
+  // info. If not using Envoy GRPC, emits only latency. Note that stats are ONLY added to filter
+  // state if a check request is actually made to an ext_authz service.
+  //
+  // If this is false the filter will not emit stats, but filter_metadata will still be respected if
+  // it has a value.
+  bool emit_filter_state_stats = 29;
 }
 
 // Configuration for buffering the request data.

changelogs/current.yaml

@@ -284,6 +284,10 @@ new_features:
   change: |
     Added :ref:`delay_deny <envoy_v3_api_msg_extensions.filters.network.rbac.v3.RBAC>` to support deny connection after
     the configured duration.
+- area: ext_authz
+  change: |
+    Added :ref:`emit_filter_state_stats <envoy_v3_api_field_extensions.filters.http.ext_authz.v3.ExtAuthz.emit_filter_state_stats>`
+    which when true enables filter state stats for access logging.
 - area: extension_discovery_service
   change: |
     added ECDS support for :ref:`UDP session filters

envoy/grpc/async_client.h

@@ -29,6 +29,11 @@ class AsyncRequest {
    * Signals that the request should be cancelled. No further callbacks will be invoked.
    */
   virtual void cancel() PURE;
+
+  /**
+   * Returns the underlying stream info.
+   */
+  virtual const StreamInfo::StreamInfo& streamInfo() const PURE;
 };
 
 /**

source/common/grpc/async_client_impl.cc

@@ -333,6 +333,10 @@ void AsyncRequestImpl::cancel() {
   this->resetStream();
 }
 
+const StreamInfo::StreamInfo& AsyncRequestImpl::streamInfo() const {
+  return AsyncStreamImpl::streamInfo();
+}
+
 void AsyncRequestImpl::onCreateInitialMetadata(Http::RequestHeaderMap& metadata) {
   Tracing::HttpTraceContext trace_context(metadata);
   Tracing::UpstreamContext upstream_context(nullptr,                         // host_

source/common/grpc/async_client_impl.h

@@ -138,8 +138,10 @@ class AsyncRequestImpl : public AsyncRequest, public AsyncStreamImpl, RawAsyncSt
 
   // Grpc::AsyncRequest
   void cancel() override;
+  const StreamInfo::StreamInfo& streamInfo() const override;
 
 private:
+  using AsyncStreamImpl::streamInfo;
   // Grpc::AsyncStreamCallbacks
   void onCreateInitialMetadata(Http::RequestHeaderMap& metadata) override;
   void onReceiveInitialMetadata(Http::ResponseHeaderMapPtr&&) override;

source/common/grpc/google_async_client_impl.h

@@ -346,8 +346,12 @@ class GoogleAsyncRequestImpl : public AsyncRequest,
 
   // Grpc::AsyncRequest
   void cancel() override;
+  const StreamInfo::StreamInfo& streamInfo() const override {
+    return GoogleAsyncStreamImpl::streamInfo();
+  }
 
 private:
+  using GoogleAsyncStreamImpl::streamInfo;
   // Grpc::RawAsyncStreamCallbacks
   void onCreateInitialMetadata(Http::RequestHeaderMap& metadata) override;
   void onReceiveInitialMetadata(Http::ResponseHeaderMapPtr&&) override;

source/extensions/filters/common/ext_authz/ext_authz.h

@@ -165,6 +165,11 @@ class Client {
   virtual void check(RequestCallbacks& callback,
                      const envoy::service::auth::v3::CheckRequest& request,
                      Tracing::Span& parent_span, const StreamInfo::StreamInfo& stream_info) PURE;
+
+  /**
+   * Returns streamInfo of the current request if possible. By default just return a nullptr.
+   */
+  virtual StreamInfo::StreamInfo const* streamInfo() const { return nullptr; }
 };
 
 using ClientPtr = std::unique_ptr<Client>;

source/extensions/filters/common/ext_authz/ext_authz_grpc_impl.h

@@ -51,6 +51,9 @@ class GrpcClientImpl : public Client,
   void cancel() override;
   void check(RequestCallbacks& callbacks, const envoy::service::auth::v3::CheckRequest& request,
              Tracing::Span& parent_span, const StreamInfo::StreamInfo& stream_info) override;
+  StreamInfo::StreamInfo const* streamInfo() const override {
+    return request_ ? &request_->streamInfo() : nullptr;
+  }
 
   // Grpc::AsyncRequestCallbacks
   void onCreateInitialMetadata(Http::RequestHeaderMap&) override {}

source/extensions/filters/http/ext_authz/ext_authz.cc

@@ -90,6 +90,7 @@ FilterConfig::FilterConfig(const envoy::extensions::filters::http::ext_authz::v3
       runtime_(factory_context.runtime()), http_context_(factory_context.httpContext()),
       filter_metadata_(config.has_filter_metadata() ? absl::optional(config.filter_metadata())
                                                     : absl::nullopt),
+      emit_filter_state_stats_(config.emit_filter_state_stats()),
       filter_enabled_(config.has_filter_enabled()
                           ? absl::optional<Runtime::FractionalPercent>(
                                 Runtime::FractionalPercent(config.filter_enabled(), runtime_))
@@ -176,6 +177,20 @@ void Filter::initiateCall(const Http::RequestHeaderMap& headers) {
     return;
   }
 
+  // Now that we'll definitely be making the request, add filter state stats if configured to do so.
+  const Envoy::StreamInfo::FilterStateSharedPtr& filter_state =
+      decoder_callbacks_->streamInfo().filterState();
+  if ((config_->emitFilterStateStats() || config_->filterMetadata().has_value()) &&
+      !filter_state->hasData<ExtAuthzLoggingInfo>(decoder_callbacks_->filterConfigName())) {
+    filter_state->setData(decoder_callbacks_->filterConfigName(),
+                          std::make_shared<ExtAuthzLoggingInfo>(config_->filterMetadata()),
+                          Envoy::StreamInfo::FilterState::StateType::Mutable,
+                          Envoy::StreamInfo::FilterState::LifeSpan::Request);
+
+    logging_info_ =
+        filter_state->getDataMutable<ExtAuthzLoggingInfo>(decoder_callbacks_->filterConfigName());
+  }
+
   absl::optional<FilterConfigPerRoute> maybe_merged_per_route_config;
   for (const auto* cfg :
        Http::Utility::getAllPerFilterConfig<FilterConfigPerRoute>(decoder_callbacks_)) {
@@ -384,14 +399,36 @@ Http::FilterMetadataStatus Filter::encodeMetadata(Http::MetadataMap&) {
 
 void Filter::setDecoderFilterCallbacks(Http::StreamDecoderFilterCallbacks& callbacks) {
   decoder_callbacks_ = &callbacks;
-  const Envoy::StreamInfo::FilterStateSharedPtr& filter_state =
-      decoder_callbacks_->streamInfo().filterState();
-  if (config_->filterMetadata().has_value() &&
-      !filter_state->hasData<ExtAuthzLoggingInfo>(decoder_callbacks_->filterConfigName())) {
-    filter_state->setData(decoder_callbacks_->filterConfigName(),
-                          std::make_shared<ExtAuthzLoggingInfo>(*config_->filterMetadata()),
-                          Envoy::StreamInfo::FilterState::StateType::ReadOnly,
-                          Envoy::StreamInfo::FilterState::LifeSpan::Request);
+}
+
+void Filter::updateLoggingInfo() {
+  if (!config_->emitFilterStateStats()) {
+    return;
+  }
+
+  // Latency is the only stat available if we aren't using envoy grpc.
+  if (start_time_.has_value()) {
+    logging_info_->setLatency(std::chrono::duration_cast<std::chrono::microseconds>(
+        decoder_callbacks_->dispatcher().timeSource().monotonicTime() - start_time_.value()));
+  }
+
+  auto const* stream_info = client_->streamInfo();
+  if (stream_info == nullptr) {
+    return;
+  }
+
+  const auto& bytes_meter = stream_info->getUpstreamBytesMeter();
+  if (bytes_meter != nullptr) {
+    logging_info_->setBytesSent(bytes_meter->wireBytesSent());
+    logging_info_->setBytesReceived(bytes_meter->wireBytesReceived());
+  }
+  if (stream_info->upstreamInfo().has_value()) {
+    logging_info_->setUpstreamHost(stream_info->upstreamInfo()->upstreamHost());
+  }
+  absl::optional<Upstream::ClusterInfoConstSharedPtr> cluster_info =
+      stream_info->upstreamClusterInfo();
+  if (cluster_info) {
+    logging_info_->setClusterInfo(std::move(*cluster_info));
   }
 }
 
@@ -422,6 +459,8 @@ void Filter::onComplete(Filters::Common::ExtAuthz::ResponsePtr&& response) {
   using Filters::Common::ExtAuthz::CheckStatus;
   Stats::StatName empty_stat_name;
 
+  updateLoggingInfo();
+
   if (!response->dynamic_metadata.fields().empty()) {
     if (!config_->enableDynamicMetadataIngestion()) {
       ENVOY_STREAM_LOG(trace,

source/extensions/filters/http/ext_authz/ext_authz.h

@@ -53,13 +53,41 @@ struct ExtAuthzFilterStats {
 
 class ExtAuthzLoggingInfo : public Envoy::StreamInfo::FilterState::Object {
 public:
-  explicit ExtAuthzLoggingInfo(const Envoy::ProtobufWkt::Struct& filter_metadata)
+  explicit ExtAuthzLoggingInfo(const absl::optional<Envoy::ProtobufWkt::Struct> filter_metadata)
       : filter_metadata_(filter_metadata) {}
 
-  const ProtobufWkt::Struct& filterMetadata() const { return filter_metadata_; }
+  const absl::optional<ProtobufWkt::Struct>& filterMetadata() const { return filter_metadata_; }
+  absl::optional<std::chrono::microseconds> latency() const { return latency_; };
+  absl::optional<uint64_t> bytesSent() const { return bytes_sent_; }
+  absl::optional<uint64_t> bytesReceived() const { return bytes_received_; }
+  Upstream::ClusterInfoConstSharedPtr clusterInfo() const { return cluster_info_; }
+  Upstream::HostDescriptionConstSharedPtr upstreamHost() const { return upstream_host_; }
+
+  void setLatency(std::chrono::microseconds ms) { latency_ = ms; };
+  void setBytesSent(uint64_t bytes_sent) { bytes_sent_ = bytes_sent; }
+  void setBytesReceived(uint64_t bytes_received) { bytes_received_ = bytes_received; }
+  void setClusterInfo(Upstream::ClusterInfoConstSharedPtr cluster_info) {
+    cluster_info_ = std::move(cluster_info);
+  }
+  void setUpstreamHost(Upstream::HostDescriptionConstSharedPtr upstream_host) {
+    upstream_host_ = std::move(upstream_host);
+  }
+
+  // For convenience in testing.
+  void clearLatency() { latency_ = absl::nullopt; };
+  void clearBytesSent() { bytes_sent_ = absl::nullopt; }
+  void clearBytesReceived() { bytes_received_ = absl::nullopt; }
+  void clearClusterInfo() { cluster_info_ = nullptr; }
+  void clearUpstreamHost() { upstream_host_ = nullptr; }
 
 private:
-  const Envoy::ProtobufWkt::Struct filter_metadata_;
+  const absl::optional<Envoy::ProtobufWkt::Struct> filter_metadata_;
+  absl::optional<std::chrono::microseconds> latency_;
+  // The following stats are populated for ext_authz filters using Envoy gRPC only.
+  absl::optional<uint64_t> bytes_sent_;
+  absl::optional<uint64_t> bytes_received_;
+  Upstream::ClusterInfoConstSharedPtr cluster_info_;
+  Upstream::HostDescriptionConstSharedPtr upstream_host_;
 };
 
 /**
@@ -152,6 +180,8 @@ class FilterConfig {
 
   const absl::optional<ProtobufWkt::Struct>& filterMetadata() const { return filter_metadata_; }
 
+  bool emitFilterStateStats() const { return emit_filter_state_stats_; }
+
   bool chargeClusterResponseStats() const { return charge_cluster_response_stats_; }
 
   const Filters::Common::ExtAuthz::MatcherSharedPtr& allowedHeadersMatcher() const {
@@ -203,6 +233,7 @@ class FilterConfig {
   Http::Context& http_context_;
   LabelsMap destination_labels_;
   const absl::optional<ProtobufWkt::Struct> filter_metadata_;
+  const bool emit_filter_state_stats_;
 
   const absl::optional<Runtime::FractionalPercent> filter_enabled_;
   const absl::optional<Matchers::MetadataMatcher> filter_enabled_metadata_;
@@ -337,6 +368,7 @@ class Filter : public Logger::Loggable<Logger::Id::ext_authz>,
   void initiateCall(const Http::RequestHeaderMap& headers);
   void continueDecoding();
   bool isBufferFull(uint64_t num_bytes_processing) const;
+  void updateLoggingInfo();
 
   // This holds a set of flags defined in per-route configuration.
   struct PerRouteFlags {
@@ -370,6 +402,7 @@ class Filter : public Logger::Loggable<Logger::Id::ext_authz>,
   Upstream::ClusterInfoConstSharedPtr cluster_;
   // The stats for the filter.
   ExtAuthzFilterStats stats_;
+  ExtAuthzLoggingInfo* logging_info_;
 
   // This is used to hold the final configs after we merge them with per-route configs.
   bool allow_partial_message_{};

test/extensions/filters/common/ext_authz/ext_authz_grpc_impl_test.cc

@@ -100,6 +100,21 @@ TEST_F(ExtAuthzGrpcClientTest, AuthorizationOk) {
   client_->onSuccess(std::move(check_response), span_);
 }
 
+TEST_F(ExtAuthzGrpcClientTest, StreamInfo) {
+  initialize();
+
+  envoy::service::auth::v3::CheckRequest request;
+  EXPECT_CALL(*async_client_, sendRaw(_, _, _, _, _, _)).WillOnce(Return(&async_request_));
+  client_->check(request_callbacks_, request, Tracing::NullSpan::instance(), stream_info_);
+
+  NiceMock<StreamInfo::MockStreamInfo> ext_authz_stream_info;
+  EXPECT_CALL(async_request_, streamInfo()).WillOnce(ReturnRef(ext_authz_stream_info));
+  EXPECT_NE(client_->streamInfo(), nullptr);
+
+  EXPECT_CALL(async_request_, cancel());
+  client_->cancel();
+}
+
 // Test the client when an ok response is received.
 TEST_F(ExtAuthzGrpcClientTest, AuthorizationOkWithAllAtributes) {
   initialize();

test/extensions/filters/common/ext_authz/ext_authz_http_impl_test.cc

@@ -209,6 +209,16 @@ class ExtAuthzHttpClientTest : public testing::Test {
   NiceMock<StreamInfo::MockStreamInfo> stream_info_;
 };
 
+TEST_F(ExtAuthzHttpClientTest, StreamInfo) {
+  envoy::service::auth::v3::CheckRequest request;
+  client_->check(request_callbacks_, request, parent_span_, stream_info_);
+  EXPECT_EQ(client_->streamInfo(), nullptr);
+  auto check_response = TestCommon::makeMessageResponse(
+      TestCommon::makeHeaderValueOption({{":status", "200", false}}));
+  EXPECT_CALL(request_callbacks_, onComplete_(_));
+  client_->onSuccess(async_request_, std::move(check_response));
+}
+
 // Test HTTP client config default values.
 TEST_F(ExtAuthzHttpClientTest, ClientConfig) {
   const Http::LowerCaseString foo{"foo"};

test/extensions/filters/common/ext_authz/mocks.h

@@ -25,6 +25,7 @@ class MockClient : public Client {
   MOCK_METHOD(void, check,
               (RequestCallbacks & callbacks, const envoy::service::auth::v3::CheckRequest& request,
                Tracing::Span& parent_span, const StreamInfo::StreamInfo& stream_info));
+  MOCK_METHOD(StreamInfo::StreamInfo const*, streamInfo, (), (const));
 };
 
 class MockRequestCallbacks : public RequestCallbacks {

test/extensions/filters/http/ext_authz/BUILD

@@ -8,6 +8,7 @@ load(
 load(
     "//test/extensions:extensions_build_system.bzl",
     "envoy_extension_cc_test",
+    "envoy_extension_cc_test_library",
 )
 
 licenses(["notice"])  # Apache 2
@@ -73,6 +74,8 @@ envoy_extension_cc_test(
     ],
     extension_names = ["envoy.filters.http.ext_authz"],
     deps = [
+        ":ext_authz_fuzz_proto_cc_proto",
+        ":logging_test_filter_lib",
         "//source/extensions/clusters/strict_dns:strict_dns_cluster_lib",
         "//source/extensions/filters/http/ext_authz:config",
         "//source/extensions/listener_managers/validation_listener_manager:validation_listener_manager_lib",
@@ -149,3 +152,27 @@ envoy_cc_test_library(
         "@envoy_api//envoy/config/core/v3:pkg_cc_proto",
     ],
 )
+
+envoy_proto_library(
+    name = "logging_test_filter_proto",
+    srcs = ["logging_test_filter.proto"],
+)
+
+envoy_extension_cc_test_library(
+    name = "logging_test_filter_lib",
+    srcs = [
+        "logging_test_filter.cc",
+    ],
+    extension_names = ["envoy.filters.http.ext_authz"],
+    deps = [
+        ":logging_test_filter_proto_cc_proto",
+        "//envoy/http:filter_interface",
+        "//envoy/registry",
+        "//envoy/server:filter_config_interface",
+        "//source/common/router:string_accessor_lib",
+        "//source/extensions/filters/http/common:factory_base_lib",
+        "//source/extensions/filters/http/common:pass_through_filter_lib",
+        "//source/extensions/filters/http/ext_authz",
+        "//test/test_common:utility_lib",
+    ],
+)