From f83118977e1fa322ae7069b9b3db30a7cf56e4e2 Mon Sep 17 00:00:00 2001 From: Kristaps Fabians Geikins Date: Tue, 23 May 2023 12:20:40 +0300 Subject: [PATCH] fix(server): subscription request logging --- packages/server/app.ts | 47 ++++++++++++++++++- packages/server/logging/apolloPlugin.js | 15 +++--- .../modules/shared/helpers/typeHelper.ts | 3 ++ .../server/modules/shared/middleware/index.ts | 23 +++++---- 4 files changed, 69 insertions(+), 19 deletions(-) diff --git a/packages/server/app.ts b/packages/server/app.ts index 26bc98c38..1edea2c7f 100644 --- a/packages/server/app.ts +++ b/packages/server/app.ts @@ -1,3 +1,4 @@ +/* eslint-disable camelcase */ /* istanbul ignore file */ import './bootstrap' import http from 'http' @@ -22,7 +23,8 @@ import prometheusClient from 'prom-client' import { ApolloServer, ForbiddenError, - ApolloServerExpressConfig + ApolloServerExpressConfig, + ApolloError } from 'apollo-server-express' import { ApolloServerPluginLandingPageLocalDefault } from 'apollo-server-core' @@ -51,9 +53,47 @@ import { determineClientIpAddressMiddleware, mixpanelTrackerHelperMiddleware } from '@/modules/shared/middleware' +import { GraphQLError } from 'graphql' +import { redactSensitiveVariables } from '@/logging/loggingHelper' let graphqlServer: ApolloServer +// eslint-disable-next-line @typescript-eslint/no-explicit-any +type SubscriptionResponse = { errors?: GraphQLError[]; data?: any } + +function logSubscriptionOperation(params: { + ctx: GraphQLContext + execParams: ExecutionParams + error?: Error + response?: SubscriptionResponse +}) { + const { error, response, ctx, execParams } = params + if (!error && !response) return + + const logger = ctx.log.child({ + graphql_query: execParams.query.toString(), + graphql_variables: redactSensitiveVariables(execParams.variables), + graphql_operation_name: execParams.operationName, + graphql_operation_type: 'subscription' + }) + + const errors = response?.errors || (error ? [error] : []) + if (errors.length) { + for (const error of errors) { + if ( + (error instanceof GraphQLError && error.extensions?.code === 'FORBIDDEN') || + error instanceof ApolloError + ) { + logger.info(error, 'graphql error') + } else { + logger.error(error, 'graphql error') + } + } + } else if (response?.data) { + logger.info('graphql response') + } +} + /** * TODO: subscriptions-transport-ws is no longer maintained, we should migrate to graphql-ws insted. The problem * is that graphql-ws uses an entirely different protocol, so the client-side has to change as well, and so old clients @@ -135,12 +175,15 @@ function buildApolloSubscriptionServer( const baseParams = params[1] const ctx = baseParams.context as GraphQLContext - baseParams.formatResponse = (val: unknown) => { + // eslint-disable-next-line @typescript-eslint/no-explicit-any + baseParams.formatResponse = (val: SubscriptionResponse) => { ctx.loaders.clearAll() + logSubscriptionOperation({ ctx, execParams: baseParams, response: val }) return val } baseParams.formatError = (e: Error) => { ctx.loaders.clearAll() + logSubscriptionOperation({ ctx, execParams: baseParams, error: e }) return e } diff --git a/packages/server/logging/apolloPlugin.js b/packages/server/logging/apolloPlugin.js index 0846aecd6..179b46123 100644 --- a/packages/server/logging/apolloPlugin.js +++ b/packages/server/logging/apolloPlugin.js @@ -58,30 +58,27 @@ module.exports = { ctx.context.log = logger }, didEncounterErrors(ctx) { - if (!ctx.operation) return - let logger = ctx.context.log || graphqlLogger for (const err of ctx.errors) { - if (err instanceof ApolloError) { - continue - } - - const kind = ctx.operation.operation + const operationName = ctx.request.operationName || null const query = ctx.request.query const variables = ctx.request.variables if (err.path) { logger = logger.child({ 'query-path': err.path.join(' > ') }) } - if (err instanceof GraphQLError && err.extensions?.code === 'FORBIDDEN') { + if ( + (err instanceof GraphQLError && err.extensions?.code === 'FORBIDDEN') || + err instanceof ApolloError + ) { logger.info(err, 'graphql error') } else { logger.error(err, 'graphql error') } Sentry.withScope((scope) => { - scope.setTag('kind', kind) + scope.setTag('operationName', operationName) scope.setExtra('query', query) scope.setExtra('variables', variables) if (err.path) { diff --git a/packages/server/modules/shared/helpers/typeHelper.ts b/packages/server/modules/shared/helpers/typeHelper.ts index 7e2761a0a..aa876cd19 100644 --- a/packages/server/modules/shared/helpers/typeHelper.ts +++ b/packages/server/modules/shared/helpers/typeHelper.ts @@ -9,6 +9,7 @@ import { RequestDataLoaders } from '@/modules/core/loaders' import { AuthContext } from '@/modules/shared/authz' import { Express } from 'express' import { ConditionalKeys, SetRequired } from 'type-fest' +import pino from 'pino' export type MarkNullableOptional = SetRequired< Partial, @@ -45,6 +46,8 @@ export type GraphQLContext = AuthContext & { * @see https://github.com/graphql/dataloader */ loaders: RequestDataLoaders + + log: pino.Logger } export { Nullable, Optional, MaybeNullOrUndefined, MaybeAsync, MaybeFalsy } diff --git a/packages/server/modules/shared/middleware/index.ts b/packages/server/modules/shared/middleware/index.ts index 4c3987ee4..9f34b4271 100644 --- a/packages/server/modules/shared/middleware/index.ts +++ b/packages/server/modules/shared/middleware/index.ts @@ -17,12 +17,13 @@ import { Nullable } from '@/modules/shared/helpers/typeHelper' import { getUser } from '@/modules/core/repositories/users' -import { resolveMixpanelUserId } from '@speckle/shared' +import { Optional, resolveMixpanelUserId } from '@speckle/shared' import { mixpanel } from '@/modules/shared/utils/mixpanel' import { Observability } from '@speckle/shared' import { pino } from 'pino' import { getIpFromRequest } from '@/modules/shared/utils/ip' import { Netmask } from 'netmask' +import { Merge } from 'type-fest' export const authMiddlewareCreator = (steps: AuthPipelineFunction[]) => { const pipeline = authPipelineCreator(steps) @@ -110,15 +111,15 @@ export async function authContextMiddleware( } export function addLoadersToCtx( - ctx: AuthContext, + ctx: Merge, { log?: Optional }>, options?: Partial<{ cleanLoadersEarly: boolean }> ): GraphQLContext { + const log = + ctx.log || Observability.extendLoggerComponent(Observability.getLogger(), 'graphql') const loaders = buildRequestLoaders(ctx, options) - return { ...ctx, loaders } + return { ...ctx, loaders, log } } -type ApolloContext = AuthContext & { log?: pino.Logger } - /** * Build context for GQL operations */ @@ -131,17 +132,23 @@ export async function buildContext({ token: Nullable cleanLoadersEarly?: boolean }): Promise { - const ctx: ApolloContext = + const ctx = req?.context || (await createAuthContextFromToken(token ?? getTokenFromRequest(req))) - ctx.log = Observability.extendLoggerComponent( + const log = Observability.extendLoggerComponent( req?.log || Observability.getLogger(), 'graphql' ) // Adding request data loaders - return addLoadersToCtx(ctx, { cleanLoadersEarly }) + return addLoadersToCtx( + { + ...ctx, + log + }, + { cleanLoadersEarly } + ) } /**