ext_auth: add option to measure timeout when check request is created.

docs/root/version_history/current.rst

@@ -15,6 +15,8 @@ Minor Behavior Changes
 * build: the debug information will be generated separately to reduce target size and reduce compilation time when build in compilation mode `dbg` and `opt`. Users will need to build dwp file to debug with gdb.
 * compressor: always insert `Vary` headers for compressible resources even if it's decided not to compress a response due to incompatible `Accept-Encoding` value. The `Vary` header needs to be inserted to let a caching proxy in front of Envoy know that the requested resource still can be served with compression applied.
 * decompressor: headers-only requests were incorrectly not advertising accept-encoding when configured to do so. This is now fixed.
+* ext_authz filter: request timeout will now count from the time the check request is created, instead of when it becomes active. This makes sure that the timeout is enforced even if the ext_authz cluster's circuit breaker is engaged.
+  This behavior can be reverted by setting runtime feature ``envoy.reloadable_features.ext_authz_measure_timeout_on_check_created`` to false.
 * http: added :ref:`contains <envoy_api_msg_type.matcher.StringMatcher>` a new string matcher type which matches if the value of the string has the substring mentioned in contains matcher.
 * http: added :ref:`contains <envoy_api_msg_route.HeaderMatcher>` a new header matcher type which matches if the value of the header has the substring mentioned in contains matcher.
 * http: added :ref:`headers_to_add <envoy_v3_api_field_extensions.filters.network.http_connection_manager.v3.ResponseMapper.headers_to_add>` to :ref:`local reply mapper <config_http_conn_man_local_reply>` to allow its users to add/append/override response HTTP headers to local replies.

source/common/runtime/runtime_features.cc

