diff --git a/.prettierignore b/.prettierignore index a7733da94..242072ef1 100644 --- a/.prettierignore +++ b/.prettierignore @@ -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 diff --git a/packages/server/modules/automate/clients/executionEngine.ts b/packages/server/modules/automate/clients/executionEngine.ts index 1248629ec..fc6890f3a 100644 --- a/packages/server/modules/automate/clients/executionEngine.ts +++ b/packages/server/modules/automate/clients/executionEngine.ts @@ -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 - }> + }> & { 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({ @@ -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({ @@ -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({ @@ -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({ 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({ logger diff --git a/packages/server/modules/automate/graph/resolvers/automate.ts b/packages/server/modules/automate/graph/resolvers/automate.ts index ea9fb53b6..1983ec04a 100644 --- a/packages/server/modules/automate/graph/resolvers/automate.ts +++ b/packages/server/modules/automate/graph/resolvers/automate.ts @@ -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 }, diff --git a/packages/server/modules/automate/services/functionManagement.ts b/packages/server/modules/automate/services/functionManagement.ts index 907c4255a..40ba3e02d 100644 --- a/packages/server/modules/automate/services/functionManagement.ts +++ b/packages/server/modules/automate/services/functionManagement.ts @@ -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 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) } diff --git a/packages/server/modules/automate/services/runsManagement.ts b/packages/server/modules/automate/services/runsManagement.ts index 9dc6e0902..65daf91ba 100644 --- a/packages/server/modules/automate/services/runsManagement.ts +++ b/packages/server/modules/automate/services/runsManagement.ts @@ -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, diff --git a/packages/server/test/hooks.ts b/packages/server/test/hooks.ts index 3bb73a083..03697c1ba 100644 --- a/packages/server/test/hooks.ts +++ b/packages/server/test/hooks.ts @@ -354,7 +354,7 @@ let graphqlServer: Optional> = 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')