Add time-limited logs to Epp Login flow to test increased latency

Author: ptkach

core/src/main/java/google/registry/flows/EppRequestHandler.java

@@ -26,7 +26,9 @@
 import google.registry.model.eppoutput.EppOutput;
 import google.registry.request.Response;
 import google.registry.util.ProxyHttpHeaders;
+import google.registry.util.StopwatchLogger;
 import jakarta.inject.Inject;
+import java.time.Duration;
 
 /** Handle an EPP request and response. */
 public class EppRequestHandler {
@@ -55,7 +57,10 @@ public void executeEpp(
           eppController.handleEppCommand(
               sessionMetadata, credentials, eppRequestSource, isDryRun, isSuperuser, inputXmlBytes);
       response.setContentType(APPLICATION_EPP_XML);
+      final StopwatchLogger stopwatch = new StopwatchLogger(logger, Duration.ofMillis(400));
       byte[] eppResponseXmlBytes = marshalWithLenientRetry(eppOutput);
+      stopwatch.tick("Completed EPP output marshaling.");
+
       response.setPayload(new String(eppResponseXmlBytes, UTF_8));
       logger.atInfo().log(
           "EPP response: %s", prettyPrint(EppXmlSanitizer.sanitizeEppXml(eppResponseXmlBytes)));

core/src/main/java/google/registry/flows/FlowRunner.java

@@ -29,8 +29,10 @@
 import google.registry.monitoring.whitebox.EppMetric;
 import google.registry.persistence.PersistenceModule.TransactionIsolationLevel;
 import google.registry.persistence.transaction.JpaTransactionManager;
+import google.registry.util.StopwatchLogger;
 import jakarta.inject.Inject;
 import jakarta.inject.Provider;
+import java.time.Duration;
 import java.util.Optional;
 
 /** Run a flow, either transactionally or not, with logging and retrying as needed. */
@@ -77,23 +79,32 @@ public EppOutput run(final EppMetric.Builder eppMetricBuilder) throws EppExcepti
       flowReporter.recordToLogs();
     }
     eppMetricBuilder.setCommandNameFromFlow(flowClass.getSimpleName());
+    final StopwatchLogger stopwatch = new StopwatchLogger(logger, Duration.ofMillis(400));
+
     // We may already be in a transaction, e.g., when invoked by DeleteExpiredDomainsAction.
     if (!isTransactional || jpaTransactionManager.inTransaction()) {
+      stopwatch.tick("We're in transaction, running the flow now.");
       return EppOutput.create(flowProvider.get().run());
     }
+
+    stopwatch.tick("We're not in transaction, calling transact.");
     try {
       return jpaTransactionManager.transact(
           isolationLevelOverride.orElse(null),
           () -> {
             try {
+              stopwatch.tick("Running the flow in transaction.");
               EppOutput output = EppOutput.create(flowProvider.get().run());
+              stopwatch.tick("Completed the flow in transaction.");
               if (isDryRun) {
                 throw new DryRunException(output);
               }
               if (flowClass.equals(LoginFlow.class)) {
                 // In LoginFlow, registrarId isn't known until after the flow executes, so save
                 // it then.
+                stopwatch.tick("Login flow started setting registrar id.");
                 eppMetricBuilder.setRegistrarId(sessionMetadata.getRegistrarId());
+                stopwatch.tick("Login flow finished setting registrar id.");
               }
               return output;
             } catch (EppException e) {

core/src/main/java/google/registry/flows/session/LoginFlow.java

@@ -47,7 +47,9 @@
 import google.registry.model.eppinput.EppInput.Services;
 import google.registry.model.eppoutput.EppResponse;
 import google.registry.model.registrar.Registrar;
+import google.registry.util.StopwatchLogger;
 import jakarta.inject.Inject;
+import java.time.Duration;
 import java.util.Optional;
 import java.util.Set;
 
@@ -97,19 +99,25 @@ public final EppResponse run() throws EppException {
 
   /** Run the flow without bothering to log errors. The {@link #run} method will do that for us. */
   private EppResponse runWithoutLogging() throws EppException {
+    final StopwatchLogger stopwatch = new StopwatchLogger(logger, Duration.ofMillis(400));
     extensionManager.validate();  // There are no legal extensions for this flow.
+    stopwatch.tick("LoginFlow extension validate");
     Login login = (Login) eppInput.getCommandWrapper().getCommand();
+    stopwatch.tick("LoginFlow getCommand");
     if (!registrarId.isEmpty()) {
       throw new AlreadyLoggedInException();
     }
     Options options = login.getOptions();
+    stopwatch.tick("LoginFlow getOptions");
     if (!ProtocolDefinition.LANGUAGE.equals(options.getLanguage())) {
       throw new UnsupportedLanguageException();
     }
     Services services = login.getServices();
+    stopwatch.tick("LoginFlow getServices");
     Set<String> unsupportedObjectServices = difference(
         nullToEmpty(services.getObjectServices()),
         ProtocolDefinition.SUPPORTED_OBJECT_SERVICES);
+    stopwatch.tick("LoginFlow difference unsupportedObjectServices");
     if (!unsupportedObjectServices.isEmpty()) {
       throw new UnimplementedObjectServiceException();
     }
@@ -121,11 +129,12 @@ private EppResponse runWithoutLogging() throws EppException {
       }
       serviceExtensionUrisBuilder.add(uri);
     }
+    stopwatch.tick("LoginFlow serviceExtensionUrisBuilder");
     Optional<Registrar> registrar = Registrar.loadByRegistrarIdCached(login.getClientId());
     if (registrar.isEmpty()) {
       throw new BadRegistrarIdException(login.getClientId());
     }
-
+    stopwatch.tick("LoginFlow loadByRegistrarIdCached");
     // AuthenticationErrorExceptions will propagate up through here.
     try {
       credentials.validate(registrar.get(), login.getPassword());
@@ -137,6 +146,7 @@ private EppResponse runWithoutLogging() throws EppException {
         throw e;
       }
     }
+    stopwatch.tick("LoginFlow credentials.validate");
     if (!registrar.get().isLive()) {
       throw new RegistrarAccountNotActiveException();
     }
@@ -145,17 +155,24 @@ private EppResponse runWithoutLogging() throws EppException {
       String newPassword = login.getNewPassword().get();
       // Load fresh from database (bypassing the cache) to ensure we don't save stale data.
       Optional<Registrar> freshRegistrar = Registrar.loadByRegistrarId(login.getClientId());
+      stopwatch.tick("LoginFlow reload freshRegistrar");
       if (freshRegistrar.isEmpty()) {
         throw new BadRegistrarIdException(login.getClientId());
       }
       tm().put(freshRegistrar.get().asBuilder().setPassword(newPassword).build());
+      stopwatch.tick("LoginFlow updated password");
     }
 
     // We are in!
     sessionMetadata.resetFailedLoginAttempts();
+    stopwatch.tick("LoginFlow resetFailedLoginAttempts");
     sessionMetadata.setRegistrarId(login.getClientId());
+    stopwatch.tick("LoginFlow setRegistrarId");
     sessionMetadata.setServiceExtensionUris(serviceExtensionUrisBuilder.build());
-    return responseBuilder.setIsLoginResponse().build();
+    stopwatch.tick("LoginFlow setServiceExtensionUris");
+    EppResponse eppResponse = responseBuilder.setIsLoginResponse().build();
+    stopwatch.tick("LoginFlow eppResponse build()");
+    return eppResponse;
   }
 
   /** Registrar with this ID could not be found. */

util/src/main/java/google/registry/util/StopwatchLogger.java

@@ -0,0 +1,32 @@
+package google.registry.util;
+
+import com.google.common.flogger.FluentLogger;
+import java.time.Duration;
+
+/**
+ * A helper class to log only if the time elapsed between calls is more than a specified threshold.
+ */
+public final class StopwatchLogger {
+
+  private final FluentLogger logger;
+  private final long thresholdNanos;
+  private long lastTickNanos;
+
+  public StopwatchLogger(FluentLogger logger, Duration threshold) {
+    this.logger = logger;
+    this.thresholdNanos = threshold.toNanos();
+    this.lastTickNanos = System.nanoTime();
+  }
+
+  public void tick(String message) {
+    long currentNanos = System.nanoTime();
+    long elapsedNanos = currentNanos - lastTickNanos;
+
+    // Only log if the elapsed time is over the threshold.
+    if (elapsedNanos > thresholdNanos) {
+      logger.atInfo().log("%s (took %d ms)", message, Duration.ofNanos(elapsedNanos).toMillis());
+    }
+
+    this.lastTickNanos = currentNanos;
+  }
+}