chore(server/logging): add operation logging to automate module

- tidy up some passing of loggers to automate - do not use console.log, instead use @/observability/logging
2025-04-15 11:37:06 +01:00
parent 5e4890929f
commit a50e053096
6 changed files with 255 additions and 108 deletions
@@ -6,7 +6,7 @@ dist-*
 coverage
 .nyc_output
 packages/server/reports*
-packages/preview-service/public/render/**/*
+packages/preview-service/public/**/*
 packages/objectloader/examples/browser/objectloader.web.js
 packages/viewer/example/speckleviewer.web.js

@@ -1,4 +1,3 @@
-import { automateLogger } from '@/observability/logging'
 import {
  ExecutionEngineBadResponseBodyError,
  type ExecutionEngineErrorResponse,
@@ -29,8 +28,9 @@ import {
  timeoutAt
 } from '@speckle/shared'
 import { randomUUID } from 'crypto'
-import { Logger } from 'pino'
+import { automateLogger, type Logger } from '@/observability/logging'
 import { has, isObjectLike, isEmpty } from 'lodash'
+import { getRequestLogger } from '@/observability/components/express/requestContext'

 export type AuthCodePayloadWithOrigin = AuthCodePayload & { origin: string }

@@ -51,8 +51,10 @@ const getApiUrl = (
  path?: string,
  options?: Partial<{
    query: Record<string, string[] | string | number | boolean | undefined>
-  }>
+  }> & { logger?: Logger }
 ) => {
+  const logger = options?.logger || getRequestLogger() || automateLogger
+
  const automateUrl = speckleAutomateUrl()
  if (!automateUrl)
    throw new MisconfiguredEnvironmentError(
@@ -70,7 +72,8 @@ const getApiUrl = (
        const urlValue = typeof val === 'object' ? val.join(',') : val.toString()
        url.searchParams.append(key, urlValue)
      } catch {
-        console.log({ val })
+        logger.warn({ automateUrl: val }, 'Failed to parse query param')
+        //ignore
      }
    })
  }
