From 7d70734862351004831d18b349b3cebc78048614 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gerg=C5=91=20Jedlicska?= Date: Tue, 9 Jan 2024 16:45:23 +0100 Subject: [PATCH 1/3] add apollo query duration --- packages/server/logging/apolloPlugin.js | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/packages/server/logging/apolloPlugin.js b/packages/server/logging/apolloPlugin.js index 44cf779197..7a3938c130 100644 --- a/packages/server/logging/apolloPlugin.js +++ b/packages/server/logging/apolloPlugin.js @@ -20,6 +20,7 @@ module.exports = { requestDidStart(ctx) { return { didResolveOperation(ctx) { + const apolloRequestStart = new Date() let logger = ctx.context.log || graphqlLogger const op = `GQL ${ctx.operation.operation} ${ctx.operation.selectionSet.selections[0].name.value}` @@ -53,6 +54,7 @@ module.exports = { Sentry.configureScope((scope) => scope.setSpan(transaction)) ctx.request.transaction = transaction ctx.context.log = logger + ctx.context.apolloRequestStart = apolloRequestStart }, didEncounterErrors(ctx) { let logger = ctx.context.log || graphqlLogger @@ -91,12 +93,16 @@ module.exports = { } }, willSendResponse(ctx) { - const logger = ctx.context.log || graphqlLogger - logger.info('graphql response') + let logger = ctx.context.log || graphqlLogger + if (ctx.context.apolloRequestStart) + logger = logger.child({ + 'apollo-query-duration': new Date() - ctx.context.apolloRequestStart + }) if (ctx.request.transaction) { ctx.request.transaction.finish() } + logger.info('graphql response') } } } From 6a6a0ea1d802027224d9dfadb164999907449a46 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gerg=C5=91=20Jedlicska?= Date: Tue, 9 Jan 2024 19:12:13 +0100 Subject: [PATCH 2/3] feat: add more details to apollo query logging --- packages/server/logging/apolloPlugin.js | 28 +++++++++++++++++-------- 1 file changed, 19 insertions(+), 9 deletions(-) diff --git a/packages/server/logging/apolloPlugin.js b/packages/server/logging/apolloPlugin.js index 7a3938c130..edfb1b165c 100644 --- a/packages/server/logging/apolloPlugin.js +++ b/packages/server/logging/apolloPlugin.js @@ -18,9 +18,9 @@ const metricCallCount = new prometheusClient.Counter({ module.exports = { // eslint-disable-next-line no-unused-vars requestDidStart(ctx) { + const apolloRequestStart = new Date() return { didResolveOperation(ctx) { - const apolloRequestStart = new Date() let logger = ctx.context.log || graphqlLogger const op = `GQL ${ctx.operation.operation} ${ctx.operation.selectionSet.selections[0].name.value}` @@ -54,10 +54,12 @@ module.exports = { Sentry.configureScope((scope) => scope.setSpan(transaction)) ctx.request.transaction = transaction ctx.context.log = logger - ctx.context.apolloRequestStart = apolloRequestStart }, didEncounterErrors(ctx) { let logger = ctx.context.log || graphqlLogger + logger = logger.child({ + apollo_query_duration_ms: new Date() - apolloRequestStart + }) for (const err of ctx.errors) { const operationName = ctx.request.operationName || null @@ -71,9 +73,15 @@ module.exports = { (err instanceof GraphQLError && err.extensions?.code === 'FORBIDDEN') || err instanceof ApolloError ) { - logger.info(err, 'graphql error') + logger.info( + err, + '{graphql_operation_value} failed after {apollo_query_duration_ms} ms' + ) } else { - logger.error(err, 'graphql error') + logger.error( + err, + '{graphql_operation_value} failed after {apollo_query_duration_ms} ms' + ) } Sentry.withScope((scope) => { @@ -94,15 +102,17 @@ module.exports = { }, willSendResponse(ctx) { let logger = ctx.context.log || graphqlLogger - if (ctx.context.apolloRequestStart) - logger = logger.child({ - 'apollo-query-duration': new Date() - ctx.context.apolloRequestStart - }) + logger = logger.child() if (ctx.request.transaction) { ctx.request.transaction.finish() } - logger.info('graphql response') + logger.info( + { + apollo_query_duration_ms: new Date() - apolloRequestStart + }, + '{graphql_operation_value} finished after {apollo_query_duration_ms} ms' + ) } } } From de3b5a7c5b3bb4e207c69fee9c1ed912597db00f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gerg=C5=91=20Jedlicska?= Date: Wed, 10 Jan 2024 10:43:36 +0100 Subject: [PATCH 3/3] fix: pr review --- packages/server/logging/apolloPlugin.js | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/packages/server/logging/apolloPlugin.js b/packages/server/logging/apolloPlugin.js index edfb1b165c..d47862688d 100644 --- a/packages/server/logging/apolloPlugin.js +++ b/packages/server/logging/apolloPlugin.js @@ -18,7 +18,7 @@ const metricCallCount = new prometheusClient.Counter({ module.exports = { // eslint-disable-next-line no-unused-vars requestDidStart(ctx) { - const apolloRequestStart = new Date() + const apolloRequestStart = Date.now() return { didResolveOperation(ctx) { let logger = ctx.context.log || graphqlLogger @@ -58,7 +58,7 @@ module.exports = { didEncounterErrors(ctx) { let logger = ctx.context.log || graphqlLogger logger = logger.child({ - apollo_query_duration_ms: new Date() - apolloRequestStart + apollo_query_duration_ms: Date.now() - apolloRequestStart }) for (const err of ctx.errors) { @@ -74,7 +74,7 @@ module.exports = { err instanceof ApolloError ) { logger.info( - err, + { err }, '{graphql_operation_value} failed after {apollo_query_duration_ms} ms' ) } else { @@ -101,15 +101,14 @@ module.exports = { } }, willSendResponse(ctx) { - let logger = ctx.context.log || graphqlLogger - logger = logger.child() + const logger = ctx.context.log || graphqlLogger if (ctx.request.transaction) { ctx.request.transaction.finish() } logger.info( { - apollo_query_duration_ms: new Date() - apolloRequestStart + apollo_query_duration_ms: Date.now() - apolloRequestStart }, '{graphql_operation_value} finished after {apollo_query_duration_ms} ms' )