From f3c42f611ee59d618aef2e597b568b7de8fad0a7 Mon Sep 17 00:00:00 2001 From: Davi Arnaut Date: Wed, 1 May 2024 19:12:16 -0700 Subject: [PATCH] feat(graphql): Improve logging of GraphQL requests (#10404) --- .../datahub/graphql/GraphQLController.java | 53 +++++++++++-------- .../war/src/main/resources/logback.xml | 32 +++++++++++ 2 files changed, 62 insertions(+), 23 deletions(-) diff --git a/metadata-service/graphql-servlet-impl/src/main/java/com/datahub/graphql/GraphQLController.java b/metadata-service/graphql-servlet-impl/src/main/java/com/datahub/graphql/GraphQLController.java index 31e4b58a56e74e..2ab5e49673966a 100644 --- a/metadata-service/graphql-servlet-impl/src/main/java/com/datahub/graphql/GraphQLController.java +++ b/metadata-service/graphql-servlet-impl/src/main/java/com/datahub/graphql/GraphQLController.java @@ -28,6 +28,7 @@ import java.util.concurrent.TimeUnit; import javax.annotation.Nonnull; import lombok.extern.slf4j.Slf4j; +import org.apache.commons.lang3.StringUtils; import org.springframework.http.HttpEntity; import org.springframework.http.HttpStatus; import org.springframework.http.ResponseEntity; @@ -54,6 +55,8 @@ public GraphQLController() { @Named("systemOperationContext") private OperationContext systemOperationContext; + private static final int MAX_LOG_WIDTH = 512; + @PostMapping(value = "/graphql", produces = "application/json;charset=utf-8") CompletableFuture> postGraphQL(HttpEntity httpEntity) { @@ -70,7 +73,7 @@ CompletableFuture> postGraphQL(HttpEntity httpEnt try { bodyJson = mapper.readTree(jsonStr); } catch (JsonProcessingException e) { - log.error(String.format("Failed to parse json %s", jsonStr)); + log.error("Failed to parse json {}", jsonStr); return CompletableFuture.completedFuture(new ResponseEntity<>(HttpStatus.BAD_REQUEST)); } @@ -85,6 +88,7 @@ CompletableFuture> postGraphQL(HttpEntity httpEnt if (queryJson == null) { return CompletableFuture.completedFuture(new ResponseEntity<>(HttpStatus.BAD_REQUEST)); } + final String query = queryJson.asText(); /* * Extract "operationName" field @@ -105,8 +109,6 @@ CompletableFuture> postGraphQL(HttpEntity httpEnt .convertValue(variablesJson, new TypeReference>() {}) : Collections.emptyMap(); - log.debug(String.format("Executing graphQL query: %s, variables: %s", queryJson, variables)); - /* * Init QueryContext */ @@ -114,50 +116,52 @@ CompletableFuture> postGraphQL(HttpEntity httpEnt SpringQueryContext context = new SpringQueryContext( - true, - authentication, - _authorizerChain, - systemOperationContext, - queryJson.asText(), - variables); + true, authentication, _authorizerChain, systemOperationContext, query, variables); Span.current().setAttribute("actor.urn", context.getActorUrn()); + final String threadName = Thread.currentThread().getName(); + log.info( + "Processing request, operation: {}, actor urn: {}", operationName, context.getActorUrn()); + log.debug("Query: {}, variables: {}", query, variables); + return CompletableFuture.supplyAsync( () -> { + log.info("Executing operation {} for {}", operationName, threadName); + /* * Execute GraphQL Query */ ExecutionResult executionResult = - _engine.execute(queryJson.asText(), operationName, variables, context); + _engine.execute(query, operationName, variables, context); if (executionResult.getErrors().size() != 0) { // There were GraphQL errors. Report in error logs. log.error( - String.format( - "Errors while executing graphQL query: %s, result: %s, errors: %s", - queryJson, executionResult.toSpecification(), executionResult.getErrors())); - } else { - log.debug( - String.format( - "Executed graphQL query: %s, result: %s", - queryJson, executionResult.toSpecification())); + "Errors while executing query: {}, result: {}, errors: {}", + StringUtils.abbreviate(query, MAX_LOG_WIDTH), + executionResult.toSpecification(), + executionResult.getErrors()); } /* * Format & Return Response */ try { - submitMetrics(executionResult); + long totalDuration = submitMetrics(executionResult); + String executionTook = totalDuration > 0 ? " in " + totalDuration + " ms" : ""; + log.info("Executed operation {}" + executionTook, operationName); // Remove tracing from response to reduce bulk, not used by the frontend executionResult.getExtensions().remove("tracing"); String responseBodyStr = new ObjectMapper().writeValueAsString(executionResult.toSpecification()); + log.info( + "Operation {} execution result size: {}", operationName, responseBodyStr.length()); + log.trace("Execution result: {}", responseBodyStr); return new ResponseEntity<>(responseBodyStr, HttpStatus.OK); } catch (IllegalArgumentException | JsonProcessingException e) { log.error( - String.format( - "Failed to convert execution result %s into a JsonNode", - executionResult.toSpecification())); + "Failed to convert execution result {} into a JsonNode", + executionResult.toSpecification()); return new ResponseEntity<>(HttpStatus.SERVICE_UNAVAILABLE); } }); @@ -197,7 +201,7 @@ private void observeErrors(ExecutionResult executionResult) { } @SuppressWarnings("unchecked") - private void submitMetrics(ExecutionResult executionResult) { + private long submitMetrics(ExecutionResult executionResult) { try { observeErrors(executionResult); MetricUtils.get().counter(MetricRegistry.name(this.getClass(), "call")).inc(); @@ -220,6 +224,7 @@ private void submitMetrics(ExecutionResult executionResult) { MetricUtils.get() .histogram(MetricRegistry.name(this.getClass(), fieldName)) .update(totalDuration); + return totalDuration; } } catch (Exception e) { MetricUtils.get() @@ -227,5 +232,7 @@ private void submitMetrics(ExecutionResult executionResult) { .inc(); log.error("Unable to submit metrics for GraphQL call.", e); } + + return -1; } } diff --git a/metadata-service/war/src/main/resources/logback.xml b/metadata-service/war/src/main/resources/logback.xml index ba15f3045d1a2e..ebd161023d13c5 100644 --- a/metadata-service/war/src/main/resources/logback.xml +++ b/metadata-service/war/src/main/resources/logback.xml @@ -58,6 +58,31 @@ + + ${LOG_DIR}/gms.graphql.log + + ${LOG_DIR}/gms.graphql.%d{yyyy-dd-MM}-%i.log + + 100MB + + 2GB + + 1 + + + ${logging.appender.graphql_debug_file.level:-DEBUG} + ACCEPT + DENY + + + %date{ISO8601} [%thread] %-5level %logger{36} - %msg%n + + + + + + + @@ -75,6 +100,13 @@ + + + + + + +