From 57f06258d35db6e6d5630b81e6c7039d2a56e4ec Mon Sep 17 00:00:00 2001 From: guyben Date: Tue, 30 Oct 2018 09:23:55 -0700 Subject: [PATCH] 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 | 1 + .../registry/request/RequestHandler.java | 18 ++++++ .../registry/request/RequestMetrics.java | 61 +++++++++++++++++++ javatests/google/registry/request/BUILD | 1 + .../registry/request/RequestHandlerTest.java | 25 +++++++- 5 files changed, 103 insertions(+), 3 deletions(-) create mode 100644 java/google/registry/request/RequestMetrics.java diff --git a/java/google/registry/request/BUILD b/java/google/registry/request/BUILD index 3b9eee131..870cb29f9 100644 --- a/java/google/registry/request/BUILD +++ b/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", diff --git a/java/google/registry/request/RequestHandler.java b/java/google/registry/request/RequestHandler.java index c2748faa2..a2f8421fb 100644 --- a/java/google/registry/request/RequestHandler.java +++ b/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 { private final Router router; private final Provider> 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 { .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 { } } catch (HttpException e) { e.send(rsp); + success = false; + } finally { + requestMetrics.record( + new Duration(startTime, clock.nowUtc()), + path, + method, + authResult.get().authLevel(), + success); } } } diff --git a/java/google/registry/request/RequestMetrics.java b/java/google/registry/request/RequestMetrics.java new file mode 100644 index 000000000..e7f88d954 --- /dev/null +++ b/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 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); + } +} diff --git a/javatests/google/registry/request/BUILD b/javatests/google/registry/request/BUILD index 270178661..e4ed50602 100644 --- a/javatests/google/registry/request/BUILD +++ b/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", diff --git a/javatests/google/registry/request/RequestHandlerTest.java b/javatests/google/registry/request/RequestHandlerTest.java index 9a3bdb0aa..93fb43de8 100644 --- a/javatests/google/registry/request/RequestHandlerTest.java +++ b/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); } }