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

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

@@ -133,7 +133,8 @@ The HTTP filter outputs statistics in the *cluster.<route target cluster>.ext_au
   :widths: 1, 1, 2
 
   ok, Counter, Total responses from the filter.
-  error, Counter, Total errors contacting the external service.
+  error, Counter, Total errors (including timeouts) contacting the external service.
+  timeout, Counter, Total timeouts contacting the external service (only counted when timeout is measured when check request is created).
   denied, Counter, Total responses from the authorizations service that were to deny the traffic.
   failure_mode_allowed, Counter, "Total requests that were error(s) but were allowed through because
   of failure_mode_allow set to true."

docs/root/version_history/current.rst

@@ -15,6 +15,9 @@ 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. When enabled, a new `ext_authz.timeout` stat is counted when timeout occurs. See :ref:`stats
+  // <config_http_filters_ext_authz_stats>`.
 * 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 {
@@ -43,12 +45,27 @@ enum class CheckStatus {
   Denied
 };
 
+/**
+ * Possible error kind for Error status..
+ */
+enum class ErrorKind {
+  // Other error.
+  Other,
+  // The request timed out. This will only be set if the timeout is measure when the check request
+  // was created.
+  Timedout,
+};
+
 /**
  * Authorization response object for a RequestCallback.
  */
 struct Response {
   // Call status.
   CheckStatus status;
+
+  // In case status is Error, this will contain the kind of error that occurred.
+  ErrorKind error_kind{ErrorKind::Other};
+
   // A set of HTTP headers returned by the authorization server, that will be optionally appended
   // to the request to the upstream server.
   Http::HeaderVector headers_to_append;
@@ -98,13 +115,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 in
+      // the future if the implementations converge.
+      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_);
 }
 
@@ -81,16 +95,31 @@ void GrpcClientImpl::onSuccess(std::unique_ptr<envoy::service::auth::v3::CheckRe
 
   callbacks_->onComplete(std::move(authz_response));
   callbacks_ = nullptr;
+  timeout_timer_.reset();
 }
 
 void GrpcClientImpl::onFailure(Grpc::Status::GrpcStatus status, const std::string&,
                                Tracing::Span&) {
   ENVOY_LOG(trace, "CheckRequest call failed with status: {}",
             Grpc::Utility::grpcStatusToString(status));
   ASSERT(status != Grpc::Status::WellKnownGrpcStatus::Ok);
+  timeout_timer_.reset();
+  respondFailure(ErrorKind::Other);
+}
+
+void GrpcClientImpl::onTimeout() {
+  ENVOY_LOG(trace, "CheckRequest timed-out");
+  ASSERT(request_ != nullptr);
+  request_->cancel();
+  // let the client know of failure:
+  respondFailure(ErrorKind::Timedout);
+}
+
+void GrpcClientImpl::respondFailure(ErrorKind kind) {
   Response response{};
   response.status = CheckStatus::Error;
   response.status_code = Http::Code::Forbidden;
+  response.error_kind = kind;
   callbacks_->onComplete(std::make_unique<Response>(response));
   callbacks_ = nullptr;
 }

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(Filters::Common::ExtAuthz::ErrorKind kind);
   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

@@ -32,9 +32,9 @@ const Http::HeaderMap& lengthZeroHeader() {
 // Static response used for creating authorization ERROR responses.
 const Response& errorResponse() {
   CONSTRUCT_ON_FIRST_USE(Response,
-                         Response{CheckStatus::Error, Http::HeaderVector{}, Http::HeaderVector{},
-                                  Http::HeaderVector{}, EMPTY_STRING, Http::Code::Forbidden,
-                                  ProtobufWkt::Struct{}});
+                         Response{CheckStatus::Error, ErrorKind::Other, Http::HeaderVector{},
+                                  Http::HeaderVector{}, Http::HeaderVector{}, EMPTY_STRING,
+                                  Http::Code::Forbidden, ProtobufWkt::Struct{}});
 }
 
 // SuccessResponse used for creating either DENIED or OK authorization responses.
@@ -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,23 +268,31 @@ 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);
   }
 }
 
 void RawHttpClientImpl::onSuccess(const Http::AsyncClient::Request&,
                                   Http::ResponseMessagePtr&& message) {
+  timeout_timer_.reset();
   callbacks_->onComplete(toResponse(std::move(message)));
   callbacks_ = nullptr;
 }
 
 void RawHttpClientImpl::onFailure(const Http::AsyncClient::Request&,
                                   Http::AsyncClient::FailureReason reason) {
   ASSERT(reason == Http::AsyncClient::FailureReason::Reset);
+  timeout_timer_.reset();
   callbacks_->onComplete(std::make_unique<Response>(errorResponse()));
   callbacks_ = nullptr;
 }
