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); } }