1
0
mirror of https://github.com/google/nomulus synced 2026-01-04 04:04:22 +00:00

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).
This commit is contained in:
gbrodman
2025-01-29 11:00:19 -05:00
committed by GitHub
parent 2ceb52a7c4
commit 6649e00df7
8 changed files with 100 additions and 5 deletions

View File

@@ -147,6 +147,13 @@ public class FlowModule {
.map(IsolationLevel::value);
}
@Provides
@FlowScope
@LogSqlStatements
boolean provideShouldLogSqlStatements(Class<? extends Flow> 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 {}
}

View File

@@ -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) {

View File

@@ -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.
*
* <p>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 {}

View File

@@ -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();

View File

@@ -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> T transact(
TransactionIsolationLevel isolationLevel, Callable<T> work, boolean logSqlStatements);
/**
* Executes the work with the given isolation level without retry, possibly logging all SQL
* statements used.
*/
<T> T transactNoRetry(
TransactionIsolationLevel isolationLevel, Callable<T> work, boolean logSqlStatements);
}

View File

@@ -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> T transact(TransactionIsolationLevel isolationLevel, Callable<T> work) {
return transact(isolationLevel, work, false);
}
@Override
public <T> T transact(
TransactionIsolationLevel isolationLevel, Callable<T> 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> T transactNoRetry(
@Nullable TransactionIsolationLevel isolationLevel, Callable<T> work) {
return transactNoRetry(isolationLevel, work, false);
}
@Override
public <T> T transactNoRetry(
@Nullable TransactionIsolationLevel isolationLevel,
Callable<T> 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);

View File

@@ -56,7 +56,7 @@ import org.junit.jupiter.api.extension.RegisterExtension;
public abstract class ResourceFlowTestCase<F extends Flow, R extends EppResource>
extends FlowTestCase<F> {
private final TestLogHandler logHandler = new TestLogHandler();
protected final TestLogHandler logHandler = new TestLogHandler();
@RegisterExtension
public final TestCacheExtension testCacheExtension =

View File

@@ -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<DomainDeleteFlow, Domain
runFlowAssertResponse(loadFile("domain_delete_response_pending.xml"));
assertPollMessages();
}
@Test
void testSuccess_logsSqlStatements() throws Exception {
setUpSuccessfulTest();
runFlowAssertResponse(loadFile("domain_delete_response_pending.xml"));
LogsSubject.assertAboutLogs()
.that(logHandler)
.hasLogAtLevelWithMessage(
Level.INFO,
"SQL_STATEMENT_LOG: insert into \"DomainHistory\" (history_by_superuser,"
+ "history_registrar_id,history_modification_time,history_other_registrar_id,"
+ "history_period_unit,history_period_value,history_reason,history");
}
}