From 3ce8a7ccef43c6c0f3ba5fdd844219b43f21f66e Mon Sep 17 00:00:00 2001
From: Davi Arnaut <davi.arnaut@acryl.io>
Date: Tue, 30 Apr 2024 21:48:47 -0700
Subject: [PATCH] feat(graphql): Improve logging of GraphQL requests

---
 .../datahub/graphql/GraphQLController.java    | 50 ++++++++++---------
 .../war/src/main/resources/logback.xml        | 32 ++++++++++++
 2 files changed, 59 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..7ff54130060382 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
@@ -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));
     }
 
@@ -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
@@ -105,8 +106,6 @@ 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
      */
@@ -114,50 +113,52 @@ CompletableFuture<ResponseEntity<String>> postGraphQL(HttpEntity<String> 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: {}",
+                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);
           }
         });
@@ -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();
@@ -220,6 +221,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 +229,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 @@
         </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"/>
@@ -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" />