feat(server): add db metrics to GQL finished log entries (#3826)

* feat(server): add db metrics to GQL finished log entries

* logging for query errored as well

packages/server/logging/knexMonitoring.ts

@@ -216,6 +216,14 @@ const initKnexPrometheusMetricsForRegionEvents = async (params: {
 
     const trace = (new Error().stack || '').split('\n').slice(1).join('\n').trim()
     const reqCtx = getRequestContext()
+
+    // Update reqCtx with DB query metrics
+    if (reqCtx) {
+      reqCtx.dbMetrics.totalCount++
+      reqCtx.dbMetrics.totalDuration += durationMs || 0
+      reqCtx.dbMetrics.queries.push(data.sql)
+    }
+
     params.logger.info(
       {
         region,
@@ -246,6 +254,17 @@ const initKnexPrometheusMetricsForRegionEvents = async (params: {
         })
         .observe(durationSec)
     metricQueryErrors.inc()
+
+    const trace = (new Error().stack || '').split('\n').slice(1).join('\n').trim()
+    const reqCtx = getRequestContext()
+
+    // Update reqCtx with DB query metrics
+    if (reqCtx) {
+      reqCtx.dbMetrics.totalCount++
+      reqCtx.dbMetrics.totalDuration += durationMs || 0
+      reqCtx.dbMetrics.queries.push(data.sql)
+    }
+
     params.logger.warn(
       {
         err: typeof err === 'object' ? omit(err, 'detail') : err,
@@ -254,7 +273,9 @@ const initKnexPrometheusMetricsForRegionEvents = async (params: {
         sqlMethod: normalizeSqlMethod(data.method),
         sqlQueryId: queryId,
         sqlQueryDurationMs: toNDecimalPlaces(durationMs, 0),
-        sqlNumberBindings: data.bindings?.length || -1
+        sqlNumberBindings: data.bindings?.length || -1,
+        trace,
+        ...(reqCtx ? { req: { id: reqCtx.requestId } } : {})
       },
       'DB query errored for {sqlMethod} after {sqlQueryDurationMs}ms'
     )

packages/server/logging/requestContext.ts

@@ -5,6 +5,11 @@ import { AsyncLocalStorage } from 'node:async_hooks'
 
 type StorageType = {
   requestId: string
+  dbMetrics: {
+    totalDuration: number
+    totalCount: number
+    queries: string[]
+  }
 }
 
 const storage = asyncRequestContextEnabled()
@@ -17,7 +22,14 @@ export const initiateRequestContextMiddleware: express.RequestHandler = (
   next
 ) => {
   const reqId = req.headers[REQUEST_ID_HEADER] || 'unknown'
-  const store: StorageType = { requestId: reqId as string }
+  const store: StorageType = {
+    requestId: reqId as string,
+    dbMetrics: {
+      totalCount: 0,
+      totalDuration: 0,
+      queries: []
+    }
+  }
   storage?.enterWith(store)
   next()
 }

packages/server/modules/core/graph/plugins/logging.ts

@@ -6,6 +6,7 @@ import { FieldNode, SelectionNode } from 'graphql'
 import { ApolloServerPlugin } from '@apollo/server'
 import { GraphQLContext } from '@/modules/shared/helpers/typeHelper'
 import { shouldLogAsInfoLevel } from '@/logging/graphqlError'
+import { getRequestContext } from '@/logging/requestContext'
 
 type ApolloLoggingPluginTransaction = {
   start: number
@@ -62,7 +63,9 @@ export const loggingPluginFactory: (deps: {
         const auth = ctx.contextValue
         const userId = auth?.userId
 
-        const actionName = `${ctx.operation.operation} ${firstSelectedField.name.value}`
+        const operationName = ctx.operationName || ctx.operation?.name?.value
+        const actionName =
+          operationName || `${ctx.operation.operation} ${firstSelectedField.name.value}`
         const op = `GQL ${actionName}`
         const name = `GQL ${firstSelectedField.name.value}`
         const kind = ctx.operation.operation
@@ -73,8 +76,8 @@ export const loggingPluginFactory: (deps: {
           graphql_operation_kind: kind,
           graphql_query: query,
           graphql_variables: redactSensitiveVariables(variables),
-          graphql_operation_value: op,
-          graphql_operation_name: name,
+          graphql_operation_name: actionName,
+          graphql_operation_title: op,
           userId
         })
 
@@ -109,6 +112,13 @@ export const loggingPluginFactory: (deps: {
           const query = ctx.request.query
           const variables = redactSensitiveVariables(ctx.request.variables)
 
+          const reqCtx = getRequestContext()
+          if (reqCtx) {
+            logger = logger.child({
+              dbMetrics: reqCtx.dbMetrics
+            })
+          }
+
           if (err.path) {
             logger = logger.child({
               'query-path': err.path.join(' > '),
@@ -120,28 +130,35 @@ export const loggingPluginFactory: (deps: {
           if (shouldLogAsInfoLevel(err)) {
             logger.info(
               { err },
-              '{graphql_operation_value} failed after {apollo_query_duration_ms} ms'
+              '{graphql_operation_title} failed after {apollo_query_duration_ms} ms'
             )
           } else {
             logger.error(
               err,
-              '{graphql_operation_value} failed after {apollo_query_duration_ms} ms'
+              '{graphql_operation_title} failed after {apollo_query_duration_ms} ms'
             )
           }
         }
       },
       willSendResponse: async (ctx) => {
-        const logger = ctx.contextValue.log || graphqlLogger
+        let logger = ctx.contextValue.log || graphqlLogger
 
         if (ctx.request.transaction) {
           ctx.request.transaction.finish()
         }
 
+        const reqCtx = getRequestContext()
+        if (reqCtx) {
+          logger = logger.child({
+            dbMetrics: reqCtx.dbMetrics
+          })
+        }
+
         logger.info(
           {
             apollo_query_duration_ms: Date.now() - apolloRequestStart
           },
-          '{graphql_operation_value} finished after {apollo_query_duration_ms} ms'
+          '{graphql_operation_title} finished after {apollo_query_duration_ms} ms'
         )
       }
     }