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

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> 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");
+    DateTime startTime = clock.nowUtc();
+    try {
       requestHandler.handleRequest(req, rsp);
+    } finally {
+      logger.atInfo().log(
+          "Finished backend request. Latency: %.3fs",
+          (clock.nowUtc().getMillis() - startTime.getMillis()) / 1000d);
+    }
   }
 }

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",
     ],
 )

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> 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");
+    DateTime startTime = clock.nowUtc();
+    try {
       requestHandler.handleRequest(req, rsp);
+    } finally {
+      logger.atInfo().log(
+          "Finished frontend request. Latency: %.3fs",
+          (clock.nowUtc().getMillis() - startTime.getMillis()) / 1000d);
+    }
   }
 }

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",
     ],
 )

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

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",
     ],
 )

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");
+    DateTime startTime = clock.nowUtc();
+    try {
       requestHandler.handleRequest(req, rsp);
+    } finally {
+      logger.atInfo().log(
+          "Finished tools request. Latency: %.3fs",
+          (clock.nowUtc().getMillis() - startTime.getMillis()) / 1000d);
+    }
   }
 }