From d9c46170dd50caef7ab1eff34015f543911d84ad Mon Sep 17 00:00:00 2001 From: Pavlo Tkach <3469726+ptkach@users.noreply.github.com> Date: Fri, 22 Aug 2025 16:30:53 -0400 Subject: [PATCH] Add time-limited logs to Epp Login flow to test increased latency (#2810) --- .../registry/flows/EppRequestHandler.java | 4 ++ .../google/registry/flows/FlowRunner.java | 10 +++++ .../registry/flows/session/LoginFlow.java | 20 ++++++++- .../OidcTokenAuthenticationMechanism.java | 6 ++- .../google/registry/util/StopwatchLogger.java | 45 +++++++++++++++++++ 5 files changed, 82 insertions(+), 3 deletions(-) create mode 100644 util/src/main/java/google/registry/util/StopwatchLogger.java diff --git a/core/src/main/java/google/registry/flows/EppRequestHandler.java b/core/src/main/java/google/registry/flows/EppRequestHandler.java index 7784e63ea..e38e82ed7 100644 --- a/core/src/main/java/google/registry/flows/EppRequestHandler.java +++ b/core/src/main/java/google/registry/flows/EppRequestHandler.java @@ -26,6 +26,7 @@ import com.google.common.net.MediaType; 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 class EppRequestHandler { 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))); diff --git a/core/src/main/java/google/registry/flows/FlowRunner.java b/core/src/main/java/google/registry/flows/FlowRunner.java index f634afa21..f1e6c202b 100644 --- a/core/src/main/java/google/registry/flows/FlowRunner.java +++ b/core/src/main/java/google/registry/flows/FlowRunner.java @@ -29,6 +29,7 @@ import google.registry.model.eppoutput.EppOutput; 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 class FlowRunner { 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) { diff --git a/core/src/main/java/google/registry/flows/session/LoginFlow.java b/core/src/main/java/google/registry/flows/session/LoginFlow.java index 50ef6bce6..406c3d2b1 100644 --- a/core/src/main/java/google/registry/flows/session/LoginFlow.java +++ b/core/src/main/java/google/registry/flows/session/LoginFlow.java @@ -47,6 +47,7 @@ import google.registry.model.eppinput.EppInput.Options; 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 class LoginFlow implements MutatingFlow { /** 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 unsupportedObjectServices = difference( nullToEmpty(services.getObjectServices()), ProtocolDefinition.SUPPORTED_OBJECT_SERVICES); + stopwatch.tick("LoginFlow difference unsupportedObjectServices"); if (!unsupportedObjectServices.isEmpty()) { throw new UnimplementedObjectServiceException(); } @@ -121,11 +128,12 @@ public class LoginFlow implements MutatingFlow { } serviceExtensionUrisBuilder.add(uri); } + stopwatch.tick("LoginFlow serviceExtensionUrisBuilder"); Optional 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 @@ public class LoginFlow implements MutatingFlow { throw e; } } + stopwatch.tick("LoginFlow credentials.validate"); if (!registrar.get().isLive()) { throw new RegistrarAccountNotActiveException(); } @@ -145,17 +154,24 @@ public class LoginFlow implements MutatingFlow { String newPassword = login.getNewPassword().get(); // Load fresh from database (bypassing the cache) to ensure we don't save stale data. Optional 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. */ diff --git a/core/src/main/java/google/registry/request/auth/OidcTokenAuthenticationMechanism.java b/core/src/main/java/google/registry/request/auth/OidcTokenAuthenticationMechanism.java index d6c05dabe..53dea42f0 100644 --- a/core/src/main/java/google/registry/request/auth/OidcTokenAuthenticationMechanism.java +++ b/core/src/main/java/google/registry/request/auth/OidcTokenAuthenticationMechanism.java @@ -30,6 +30,7 @@ import google.registry.request.auth.AuthModule.IapOidc; 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 abstract class OidcTokenAuthenticationMechanism implements Authentication 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 abstract class OidcTokenAuthenticationMechanism implements Authentication ? "Raw token redacted in prod" : rawIdToken); } - + stopwatch.tick("OidcTokenAuthenticationMechanism token verified"); if (token == null) { return AuthResult.NOT_AUTHENTICATED; } @@ -111,6 +114,7 @@ public abstract class OidcTokenAuthenticationMechanism implements Authentication } Optional maybeUser = tm().transact(() -> tm().loadByKeyIfPresent(VKey.create(User.class, email))); + stopwatch.tick("OidcTokenAuthenticationMechanism maybeUser loaded"); if (maybeUser.isPresent()) { return AuthResult.createUser(maybeUser.get()); } diff --git a/util/src/main/java/google/registry/util/StopwatchLogger.java b/util/src/main/java/google/registry/util/StopwatchLogger.java new file mode 100644 index 000000000..58893622d --- /dev/null +++ b/util/src/main/java/google/registry/util/StopwatchLogger.java @@ -0,0 +1,45 @@ +// Copyright 2025 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.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; + } +}