fix(server): subscription request logging

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
         }
 

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) {

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<T> = SetRequired<
   Partial<T>,
@@ -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 }

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<Omit<GraphQLContext, 'loaders'>, { log?: Optional<pino.Logger> }>,
   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<string>
   cleanLoadersEarly?: boolean
 }): Promise<GraphQLContext> {
-  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 }
+  )
 }
 
 /**