From a45d3d3bc73b7a3deaa0fba5ff8b64cf539c4408 Mon Sep 17 00:00:00 2001 From: guyben Date: Tue, 30 Oct 2018 09:06:03 -0700 Subject: [PATCH] Add a log statement at the very end of our code Having a log at the very begining of "our" code helped us find issues with App-Engine's dispatcher, where we could clearly see in the logs that "our" code started many seconds after the request came in. We now suspect there is something similar going on after the end of "our" code - where the reply is sent back many seconds after our code finished running. To make sure - we add a log statement at the very last line of "our" code, so we know exactly when it ended. ------------- Created by MOE: https://github.com/google/moe MOE_MIGRATED_REVID=219309962 --- .../registry/module/backend/BackendServlet.java | 12 +++++++++++- java/google/registry/module/frontend/BUILD | 1 + .../registry/module/frontend/FrontendServlet.java | 12 +++++++++++- java/google/registry/module/pubapi/BUILD | 1 + .../registry/module/pubapi/PubApiServlet.java | 14 ++++++++++++-- java/google/registry/module/tools/BUILD | 1 + .../google/registry/module/tools/ToolsServlet.java | 12 +++++++++++- 7 files changed, 48 insertions(+), 5 deletions(-) diff --git a/java/google/registry/module/backend/BackendServlet.java b/java/google/registry/module/backend/BackendServlet.java index 328775f13..5a7f7f4fa 100644 --- a/java/google/registry/module/backend/BackendServlet.java +++ b/java/google/registry/module/backend/BackendServlet.java @@ -18,6 +18,7 @@ import com.google.appengine.api.LifecycleManager; import com.google.common.flogger.FluentLogger; import com.google.monitoring.metrics.MetricReporter; import dagger.Lazy; +import google.registry.util.SystemClock; import java.io.IOException; import java.security.Security; import java.util.concurrent.TimeUnit; @@ -26,6 +27,7 @@ import javax.servlet.http.HttpServlet; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; import org.bouncycastle.jce.provider.BouncyCastleProvider; +import org.joda.time.DateTime; /** Servlet that should handle all requests to our "backend" App Engine module. */ public final class BackendServlet extends HttpServlet { @@ -34,6 +36,7 @@ public final class BackendServlet extends HttpServlet { private static final BackendRequestHandler requestHandler = component.requestHandler(); private static final Lazy metricReporter = component.metricReporter(); private static final FluentLogger logger = FluentLogger.forEnclosingClass(); + private static final SystemClock clock = new SystemClock(); @Override public void init() { @@ -64,6 +67,13 @@ public final class BackendServlet extends HttpServlet { @Override public void service(HttpServletRequest req, HttpServletResponse rsp) throws IOException { logger.atInfo().log("Received backend request"); - requestHandler.handleRequest(req, rsp); + DateTime startTime = clock.nowUtc(); + try { + requestHandler.handleRequest(req, rsp); + } finally { + logger.atInfo().log( + "Finished backend request. Latency: %.3fs", + (clock.nowUtc().getMillis() - startTime.getMillis()) / 1000d); + } } } diff --git a/java/google/registry/module/frontend/BUILD b/java/google/registry/module/frontend/BUILD index 589a82287..246b6c426 100644 --- a/java/google/registry/module/frontend/BUILD +++ b/java/google/registry/module/frontend/BUILD @@ -29,6 +29,7 @@ java_library( "@com_google_monitoring_client_metrics", "@javax_inject", "@javax_servlet_api", + "@joda_time", "@org_bouncycastle_bcpkix_jdk15on", ], ) diff --git a/java/google/registry/module/frontend/FrontendServlet.java b/java/google/registry/module/frontend/FrontendServlet.java index 455c410e5..3043392eb 100644 --- a/java/google/registry/module/frontend/FrontendServlet.java +++ b/java/google/registry/module/frontend/FrontendServlet.java @@ -18,6 +18,7 @@ import com.google.appengine.api.LifecycleManager; import com.google.common.flogger.FluentLogger; import com.google.monitoring.metrics.MetricReporter; import dagger.Lazy; +import google.registry.util.SystemClock; import java.io.IOException; import java.security.Security; import java.util.concurrent.TimeUnit; @@ -26,6 +27,7 @@ import javax.servlet.http.HttpServlet; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; import org.bouncycastle.jce.provider.BouncyCastleProvider; +import org.joda.time.DateTime; /** Servlet that should handle all requests to our "default" App Engine module. */ public final class FrontendServlet extends HttpServlet { @@ -34,6 +36,7 @@ public final class FrontendServlet extends HttpServlet { private static final FrontendRequestHandler requestHandler = component.requestHandler(); private static final Lazy metricReporter = component.metricReporter(); private static final FluentLogger logger = FluentLogger.forEnclosingClass(); + private static final SystemClock clock = new SystemClock(); @Override public void init() { @@ -63,6 +66,13 @@ public final class FrontendServlet extends HttpServlet { @Override public void service(HttpServletRequest req, HttpServletResponse rsp) throws IOException { logger.atInfo().log("Received frontend request"); - requestHandler.handleRequest(req, rsp); + DateTime startTime = clock.nowUtc(); + try { + requestHandler.handleRequest(req, rsp); + } finally { + logger.atInfo().log( + "Finished frontend request. Latency: %.3fs", + (clock.nowUtc().getMillis() - startTime.getMillis()) / 1000d); + } } } diff --git a/java/google/registry/module/pubapi/BUILD b/java/google/registry/module/pubapi/BUILD index e3d388311..be2d79e5e 100644 --- a/java/google/registry/module/pubapi/BUILD +++ b/java/google/registry/module/pubapi/BUILD @@ -29,6 +29,7 @@ java_library( "@com_google_monitoring_client_metrics", "@javax_inject", "@javax_servlet_api", + "@joda_time", "@org_bouncycastle_bcpkix_jdk15on", ], ) diff --git a/java/google/registry/module/pubapi/PubApiServlet.java b/java/google/registry/module/pubapi/PubApiServlet.java index 15d48d9a9..47df81a93 100644 --- a/java/google/registry/module/pubapi/PubApiServlet.java +++ b/java/google/registry/module/pubapi/PubApiServlet.java @@ -18,6 +18,7 @@ import com.google.appengine.api.LifecycleManager; import com.google.common.flogger.FluentLogger; import com.google.monitoring.metrics.MetricReporter; import dagger.Lazy; +import google.registry.util.SystemClock; import java.io.IOException; import java.security.Security; import java.util.concurrent.TimeUnit; @@ -26,6 +27,7 @@ import javax.servlet.http.HttpServlet; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; import org.bouncycastle.jce.provider.BouncyCastleProvider; +import org.joda.time.DateTime; /** Servlet that should handle all requests to our "default" App Engine module. */ public final class PubApiServlet extends HttpServlet { @@ -34,6 +36,7 @@ public final class PubApiServlet extends HttpServlet { private static final PubApiRequestHandler requestHandler = component.requestHandler(); private static final Lazy metricReporter = component.metricReporter(); private static final FluentLogger logger = FluentLogger.forEnclosingClass(); + private static final SystemClock clock = new SystemClock(); @Override public void init() { @@ -62,7 +65,14 @@ public final class PubApiServlet extends HttpServlet { @Override public void service(HttpServletRequest req, HttpServletResponse rsp) throws IOException { - logger.atInfo().log("Received frontend request"); - requestHandler.handleRequest(req, rsp); + logger.atInfo().log("Received pubapi request"); + DateTime startTime = clock.nowUtc(); + try { + requestHandler.handleRequest(req, rsp); + } finally { + logger.atInfo().log( + "Finished pubapi request. Latency: %.3fs", + (clock.nowUtc().getMillis() - startTime.getMillis()) / 1000d); + } } } diff --git a/java/google/registry/module/tools/BUILD b/java/google/registry/module/tools/BUILD index a46e09e90..6b0767ba8 100644 --- a/java/google/registry/module/tools/BUILD +++ b/java/google/registry/module/tools/BUILD @@ -32,6 +32,7 @@ java_library( "@com_google_flogger_system_backend", "@javax_inject", "@javax_servlet_api", + "@joda_time", "@org_bouncycastle_bcpkix_jdk15on", ], ) diff --git a/java/google/registry/module/tools/ToolsServlet.java b/java/google/registry/module/tools/ToolsServlet.java index 79dd085b6..5914dcdb7 100644 --- a/java/google/registry/module/tools/ToolsServlet.java +++ b/java/google/registry/module/tools/ToolsServlet.java @@ -15,12 +15,14 @@ package google.registry.module.tools; import com.google.common.flogger.FluentLogger; +import google.registry.util.SystemClock; import java.io.IOException; import java.security.Security; import javax.servlet.http.HttpServlet; import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletResponse; import org.bouncycastle.jce.provider.BouncyCastleProvider; +import org.joda.time.DateTime; /** Servlet that should handle all requests to our "tools" App Engine module. */ public final class ToolsServlet extends HttpServlet { @@ -28,6 +30,7 @@ public final class ToolsServlet extends HttpServlet { private static final ToolsComponent component = DaggerToolsComponent.create(); private static final ToolsRequestHandler requestHandler = component.requestHandler(); private static final FluentLogger logger = FluentLogger.forEnclosingClass(); + private static final SystemClock clock = new SystemClock(); @Override public void init() { @@ -37,6 +40,13 @@ public final class ToolsServlet extends HttpServlet { @Override public void service(HttpServletRequest req, HttpServletResponse rsp) throws IOException { logger.atInfo().log("Received tools request"); - requestHandler.handleRequest(req, rsp); + DateTime startTime = clock.nowUtc(); + try { + requestHandler.handleRequest(req, rsp); + } finally { + logger.atInfo().log( + "Finished tools request. Latency: %.3fs", + (clock.nowUtc().getMillis() - startTime.getMillis()) / 1000d); + } } }