diff --git a/packages/server/logging/knexMonitoring.ts b/packages/server/logging/knexMonitoring.ts index 000b70f1b..28834d6d2 100644 --- a/packages/server/logging/knexMonitoring.ts +++ b/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' ) diff --git a/packages/server/logging/requestContext.ts b/packages/server/logging/requestContext.ts index ceec68b68..303b433a8 100644 --- a/packages/server/logging/requestContext.ts +++ b/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() } diff --git a/packages/server/modules/core/graph/plugins/logging.ts b/packages/server/modules/core/graph/plugins/logging.ts index a5febf63c..fdba4f0d2 100644 --- a/packages/server/modules/core/graph/plugins/logging.ts +++ b/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' ) } }