Permalink
Browse files

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
  • Loading branch information...
guyben13 authored and jianglai committed Oct 30, 2018
1 parent a45d3d3 commit 57f06258d35db6e6d5630b81e6c7039d2a56e4ec
@@ -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",
@@ -23,13 +23,17 @@
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;
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 @@
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 void handleRequest(HttpServletRequest req, HttpServletResponse rsp) throw
.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 void handleRequest(HttpServletRequest req, HttpServletResponse rsp) throw
}
} catch (HttpException e) {
e.send(rsp);
success = false;
} finally {
requestMetrics.record(
new Duration(startTime, clock.nowUtc()),
path,
method,
authResult.get().authLevel(),
success);
}
}
}
@@ -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);
}
}
@@ -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",
@@ -20,6 +20,8 @@
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 void run() {
@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 void run() {
@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 Builder requestModule(RequestModule requestModule) {
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 Component build() {
},
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 void testHandleRequest_normalRequest_works() throws Exception {
verifyZeroInteractions(rsp);
verify(bumblebeeTask).run();
assertMetric("/bumblebee", GET, AuthLevel.NONE, true);
}
@Test
@@ -253,6 +263,7 @@ public void testHandleRequest_multipleMethodMappings_works() throws Exception {
handler.handleRequest(req, rsp);
verify(bumblebeeTask).run();
assertMetric("/bumblebee", POST, AuthLevel.NONE, true);
}
@Test
@@ -265,6 +276,7 @@ public void testHandleRequest_prefixEnabled_subpathsWork() throws Exception {
handler.handleRequest(req, rsp);
verify(bumblebeeTask).run();
assertMetric("/bumblebee/hive", GET, AuthLevel.NONE, true);
}
@Test
@@ -280,6 +292,7 @@ public void testHandleRequest_taskHasAutoPrintOk_printsOk() throws Exception {
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 void testHandleRequest_taskThrowsHttpException_getsHandledByHandler() thr
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 void testHandleRequest_taskThrowsHttpException_atConstructionTime_getsHan
handler.handleRequest(req, rsp);
verify(rsp).sendError(503, "Fail at construction");
assertMetric("/failAtConstruction", GET, AuthLevel.NONE, false);
}
@Test
@@ -389,6 +404,7 @@ public void testXsrfProtection_validTokenProvided_runsAction() throws Exception
handler.handleRequest(req, rsp);
verify(safeSlothTask).run();
assertMetric("/safe-sloth", POST, AuthLevel.NONE, true);
}
@Test
@@ -401,6 +417,7 @@ public void testXsrfProtection_GETMethodWithoutToken_doesntCheckToken() throws E
handler.handleRequest(req, rsp);
verify(safeSlothTask).run();
assertMetric("/safe-sloth", GET, AuthLevel.NONE, true);
}
@Test
@@ -415,6 +432,7 @@ public void testNoAuthNeeded_success() throws Exception {
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 void testAuthNeeded_success() throws Exception {
assertThat(providedAuthResult.userAuthInfo()).isPresent();
assertThat(providedAuthResult.userAuthInfo().get().user()).isEqualTo(testUser);
assertThat(providedAuthResult.userAuthInfo().get().oauthTokenInfo()).isEmpty();
assertMetric("/auth/adminUser", GET, AuthLevel.USER, true);
}
}

0 comments on commit 57f0625

Please sign in to comment.