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

Author: ptkach

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

@@ -26,6 +26,7 @@
 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;
 
 /** Handle an EPP request and response. */
@@ -55,7 +56,10 @@ public void executeEpp(
           eppController.handleEppCommand(
               sessionMetadata, credentials, eppRequestSource, isDryRun, isSuperuser, inputXmlBytes);
       response.setContentType(APPLICATION_EPP_XML);
+      final StopwatchLogger stopwatch = new StopwatchLogger();
       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,6 +29,7 @@
 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.util.Optional;
@@ -77,23 +78,32 @@ public EppOutput run(final EppMetric.Builder eppMetricBuilder) throws EppExcepti
       flowReporter.recordToLogs();
     }
     eppMetricBuilder.setCommandNameFromFlow(flowClass.getSimpleName());
+    final StopwatchLogger stopwatch = new StopwatchLogger();
+
     // 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,6 +47,7 @@
 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.util.Optional;
 import java.util.Set;
@@ -97,19 +98,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();
     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 +128,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 +145,7 @@ private EppResponse runWithoutLogging() throws EppException {
         throw e;
       }
     }
+    stopwatch.tick("LoginFlow credentials.validate");
     if (!registrar.get().isLive()) {
       throw new RegistrarAccountNotActiveException();
     }
@@ -145,17 +154,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. */

core/src/main/java/google/registry/request/auth/OidcTokenAuthenticationMechanism.java

@@ -30,6 +30,7 @@
 import google.registry.request.auth.AuthModule.RegularOidc;
 import google.registry.request.auth.AuthSettings.AuthLevel;
 import google.registry.util.RegistryEnvironment;
+import google.registry.util.StopwatchLogger;
 import jakarta.inject.Inject;
 import jakarta.servlet.http.HttpServletRequest;
 import java.util.Optional;
@@ -77,7 +78,9 @@ public AuthResult authenticate(HttpServletRequest request) {
       logger.atWarning().log("Using AuthResult %s for testing.", authResultForTesting);
       return authResultForTesting;
     }
+    final StopwatchLogger stopwatch = new StopwatchLogger();
     String rawIdToken = tokenExtractor.extract(request);
+    stopwatch.tick("OidcTokenAuthenticationMechanism tokenExtractor extracted");
     if (rawIdToken == null) {
       return AuthResult.NOT_AUTHENTICATED;
     }
@@ -99,7 +102,7 @@ public AuthResult authenticate(HttpServletRequest request) {
               ? "Raw token redacted in prod"
               : rawIdToken);
     }
-
+    stopwatch.tick("OidcTokenAuthenticationMechanism token verified");
     if (token == null) {
       return AuthResult.NOT_AUTHENTICATED;
     }
@@ -111,6 +114,7 @@ public AuthResult authenticate(HttpServletRequest request) {
     }
     Optional<User> maybeUser =
         tm().transact(() -> tm().loadByKeyIfPresent(VKey.create(User.class, email)));
+    stopwatch.tick("OidcTokenAuthenticationMechanism maybeUser loaded");
     if (maybeUser.isPresent()) {
       return AuthResult.createUser(maybeUser.get());
     }

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

@@ -0,0 +1,31 @@
+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 static final FluentLogger logger = FluentLogger.forEnclosingClass();
+  Duration threshold = Duration.ofMillis(400);
+  private final long thresholdNanos;
+  private long lastTickNanos;
+
+  public StopwatchLogger() {
+    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;
+  }
+}