fix(web): Emit a controller.invocations metric whenever a request i…

…s limited or shed (#1378)

Just closing out some small todo's as part of converting these two into filters that
run ahead of the security filter chain and endpoint interceptors.

In the future I could see collapsing what `MetricsInterceptor` is currently doing into
the `RequestLoggingFilter`. Given that these two are used differently between `gate`
and the other internal services, I've left that as a later exercise.

Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>

gate-web/src/main/groovy/com/netflix/spinnaker/gate/filters/RequestSheddingFilter.java

@@ -15,13 +15,15 @@
  */
 package com.netflix.spinnaker.gate.filters;
 
+import static com.netflix.spinnaker.gate.filters.RequestLoggingFilter.REQUEST_START_TIME;
 import static org.springframework.http.HttpStatus.SERVICE_UNAVAILABLE;
 
 import com.google.common.annotations.VisibleForTesting;
 import com.google.common.base.Splitter;
 import com.google.common.base.Strings;
 import com.netflix.spectator.api.Id;
 import com.netflix.spectator.api.Registry;
+import com.netflix.spectator.api.histogram.PercentileTimer;
 import com.netflix.spinnaker.kork.dynamicconfig.DynamicConfigService;
 import java.io.IOException;
 import java.time.Duration;
@@ -44,6 +46,7 @@
 import javax.servlet.http.HttpServletResponse;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.slf4j.MDC;
 
 /**
  * A request interceptor for shedding low-priority requests from Deck.
@@ -82,6 +85,7 @@ public class RequestSheddingFilter extends HttpFilter {
   private final ScheduledExecutorService executorService;
 
   private final Id requestsId;
+  private final Id controllerInvocationsId;
 
   private final CopyOnWriteArrayList<Pattern> pathPatterns = new CopyOnWriteArrayList<>();
 
@@ -105,6 +109,16 @@ public RequestSheddingFilter(DynamicConfigService configService, Registry regist
     } else {
       this.executorService = null;
     }
+
+    this.controllerInvocationsId =
+        registry
+            .createId("controller.invocations")
+            .withTag("controller", "unknown")
+            .withTag("method", "unknown")
+            .withTag("status", "5xx")
+            .withTag("statusCode", "503")
+            .withTag("success", "false")
+            .withTag("cause", "RequestSheddingFilter");
   }
 
   @PreDestroy
@@ -136,6 +150,16 @@ protected void doFilter(
         response
             .getWriter()
             .write("{\"message\": \"Low priority requests are not currently being accepted\"}");
+
+        Optional.ofNullable(MDC.get(REQUEST_START_TIME))
+            .ifPresent(
+                startTime -> {
+                  PercentileTimer.get(registry, controllerInvocationsId)
+                      .record(
+                          System.currentTimeMillis() - Long.parseLong(startTime),
+                          TimeUnit.MILLISECONDS);
+                });
+
         return;
       }
       log.debug("Dice roll prevented low priority request shedding: {}", request.getRequestURI());

gate-web/src/main/groovy/com/netflix/spinnaker/gate/ratelimit/RateLimitingFilter.java

@@ -15,20 +15,24 @@
  */
 package com.netflix.spinnaker.gate.ratelimit;
 
+import static com.netflix.spinnaker.gate.filters.RequestLoggingFilter.REQUEST_START_TIME;
 import static net.logstash.logback.argument.StructuredArguments.value;
 import static org.springframework.http.HttpStatus.TOO_MANY_REQUESTS;
 
 import com.netflix.spectator.api.BasicTag;
 import com.netflix.spectator.api.Counter;
+import com.netflix.spectator.api.Id;
 import com.netflix.spectator.api.Registry;
 import com.netflix.spectator.api.Tag;
+import com.netflix.spectator.api.histogram.PercentileTimer;
 import com.netflix.spinnaker.gate.security.x509.X509AuthenticationUserDetailsService;
 import com.netflix.spinnaker.security.User;
 import java.io.IOException;
 import java.security.cert.X509Certificate;
 import java.time.ZonedDateTime;
 import java.util.Collections;
 import java.util.Optional;
+import java.util.concurrent.TimeUnit;
 import javax.servlet.FilterChain;
 import javax.servlet.ServletException;
 import javax.servlet.http.HttpFilter;
@@ -53,8 +57,9 @@ public class RateLimitingFilter extends HttpFilter {
   private RateLimitPrincipalProvider rateLimitPrincipalProvider;
   private Optional<X509AuthenticationUserDetailsService> x509AuthenticationUserDetailsService;
 
-  private Counter throttlingCounter;
-  private Counter learningThrottlingCounter;
+  private final Counter throttlingCounter;
+  private final Counter learningThrottlingCounter;
+  private final Id controllerInvocationsId;
 
   public RateLimitingFilter(
       RateLimiter rateLimiter,
@@ -68,16 +73,36 @@ public RateLimitingFilter(
 
     throttlingCounter = registry.counter("rateLimit.throttling");
     learningThrottlingCounter = registry.counter("rateLimit.throttlingLearning");
+
+    this.controllerInvocationsId =
+        registry
+            .createId("controller.invocations")
+            .withTag("controller", "unknown")
+            .withTag("method", "unknown")
+            .withTag("status", "4xx")
+            .withTag("statusCode", "429")
+            .withTag("success", "false")
+            .withTag("cause", "RateLimitingFilter");
   }
 
   @Override
   protected void doFilter(
       HttpServletRequest request, HttpServletResponse response, FilterChain chain)
       throws IOException, ServletException {
     try {
-      if (preHandle(request, response)) {
-        chain.doFilter(request, response);
+      if (!preHandle(request, response)) {
+        Optional.ofNullable(MDC.get(REQUEST_START_TIME))
+            .ifPresent(
+                startTime -> {
+                  PercentileTimer.get(registry, controllerInvocationsId)
+                      .record(
+                          System.currentTimeMillis() - Long.parseLong(startTime),
+                          TimeUnit.MILLISECONDS);
+                });
+        return;
       }
+
+      chain.doFilter(request, response);
     } finally {
       postHandle(request, response);
     }