Add metrics measuring all request processing times

The cardinality of this new metric is:
buckets - 16
path + method - around 100 (the number of Actions we have)
authLevel - at most 3
success - 2

Total: 16*100*3*2 = 9,600

This is still low, especially for the value it could give in understanding our system (graphs of all endpoints, how often are they called, how long they take, how often do they fail)

Instead of "success true/false", we might want to give the actual status code. This can be a bit annoying because HttpServletResponse doesn't have a getStatus.

But it's possible, and worth considering.

-------------
Created by MOE: https://github.com/google/moe
MOE_MIGRATED_REVID=219312400

java/google/registry/request/BUILD

@@ -21,6 +21,7 @@ java_library(
         "@com_google_flogger",
         "@com_google_flogger_system_backend",
         "@com_google_guava",
+        "@com_google_monitoring_client_metrics",
         "@com_googlecode_json_simple",
         "@javax_inject",
         "@javax_servlet_api",

java/google/registry/request/RequestHandler.java

@@ -23,6 +23,8 @@ import static javax.servlet.http.HttpServletResponse.SC_NOT_FOUND;
 import com.google.common.flogger.FluentLogger;
 import google.registry.request.auth.AuthResult;
 import google.registry.request.auth.RequestAuthenticator;
+import google.registry.util.NonFinalForTesting;
+import google.registry.util.SystemClock;
 import google.registry.util.TypeUtils.TypeInstantiator;
 import java.io.IOException;
 import java.util.Optional;
@@ -30,6 +32,8 @@ import javax.annotation.Nullable;
 import javax.inject.Provider;
 import javax.servlet.http.HttpServletRequest;
 import javax.servlet.http.HttpServletResponse;
+import org.joda.time.DateTime;
+import org.joda.time.Duration;
 
 /**
  * Dagger-based request processor.
@@ -64,6 +68,10 @@ public class RequestHandler<C> {
   private final Router router;
   private final Provider<? extends RequestComponentBuilder<C>> requestComponentBuilderProvider;
   private final RequestAuthenticator requestAuthenticator;
+  private final SystemClock clock = new SystemClock();
+
+  @NonFinalForTesting
+  RequestMetrics requestMetrics = new RequestMetrics();
 
   /**
    * Constructor for subclasses to create a new request handler for a specific request component.
@@ -143,6 +151,8 @@ public class RequestHandler<C> {
         .requestModule(new RequestModule(req, rsp, authResult.get()))
         .build();
     // Apply the selected Route to the component to produce an Action instance, and run it.
+    boolean success = true;
+    DateTime startTime = clock.nowUtc();
     try {
       route.get().instantiator().apply(component).run();
       if (route.get().action().automaticallyPrintOk()) {
@@ -151,6 +161,14 @@ public class RequestHandler<C> {
       }
     } catch (HttpException e) {
       e.send(rsp);
+      success = false;
+    } finally {
+      requestMetrics.record(
+          new Duration(startTime, clock.nowUtc()),
+          path,
+          method,
+          authResult.get().authLevel(),
+          success);
     }
   }
 }

java/google/registry/request/RequestMetrics.java

@@ -0,0 +1,61 @@
+// Copyright 2018 The Nomulus Authors. All Rights Reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package google.registry.request;
+
+import static com.google.monitoring.metrics.EventMetric.DEFAULT_FITTER;
+
+import com.google.common.collect.ImmutableSet;
+import com.google.common.flogger.FluentLogger;
+import com.google.monitoring.metrics.EventMetric;
+import com.google.monitoring.metrics.LabelDescriptor;
+import com.google.monitoring.metrics.MetricRegistryImpl;
+import google.registry.request.auth.AuthLevel;
+import org.joda.time.Duration;
+
+class RequestMetrics {
+
+  private static final FluentLogger logger = FluentLogger.forEnclosingClass();
+
+  private static final ImmutableSet<LabelDescriptor> REQUEST_LABEL_DESCRIPTORS =
+      ImmutableSet.of(
+          LabelDescriptor.create("path", "target path"),
+          LabelDescriptor.create("method", "request method"),
+          LabelDescriptor.create("authLevel", "how the user was authenticated"),
+          LabelDescriptor.create("success", "whether the request succeeded"));
+
+  static final EventMetric requestDurationMetric =
+      MetricRegistryImpl.getDefault()
+          .newEventMetric(
+              "/request/processing_time",
+              "Action processing time",
+              "milliseconds",
+              REQUEST_LABEL_DESCRIPTORS,
+              DEFAULT_FITTER);
+
+  public RequestMetrics() {}
+
+  public void record(
+      Duration duration, String path, Action.Method method, AuthLevel authLevel, boolean success) {
+    requestDurationMetric.record(
+        duration.getMillis(),
+        path,
+        String.valueOf(method),
+        String.valueOf(authLevel),
+        String.valueOf(success));
+    logger.atInfo().log(
+        "Action called for path=%s, method=%s, authLevel=%s, success=%s. Took: %.3fs",
+        path, method, authLevel, success, duration.getMillis() / 1000d);
+  }
+}

javatests/google/registry/request/BUILD

@@ -17,6 +17,7 @@ java_library(
         "@com_google_appengine_api_1_0_sdk",
         "@com_google_guava",
         "@com_google_guava_testlib",
+        "@com_google_monitoring_client_contrib",
         "@com_google_truth",
         "@com_google_truth_extensions_truth_java8_extension",
         "@com_googlecode_json_simple",

javatests/google/registry/request/RequestHandlerTest.java

@@ -20,6 +20,8 @@ import static google.registry.request.Action.Method.GET;
 import static google.registry.request.Action.Method.POST;
 import static google.registry.request.auth.Auth.AUTH_INTERNAL_OR_ADMIN;
 import static google.registry.request.auth.Auth.AUTH_PUBLIC;
+import static org.mockito.Matchers.any;
+import static org.mockito.Matchers.eq;
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.verifyNoMoreInteractions;
@@ -126,7 +128,7 @@ public final class RequestHandlerTest {
   @Action(
     path = "/auth/none",
     auth = AUTH_PUBLIC,
-    method = Action.Method.GET
+    method = GET
   )
   public class AuthNoneAction extends AuthBase {
     AuthNoneAction(AuthResult authResult) {
@@ -137,7 +139,7 @@ public final class RequestHandlerTest {
   @Action(
       path = "/auth/adminUser",
       auth = AUTH_INTERNAL_OR_ADMIN,
-      method = Action.Method.GET)
+      method = GET)
   public class AuthAdminUserAction extends AuthBase {
     AuthAdminUserAction(AuthResult authResult) {
       super(authResult);
@@ -200,6 +202,7 @@ public final class RequestHandlerTest {
   private final SlothTask slothTask = mock(SlothTask.class);
   private final SafeSlothTask safeSlothTask = mock(SafeSlothTask.class);
   private final RequestAuthenticator requestAuthenticator = mock(RequestAuthenticator.class);
+  private final RequestMetrics requestMetrics = mock(RequestMetrics.class);
 
   private final Component component = new Component();
   private final StringWriter httpOutput = new StringWriter();
@@ -223,11 +226,17 @@ public final class RequestHandlerTest {
                 },
             requestAuthenticator);
     when(rsp.getWriter()).thenReturn(new PrintWriter(httpOutput));
+    handler.requestMetrics = requestMetrics;
   }
 
   @After
   public void after() {
-    verifyNoMoreInteractions(rsp, bumblebeeTask, slothTask, safeSlothTask);
+    verifyNoMoreInteractions(rsp, bumblebeeTask, slothTask, safeSlothTask, requestMetrics);
+  }
+
+  private void assertMetric(
+      String path, Action.Method method, AuthLevel authLevel, boolean success) {
+    verify(requestMetrics).record(any(), eq(path), eq(method), eq(authLevel), eq(success));
   }
 
   @Test
@@ -241,6 +250,7 @@ public final class RequestHandlerTest {
 
     verifyZeroInteractions(rsp);
     verify(bumblebeeTask).run();
+    assertMetric("/bumblebee", GET, AuthLevel.NONE, true);
   }
 
   @Test
@@ -253,6 +263,7 @@ public final class RequestHandlerTest {
     handler.handleRequest(req, rsp);
 
     verify(bumblebeeTask).run();
+    assertMetric("/bumblebee", POST, AuthLevel.NONE, true);
   }
 
   @Test
@@ -265,6 +276,7 @@ public final class RequestHandlerTest {
     handler.handleRequest(req, rsp);
 
     verify(bumblebeeTask).run();
+    assertMetric("/bumblebee/hive", GET, AuthLevel.NONE, true);
   }
 
   @Test
@@ -280,6 +292,7 @@ public final class RequestHandlerTest {
     verify(rsp).setContentType("text/plain; charset=utf-8");
     verify(rsp).getWriter();
     assertThat(httpOutput.toString()).isEqualTo("OK\n");
+    assertMetric("/sloth", POST, AuthLevel.NONE, true);
   }
 
   @Test
@@ -304,6 +317,7 @@ public final class RequestHandlerTest {
     handler.handleRequest(req, rsp);
 
     verify(rsp).sendError(503, "Set sail for fail");
+    assertMetric("/fail", GET, AuthLevel.NONE, false);
   }
 
   /** Test for a regression of the issue in b/21377705. */
@@ -318,6 +332,7 @@ public final class RequestHandlerTest {
     handler.handleRequest(req, rsp);
 
     verify(rsp).sendError(503, "Fail at construction");
+    assertMetric("/failAtConstruction", GET, AuthLevel.NONE, false);
   }
 
   @Test
@@ -389,6 +404,7 @@ public final class RequestHandlerTest {
     handler.handleRequest(req, rsp);
 
     verify(safeSlothTask).run();
+    assertMetric("/safe-sloth", POST, AuthLevel.NONE, true);
   }
 
   @Test
@@ -401,6 +417,7 @@ public final class RequestHandlerTest {
     handler.handleRequest(req, rsp);
 
     verify(safeSlothTask).run();
+    assertMetric("/safe-sloth", GET, AuthLevel.NONE, true);
   }
 
   @Test
@@ -415,6 +432,7 @@ public final class RequestHandlerTest {
     assertThat(providedAuthResult).isNotNull();
     assertThat(providedAuthResult.authLevel()).isEqualTo(AuthLevel.NONE);
     assertThat(providedAuthResult.userAuthInfo()).isEmpty();
+    assertMetric("/auth/none", GET, AuthLevel.NONE, true);
   }
 
   @Test
@@ -445,6 +463,7 @@ public final class RequestHandlerTest {
     assertThat(providedAuthResult.userAuthInfo()).isPresent();
     assertThat(providedAuthResult.userAuthInfo().get().user()).isEqualTo(testUser);
     assertThat(providedAuthResult.userAuthInfo().get().oauthTokenInfo()).isEmpty();
+    assertMetric("/auth/adminUser", GET, AuthLevel.USER, true);
   }
 
 }