@@ -300,6 +309,18 @@ 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);
+  Response response = errorResponse();
+  response.error_kind = ErrorKind::Timedout;
+  callbacks_->onComplete(std::make_unique<Response>(response));
+  callbacks_ = nullptr;
+}
+
 ResponsePtr RawHttpClientImpl::toResponse(Http::ResponseMessagePtr message) {
   const uint64_t status_code = Http::Utility::getResponseStatus(message->headers());
 
@@ -314,18 +335,19 @@ ResponsePtr RawHttpClientImpl::toResponse(Http::ResponseMessagePtr message) {
   if (status_code == enumToInt(Http::Code::OK)) {
     SuccessResponse ok{message->headers(), config_->upstreamHeaderMatchers(),
                        config_->upstreamHeaderToAppendMatchers(),
-                       Response{CheckStatus::OK, Http::HeaderVector{}, Http::HeaderVector{},
-                                Http::HeaderVector{}, EMPTY_STRING, Http::Code::OK,
-                                ProtobufWkt::Struct{}}};
+                       Response{CheckStatus::OK, ErrorKind::Other, Http::HeaderVector{},
+                                Http::HeaderVector{}, Http::HeaderVector{}, EMPTY_STRING,
+                                Http::Code::OK, ProtobufWkt::Struct{}}};
     return std::move(ok.response_);
   }
 
   // Create a Denied authorization response.
   SuccessResponse denied{message->headers(), config_->clientHeaderMatchers(),
                          config_->upstreamHeaderToAppendMatchers(),
-                         Response{CheckStatus::Denied, Http::HeaderVector{}, Http::HeaderVector{},
-                                  Http::HeaderVector{}, message->bodyAsString(),
-                                  static_cast<Http::Code>(status_code), ProtobufWkt::Struct{}}};
+                         Response{CheckStatus::Denied, ErrorKind::Other, Http::HeaderVector{},
+                                  Http::HeaderVector{}, Http::HeaderVector{},
+                                  message->bodyAsString(), static_cast<Http::Code>(status_code),
+                                  ProtobufWkt::Struct{}}};
   return std::move(denied.response_);
 }
 

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;
 }
 
@@ -258,8 +259,14 @@ void Filter::onComplete(Filters::Common::ExtAuthz::ResponsePtr&& response) {
   case CheckStatus::Error: {
     if (cluster_) {
       config_->incCounter(cluster_->statsScope(), config_->ext_authz_error_);
+      if (response->error_kind == Filters::Common::ExtAuthz::ErrorKind::Timedout) {
+        config_->incCounter(cluster_->statsScope(), config_->ext_authz_timeout_);
+      }
     }
     stats_.error_.inc();
+    if (response->error_kind == Filters::Common::ExtAuthz::ErrorKind::Timedout) {
+      stats_.timeout_.inc();
+    }
     if (config_->failureModeAllow()) {
       ENVOY_STREAM_LOG(trace, "ext_authz filter allowed the request with error", *callbacks_);
       stats_.failure_mode_allowed_.inc();

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

@@ -38,6 +38,7 @@ namespace ExtAuthz {
   COUNTER(ok)                                                                                      \
   COUNTER(denied)                                                                                  \
   COUNTER(error)                                                                                   \
+  COUNTER(timeout)                                                                                 \
   COUNTER(failure_mode_allowed)
 
 /**
@@ -76,6 +77,7 @@ class FilterConfig {
         stats_(generateStats(stats_prefix, scope)), ext_authz_ok_(pool_.add("ext_authz.ok")),
         ext_authz_denied_(pool_.add("ext_authz.denied")),
         ext_authz_error_(pool_.add("ext_authz.error")),
+        ext_authz_timeout_(pool_.add("ext_authz.timeout")),
         ext_authz_failure_mode_allowed_(pool_.add("ext_authz.failure_mode_allowed")) {}
 
   bool allowPartialMessage() const { return allow_partial_message_; }
@@ -154,6 +156,7 @@ class FilterConfig {
   const Stats::StatName ext_authz_ok_;
   const Stats::StatName ext_authz_denied_;
   const Stats::StatName ext_authz_error_;
+  const Stats::StatName ext_authz_timeout_;
   const Stats::StatName ext_authz_failure_mode_allowed_;
 };