Skip to content

Commit 98bb45a

Browse files
fvilla-amazonfvilla-amazon
authored
#1929: Protect logging debug calls with isDebugEnabled() (#1930)
Description: Protect against potential performance degradation from debug logging by utilizing the logging libraries isDebugEnabled() check directly. Changes: * Protected all Logger.debug(...) calls with Logger.isDebugEnabled() Unit Tests: * N/A
1 parent eff6106 commit 98bb45a

10 files changed

Lines changed: 71 additions & 30 deletions

File tree

‎src/main/java/graphql/GraphQL.java‎

Lines changed: 19 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -477,7 +477,9 @@ public CompletableFuture<ExecutionResult> executeAsync(UnaryOperator<ExecutionIn
477477
*/
478478
public CompletableFuture<ExecutionResult> executeAsync(ExecutionInput executionInput) {
479479
try {
480-
logNotSafe.debug("Executing request. operation name: '{}'. query: '{}'. variables '{}'", executionInput.getOperationName(), executionInput.getQuery(), executionInput.getVariables());
480+
if (logNotSafe.isDebugEnabled()) {
481+
logNotSafe.debug("Executing request. operation name: '{}'. query: '{}'. variables '{}'", executionInput.getOperationName(), executionInput.getQuery(), executionInput.getVariables());
482+
}
481483
executionInput = ensureInputHasId(executionInput);
482484

483485
InstrumentationState instrumentationState = instrumentation.createState(new InstrumentationCreateStateParameters(this.graphQLSchema, executionInput));
@@ -534,7 +536,9 @@ private PreparsedDocumentEntry parseAndValidate(AtomicReference<ExecutionInput>
534536
ExecutionInput executionInput = executionInputRef.get();
535537
String query = executionInput.getQuery();
536538

537-
logNotSafe.debug("Parsing query: '{}'...", query);
539+
if (logNotSafe.isDebugEnabled()) {
540+
logNotSafe.debug("Parsing query: '{}'...", query);
541+
}
538542
ParseAndValidateResult parseResult = parse(executionInput, graphQLSchema, instrumentationState);
539543
if (parseResult.isFailure()) {
540544
logNotSafe.warn("Query failed to parse : '{}'", executionInput.getQuery());
@@ -545,7 +549,9 @@ private PreparsedDocumentEntry parseAndValidate(AtomicReference<ExecutionInput>
545549
executionInput = executionInput.transform(builder -> builder.variables(parseResult.getVariables()));
546550
executionInputRef.set(executionInput);
547551

548-
logNotSafe.debug("Validating query: '{}'", query);
552+
if (logNotSafe.isDebugEnabled()) {
553+
logNotSafe.debug("Validating query: '{}'", query);
554+
}
549555
final List<ValidationError> errors = validate(executionInput, document, graphQLSchema, instrumentationState);
550556
if (!errors.isEmpty()) {
551557
logNotSafe.warn("Query failed to validate : '{}'", query);
@@ -594,17 +600,21 @@ private CompletableFuture<ExecutionResult> execute(ExecutionInput executionInput
594600
Execution execution = new Execution(queryStrategy, mutationStrategy, subscriptionStrategy, instrumentation, valueUnboxer);
595601
ExecutionId executionId = executionInput.getExecutionId();
596602

597-
logNotSafe.debug("Executing '{}'. operation name: '{}'. query: '{}'. variables '{}'", executionId, executionInput.getOperationName(), executionInput.getQuery(), executionInput.getVariables());
603+
if (logNotSafe.isDebugEnabled()) {
604+
logNotSafe.debug("Executing '{}'. operation name: '{}'. query: '{}'. variables '{}'", executionId, executionInput.getOperationName(), executionInput.getQuery(), executionInput.getVariables());
605+
}
598606
CompletableFuture<ExecutionResult> future = execution.execute(document, graphQLSchema, executionId, executionInput, instrumentationState);
599607
future = future.whenComplete((result, throwable) -> {
600608
if (throwable != null) {
601609
logNotSafe.error(String.format("Execution '%s' threw exception when executing : query : '%s'. variables '%s'", executionId, executionInput.getQuery(), executionInput.getVariables()), throwable);
602610
} else {
603-
int errorCount = result.getErrors().size();
604-
if (errorCount > 0) {
605-
log.debug("Execution '{}' completed with '{}' errors", executionId, errorCount);
606-
} else {
607-
log.debug("Execution '{}' completed with zero errors", executionId);
611+
if (log.isDebugEnabled()) {
612+
int errorCount = result.getErrors().size();
613+
if (errorCount > 0) {
614+
log.debug("Execution '{}' completed with '{}' errors", executionId, errorCount);
615+
} else {
616+
log.debug("Execution '{}' completed with zero errors", executionId);
617+
}
608618
}
609619
}
610620
});

‎src/main/java/graphql/analysis/MaxQueryComplexityInstrumentation.java‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -97,7 +97,9 @@ public void visitField(QueryVisitorFieldEnvironment env) {
9797
}
9898
});
9999
int totalComplexity = valuesByParent.getOrDefault(null, 0);
100-
log.debug("Query complexity: {}", totalComplexity);
100+
if (log.isDebugEnabled()) {
101+
log.debug("Query complexity: {}", totalComplexity);
102+
}
101103
if (totalComplexity > maxComplexity) {
102104
QueryComplexityInfo queryComplexityInfo = QueryComplexityInfo.newQueryComplexityInfo()
103105
.complexity(totalComplexity)

‎src/main/java/graphql/analysis/MaxQueryDepthInstrumentation.java‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -56,7 +56,9 @@ public InstrumentationContext<List<ValidationError>> beginValidation(Instrumenta
5656
}
5757
QueryTraverser queryTraverser = newQueryTraverser(parameters);
5858
int depth = queryTraverser.reducePreOrder((env, acc) -> Math.max(getPathLength(env.getParentEnvironment()), acc), 0);
59-
log.debug("Query depth info: {}", depth);
59+
if (log.isDebugEnabled()) {
60+
log.debug("Query depth info: {}", depth);
61+
}
6062
if (depth > maxDepth) {
6163
QueryDepthInfo queryDepthInfo = QueryDepthInfo.newQueryDepthInfo()
6264
.depth(depth)

‎src/main/java/graphql/execution/Execution.java‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -163,7 +163,9 @@ private CompletableFuture<ExecutionResult> executeOperation(ExecutionContext exe
163163
} else {
164164
executionStrategy = executionContext.getQueryStrategy();
165165
}
166-
logNotSafe.debug("Executing '{}' query operation: '{}' using '{}' execution strategy", executionContext.getExecutionId(), operation, executionStrategy.getClass().getName());
166+
if (logNotSafe.isDebugEnabled()) {
167+
logNotSafe.debug("Executing '{}' query operation: '{}' using '{}' execution strategy", executionContext.getExecutionId(), operation, executionStrategy.getClass().getName());
168+
}
167169
result = executionStrategy.execute(executionContext, parameters);
168170
} catch (NonNullableFieldWasNullException e) {
169171
// this means it was non null types all the way from an offending non null type

‎src/main/java/graphql/execution/ExecutionStrategy.java‎

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -277,7 +277,9 @@ protected CompletableFuture<FetchedValue> fetchField(ExecutionContext executionC
277277
Object fetchedValueRaw = dataFetcher.get(environment);
278278
fetchedValue = Async.toCompletableFuture(fetchedValueRaw);
279279
} catch (Exception e) {
280-
logNotSafe.debug(String.format("'%s', field '%s' fetch threw exception", executionId, executionStepInfo.get().getPath()), e);
280+
if (logNotSafe.isDebugEnabled()) {
281+
logNotSafe.debug(String.format("'%s', field '%s' fetch threw exception", executionId, executionStepInfo.get().getPath()), e);
282+
}
281283

282284
fetchedValue = new CompletableFuture<>();
283285
fetchedValue.completeExceptionally(e);
@@ -388,7 +390,9 @@ protected FieldValueInfo completeField(ExecutionContext executionContext, Execut
388390
.nonNullFieldValidator(nonNullableFieldValidator)
389391
);
390392

391-
log.debug("'{}' completing field '{}'...", executionContext.getExecutionId(), executionStepInfo.getPath());
393+
if (log.isDebugEnabled()) {
394+
log.debug("'{}' completing field '{}'...", executionContext.getExecutionId(), executionStepInfo.getPath());
395+
}
392396

393397
FieldValueInfo fieldValueInfo = completeValue(executionContext, newParameters);
394398

‎src/main/java/graphql/execution/instrumentation/dataloader/DataLoaderDispatcherInstrumentation.java‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -188,7 +188,9 @@ public CompletableFuture<ExecutionResult> instrumentExecutionResult(ExecutionRes
188188
Map<Object, Object> dataLoaderStats = buildStatsMap(state);
189189
statsMap.put("dataloader", dataLoaderStats);
190190

191-
log.debug("Data loader stats : {}", dataLoaderStats);
191+
if (log.isDebugEnabled()) {
192+
log.debug("Data loader stats : {}", dataLoaderStats);
193+
}
192194

193195
return CompletableFuture.completedFuture(new ExecutionResultImpl(executionResult.getData(), executionResult.getErrors(), statsMap));
194196
}

‎src/main/java/graphql/execution/instrumentation/dataloader/FieldLevelTrackingApproach.java‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -288,7 +288,9 @@ private boolean levelReady(CallStack callStack, int level) {
288288

289289
void dispatch() {
290290
DataLoaderRegistry dataLoaderRegistry = getDataLoaderRegistry();
291-
log.debug("Dispatching data loaders ({})", dataLoaderRegistry.getKeys());
291+
if (log.isDebugEnabled()) {
292+
log.debug("Dispatching data loaders ({})", dataLoaderRegistry.getKeys());
293+
}
292294
dataLoaderRegistry.dispatchAll();
293295
}
294296

‎src/main/java/graphql/execution/nextgen/ValueFetcher.java‎

Lines changed: 9 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -164,12 +164,18 @@ private CompletableFuture<Object> callDataFetcher(GraphQLCodeRegistry codeRegist
164164
CompletableFuture<Object> result = new CompletableFuture<>();
165165
try {
166166
DataFetcher dataFetcher = codeRegistry.getDataFetcher(parentType, fieldDef);
167-
log.debug("'{}' fetching field '{}' using data fetcher '{}'...", executionId, path, dataFetcher.getClass().getName());
167+
if (log.isDebugEnabled()) {
168+
log.debug("'{}' fetching field '{}' using data fetcher '{}'...", executionId, path, dataFetcher.getClass().getName());
169+
}
168170
Object fetchedValueRaw = dataFetcher.get(environment);
169-
logNotSafe.debug("'{}' field '{}' fetch returned '{}'", executionId, path, fetchedValueRaw == null ? "null" : fetchedValueRaw.getClass().getName());
171+
if (logNotSafe.isDebugEnabled()) {
172+
logNotSafe.debug("'{}' field '{}' fetch returned '{}'", executionId, path, fetchedValueRaw == null ? "null" : fetchedValueRaw.getClass().getName());
173+
}
170174
handleFetchedValue(fetchedValueRaw, result);
171175
} catch (Exception e) {
172-
logNotSafe.debug(String.format("'%s', field '%s' fetch threw exception", executionId, path), e);
176+
if (logNotSafe.isDebugEnabled()) {
177+
logNotSafe.debug("'{}', field '{}' fetch threw exception", executionId, path, e);
178+
}
173179
result.completeExceptionally(e);
174180
}
175181
return result;

‎src/main/java/graphql/nextgen/GraphQL.java‎

Lines changed: 19 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -148,7 +148,9 @@ public CompletableFuture<ExecutionResult> executeAsync(UnaryOperator<ExecutionIn
148148
*/
149149
public CompletableFuture<ExecutionResult> executeAsync(ExecutionInput executionInput) {
150150
try {
151-
logNotSafe.debug("Executing request. operation name: '{}'. query: '{}'. variables '{}'", executionInput.getOperationName(), executionInput.getQuery(), executionInput.getVariables());
151+
if (logNotSafe.isDebugEnabled()) {
152+
logNotSafe.debug("Executing request. operation name: '{}'. query: '{}'. variables '{}'", executionInput.getOperationName(), executionInput.getQuery(), executionInput.getVariables());
153+
}
152154

153155
InstrumentationState instrumentationState = instrumentation.createState(new InstrumentationCreateStateParameters(this.graphQLSchema, executionInput));
154156

@@ -192,7 +194,9 @@ private PreparsedDocumentEntry parseAndValidate(AtomicReference<ExecutionInput>
192194
ExecutionInput executionInput = executionInputRef.get();
193195
String query = executionInput.getQuery();
194196

195-
logNotSafe.debug("Parsing query: '{}'...", query);
197+
if (logNotSafe.isDebugEnabled()) {
198+
logNotSafe.debug("Parsing query: '{}'...", query);
199+
}
196200
ParseAndValidateResult parseResult = parse(executionInput, graphQLSchema, instrumentationState);
197201
if (parseResult.isFailure()) {
198202
logNotSafe.warn("Query failed to parse : '{}'", executionInput.getQuery());
@@ -203,7 +207,9 @@ private PreparsedDocumentEntry parseAndValidate(AtomicReference<ExecutionInput>
203207
executionInput = executionInput.transform(builder -> builder.variables(parseResult.getVariables()));
204208
executionInputRef.set(executionInput);
205209

206-
logNotSafe.debug("Validating query: '{}'", query);
210+
if (logNotSafe.isDebugEnabled()) {
211+
logNotSafe.debug("Validating query: '{}'", query);
212+
}
207213
final List<ValidationError> errors = validate(executionInput, document, graphQLSchema, instrumentationState);
208214
if (!errors.isEmpty()) {
209215
logNotSafe.warn("Query failed to validate : '{}'", query);
@@ -255,17 +261,21 @@ private CompletableFuture<ExecutionResult> execute(ExecutionInput executionInput
255261
Execution execution = new Execution();
256262
ExecutionId executionId = idProvider.provide(query, operationName, context);
257263

258-
logNotSafe.debug("Executing '{}'. operation name: '{}'. query: '{}'. variables '{}'", executionId, executionInput.getOperationName(), executionInput.getQuery(), executionInput.getVariables());
264+
if (logNotSafe.isDebugEnabled()) {
265+
logNotSafe.debug("Executing '{}'. operation name: '{}'. query: '{}'. variables '{}'", executionId, executionInput.getOperationName(), executionInput.getQuery(), executionInput.getVariables());
266+
}
259267
CompletableFuture<ExecutionResult> future = execution.execute(executionStrategy, document, graphQLSchema, executionId, executionInput, instrumentationState);
260268
future = future.whenComplete((result, throwable) -> {
261269
if (throwable != null) {
262270
log.error(String.format("Execution '%s' threw exception when executing : query : '%s'. variables '%s'", executionId, executionInput.getQuery(), executionInput.getVariables()), throwable);
263271
} else {
264-
int errorCount = result.getErrors().size();
265-
if (errorCount > 0) {
266-
log.debug("Execution '{}' completed with '{}' errors", executionId, errorCount);
267-
} else {
268-
log.debug("Execution '{}' completed with zero errors", executionId);
272+
if (log.isDebugEnabled()) {
273+
int errorCount = result.getErrors().size();
274+
if (errorCount > 0) {
275+
log.debug("Execution '{}' completed with '{}' errors", executionId, errorCount);
276+
} else {
277+
log.debug("Execution '{}' completed with zero errors", executionId);
278+
}
269279
}
270280
}
271281
});

‎src/main/java/graphql/schema/idl/ArgValueOfAllowedTypeChecker.java‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,6 @@
2727
import graphql.schema.idl.errors.DirectiveIllegalArgumentTypeError;
2828
import graphql.util.LogKit;
2929
import org.slf4j.Logger;
30-
import org.slf4j.LoggerFactory;
3130

3231
import java.util.List;
3332
import java.util.Map;
@@ -264,7 +263,9 @@ private boolean isArgumentValueScalarLiteral(GraphQLScalarType scalarType, Value
264263
scalarType.getCoercing().parseLiteral(instanceValue);
265264
return true;
266265
} catch (CoercingParseLiteralException ex) {
267-
logNotSafe.debug("Attempted parsing literal into '{}' but got the following error: ", scalarType.getName(), ex);
266+
if (logNotSafe.isDebugEnabled()) {
267+
logNotSafe.debug("Attempted parsing literal into '{}' but got the following error: ", scalarType.getName(), ex);
268+
}
268269
return false;
269270
}
270271
}

0 commit comments

Comments
 (0)