Skip to content

Commit

Permalink
feat(graphql): Improve logging of GraphQL requests
Browse files Browse the repository at this point in the history
  • Loading branch information
@darnaut
darnaut committed May 1, 2024
1 parent 77045f9 commit 3ce8a7c
Show file tree
Hide file tree
Showing 2 changed files with 59 additions and 23 deletions.
50 changes: 27 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 @@ -70,7 +70,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 +85,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 +106,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: {}",
query,
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 +198,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 +221,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 3ce8a7c

Please sign in to comment.