From 6649e00df7172512258aa14028bf3f82d2876437 Mon Sep 17 00:00:00 2001 From: gbrodman Date: Wed, 29 Jan 2025 11:00:19 -0500 Subject: [PATCH] Allow for particular flows to log all SQL statements executed (#2653) We use this now for the DomainDeleteFlow in an attempt to figure out what statements it's running (cross-referencing that with PSQL's own statement logging to find slow statements). --- .../google/registry/flows/FlowModule.java | 12 +++++++ .../google/registry/flows/FlowRunner.java | 5 ++- .../flows/SqlStatementLoggingFlow.java | 24 ++++++++++++++ .../flows/domain/DomainDeleteFlow.java | 3 +- .../transaction/JpaTransactionManager.java | 12 +++++++ .../JpaTransactionManagerImpl.java | 32 +++++++++++++++++-- .../registry/flows/ResourceFlowTestCase.java | 2 +- .../flows/domain/DomainDeleteFlowTest.java | 15 +++++++++ 8 files changed, 100 insertions(+), 5 deletions(-) create mode 100644 core/src/main/java/google/registry/flows/SqlStatementLoggingFlow.java diff --git a/core/src/main/java/google/registry/flows/FlowModule.java b/core/src/main/java/google/registry/flows/FlowModule.java index 6e14afe9e..0aa634655 100644 --- a/core/src/main/java/google/registry/flows/FlowModule.java +++ b/core/src/main/java/google/registry/flows/FlowModule.java @@ -147,6 +147,13 @@ public class FlowModule { .map(IsolationLevel::value); } + @Provides + @FlowScope + @LogSqlStatements + boolean provideShouldLogSqlStatements(Class flowClass) { + return SqlStatementLoggingFlow.class.isAssignableFrom(flowClass); + } + @Provides @FlowScope @Superuser @@ -370,4 +377,9 @@ public class FlowModule { @Qualifier @Documented public @interface Transactional {} + + /** Dagger qualifier for if we should log all SQL statements in a flow. */ + @Qualifier + @Documented + public @interface LogSqlStatements {} } diff --git a/core/src/main/java/google/registry/flows/FlowRunner.java b/core/src/main/java/google/registry/flows/FlowRunner.java index cdc36b497..41c97d29c 100644 --- a/core/src/main/java/google/registry/flows/FlowRunner.java +++ b/core/src/main/java/google/registry/flows/FlowRunner.java @@ -19,6 +19,7 @@ import static google.registry.xml.XmlTransformer.prettyPrint; import com.google.common.flogger.FluentLogger; import google.registry.flows.FlowModule.DryRun; import google.registry.flows.FlowModule.InputXml; +import google.registry.flows.FlowModule.LogSqlStatements; import google.registry.flows.FlowModule.RegistrarId; import google.registry.flows.FlowModule.Superuser; import google.registry.flows.FlowModule.Transactional; @@ -49,6 +50,7 @@ public class FlowRunner { @Inject @DryRun boolean isDryRun; @Inject @Superuser boolean isSuperuser; @Inject @Transactional boolean isTransactional; + @Inject @LogSqlStatements boolean logSqlStatements; @Inject SessionMetadata sessionMetadata; @Inject Trid trid; @Inject FlowReporter flowReporter; @@ -97,7 +99,8 @@ public class FlowRunner { } catch (EppException e) { throw new EppRuntimeException(e); } - }); + }, + logSqlStatements); } catch (DryRunException e) { return e.output; } catch (EppRuntimeException e) { diff --git a/core/src/main/java/google/registry/flows/SqlStatementLoggingFlow.java b/core/src/main/java/google/registry/flows/SqlStatementLoggingFlow.java new file mode 100644 index 000000000..d5c13fbd7 --- /dev/null +++ b/core/src/main/java/google/registry/flows/SqlStatementLoggingFlow.java @@ -0,0 +1,24 @@ +// 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.flows; + +/** + * Interface for a {@link Flow} that logs its SQL statements when running transactionally. + * + *

We don't wish to log all SQL statements ever executed (that'll create too much log bloat) but + * for some flows and some occasions we may wish to know precisely what SQL statements are being + * run. + */ +public interface SqlStatementLoggingFlow extends TransactionalFlow {} diff --git a/core/src/main/java/google/registry/flows/domain/DomainDeleteFlow.java b/core/src/main/java/google/registry/flows/domain/DomainDeleteFlow.java index 4dfeabfe3..3c97cdc26 100644 --- a/core/src/main/java/google/registry/flows/domain/DomainDeleteFlow.java +++ b/core/src/main/java/google/registry/flows/domain/DomainDeleteFlow.java @@ -55,6 +55,7 @@ import google.registry.flows.FlowModule.Superuser; import google.registry.flows.FlowModule.TargetId; import google.registry.flows.MutatingFlow; import google.registry.flows.SessionMetadata; +import google.registry.flows.SqlStatementLoggingFlow; import google.registry.flows.annotations.ReportingSpec; import google.registry.flows.custom.DomainDeleteFlowCustomLogic; import google.registry.flows.custom.DomainDeleteFlowCustomLogic.AfterValidationParameters; @@ -117,7 +118,7 @@ import org.joda.time.Duration; * @error {@link DomainFlowUtils.NotAuthorizedForTldException} */ @ReportingSpec(ActivityReportField.DOMAIN_DELETE) -public final class DomainDeleteFlow implements MutatingFlow { +public final class DomainDeleteFlow implements MutatingFlow, SqlStatementLoggingFlow { private static final FluentLogger logger = FluentLogger.forEnclosingClass(); diff --git a/core/src/main/java/google/registry/persistence/transaction/JpaTransactionManager.java b/core/src/main/java/google/registry/persistence/transaction/JpaTransactionManager.java index 7410dba5c..7a7d4d5df 100644 --- a/core/src/main/java/google/registry/persistence/transaction/JpaTransactionManager.java +++ b/core/src/main/java/google/registry/persistence/transaction/JpaTransactionManager.java @@ -21,6 +21,7 @@ import jakarta.persistence.Query; import jakarta.persistence.TypedQuery; import jakarta.persistence.criteria.CriteriaQuery; import jakarta.persistence.metamodel.Metamodel; +import java.util.concurrent.Callable; /** Sub-interface of {@link TransactionManager} which defines JPA related methods. */ public interface JpaTransactionManager extends TransactionManager { @@ -92,4 +93,15 @@ public interface JpaTransactionManager extends TransactionManager { /** Return the {@link TransactionIsolationLevel} used in the current transaction. */ TransactionIsolationLevel getCurrentTransactionIsolationLevel(); + + /** Executes the work with the given isolation level, possibly logging all SQL statements used. */ + T transact( + TransactionIsolationLevel isolationLevel, Callable work, boolean logSqlStatements); + + /** + * Executes the work with the given isolation level without retry, possibly logging all SQL + * statements used. + */ + T transactNoRetry( + TransactionIsolationLevel isolationLevel, Callable work, boolean logSqlStatements); } diff --git a/core/src/main/java/google/registry/persistence/transaction/JpaTransactionManagerImpl.java b/core/src/main/java/google/registry/persistence/transaction/JpaTransactionManagerImpl.java index 16240ba1d..726159a85 100644 --- a/core/src/main/java/google/registry/persistence/transaction/JpaTransactionManagerImpl.java +++ b/core/src/main/java/google/registry/persistence/transaction/JpaTransactionManagerImpl.java @@ -78,6 +78,7 @@ import java.util.stream.Stream; import java.util.stream.StreamSupport; import javax.annotation.Nullable; import org.hibernate.Session; +import org.hibernate.SessionFactory; import org.hibernate.cfg.Environment; import org.joda.time.DateTime; @@ -89,6 +90,7 @@ public class JpaTransactionManagerImpl implements JpaTransactionManager { private static final String NESTED_TRANSACTION_MESSAGE = "Nested transaction detected. Try refactoring to avoid nested transactions. If unachievable," + " use reTransact() in nested transactions"; + private static final String SQL_STATEMENT_LOG_SENTINEL_FORMAT = "SQL_STATEMENT_LOG: %s"; // EntityManagerFactory is thread safe. private final EntityManagerFactory emf; @@ -174,6 +176,12 @@ public class JpaTransactionManagerImpl implements JpaTransactionManager { @Override public T transact(TransactionIsolationLevel isolationLevel, Callable work) { + return transact(isolationLevel, work, false); + } + + @Override + public T transact( + TransactionIsolationLevel isolationLevel, Callable work, boolean logSqlStatements) { if (inTransaction()) { if (!getHibernateAllowNestedTransactions()) { throw new IllegalStateException(NESTED_TRANSACTION_MESSAGE); @@ -186,7 +194,8 @@ public class JpaTransactionManagerImpl implements JpaTransactionManager { return transactNoRetry(isolationLevel, work); } return retrier.callWithRetry( - () -> transactNoRetry(isolationLevel, work), JpaRetries::isFailedTxnRetriable); + () -> transactNoRetry(isolationLevel, work, logSqlStatements), + JpaRetries::isFailedTxnRetriable); } @Override @@ -202,6 +211,14 @@ public class JpaTransactionManagerImpl implements JpaTransactionManager { @Override public T transactNoRetry( @Nullable TransactionIsolationLevel isolationLevel, Callable work) { + return transactNoRetry(isolationLevel, work, false); + } + + @Override + public T transactNoRetry( + @Nullable TransactionIsolationLevel isolationLevel, + Callable work, + boolean logSqlStatements) { if (inTransaction()) { // This check will no longer be necessary when the transact() method always throws // inside a nested transaction, as the only way to pass a non-null isolation level @@ -224,7 +241,18 @@ public class JpaTransactionManagerImpl implements JpaTransactionManager { } } TransactionInfo txnInfo = transactionInfo.get(); - txnInfo.entityManager = emf.createEntityManager(); + + txnInfo.entityManager = + logSqlStatements + ? emf.unwrap(SessionFactory.class) + .withOptions() + .statementInspector( + s -> { + logger.atInfo().log(SQL_STATEMENT_LOG_SENTINEL_FORMAT, s); + return s; + }) + .openSession() + : emf.createEntityManager(); if (readOnly) { // Disable Hibernate's dirty object check on flushing, it has become more aggressive in v6. txnInfo.entityManager.unwrap(Session.class).setDefaultReadOnly(true); diff --git a/core/src/test/java/google/registry/flows/ResourceFlowTestCase.java b/core/src/test/java/google/registry/flows/ResourceFlowTestCase.java index e338b70b2..933dd3f16 100644 --- a/core/src/test/java/google/registry/flows/ResourceFlowTestCase.java +++ b/core/src/test/java/google/registry/flows/ResourceFlowTestCase.java @@ -56,7 +56,7 @@ import org.junit.jupiter.api.extension.RegisterExtension; public abstract class ResourceFlowTestCase extends FlowTestCase { - private final TestLogHandler logHandler = new TestLogHandler(); + protected final TestLogHandler logHandler = new TestLogHandler(); @RegisterExtension public final TestCacheExtension testCacheExtension = diff --git a/core/src/test/java/google/registry/flows/domain/DomainDeleteFlowTest.java b/core/src/test/java/google/registry/flows/domain/DomainDeleteFlowTest.java index 0afa55d23..a336ca532 100644 --- a/core/src/test/java/google/registry/flows/domain/DomainDeleteFlowTest.java +++ b/core/src/test/java/google/registry/flows/domain/DomainDeleteFlowTest.java @@ -102,8 +102,10 @@ import google.registry.model.transfer.TransferResponse; import google.registry.model.transfer.TransferStatus; import google.registry.testing.CloudTasksHelper.TaskMatcher; import google.registry.testing.DatabaseHelper; +import google.registry.testing.LogsSubject; import java.util.Map; import java.util.Optional; +import java.util.logging.Level; import org.joda.money.Money; import org.joda.time.DateTime; import org.joda.time.Duration; @@ -1258,4 +1260,17 @@ class DomainDeleteFlowTest extends ResourceFlowTestCase