@@ -119,6 +122,7 @@ const invokeRequest = async (params: {
  retry?: boolean
 }) => {
  const { url, method = 'get', body, token, requestId } = params
+  const logger = getRequestLogger() || automateLogger

  const response = await retry(
    async () =>
@@ -138,7 +142,7 @@ const invokeRequest = async (params: {
      ]),
    params.retry !== false ? 3 : 1,
    (i, error) => {
-      automateLogger.warn(
+      logger.warn(
        { url, method, err: error },
        'Automate Execution Engine API call failed, retrying...'
      )
@@ -408,7 +412,8 @@ export const getFunctionFactory =
      : undefined

    const url = getApiUrl(`/api/v1/functions/${functionId}`, {
-      query
+      query,
+      logger
    })

    return await invokeSafeJsonRequestFactory<GetFunctionResponse>({
@@ -462,7 +467,10 @@ export const getFunctionReleaseFactory =
    const { logger } = deps
    const { functionId, functionReleaseId } = params
    const url = getApiUrl(
-      `/api/v1/functions/${functionId}/versions/${functionReleaseId}`
+      `/api/v1/functions/${functionId}/versions/${functionReleaseId}`,
+      {
+        logger
+      }
    )

    const result = await invokeSafeJsonRequestFactory<GetFunctionReleaseResponse>({
@@ -507,7 +515,8 @@ export const getFunctionsFactory =
      query: {
        requireRelease: true,
        ...params.filters
-      }
+      },
+      logger
    })

    const authToken = params.auth
@@ -548,7 +557,8 @@ export const getPublicFunctionsFactory =
      query: {
        ...query,
        featuredFunctionsOnly: true
-      }
+      },
+      logger
    })

    return await invokeSafeJsonRequestFactory<GetFunctionsResponse>({
@@ -578,7 +588,7 @@ export const getUserFunctionsFactory =
  }) => {
    const { logger } = deps
    const { userId, query, body } = params
-    const url = getApiUrl(`/api/v2/users/${userId}/functions`, { query })
+    const url = getApiUrl(`/api/v2/users/${userId}/functions`, { query, logger })

    return await invokeSafeJsonRequestFactory<GetUserFunctionsResponse>({
      logger
@@ -609,7 +619,10 @@ export const getWorkspaceFunctionsFactory =
  }) => {
    const { logger } = deps
    const { workspaceId, query, body } = params
-    const url = getApiUrl(`/api/v2/workspaces/${workspaceId}/functions`, { query })
+    const url = getApiUrl(`/api/v2/workspaces/${workspaceId}/functions`, {
+      query,
+      logger
+    })

    return await invokeSafeJsonRequestFactory<GetWorkspaceFunctionsResponse>({
      logger
@@ -73,10 +73,7 @@ import {
  manuallyTriggerAutomationFactory,
  triggerAutomationRevisionRunFactory
 } from '@/modules/automate/services/trigger'
-import {
-  reportFunctionRunStatusFactory,
-  ReportFunctionRunStatusDeps
-} from '@/modules/automate/services/runsManagement'
+import { reportFunctionRunStatusFactory } from '@/modules/automate/services/runsManagement'
 import {
  AutomationNotFoundError,
  FunctionNotFoundError
@@ -125,6 +122,7 @@ import {
 import { getEventBus } from '@/modules/shared/services/eventBus'
 import { getProjectDbClient } from '@/modules/multiregion/utils/dbSelector'
 import { BranchNotFoundError } from '@/modules/core/errors/branch'
+import { withOperationLogging } from '@/observability/domain/businessLogging'

 const { FF_AUTOMATE_MODULE_ENABLED } = getFeatureFlags()

@@ -533,54 +531,90 @@ export = (FF_AUTOMATE_MODULE_ENABLED
      },
      AutomateMutations: {
        async createFunction(_parent, args, ctx) {
+          const logger = ctx.log
          const create = createFunctionFromTemplateFactory({
            createExecutionEngineFn: createFunction,
            getUser: getUserFactory({ db }),
            createStoredAuthCode: createStoredAuthCodeFactory({
              redis: getGenericRedis()
-            })
+            }),
+            logger
          })

-          return (await create({ input: args.input, userId: ctx.userId! }))
-            .graphqlReturn
+          const { graphqlReturn } = await withOperationLogging(
+            async () => await create({ input: args.input, userId: ctx.userId! }),
+            {
+              logger,
+              operationName: 'createFunction',
+              operationDescription: 'Create a new Automate function'
+            }
+          )
+          return graphqlReturn
        },
        async createFunctionWithoutVersion(_parent, args, ctx) {
+          const logger = ctx.log
+
          const authCode = await createStoredAuthCodeFactory({
            redis: getGenericRedis()
          })({
            userId: ctx.userId!,
            action: AuthCodePayloadAction.CreateFunction
          })
-          return await createFunctionWithoutVersion({
-            body: {
-              speckleServerAuthenticationPayload: {
-                ...authCode,
-                origin: getServerOrigin()
-              },
-              functionName: args.input.name,
-              description: args.input.description,
-              repositoryUrl:
-                'https://github.com/specklesystems/speckle_automate_python_example',
-              supportedSourceApps: [],
-              tags: []
+          return await withOperationLogging(
+            async () =>
+              await createFunctionWithoutVersion({
+                body: {
+                  speckleServerAuthenticationPayload: {
+                    ...authCode,
+                    origin: getServerOrigin()
+                  },
+                  functionName: args.input.name,
+                  description: args.input.description,
+                  repositoryUrl:
+                    'https://github.com/specklesystems/speckle_automate_python_example',
+                  supportedSourceApps: [],
+                  tags: []
+                }
+              }),
+            {
+              logger,
+              operationName: 'createFunctionWithoutVersion',
+              operationDescription: 'Create a new Automate function without version'
            }
-          })
+          )
        },
        async updateFunction(_parent, args, ctx) {
+          const functionId = args.input.id
+          const logger = ctx.log.child({
+            functionId
+          })
          const update = updateFunctionFactory({
            updateFunction: execEngineUpdateFunction,
-            getFunction: getFunctionFactory({ logger: ctx.log }),
+            getFunction: getFunctionFactory({ logger }),
            createStoredAuthCode: createStoredAuthCodeFactory({
              redis: getGenericRedis()
-            }),
-            logger: ctx.log
+            })
          })
-          return await update({ input: args.input, userId: ctx.userId! })
+          return await withOperationLogging(
+            async () => await update({ input: args.input, userId: ctx.userId! }),
+            {
+              logger,
+              operationName: 'updateFunction',
+              operationDescription: 'Update an Automate function'
+            }
+          )
        }
      },
      ProjectAutomationMutations: {
        async create(parent, { input }, ctx) {
-          const projectDb = await getProjectDbClient({ projectId: parent.projectId })
+          const projectId = parent.projectId
+
+          const logger = ctx.log.child({
+            projectId,
+            streamId: projectId //legacy
+          })
+
+          const projectDb = await getProjectDbClient({ projectId })

          const create = createAutomationFactory({
            createAuthCode: createStoredAuthCodeFactory({ redis: getGenericRedis() }),
@@ -591,17 +625,34 @@ export = (FF_AUTOMATE_MODULE_ENABLED
            eventEmit: getEventBus().emit
          })

-          return (
-            await create({
-              input,
-              userId: ctx.userId!,
-              projectId: parent.projectId,
-              userResourceAccessRules: ctx.resourceAccessRules
-            })
-          ).automation
+          const { automation } = await withOperationLogging(
+            async () =>
+              await create({
+                input,
+                userId: ctx.userId!,
+                projectId,
+                userResourceAccessRules: ctx.resourceAccessRules
+              }),
+            {
+              logger,
+              operationName: 'createProjectAutomation',
+              operationDescription: 'Create a new Automation attached to a project'
+            }
+          )
+
+          return automation
        },
        async update(parent, { input }, ctx) {
-          const projectDb = await getProjectDbClient({ projectId: parent.projectId })
+          const projectId = parent.projectId
+          const automationId = input.id
+
+          const logger = ctx.log.child({
+            projectId,
+            streamId: projectId, //legacy
+            automationId
+          })
+
+          const projectDb = await getProjectDbClient({ projectId })

          const update = validateAndUpdateAutomationFactory({
            getAutomation: getAutomationFactory({ db: projectDb }),
@@ -610,15 +661,32 @@ export = (FF_AUTOMATE_MODULE_ENABLED
            eventEmit: getEventBus().emit
          })

-          return await update({
-            input,
-            userId: ctx.userId!,
-            projectId: parent.projectId,
-            userResourceAccessRules: ctx.resourceAccessRules
-          })
+          return await withOperationLogging(
+            async () =>
+              await update({
+                input,
+                userId: ctx.userId!,
+                projectId,
+                userResourceAccessRules: ctx.resourceAccessRules
+              }),
+            {
+              logger,
+              operationName: 'updateProjectAutomation',
+              operationDescription: 'Update an Automation attached to a project'
+            }
+          )
        },
        async createRevision(parent, { input }, ctx) {
-          const projectDb = await getProjectDbClient({ projectId: parent.projectId })
+          const projectId = parent.projectId
+          const automationId = input.automationId
+
+          const logger = ctx.log.child({
+            projectId,
+            streamId: projectId, //legacy
+            automationId
+          })
+
+          const projectDb = await getProjectDbClient({ projectId })

          const create = createAutomationRevisionFactory({
            getAutomation: getAutomationFactory({ db: projectDb }),
@@ -634,15 +702,31 @@ export = (FF_AUTOMATE_MODULE_ENABLED
            validateStreamAccess
          })

-          return await create({
-            input,
-            projectId: parent.projectId,
-            userId: ctx.userId!,
-            userResourceAccessRules: ctx.resourceAccessRules
-          })
+          return await withOperationLogging(
+            async () =>
+              await create({
+                input,
+                projectId,
+                userId: ctx.userId!,
+                userResourceAccessRules: ctx.resourceAccessRules
+              }),
+            {
+              logger,
+              operationName: 'createAutomationRevision',
+              operationDescription: 'Create a new Automation revision'
+            }
+          )
        },
        async trigger(parent, { automationId }, ctx) {
-          const projectDb = await getProjectDbClient({ projectId: parent.projectId })
+          const projectId = parent.projectId
+
+          const logger = ctx.log.child({
+            projectId,
+            streamId: projectId, //legacy
+            automationId
+          })
+
+          const projectDb = await getProjectDbClient({ projectId })

          const trigger = manuallyTriggerAutomationFactory({
            getAutomationTriggerDefinitions: getAutomationTriggerDefinitionsFactory({
@@ -668,17 +752,32 @@ export = (FF_AUTOMATE_MODULE_ENABLED
            validateStreamAccess
          })

-          const { automationRunId } = await trigger({
-            automationId,
-            userId: ctx.userId!,
-            userResourceAccessRules: ctx.resourceAccessRules,
-            projectId: parent.projectId
-          })
+          const { automationRunId } = await withOperationLogging(
+            async () =>
+              await trigger({
+                automationId,
+                userId: ctx.userId!,
+                userResourceAccessRules: ctx.resourceAccessRules,
+                projectId
+              }),
+            {
+              logger,
+              operationName: 'triggerProjectAutomation',
+              operationDescription: 'Trigger an Automation'
+            }
+          )

          return automationRunId
        },
        async createTestAutomation(parent, { input }, ctx) {
-          const projectDb = await getProjectDbClient({ projectId: parent.projectId })
+          const projectId = parent.projectId
+
+          const logger = ctx.log.child({
+            projectId,
+            streamId: projectId //legacy
+          })
+
+          const projectDb = await getProjectDbClient({ projectId })

          const create = createTestAutomationFactory({
            getEncryptionKeyPair,
@@ -689,14 +788,30 @@ export = (FF_AUTOMATE_MODULE_ENABLED
            eventEmit: getEventBus().emit
          })

-          return await create({
-            input,
-            projectId: parent.projectId,
-            userId: ctx.userId!,
-            userResourceAccessRules: ctx.resourceAccessRules
-          })
+          return await withOperationLogging(
+            async () =>
+              await create({
+                input,
+                projectId,
+                userId: ctx.userId!,
+                userResourceAccessRules: ctx.resourceAccessRules
+              }),
+            {
+              logger,
+              operationName: 'createTestAutomation',
+              operationDescription: 'Create a new test Automation'
+            }
+          )
        },
        async createTestAutomationRun(parent, { automationId }, ctx) {
+          const projectId = parent.projectId
+
+          const logger = ctx.log.child({
+            projectId,
+            streamId: projectId, //legacy
+            automationId
+          })
+
          const projectDb = await getProjectDbClient({ projectId: parent.projectId })

          const create = createTestAutomationRunFactory({
@@ -725,11 +840,19 @@ export = (FF_AUTOMATE_MODULE_ENABLED
            validateStreamAccess
          })

-          return await create({
-            projectId: parent.projectId,
-            automationId,
-            userId: ctx.userId!
-          })
+          return await withOperationLogging(
+            async () =>
+              await create({
+                projectId: parent.projectId,
+                automationId,
+                userId: ctx.userId!
+              }),
+            {
+              logger,
+              operationName: 'createTestAutomationRun',
+              operationDescription: 'Create a new test Automation run'
+            }
+          )
        }
      },
      Query: {
@@ -928,9 +1051,17 @@ export = (FF_AUTOMATE_MODULE_ENABLED
        }
      },
      Mutation: {
-        async automateFunctionRunStatusReport(_parent, { input }) {
+        async automateFunctionRunStatusReport(_parent, { input }, ctx) {
+          const projectId = input.projectId
+          const functionRunId = input.functionRunId
+          const logger = ctx.log.child({
+            projectId,
+            streamId: projectId, //legacy
+            functionRunId
+          })
+
          const projectDb = await getProjectDbClient({ projectId: input.projectId })
-          const deps: ReportFunctionRunStatusDeps = {
+          const reportFunctionRunStatus = reportFunctionRunStatusFactory({
            getAutomationFunctionRunRecord: getFunctionRunFactory({
              db: projectDb
            }),
@@ -941,18 +1072,25 @@ export = (FF_AUTOMATE_MODULE_ENABLED
              db: projectDb
            }),
            emitEvent: getEventBus().emit
-          }
+          })

-          const payload = {
-            ...input,
-            contextView: input.contextView ?? null,
-            results: (input.results as Automate.AutomateTypes.ResultsSchema) ?? null,
-            runId: input.functionRunId,
-            status: mapGqlStatusToDbStatus(input.status),
-            statusMessage: input.statusMessage ?? null
-          }
-
-          const result = await reportFunctionRunStatusFactory(deps)(payload)
+          const result = await withOperationLogging(
+            async () =>
+              await reportFunctionRunStatus({
+                ...input,
+                contextView: input.contextView ?? null,
+                results:
+                  (input.results as Automate.AutomateTypes.ResultsSchema) ?? null,
+                runId: input.functionRunId,
+                status: mapGqlStatusToDbStatus(input.status),
+                statusMessage: input.statusMessage ?? null
+              }),
+            {
+              logger,
+              operationName: 'automateFunctionRunStatusReport',
+              operationDescription: 'Report the status of a function run'
+            }
+          )

          return result
        },
@@ -43,7 +43,7 @@ import {
  speckleAutomateUrl
 } from '@/modules/shared/helpers/envHelper'
 import { getFunctionsMarketplaceUrl } from '@/modules/core/helpers/routeHelper'
-import { automateLogger, Logger } from '@/observability/logging'
+import type { Logger } from '@/observability/logging'
 import { CreateStoredAuthCode } from '@/modules/automate/domain/operations'
 import { GetUser } from '@/modules/core/domain/users/operations'
 import { noop } from 'lodash'
@@ -132,13 +132,14 @@ export type CreateFunctionDeps = {
  createStoredAuthCode: CreateStoredAuthCode
  createExecutionEngineFn: typeof createFunction
  getUser: GetUser
+  logger: Logger
 }

 export const createFunctionFromTemplateFactory =
  (deps: CreateFunctionDeps) =>
  async (params: { input: CreateAutomateFunctionInput; userId: string }) => {
    const { input, userId } = params
-    const { createExecutionEngineFn, getUser, createStoredAuthCode } = deps
+    const { createExecutionEngineFn, getUser, createStoredAuthCode, logger } = deps

    // Validate user
    const user = await getUser(userId)
@@ -163,7 +164,7 @@ export const createFunctionFromTemplateFactory =
    const created = await createExecutionEngineFn({ body })

    if (isDevEnv() && created) {
-      automateLogger.info({ created }, `[dev] Created function #${created.functionId}`)
+      logger.info({ created }, `[dev] Created function #${created.functionId}`)
    }

    // Don't want to pull the function w/ another req, so we'll just return the input
@@ -197,16 +198,15 @@ export type UpdateFunctionDeps = {
  updateFunction: typeof updateExecEngineFunction
  getFunction: ReturnType<typeof getFunctionFactory>
  createStoredAuthCode: CreateStoredAuthCode
-  logger: Logger
 }

 export const updateFunctionFactory =
  (deps: UpdateFunctionDeps) =>
  async (params: { input: UpdateAutomateFunctionInput; userId: string }) => {
-    const { updateFunction, createStoredAuthCode, logger } = deps
+    const { getFunction, updateFunction, createStoredAuthCode } = deps
    const { input, userId } = params

-    const existingFn = await getFunctionFactory({ logger })({ functionId: input.id })
+    const existingFn = await getFunction({ functionId: input.id })
    if (!existingFn) {
      throw new AutomateFunctionUpdateError('Function not found')
    }
@@ -239,8 +239,6 @@ export const updateFunctionFactory =
      }
    })

-    console.log(JSON.stringify(apiResult, null, 2))
-
    return convertFunctionToGraphQLReturn(apiResult)
  }

@@ -85,15 +85,13 @@ export const resolveStatusFromFunctionRunStatuses = (
  return AutomationRunStatuses.succeeded
 }

-export type ReportFunctionRunStatusDeps = {
-  getAutomationFunctionRunRecord: GetFunctionRun
-  upsertAutomationFunctionRunRecord: UpsertAutomationFunctionRun
-  automationRunUpdater: UpdateAutomationRun
-  emitEvent: EventBusEmit
-}
-
 export const reportFunctionRunStatusFactory =
-  (deps: ReportFunctionRunStatusDeps) =>
+  (deps: {
+    getAutomationFunctionRunRecord: GetFunctionRun
+    upsertAutomationFunctionRunRecord: UpsertAutomationFunctionRun
+    automationRunUpdater: UpdateAutomationRun
+    emitEvent: EventBusEmit
+  }) =>
  async (
    params: Pick<
      AutomationFunctionRunRecord,
@@ -354,7 +354,7 @@ let graphqlServer: Optional<ApolloServer<GraphQLContext>> = undefined
 export const mochaHooks: mocha.RootHookObject = {
  beforeAll: async () => {
    if (isMultiRegionTestMode()) {
-      console.log('Running tests in multi-region mode...')
+      logger.info('Running tests in multi-region mode...')
    }

    logger.info('running before all')