@@ -68,6 +68,7 @@ constexpr const char* runtime_features[] = {
     "envoy.reloadable_features.enable_deprecated_v2_api_warning",
     "envoy.reloadable_features.enable_dns_cache_circuit_breakers",
     "envoy.reloadable_features.ext_authz_http_service_enable_case_sensitive_string_matcher",
+    "envoy.reloadable_features.ext_authz_measure_timeout_on_check_created",
     "envoy.reloadable_features.fix_upgrade_response",
     "envoy.reloadable_features.fix_wildcard_matching",
     "envoy.reloadable_features.fixed_connection_close",

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

@@ -6,11 +6,13 @@
 #include <vector>
 
 #include "envoy/common/pure.h"
+#include "envoy/event/dispatcher.h"
 #include "envoy/http/codes.h"
 #include "envoy/service/auth/v3/external_auth.pb.h"
 #include "envoy/stream_info/stream_info.h"
 #include "envoy/tracing/http_tracer.h"
 
+#include "common/runtime/runtime_features.h"
 #include "common/singleton/const_singleton.h"
 
 namespace Envoy {
@@ -98,13 +100,23 @@ class Client {
    * passed request parameters to make a permit/deny decision.
    * @param callback supplies the completion callbacks.
    *        NOTE: The callback may happen within the calling stack.
+   * @param dispatcher is the dispatcher of the current thread.
    * @param request is the proto message with the attributes of the specific payload.
    * @param parent_span source for generating an egress child span as part of the trace.
    * @param stream_info supplies the client's stream info.
    */
-  virtual void check(RequestCallbacks& callback,
+  virtual void check(RequestCallbacks& callback, Event::Dispatcher& dispatcher,
                      const envoy::service::auth::v3::CheckRequest& request,
                      Tracing::Span& parent_span, const StreamInfo::StreamInfo& stream_info) PURE;
+
+protected:
+  /**
+   * @return should we start the request time out when the check request is created.
+   */
+  static bool timeoutStartsAtCheckCreation() {
+    return Runtime::runtimeFeatureEnabled(
+        "envoy.reloadable_features.ext_authz_measure_timeout_on_check_created");
+  }
 };
 
 using ClientPtr = std::unique_ptr<Client>;

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

@@ -34,17 +34,31 @@ void GrpcClientImpl::cancel() {
   ASSERT(callbacks_ != nullptr);
   request_->cancel();
   callbacks_ = nullptr;
+  timeout_timer_.reset();
 }
 
-void GrpcClientImpl::check(RequestCallbacks& callbacks,
+void GrpcClientImpl::check(RequestCallbacks& callbacks, Event::Dispatcher& dispatcher,
                            const envoy::service::auth::v3::CheckRequest& request,
                            Tracing::Span& parent_span, const StreamInfo::StreamInfo&) {
   ASSERT(callbacks_ == nullptr);
   callbacks_ = &callbacks;
 
+  Http::AsyncClient::RequestOptions options;
+  if (timeout_.has_value()) {
+    if (timeoutStartsAtCheckCreation()) {
+      // TODO(yuval-k): We currently use dispatcher based timeout even if the underlying client is
+      // google gRPC client, which has it's own timeout mechanism. We may want to change that if
+      // using the google gRPC client timeout is more efficient.
+      timeout_timer_ = dispatcher.createTimer([this]() -> void { onTimeout(); });
+      timeout_timer_->enableTimer(timeout_.value());
+    } else {
+      // not starting timer on check creation, set the timeout on the request.
+      options.setTimeout(timeout_);
+    }
+  }
+
   ENVOY_LOG(trace, "Sending CheckRequest: {}", request.DebugString());
-  request_ = async_client_->send(service_method_, request, *this, parent_span,
-                                 Http::AsyncClient::RequestOptions().setTimeout(timeout_),
+  request_ = async_client_->send(service_method_, request, *this, parent_span, options,
                                  transport_api_version_);
 }
 
@@ -88,6 +102,18 @@ void GrpcClientImpl::onFailure(Grpc::Status::GrpcStatus status, const std::strin
   ENVOY_LOG(trace, "CheckRequest call failed with status: {}",
             Grpc::Utility::grpcStatusToString(status));
   ASSERT(status != Grpc::Status::WellKnownGrpcStatus::Ok);
+  respondFailure();
+}
+
+void GrpcClientImpl::onTimeout() {
+  ENVOY_LOG(trace, "CheckRequest timed-out");
+  ASSERT(request_ != nullptr);
+  request_->cancel();
+  // let the client know of failure:
+  respondFailure();
+}
+
+void GrpcClientImpl::respondFailure() {
   Response response{};
   response.status = CheckStatus::Error;
   response.status_code = Http::Code::Forbidden;

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

@@ -51,8 +51,9 @@ class GrpcClientImpl : public Client,
 
   // ExtAuthz::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;
+  void check(RequestCallbacks& callbacks, Event::Dispatcher& dispatcher,
+             const envoy::service::auth::v3::CheckRequest& request, Tracing::Span& parent_span,
+             const StreamInfo::StreamInfo& stream_info) override;
 
   // Grpc::AsyncRequestCallbacks
   void onCreateInitialMetadata(Http::RequestHeaderMap&) override {}
@@ -62,16 +63,20 @@ class GrpcClientImpl : public Client,
                  Tracing::Span& span) override;
 
 private:
+  void onTimeout();
+  void respondFailure();
   void toAuthzResponseHeader(
       ResponsePtr& response,
       const Protobuf::RepeatedPtrField<envoy::config::core::v3::HeaderValueOption>& headers);
+
   Grpc::AsyncClient<envoy::service::auth::v3::CheckRequest, envoy::service::auth::v3::CheckResponse>
       async_client_;
   Grpc::AsyncRequest* request_{};
   absl::optional<std::chrono::milliseconds> timeout_;
   RequestCallbacks* callbacks_{};
   const Protobuf::MethodDescriptor& service_method_;
   const envoy::config::core::v3::ApiVersion transport_api_version_;
+  Event::TimerPtr timeout_timer_;
 };
 
 using GrpcClientImplPtr = std::unique_ptr<GrpcClientImpl>;

source/extensions/filters/common/ext_authz/ext_authz_http_impl.cc

@@ -212,10 +212,11 @@ void RawHttpClientImpl::cancel() {
   ASSERT(callbacks_ != nullptr);
   request_->cancel();
   callbacks_ = nullptr;
+  timeout_timer_.reset();
 }
 
 // Client
-void RawHttpClientImpl::check(RequestCallbacks& callbacks,
+void RawHttpClientImpl::check(RequestCallbacks& callbacks, Event::Dispatcher& dispatcher,
                               const envoy::service::auth::v3::CheckRequest& request,
                               Tracing::Span& parent_span,
                               const StreamInfo::StreamInfo& stream_info) {
@@ -267,10 +268,16 @@ void RawHttpClientImpl::check(RequestCallbacks& callbacks,
     callbacks_ = nullptr;
   } else {
     auto options = Http::AsyncClient::RequestOptions()
-                       .setTimeout(config_->timeout())
                        .setParentSpan(parent_span)
                        .setChildSpanName(config_->tracingName());
 
+    if (timeoutStartsAtCheckCreation()) {
+      timeout_timer_ = dispatcher.createTimer([this]() -> void { onTimeout(); });
+      timeout_timer_->enableTimer(config_->timeout());
+    } else {
+      options.setTimeout(config_->timeout());
+    }
+
     request_ = cm_.httpAsyncClientForCluster(cluster).send(std::move(message), *this, options);
   }
 }
@@ -300,6 +307,16 @@ void RawHttpClientImpl::onBeforeFinalizeUpstreamSpan(
   }
 }
 
+void RawHttpClientImpl::onTimeout() {
+  ENVOY_LOG(trace, "CheckRequest timed-out");
+  ASSERT(request_ != nullptr);
+  request_->cancel();
+  // let the client know of failure:
+  ASSERT(callbacks_ != nullptr);
+  callbacks_->onComplete(std::make_unique<Response>(errorResponse()));
+  callbacks_ = nullptr;
+}
+
 ResponsePtr RawHttpClientImpl::toResponse(Http::ResponseMessagePtr message) {
   const uint64_t status_code = Http::Utility::getResponseStatus(message->headers());
 

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

@@ -159,8 +159,9 @@ class RawHttpClientImpl : public Client,
 
   // ExtAuthz::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;
+  void check(RequestCallbacks& callbacks, Event::Dispatcher& dispatcher,
+             const envoy::service::auth::v3::CheckRequest& request, Tracing::Span& parent_span,
+             const StreamInfo::StreamInfo& stream_info) override;
 
   // Http::AsyncClient::Callbacks
   void onSuccess(const Http::AsyncClient::Request&, Http::ResponseMessagePtr&& message) override;
@@ -170,12 +171,14 @@ class RawHttpClientImpl : public Client,
                                     const Http::ResponseHeaderMap* response_headers) override;
 
 private:
+  void onTimeout();
   ResponsePtr toResponse(Http::ResponseMessagePtr message);
 
   Upstream::ClusterManager& cm_;
   ClientConfigSharedPtr config_;
   Http::AsyncClient::Request* request_{};
   RequestCallbacks* callbacks_{};
+  Event::TimerPtr timeout_timer_;
 };
 
 } // namespace ExtAuthz

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

@@ -9,6 +9,7 @@
 #include "envoy/registry/registry.h"
 
 #include "common/protobuf/utility.h"
+#include "common/runtime/runtime_features.h"
 
 #include "extensions/filters/common/ext_authz/ext_authz_grpc_impl.h"
 #include "extensions/filters/common/ext_authz/ext_authz_http_impl.h"

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

@@ -69,7 +69,8 @@ void Filter::initiateCall(const Http::RequestHeaderMap& headers,
                                                // going to invoke check call.
   cluster_ = callbacks_->clusterInfo();
   initiating_call_ = true;
-  client_->check(*this, check_request_, callbacks_->activeSpan(), callbacks_->streamInfo());
+  client_->check(*this, callbacks_->dispatcher(), check_request_, callbacks_->activeSpan(),
+                 callbacks_->streamInfo());
   initiating_call_ = false;
 }
 

source/extensions/filters/network/ext_authz/ext_authz.cc

@@ -30,8 +30,9 @@ void Filter::callCheck() {
   config_->stats().total_.inc();
 
   calling_check_ = true;
-  client_->check(*this, check_request_, Tracing::NullSpan::instance(),
-                 filter_callbacks_->connection().streamInfo());
+  auto& connection = filter_callbacks_->connection();
+  client_->check(*this, connection.dispatcher(), check_request_, Tracing::NullSpan::instance(),
+                 connection.streamInfo());
   calling_check_ = false;
 }
 

test/extensions/filters/common/ext_authz/BUILD

@@ -32,6 +32,7 @@ envoy_cc_test(
         "//source/extensions/filters/common/ext_authz:ext_authz_grpc_lib",
         "//test/extensions/filters/common/ext_authz:ext_authz_test_common",
         "//test/mocks/tracing:tracing_mocks",
+        "//test/test_common:test_runtime_lib",
         "@envoy_api//envoy/service/auth/v2alpha:pkg_cc_proto",
         "@envoy_api//envoy/service/auth/v3:pkg_cc_proto",
         "@envoy_api//envoy/type/v3:pkg_cc_proto",
@@ -46,6 +47,7 @@ envoy_cc_test(
         "//test/extensions/filters/common/ext_authz:ext_authz_test_common",
         "//test/mocks/stream_info:stream_info_mocks",
         "//test/mocks/upstream:cluster_manager_mocks",
+        "//test/test_common:test_runtime_lib",
         "@envoy_api//envoy/extensions/filters/http/ext_authz/v3:pkg_cc_proto",
         "@envoy_api//envoy/service/auth/v3:pkg_cc_proto",
     ],