Skip to content

Commit

Permalink
feat(graphql): Improve logging of GraphQL requests (datahub-project#1…
Browse files Browse the repository at this point in the history 
…0404)
  • Loading branch information
@darnaut
darnaut authored May 2, 2024
1 parent 77045f9 commit f3c42f6
Show file tree
Hide file tree
Showing 2 changed files with 62 additions and 23 deletions.
53 changes: 30 additions & 23 deletions ...ata-service/graphql-servlet-impl/src/main/java/com/datahub/graphql/GraphQLController.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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<ResponseEntity<String>> postGraphQL(HttpEntity<String> httpEntity) {

Expand All @@ -70,7 +73,7 @@ CompletableFuture<ResponseEntity<String>> postGraphQL(HttpEntity<String> 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));
}

Expand All @@ -85,6 +88,7 @@ CompletableFuture<ResponseEntity<String>> postGraphQL(HttpEntity<String> httpEnt
if (queryJson == null) {
return CompletableFuture.completedFuture(new ResponseEntity<>(HttpStatus.BAD_REQUEST));
}
final String query = queryJson.asText();

/*
* Extract "operationName" field
Expand All @@ -105,59 +109,59 @@ CompletableFuture<ResponseEntity<String>> postGraphQL(HttpEntity<String> httpEnt
.convertValue(variablesJson, new TypeReference<Map<String, Object>>() {})
: Collections.emptyMap();

log.debug(String.format("Executing graphQL query: %s, variables: %s", queryJson, variables));

/*
* Init QueryContext
*/
Authentication authentication = AuthenticationContext.getAuthentication();

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);
}
});
Expand Down Expand Up @@ -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();
Expand All @@ -220,12 +224,15 @@ private void submitMetrics(ExecutionResult executionResult) {
MetricUtils.get()
.histogram(MetricRegistry.name(this.getClass(), fieldName))
.update(totalDuration);
return totalDuration;
}
} catch (Exception e) {
MetricUtils.get()
.counter(MetricRegistry.name(this.getClass(), "submitMetrics", "exception"))
.inc();
log.error("Unable to submit metrics for GraphQL call.", e);
}

return -1;
}
}
32 changes: 32 additions & 0 deletions metadata-service/war/src/main/resources/logback.xml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -58,6 +58,31 @@
</encoder>
</appender>

<appender name="GRAPHQL_DEBUG_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>${LOG_DIR}/gms.graphql.log</file>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<FileNamePattern>${LOG_DIR}/gms.graphql.%d{yyyy-dd-MM}-%i.log</FileNamePattern>
<!-- each archived file, size max 10MB -->
<maxFileSize>100MB</maxFileSize>
<!-- total size of all archive files, if total size > 2GB, it will delete old archived file -->
<totalSizeCap>2GB</totalSizeCap>
<!-- 1 days to keep -->
<maxHistory>1</maxHistory>
</rollingPolicy>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>${logging.appender.graphql_debug_file.level:-DEBUG}</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
<encoder>
<pattern>%date{ISO8601} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
</appender>

<appender name="ASYNC_GRAPHQL_DEBUG_FILE" class="ch.qos.logback.classic.AsyncAppender">
<appender-ref ref="GRAPHQL_DEBUG_FILE" />
</appender>

<!-- Remove this to disable logging debug -->
<logger name="com.linkedin" level="DEBUG">
<appender-ref ref="DEBUG_FILE"/>
Expand All @@ -75,6 +100,13 @@
<appender-ref ref="STDOUT" />
</logger>

<logger name="com.datahub.graphql" level="TRACE">
<appender-ref ref="ASYNC_GRAPHQL_DEBUG_FILE"/>
</logger>

<logger name="com.datahub.graphql" level="DEBUG">
<appender-ref ref="ASYNC_GRAPHQL_DEBUG_FILE"/>
</logger>

<root level="INFO">
<appender-ref ref="STDOUT" />
Expand Down

0 comments on commit f3c42f6

Please sign in to comment.