chore(server/observability): logging of resolver to create checkout session (#4067)

packages/server/modules/gatekeeper/graph/resolvers/index.ts

@@ -1,7 +1,7 @@
 import { getFeatureFlags, getFrontendOrigin } from '@/modules/shared/helpers/envHelper'
-import { Resolvers } from '@/modules/core/graph/generated/graphql'
+import type { Resolvers } from '@/modules/core/graph/generated/graphql'
 import { authorizeResolver } from '@/modules/shared'
-import { Roles, throwUncoveredError } from '@speckle/shared'
+import { ensureError, Roles, throwUncoveredError } from '@speckle/shared'
 import {
   countWorkspaceRoleWithOptionalProjectRoleFactory,
   getWorkspaceFactory
@@ -35,6 +35,9 @@ import { calculateSubscriptionSeats } from '@/modules/gatekeeper/domain/billing'
 import { WorkspacePaymentMethod } from '@/test/graphql/generated/graphql'
 import { LogicError, NotImplementedError } from '@/modules/shared/errors'
 import { isNewPlanType } from '@/modules/gatekeeper/helpers/plans'
+import { extendLoggerComponent } from '@/observability/logging'
+import { OperationName, OperationStatus } from '@/observability/domain/fields'
+import { logWithErr } from '@/observability/utils/logLevels'
 
 const { FF_GATEKEEPER_MODULE_ENABLED, FF_BILLING_INTEGRATION_ENABLED } =
   getFeatureFlags()
@@ -138,8 +141,15 @@ export = FF_GATEKEEPER_MODULE_ENABLED
           return true
         },
         createCheckoutSession: async (parent, args, ctx) => {
+          let logger = extendLoggerComponent(
+            ctx.log,
+            'gatekeeper',
+            'resolvers',
+            'createCheckoutSession'
+          ).child(OperationName('createCheckoutSession'))
           const { workspaceId, workspacePlan, billingInterval, isCreateFlow } =
             args.input
+          logger = logger.child({ workspaceId, workspacePlan })
           const workspace = await getWorkspaceFactory({ db })({ workspaceId })
 
           if (!workspace) throw new WorkspaceNotFoundError()
@@ -159,22 +169,37 @@ export = FF_GATEKEEPER_MODULE_ENABLED
 
           const countRole = countWorkspaceRoleWithOptionalProjectRoleFactory({ db })
 
-          const session = await startCheckoutSessionFactory({
-            getWorkspaceCheckoutSession: getWorkspaceCheckoutSessionFactory({ db }),
-            getWorkspacePlan: getWorkspacePlanFactory({ db }),
-            countRole,
-            createCheckoutSession,
-            saveCheckoutSession: saveCheckoutSessionFactory({ db }),
-            deleteCheckoutSession: deleteCheckoutSessionFactory({ db })
-          })({
-            workspacePlan,
-            workspaceId,
-            workspaceSlug: workspace.slug,
-            isCreateFlow: isCreateFlow || false,
-            billingInterval
-          })
-
-          return session
+          try {
+            logger.info(OperationStatus.start, '[{operationName} ({operationStatus})]')
+            const session = await startCheckoutSessionFactory({
+              getWorkspaceCheckoutSession: getWorkspaceCheckoutSessionFactory({ db }),
+              getWorkspacePlan: getWorkspacePlanFactory({ db }),
+              countRole,
+              createCheckoutSession,
+              saveCheckoutSession: saveCheckoutSessionFactory({ db }),
+              deleteCheckoutSession: deleteCheckoutSessionFactory({ db })
+            })({
+              workspacePlan,
+              workspaceId,
+              workspaceSlug: workspace.slug,
+              isCreateFlow: isCreateFlow || false,
+              billingInterval
+            })
+            logger.info(
+              { ...OperationStatus.success, sessionId: session.id },
+              '[{operationName} ({operationStatus})]'
+            )
+            return session
+          } catch (err) {
+            const e = ensureError(err, 'Unknown error creating checkout session')
+            logWithErr(
+              logger,
+              e,
+              { ...OperationStatus.failure },
+              '[{operationName} ({operationStatus})]'
+            )
+            throw e
+          }
         },
         upgradePlan: async (_parent, args, ctx) => {
           const { workspaceId, workspacePlan, billingInterval } = args.input

packages/server/modules/gatekeeper/services/checkout.ts

@@ -97,11 +97,7 @@ export const startCheckoutSessionFactory =
       if (workspaceCheckoutSession.paymentStatus === 'paid')
         // this is should not be possible, but its better to be checking it here, than double charging the customer
         throw new WorkspaceAlreadyPaidError()
-      if (
-        new Date().getTime() - workspaceCheckoutSession.createdAt.getTime() >
-        1000
-        // 10 * 60 * 1000
-      ) {
+      if (new Date().getTime() - workspaceCheckoutSession.createdAt.getTime() > 1000) {
         await deleteCheckoutSession({
           checkoutSessionId: workspaceCheckoutSession.id
         })

packages/server/observability/components/apollo/apolloSubscriptions.ts

@@ -1,10 +1,7 @@
 /* eslint-disable camelcase */
 import type { GraphQLContext } from '@/modules/shared/helpers/typeHelper'
 import type { ExecutionParams } from 'subscriptions-transport-ws'
-import {
-  shouldLogAsInfoLevel,
-  shouldLogAsWarnLevel
-} from '@/observability/utils/logLevels'
+import { logWithErr } from '@/observability/utils/logLevels'
 import { BaseError } from '@/modules/shared/errors'
 import { GraphQLError } from 'graphql'
 import { redactSensitiveVariables } from '@/observability/utils/redact'
@@ -108,13 +105,7 @@ export function logSubscriptionOperation(params: {
       if (error instanceof BaseError) {
         errorLogger = errorLogger.child({ ...error.info() })
       }
-      if (shouldLogAsInfoLevel(error)) {
-        errorLogger.info({ err: error }, errMsg)
-      } else if (shouldLogAsWarnLevel(error)) {
-        errorLogger.warn({ err: error }, errMsg)
-      } else {
-        errorLogger.error({ err: error }, errMsg)
-      }
+      logWithErr(errorLogger, error, errMsg)
     }
   } else if (response?.data) {
     logger.info('GQL subscription event {graphql_operation_name} emitted')

packages/server/observability/domain/fields.ts

@@ -0,0 +1,31 @@
+/**
+ * Helper constants for log fields.
+ * Intended to be used as values when logging.
+ */
+
+/**
+ * Operation status values.
+ * Intended to be used with the `operationStatus` field when logging.
+ * Helps to avoid typos and ensure consistency.
+ */
+const STATUS = {
+  START: 'start',
+  SUCCESS: 'success',
+  FAILURE: 'failure'
+} as const
+
+export const OperationStatus = {
+  start: {
+    operationStatus: STATUS.START
+  },
+  success: {
+    operationStatus: STATUS.SUCCESS
+  },
+  failure: {
+    operationStatus: STATUS.FAILURE
+  }
+} as const
+
+export const OperationName = (name: string) => ({
+  operationName: name
+})

packages/server/observability/utils/logLevels.ts

@@ -1,7 +1,28 @@
 import { BaseError } from '@/modules/shared/errors'
 import { isUserGraphqlError } from '@/modules/shared/helpers/graphqlHelper'
 import { ApolloError } from '@apollo/client/core'
+import { ensureError } from '@speckle/shared'
 import { GraphQLError } from 'graphql'
+import type { Logger } from 'pino'
+
+interface LogFn {
+  (logger: Logger, e: unknown, obj?: unknown, msg?: string, ...args: unknown[]): void
+}
+
+/**
+ * Uses the provided error to determine which log level to use, and adds the error to the logger instance.
+ * @param logger The logger instance
+ * @param e The error which will be used to determine the log level. It will be added to the logger instance.
+ * @param obj The object providing additional context to the log message (see Pino documentation https://github.com/pinojs/pino/blob/main/docs/api.md#logging-method-parameters)
+ * @param msg The message to log (see Pino documentation https://github.com/pinojs/pino/blob/main/docs/api.md#logging-method-parameters)
+ * @param args Additional arguments to log (see Pino documentation https://github.com/pinojs/pino/blob/main/docs/api.md#logging-method-parameters)
+ */
+export const logWithErr: LogFn = (logger, e, obj, msg?, ...args) => {
+  const err = ensureError(e)
+  if (shouldLogAsInfoLevel(err)) return logger.child({ err }).info(obj, msg, ...args)
+  if (shouldLogAsWarnLevel(err)) return logger.child({ err }).warn(obj, msg, ...args)
+  return logger.child({ err }).error(obj, msg, ...args)
+}
 
 export const shouldLogAsInfoLevel = (err: unknown): boolean => {
   if (err instanceof GraphQLError) {
@@ -22,7 +43,7 @@ export const shouldLogAsInfoLevel = (err: unknown): boolean => {
   return err instanceof ApolloError
 }
 
-export const shouldLogAsWarnLevel = (err: unknown): boolean => {
+const shouldLogAsWarnLevel = (err: unknown): boolean => {
   if (!(err instanceof GraphQLError)) return false
 
   if (err.message.startsWith('Cannot return null for non-nullable field')) return true