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";
@@ -292,10 +292,30 @@ message ExtAuthz {
   // If unset, defaults to true.
   google.protobuf.BoolValue enable_dynamic_metadata_ingestion = 27;
 
+  // Deprecated in favor of
+  // :ref:`LoggingOptions.filter_metadata<envoy_v3_api_field_extensions.filters.http.ext_authz.v3.LoggingOptions.filter_metadata>`.
+  google.protobuf.Struct filter_metadata = 28
+      [deprecated = true, (envoy.annotations.deprecated_at_minor_version) = "3.0"];
+
+  // When not empty, 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 empty the filter will not emit any filter state.
+  LoggingOptions logging_options = 29;
+}
+
+message LoggingOptions {
+  option (udpa.annotations.versioning).previous_message_type =
+      "envoy.config.filter.http.ext_authz.v3.LoggingOptions";
+
   // Additional metadata to be added to the filter state for logging purposes. The metadata will be
   // added to StreamInfo's filter state under the namespace corresponding to the ext_authz filter
   // name.
-  google.protobuf.Struct filter_metadata = 28;
+  google.protobuf.Struct filter_metadata = 1;
 }
 
 // Configuration for buffering the request data.

changelogs/current.yaml

@@ -244,6 +244,13 @@ 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:`logging_options <envoy_v3_api_field_extensions.filters.http.ext_authz.v3.ExtAuthz.logging_options>`
+    which when non-empty enables filter state stats for access logging. Deprecated
+    :ref:`ExtAuthz.filter_metadata <envoy_v3_api_field_extensions.filters.http.ext_authz.v3.ExtAuthz.filter_metadata>`
+    in favor of
+    :ref:`LoggingOptions.filter_metadata <envoy_v3_api_field_extensions.filters.http.ext_authz.v3.LoggingOptions.filter_metadata>`.
 - area: http3
   change: |
     ``http3_protocol_options`` in ``HttpConnectionManager`` has been upgraded to general access.

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

@@ -87,8 +87,12 @@ FilterConfig::FilterConfig(const envoy::extensions::filters::http::ext_authz::v3
       enable_dynamic_metadata_ingestion_(
           PROTOBUF_GET_WRAPPED_OR_DEFAULT(config, enable_dynamic_metadata_ingestion, true)),
       runtime_(factory_context.runtime()), http_context_(factory_context.httpContext()),
-      filter_metadata_(config.has_filter_metadata() ? absl::optional(config.filter_metadata())
-                                                    : absl::nullopt),
+      filter_metadata_(config.has_logging_options() &&
+                               config.logging_options().has_filter_metadata()
+                           ? absl::optional(config.logging_options().filter_metadata())
+                           : absl::nullopt),
+      emit_filter_state_stats_(config.has_logging_options()),
+      client_is_envoy_grpc_(config.has_grpc_service() && config.grpc_service().has_envoy_grpc()),
       filter_enabled_(config.has_filter_enabled()
                           ? absl::optional<Runtime::FractionalPercent>(
                                 Runtime::FractionalPercent(config.filter_enabled(), runtime_))
@@ -175,6 +179,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() &&
+      !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());
+  }
+
   auto&& maybe_merged_per_route_config =
       Http::Utility::getMergedPerFilterConfig<FilterConfigPerRoute>(
           decoder_callbacks_, [](FilterConfigPerRoute& cfg_base, const FilterConfigPerRoute& cfg) {
@@ -378,14 +396,39 @@ 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()));
+  }
+
+  if (!config_->clientIsEnvoyGrpc()) {
+    return;
+  }
+  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));
   }
 }
 
@@ -416,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,34 @@ 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_; }
+  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_ = cluster_info;
+  }
+  void setUpstreamHost(Upstream::HostDescriptionConstSharedPtr upstream_host) {
+    upstream_host_ = upstream_host;
+  }
 
 private:
-  const Envoy::ProtobufWkt::Struct filter_metadata_;
+  const absl::optional<Envoy::ProtobufWkt::Struct> filter_metadata_;
+  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 +173,9 @@ class FilterConfig {
 
   const absl::optional<ProtobufWkt::Struct>& filterMetadata() const { return filter_metadata_; }
 
+  bool emitFilterStateStats() const { return emit_filter_state_stats_; }
+  bool clientIsEnvoyGrpc() const { return client_is_envoy_grpc_; }
+
   bool chargeClusterResponseStats() const { return charge_cluster_response_stats_; }
 
   const Filters::Common::ExtAuthz::MatcherSharedPtr& allowedHeadersMatcher() const {
@@ -203,6 +227,8 @@ class FilterConfig {
   Http::Context& http_context_;
   LabelsMap destination_labels_;
   const absl::optional<ProtobufWkt::Struct> filter_metadata_;
+  const bool emit_filter_state_stats_;
+  const bool client_is_envoy_grpc_;
 
   const absl::optional<Runtime::FractionalPercent> filter_enabled_;
   const absl::optional<Matchers::MetadataMatcher> filter_enabled_metadata_;
@@ -337,6 +363,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 +397,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/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",
+    ],
+)