Skip to content

Commit 6649e00

Browse files
authored
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).
1 parent 2ceb52a commit 6649e00

File tree

8 files changed

+100
-5
lines changed

8 files changed

+100
-5
lines changed

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

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -147,6 +147,13 @@ Optional<TransactionIsolationLevel> provideIsolationLevelOverride(
147147
.map(IsolationLevel::value);
148148
}
149149

150+
@Provides
151+
@FlowScope
152+
@LogSqlStatements
153+
boolean provideShouldLogSqlStatements(Class<? extends Flow> flowClass) {
154+
return SqlStatementLoggingFlow.class.isAssignableFrom(flowClass);
155+
}
156+
150157
@Provides
151158
@FlowScope
152159
@Superuser
@@ -370,4 +377,9 @@ static class EppExceptionInProviderException extends RuntimeException {
370377
@Qualifier
371378
@Documented
372379
public @interface Transactional {}
380+
381+
/** Dagger qualifier for if we should log all SQL statements in a flow. */
382+
@Qualifier
383+
@Documented
384+
public @interface LogSqlStatements {}
373385
}

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

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@
1919
import com.google.common.flogger.FluentLogger;
2020
import google.registry.flows.FlowModule.DryRun;
2121
import google.registry.flows.FlowModule.InputXml;
22+
import google.registry.flows.FlowModule.LogSqlStatements;
2223
import google.registry.flows.FlowModule.RegistrarId;
2324
import google.registry.flows.FlowModule.Superuser;
2425
import google.registry.flows.FlowModule.Transactional;
@@ -49,6 +50,7 @@ public class FlowRunner {
4950
@Inject @DryRun boolean isDryRun;
5051
@Inject @Superuser boolean isSuperuser;
5152
@Inject @Transactional boolean isTransactional;
53+
@Inject @LogSqlStatements boolean logSqlStatements;
5254
@Inject SessionMetadata sessionMetadata;
5355
@Inject Trid trid;
5456
@Inject FlowReporter flowReporter;
@@ -97,7 +99,8 @@ public EppOutput run(final EppMetric.Builder eppMetricBuilder) throws EppExcepti
9799
} catch (EppException e) {
98100
throw new EppRuntimeException(e);
99101
}
100-
});
102+
},
103+
logSqlStatements);
101104
} catch (DryRunException e) {
102105
return e.output;
103106
} catch (EppRuntimeException e) {
Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,24 @@
1+
// Copyright 2025 The Nomulus Authors. All Rights Reserved.
2+
//
3+
// Licensed under the Apache License, Version 2.0 (the "License");
4+
// you may not use this file except in compliance with the License.
5+
// You may obtain a copy of the License at
6+
//
7+
// http://www.apache.org/licenses/LICENSE-2.0
8+
//
9+
// Unless required by applicable law or agreed to in writing, software
10+
// distributed under the License is distributed on an "AS IS" BASIS,
11+
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12+
// See the License for the specific language governing permissions and
13+
// limitations under the License.
14+
15+
package google.registry.flows;
16+
17+
/**
18+
* Interface for a {@link Flow} that logs its SQL statements when running transactionally.
19+
*
20+
* <p>We don't wish to log all SQL statements ever executed (that'll create too much log bloat) but
21+
* for some flows and some occasions we may wish to know precisely what SQL statements are being
22+
* run.
23+
*/
24+
public interface SqlStatementLoggingFlow extends TransactionalFlow {}

core/src/main/java/google/registry/flows/domain/DomainDeleteFlow.java

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -55,6 +55,7 @@
5555
import google.registry.flows.FlowModule.TargetId;
5656
import google.registry.flows.MutatingFlow;
5757
import google.registry.flows.SessionMetadata;
58+
import google.registry.flows.SqlStatementLoggingFlow;
5859
import google.registry.flows.annotations.ReportingSpec;
5960
import google.registry.flows.custom.DomainDeleteFlowCustomLogic;
6061
import google.registry.flows.custom.DomainDeleteFlowCustomLogic.AfterValidationParameters;
@@ -117,7 +118,7 @@
117118
* @error {@link DomainFlowUtils.NotAuthorizedForTldException}
118119
*/
119120
@ReportingSpec(ActivityReportField.DOMAIN_DELETE)
120-
public final class DomainDeleteFlow implements MutatingFlow {
121+
public final class DomainDeleteFlow implements MutatingFlow, SqlStatementLoggingFlow {
121122

122123
private static final FluentLogger logger = FluentLogger.forEnclosingClass();
123124

core/src/main/java/google/registry/persistence/transaction/JpaTransactionManager.java

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@
2121
import jakarta.persistence.TypedQuery;
2222
import jakarta.persistence.criteria.CriteriaQuery;
2323
import jakarta.persistence.metamodel.Metamodel;
24+
import java.util.concurrent.Callable;
2425

2526
/** Sub-interface of {@link TransactionManager} which defines JPA related methods. */
2627
public interface JpaTransactionManager extends TransactionManager {
@@ -92,4 +93,15 @@ static Query setQueryFetchSize(Query query, int fetchSize) {
9293

9394
/** Return the {@link TransactionIsolationLevel} used in the current transaction. */
9495
TransactionIsolationLevel getCurrentTransactionIsolationLevel();
96+
97+
/** Executes the work with the given isolation level, possibly logging all SQL statements used. */
98+
<T> T transact(
99+
TransactionIsolationLevel isolationLevel, Callable<T> work, boolean logSqlStatements);
100+
101+
/**
102+
* Executes the work with the given isolation level without retry, possibly logging all SQL
103+
* statements used.
104+
*/
105+
<T> T transactNoRetry(
106+
TransactionIsolationLevel isolationLevel, Callable<T> work, boolean logSqlStatements);
95107
}

core/src/main/java/google/registry/persistence/transaction/JpaTransactionManagerImpl.java

Lines changed: 30 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -78,6 +78,7 @@
7878
import java.util.stream.StreamSupport;
7979
import javax.annotation.Nullable;
8080
import org.hibernate.Session;
81+
import org.hibernate.SessionFactory;
8182
import org.hibernate.cfg.Environment;
8283
import org.joda.time.DateTime;
8384

@@ -89,6 +90,7 @@ public class JpaTransactionManagerImpl implements JpaTransactionManager {
8990
private static final String NESTED_TRANSACTION_MESSAGE =
9091
"Nested transaction detected. Try refactoring to avoid nested transactions. If unachievable,"
9192
+ " use reTransact() in nested transactions";
93+
private static final String SQL_STATEMENT_LOG_SENTINEL_FORMAT = "SQL_STATEMENT_LOG: %s";
9294

9395
// EntityManagerFactory is thread safe.
9496
private final EntityManagerFactory emf;
@@ -174,6 +176,12 @@ public <T> T reTransact(Callable<T> work) {
174176

175177
@Override
176178
public <T> T transact(TransactionIsolationLevel isolationLevel, Callable<T> work) {
179+
return transact(isolationLevel, work, false);
180+
}
181+
182+
@Override
183+
public <T> T transact(
184+
TransactionIsolationLevel isolationLevel, Callable<T> work, boolean logSqlStatements) {
177185
if (inTransaction()) {
178186
if (!getHibernateAllowNestedTransactions()) {
179187
throw new IllegalStateException(NESTED_TRANSACTION_MESSAGE);
@@ -186,7 +194,8 @@ public <T> T transact(TransactionIsolationLevel isolationLevel, Callable<T> work
186194
return transactNoRetry(isolationLevel, work);
187195
}
188196
return retrier.callWithRetry(
189-
() -> transactNoRetry(isolationLevel, work), JpaRetries::isFailedTxnRetriable);
197+
() -> transactNoRetry(isolationLevel, work, logSqlStatements),
198+
JpaRetries::isFailedTxnRetriable);
190199
}
191200

192201
@Override
@@ -202,6 +211,14 @@ public <T> T transactNoRetry(Callable<T> work) {
202211
@Override
203212
public <T> T transactNoRetry(
204213
@Nullable TransactionIsolationLevel isolationLevel, Callable<T> work) {
214+
return transactNoRetry(isolationLevel, work, false);
215+
}
216+
217+
@Override
218+
public <T> T transactNoRetry(
219+
@Nullable TransactionIsolationLevel isolationLevel,
220+
Callable<T> work,
221+
boolean logSqlStatements) {
205222
if (inTransaction()) {
206223
// This check will no longer be necessary when the transact() method always throws
207224
// inside a nested transaction, as the only way to pass a non-null isolation level
@@ -224,7 +241,18 @@ public <T> T transactNoRetry(
224241
}
225242
}
226243
TransactionInfo txnInfo = transactionInfo.get();
227-
txnInfo.entityManager = emf.createEntityManager();
244+
245+
txnInfo.entityManager =
246+
logSqlStatements
247+
? emf.unwrap(SessionFactory.class)
248+
.withOptions()
249+
.statementInspector(
250+
s -> {
251+
logger.atInfo().log(SQL_STATEMENT_LOG_SENTINEL_FORMAT, s);
252+
return s;
253+
})
254+
.openSession()
255+
: emf.createEntityManager();
228256
if (readOnly) {
229257
// Disable Hibernate's dirty object check on flushing, it has become more aggressive in v6.
230258
txnInfo.entityManager.unwrap(Session.class).setDefaultReadOnly(true);

core/src/test/java/google/registry/flows/ResourceFlowTestCase.java

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -56,7 +56,7 @@
5656
public abstract class ResourceFlowTestCase<F extends Flow, R extends EppResource>
5757
extends FlowTestCase<F> {
5858

59-
private final TestLogHandler logHandler = new TestLogHandler();
59+
protected final TestLogHandler logHandler = new TestLogHandler();
6060

6161
@RegisterExtension
6262
public final TestCacheExtension testCacheExtension =

core/src/test/java/google/registry/flows/domain/DomainDeleteFlowTest.java

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -102,8 +102,10 @@
102102
import google.registry.model.transfer.TransferStatus;
103103
import google.registry.testing.CloudTasksHelper.TaskMatcher;
104104
import google.registry.testing.DatabaseHelper;
105+
import google.registry.testing.LogsSubject;
105106
import java.util.Map;
106107
import java.util.Optional;
108+
import java.util.logging.Level;
107109
import org.joda.money.Money;
108110
import org.joda.time.DateTime;
109111
import org.joda.time.Duration;
@@ -1258,4 +1260,17 @@ void testSuccess_skipsPollMessage_whenConfigured() throws Exception {
12581260
runFlowAssertResponse(loadFile("domain_delete_response_pending.xml"));
12591261
assertPollMessages();
12601262
}
1263+
1264+
@Test
1265+
void testSuccess_logsSqlStatements() throws Exception {
1266+
setUpSuccessfulTest();
1267+
runFlowAssertResponse(loadFile("domain_delete_response_pending.xml"));
1268+
LogsSubject.assertAboutLogs()
1269+
.that(logHandler)
1270+
.hasLogAtLevelWithMessage(
1271+
Level.INFO,
1272+
"SQL_STATEMENT_LOG: insert into \"DomainHistory\" (history_by_superuser,"
1273+
+ "history_registrar_id,history_modification_time,history_other_registrar_id,"
1274+
+ "history_period_unit,history_period_value,history_reason,history");
1275+
}
12611276
}

0 commit comments

Comments
 (0)