Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(logging): add option to log slow GraphQL queries #11308

Merged
merged 2 commits into from
Sep 10, 2024
Merged

feat(logging): add option to log slow GraphQL queries #11308

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
2cfdf8a
feat(logging): add option to log slow GraphQL queries
nmbryant Sep 5, 2024
e7f3e77
Merge branch 'master' into graphql-verbose-logging
nmbryant Sep 5, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
46 changes: 46 additions & 0 deletions datahub-frontend/app/controllers/Application.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,12 +9,15 @@
import akka.util.ByteString;
import auth.Authenticator;
import com.datahub.authentication.AuthenticationConstants;
import com.fasterxml.jackson.databind.JsonNode;
import com.fasterxml.jackson.databind.ObjectMapper;
import com.fasterxml.jackson.databind.node.ObjectNode;
import com.linkedin.util.Pair;
import com.typesafe.config.Config;
import java.io.InputStream;
import java.net.URI;
import java.time.Duration;
import java.time.Instant;
import java.util.List;
import java.util.Map;
import java.util.Optional;
Expand All @@ -33,6 +36,7 @@
import play.libs.ws.StandaloneWSClient;
import play.libs.ws.ahc.StandaloneAhcWSClient;
import play.mvc.Controller;
import play.mvc.Http.Cookie;
import play.mvc.Http;
import play.mvc.ResponseHeader;
import play.mvc.Result;
Expand Down Expand Up @@ -132,6 +136,9 @@ public CompletableFuture<Result> proxy(String path, Http.Request request)
headers.put(Http.HeaderNames.X_FORWARDED_PROTO, List.of(schema));
}

// Get the current time to measure the duration of the request
Instant start = Instant.now();

return _ws.url(
String.format(
"%s://%s:%s%s", protocol, metadataServiceHost, metadataServicePort, resolvedUri))
Expand Down Expand Up @@ -160,6 +167,15 @@ AuthenticationConstants.LEGACY_X_DATAHUB_ACTOR_HEADER, getDataHubActorHeader(req
.execute()
.thenApply(
apiResponse -> {
// Log the query if it takes longer than the configured threshold and verbose logging is enabled
boolean verboseGraphQLLogging = _config.getBoolean("graphql.verbose.logging");
int verboseGraphQLLongQueryMillis = _config.getInt("graphql.verbose.slowQueryMillis");
Instant finish = Instant.now();
long timeElapsed = Duration.between(start, finish).toMillis();
if (verboseGraphQLLogging && timeElapsed >= verboseGraphQLLongQueryMillis) {
logSlowQuery(request, resolvedUri, timeElapsed);
}

Comment on lines +170 to +178
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Review: Logging slow GraphQL queries.

The implementation correctly checks if verbose logging is enabled and if the query duration exceeds the threshold before logging. However, consider adding error handling for potential exceptions when accessing configuration values.

Consider adding a try-catch block around the configuration access to handle possible ConfigException:

try {
    boolean verboseGraphQLLogging = _config.getBoolean("graphql.verbose.logging");
    int verboseGraphQLLongQueryMillis = _config.getInt("graphql.verbose.slowQueryMillis");
} catch (ConfigException e) {
    _logger.error("Error accessing configuration for GraphQL logging.", e);
}

final ResponseHeader header =
new ResponseHeader(
apiResponse.getStatus(),
Expand Down Expand Up @@ -359,4 +375,34 @@ private String mapPath(@Nonnull final String path) {
// Otherwise, return original path
return path;
}


/**
* Called if verbose logging is enabled and request takes longer that the slow query milliseconds defined in the config
* @param request GraphQL request that was made
* @param resolvedUri URI that was requested
* @param duration How long the query took to complete
*/
private void logSlowQuery(Http.Request request, String resolvedUri, float duration) {
StringBuilder jsonBody = new StringBuilder();
Optional<Cookie> actorCookie = request.getCookie("actor");
String actorValue = actorCookie.isPresent() ? actorCookie.get().value() : "N/A";

try {
ObjectMapper mapper = new ObjectMapper();
JsonNode jsonNode = request.body().asJson();
((ObjectNode) jsonNode).remove("query");
jsonBody.append(mapper.writerWithDefaultPrettyPrinter().writeValueAsString(jsonNode));
}
catch (Exception e) {
_logger.info("GraphQL Request Received: {}, Unable to parse JSON body", resolvedUri);
}
String jsonBodyStr = jsonBody.toString();
_logger.info("Slow GraphQL Request Received: {}, Request query string: {}, Request actor: {}, Request JSON: {}, Request completed in {} ms",
resolvedUri,
request.queryString(),
actorValue,
jsonBodyStr,
duration);
}
Comment on lines +381 to +407
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Review: logSlowQuery method implementation.

The method implementation for logging slow GraphQL queries is mostly correct. However, there are a few areas of improvement:

  1. The removal of the "query" field from the JSON body is a good practice to avoid logging sensitive data, but ensure that the JSON body is not null before casting and modifying it.
  2. The exception handling could be more specific by catching more specific exceptions than the general Exception.
  3. The logging statement at the end could benefit from more structured logging instead of concatenating strings.

Consider the following improvements:

  1. Check for null before casting the JSON body:
if (jsonNode != null && jsonNode.isObject()) {
    ((ObjectNode) jsonNode).remove("query");
}
  1. Catch more specific exceptions:
catch (IOException e) {
    _logger.info("GraphQL Request Received: {}, Unable to parse JSON body due to IO issues", resolvedUri, e);
}
  1. Use structured logging:
_logger.info("Slow GraphQL Request Received: URI={}, QueryString={}, Actor={}, JSON={}, Duration={} ms",
             resolvedUri, request.queryString(), actorValue, jsonBodyStr, duration);

}
8 changes: 7 additions & 1 deletion datahub-frontend/conf/application.conf
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -298,4 +298,10 @@ entityClient.numRetries = ${?ENTITY_CLIENT_NUM_RETRIES}
entityClient.restli.get.batchSize = 50
entityClient.restli.get.batchSize = ${?ENTITY_CLIENT_RESTLI_GET_BATCH_SIZE}
entityClient.restli.get.batchConcurrency = 2
entityClient.restli.get.batchConcurrency = ${?ENTITY_CLIENT_RESTLI_GET_BATCH_CONCURRENCY}
entityClient.restli.get.batchConcurrency = ${?ENTITY_CLIENT_RESTLI_GET_BATCH_CONCURRENCY}

# Enable verbose authentication logging
graphql.verbose.logging = false
graphql.verbose.logging = ${?GRAPHQL_VERBOSE_LOGGING}
graphql.verbose.slowQueryMillis = 2500
graphql.verbose.slowQueryMillis = ${?GRAPHQL_VERBOSE_LONG_QUERY_MILLIS}
Loading