From 3b1dd93096dc87972c6425f1d43bc8cc80ed79ae Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gerg=C5=91=20Jedlicska?= <57442769+gjedlicska@users.noreply.github.com> Date: Thu, 11 Jan 2024 13:24:30 +0100 Subject: [PATCH 01/17] gergo/apolloQueryDuration (#1949) * add apollo query duration * feat: add more details to apollo query logging * fix: pr review --- packages/server/logging/apolloPlugin.js | 21 ++++++++++++++++++--- 1 file changed, 18 insertions(+), 3 deletions(-) diff --git a/packages/server/logging/apolloPlugin.js b/packages/server/logging/apolloPlugin.js index 44cf779197..d47862688d 100644 --- a/packages/server/logging/apolloPlugin.js +++ b/packages/server/logging/apolloPlugin.js @@ -18,6 +18,7 @@ const metricCallCount = new prometheusClient.Counter({ module.exports = { // eslint-disable-next-line no-unused-vars requestDidStart(ctx) { + const apolloRequestStart = Date.now() return { didResolveOperation(ctx) { let logger = ctx.context.log || graphqlLogger @@ -56,6 +57,9 @@ module.exports = { }, didEncounterErrors(ctx) { let logger = ctx.context.log || graphqlLogger + logger = logger.child({ + apollo_query_duration_ms: Date.now() - apolloRequestStart + }) for (const err of ctx.errors) { const operationName = ctx.request.operationName || null @@ -69,9 +73,15 @@ module.exports = { (err instanceof GraphQLError && err.extensions?.code === 'FORBIDDEN') || err instanceof ApolloError ) { - logger.info(err, 'graphql error') + logger.info( + { err }, + '{graphql_operation_value} failed after {apollo_query_duration_ms} ms' + ) } else { - logger.error(err, 'graphql error') + logger.error( + err, + '{graphql_operation_value} failed after {apollo_query_duration_ms} ms' + ) } Sentry.withScope((scope) => { @@ -92,11 +102,16 @@ module.exports = { }, willSendResponse(ctx) { const logger = ctx.context.log || graphqlLogger - logger.info('graphql response') if (ctx.request.transaction) { ctx.request.transaction.finish() } + logger.info( + { + apollo_query_duration_ms: Date.now() - apolloRequestStart + }, + '{graphql_operation_value} finished after {apollo_query_duration_ms} ms' + ) } } } From 0f6938ece737b2b4e7fd8ff6436aa318d454fa58 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gerg=C5=91=20Jedlicska?= <57442769+gjedlicska@users.noreply.github.com> Date: Thu, 11 Jan 2024 13:24:42 +0100 Subject: [PATCH 02/17] feat: format log messages as clef (#1950) --- packages/shared/src/observability/index.ts | 20 ++++++++++--- packages/shared/src/observability/pinoClef.ts | 29 +++++++++++++++++++ 2 files changed, 45 insertions(+), 4 deletions(-) create mode 100644 packages/shared/src/observability/pinoClef.ts diff --git a/packages/shared/src/observability/index.ts b/packages/shared/src/observability/index.ts index b35abe5edc..b88f6b3fe8 100644 --- a/packages/shared/src/observability/index.ts +++ b/packages/shared/src/observability/index.ts @@ -1,5 +1,6 @@ import pino from 'pino' import type { LoggerOptions } from 'pino' +import { toClef, clefLevels } from './pinoClef' let logger: pino.Logger @@ -9,12 +10,23 @@ export function getLogger(logLevel = 'info', pretty = false): pino.Logger { const pinoOptions: LoggerOptions = { base: undefined, // Set to undefined to avoid adding pid, hostname properties to each log. formatters: { - level: (label: string) => { - return { level: label } - } + level: (label: string, number: number) => + // for not pretty, we're providing clef levels + pretty + ? { level: label } + : { + '@l': + number in clefLevels + ? clefLevels[number as keyof typeof clefLevels] + : clefLevels[30] + }, + log: (logObject) => (pretty ? logObject : toClef(logObject)) }, + // when not pretty, to produce a clef format, we need the message to be the message template key + messageKey: pretty ? 'msg' : '@mt', level: logLevel, - timestamp: pino.stdTimeFunctions.isoTime + // when not pretty, we need the time in the clef appropriate field, not from pino + timestamp: pretty ? pino.stdTimeFunctions.isoTime : false } if (pretty) { diff --git a/packages/shared/src/observability/pinoClef.ts b/packages/shared/src/observability/pinoClef.ts new file mode 100644 index 0000000000..8c4e8fd25d --- /dev/null +++ b/packages/shared/src/observability/pinoClef.ts @@ -0,0 +1,29 @@ +export const clefLevels = { + 60: 5, // FATAL + 50: 4, // ERROR + 40: 3, // WARN + 30: 2, // INFO = default when not provided + 20: 1, // DEBUG + 10: 0 // TRACE / Verbose +} as const + +export function toClef(log: Record): Record { + // add the stuff CLEF wants .... + if (log.time) { + log['@t'] = new Date(log.time as Date).toISOString() + } else { + log['@t'] = new Date().toISOString() + } + + if (log.level && (log.level as number) in clefLevels) { + log['@l'] = clefLevels[log.level as keyof typeof clefLevels] + } + + const exception = log.error || log.err + if (exception) { + // Seq wants it as a string - try to prettify it with a legible stack trace + log['@x'] = (exception as Error).stack + } + + return log +} From 6a5df39d0270651d6889da236f220a8c66c484c5 Mon Sep 17 00:00:00 2001 From: Iain Sproat <68657+iainsproat@users.noreply.github.com> Date: Thu, 11 Jan 2024 11:21:22 +0000 Subject: [PATCH 03/17] fix(logging): pinoClef log levels must be a string --- packages/shared/src/observability/pinoClef.ts | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/packages/shared/src/observability/pinoClef.ts b/packages/shared/src/observability/pinoClef.ts index 8c4e8fd25d..55d43f4aae 100644 --- a/packages/shared/src/observability/pinoClef.ts +++ b/packages/shared/src/observability/pinoClef.ts @@ -1,10 +1,10 @@ export const clefLevels = { - 60: 5, // FATAL - 50: 4, // ERROR - 40: 3, // WARN - 30: 2, // INFO = default when not provided - 20: 1, // DEBUG - 10: 0 // TRACE / Verbose + 60: 'Fatal', // FATAL + 50: 'Error', // ERROR + 40: 'Warning', // WARN + 30: 'Information', // INFO = default when not provided + 20: 'Debug', // DEBUG + 10: 'Verbose' // TRACE / Verbose } as const export function toClef(log: Record): Record { From d6456368cb5ed884dbb891876ce20716303f76e9 Mon Sep 17 00:00:00 2001 From: Kristaps Fabians Geikins Date: Thu, 11 Jan 2024 14:21:54 +0200 Subject: [PATCH 04/17] chore(fe2): reducing log level for some spammy req logs --- packages/frontend-2/server/middleware/001-logging.ts | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/packages/frontend-2/server/middleware/001-logging.ts b/packages/frontend-2/server/middleware/001-logging.ts index c9c6dec971..a699abbddf 100644 --- a/packages/frontend-2/server/middleware/001-logging.ts +++ b/packages/frontend-2/server/middleware/001-logging.ts @@ -42,10 +42,14 @@ export const LoggingMiddleware = pinoHttp({ // and we don't really care about 3xx stuff // all the user related 4xx responses are treated as info customLogLevel: ( - _: IncomingMessage, + req: IncomingMessage, res: ServerResponse, error: Error | undefined ) => { + // Mark some lower importance/spammy endpoints w/ 'debug' to reduce noise + const shouldBeDebug = ['/metrics', '/health'].includes(req.url || '') ?? false + if (shouldBeDebug) return 'debug' + if (res.statusCode >= 400 && res.statusCode < 500) { return 'info' } else if (res.statusCode >= 500 || error) { From 79f415228ac2599dacae46671e9a84c151c50234 Mon Sep 17 00:00:00 2001 From: Kristaps Fabians Geikins Date: Thu, 11 Jan 2024 14:23:46 +0200 Subject: [PATCH 05/17] minor adjustment --- packages/frontend-2/server/middleware/001-logging.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/frontend-2/server/middleware/001-logging.ts b/packages/frontend-2/server/middleware/001-logging.ts index a699abbddf..28f4dc8ea8 100644 --- a/packages/frontend-2/server/middleware/001-logging.ts +++ b/packages/frontend-2/server/middleware/001-logging.ts @@ -48,7 +48,6 @@ export const LoggingMiddleware = pinoHttp({ ) => { // Mark some lower importance/spammy endpoints w/ 'debug' to reduce noise const shouldBeDebug = ['/metrics', '/health'].includes(req.url || '') ?? false - if (shouldBeDebug) return 'debug' if (res.statusCode >= 400 && res.statusCode < 500) { return 'info' @@ -57,7 +56,8 @@ export const LoggingMiddleware = pinoHttp({ } else if (res.statusCode >= 300 && res.statusCode < 400) { return 'silent' } - return 'info' + + return shouldBeDebug ? 'debug' : 'info' }, // we need to redact any potential sensitive data from being logged. From a656813601577f65ac9775dbf2122700a4ddcb8c Mon Sep 17 00:00:00 2001 From: Kristaps Fabians Geikins Date: Thu, 11 Jan 2024 14:24:38 +0200 Subject: [PATCH 06/17] more robust path resolution --- packages/frontend-2/server/middleware/001-logging.ts | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/packages/frontend-2/server/middleware/001-logging.ts b/packages/frontend-2/server/middleware/001-logging.ts index 28f4dc8ea8..57de3d7016 100644 --- a/packages/frontend-2/server/middleware/001-logging.ts +++ b/packages/frontend-2/server/middleware/001-logging.ts @@ -47,7 +47,8 @@ export const LoggingMiddleware = pinoHttp({ error: Error | undefined ) => { // Mark some lower importance/spammy endpoints w/ 'debug' to reduce noise - const shouldBeDebug = ['/metrics', '/health'].includes(req.url || '') ?? false + const path = req.url?.split('?')[0] + const shouldBeDebug = ['/metrics', '/health'].includes(path || '') ?? false if (res.statusCode >= 400 && res.statusCode < 500) { return 'info' From 48f5ecfade2b06c9c692d59f2090fe5a539849f2 Mon Sep 17 00:00:00 2001 From: Kristaps Fabians Geikins Date: Tue, 9 Jan 2024 15:53:28 +0200 Subject: [PATCH 07/17] better req log text --- .../lib/common/generated/gql/graphql.ts | 15 ++++++++++++--- .../frontend-2/server/middleware/001-logging.ts | 8 ++++++++ 2 files changed, 20 insertions(+), 3 deletions(-) diff --git a/packages/frontend-2/lib/common/generated/gql/graphql.ts b/packages/frontend-2/lib/common/generated/gql/graphql.ts index 189a1f05dd..339f8b7403 100644 --- a/packages/frontend-2/lib/common/generated/gql/graphql.ts +++ b/packages/frontend-2/lib/common/generated/gql/graphql.ts @@ -910,7 +910,7 @@ export type Mutation = { adminDeleteUser: Scalars['Boolean']; /** Creates an personal api token. */ apiTokenCreate: Scalars['String']; - /** Revokes (deletes) an personal api token. */ + /** Revokes (deletes) an personal api token/app token. */ apiTokenRevoke: Scalars['Boolean']; /** Register a new third party application. */ appCreate: Scalars['String']; @@ -918,6 +918,8 @@ export type Mutation = { appDelete: Scalars['Boolean']; /** Revokes (de-authorizes) an application that you have previously authorized. */ appRevokeAccess?: Maybe; + /** Create an app token. Only apps can create app tokens and they don't show up under personal access tokens. */ + appTokenCreate: Scalars['String']; /** Update an existing third party application. **Note: This will invalidate all existing tokens, refresh tokens and access codes and will require existing users to re-authorize it.** */ appUpdate: Scalars['Boolean']; automationMutations: AutomationMutations; @@ -1058,6 +1060,11 @@ export type MutationAppRevokeAccessArgs = { }; +export type MutationAppTokenCreateArgs = { + token: ApiTokenCreateInput; +}; + + export type MutationAppUpdateArgs = { app: AppUpdateInput; }; @@ -1808,6 +1815,8 @@ export type Query = { app?: Maybe; /** Returns all the publicly available apps on this server. */ apps?: Maybe>>; + /** If user is authenticated using an app token, this will describe the app */ + authenticatedAsApp?: Maybe; comment?: Maybe; /** * This query can be used in the following ways: @@ -2562,7 +2571,7 @@ export type User = { /** All the recent activity from this user in chronological order */ activity?: Maybe; /** Returns a list of your personal api tokens. */ - apiTokens?: Maybe>>; + apiTokens: Array; /** Returns the apps you have authorized. */ authorizedApps?: Maybe>>; avatar?: Maybe; @@ -3126,7 +3135,7 @@ export type EditApplicationMutation = { __typename?: 'Mutation', appUpdate: bool export type DeveloperSettingsAccessTokensQueryVariables = Exact<{ [key: string]: never; }>; -export type DeveloperSettingsAccessTokensQuery = { __typename?: 'Query', activeUser?: { __typename?: 'User', id: string, apiTokens?: Array<{ __typename?: 'ApiToken', id: string, name: string, lastUsed: string, lastChars: string, createdAt: string, scopes: Array } | null> | null } | null }; +export type DeveloperSettingsAccessTokensQuery = { __typename?: 'Query', activeUser?: { __typename?: 'User', id: string, apiTokens: Array<{ __typename?: 'ApiToken', id: string, name: string, lastUsed: string, lastChars: string, createdAt: string, scopes: Array }> } | null }; export type DeveloperSettingsApplicationsQueryVariables = Exact<{ [key: string]: never; }>; diff --git a/packages/frontend-2/server/middleware/001-logging.ts b/packages/frontend-2/server/middleware/001-logging.ts index 57de3d7016..d6c1329672 100644 --- a/packages/frontend-2/server/middleware/001-logging.ts +++ b/packages/frontend-2/server/middleware/001-logging.ts @@ -61,6 +61,14 @@ export const LoggingMiddleware = pinoHttp({ return shouldBeDebug ? 'debug' : 'info' }, + customSuccessMessage(req, res, responseTime) { + const path = req.url?.split('?')[0] ?? 'unknown' + const isCompleted = !req.readableAborted && res.writableEnded + const statusMessage = isCompleted ? 'request completed' : 'request aborted' + + return `[${path}] ${statusMessage} in ${responseTime}ms` + }, + // we need to redact any potential sensitive data from being logged. // as we do not know what headers may be sent in a request by a user or client // we have to allow list selected headers From 594c5d0c4445e866e3d91aae1c2a852695326bed Mon Sep 17 00:00:00 2001 From: Kristaps Fabians Geikins Date: Thu, 11 Jan 2024 12:15:45 +0200 Subject: [PATCH 08/17] feat(fe2): improved and more thorough logging to help with observability (#1948) * better req log text * minor improvements to server logging * WIP FE2 req logging * FE2 apollo operation logging * undid apolloPlugin changes due to Gergos PR * seq message templates introduced --- .../frontend-2/lib/core/configs/apollo.ts | 23 ++++- packages/frontend-2/nuxt.config.ts | 4 + packages/frontend-2/plugins/001-logger.ts | 39 +++++--- .../plugins/002-healthMetrics.server.ts | 27 ++++++ .../server/middleware/001-logging.ts | 11 +++ packages/server/logging/expressLogging.ts | 11 +++ packages/server/package.json | 4 +- packages/shared/package.json | 3 +- packages/shared/pinoPrettyTransport.js | 25 +++++ packages/shared/src/observability/index.ts | 2 +- yarn.lock | 92 +++++++++++++------ 11 files changed, 192 insertions(+), 49 deletions(-) create mode 100644 packages/frontend-2/plugins/002-healthMetrics.server.ts create mode 100644 packages/shared/pinoPrettyTransport.js diff --git a/packages/frontend-2/lib/core/configs/apollo.ts b/packages/frontend-2/lib/core/configs/apollo.ts index 9fffadebf3..eff4cd5429 100644 --- a/packages/frontend-2/lib/core/configs/apollo.ts +++ b/packages/frontend-2/lib/core/configs/apollo.ts @@ -378,7 +378,28 @@ function createLink(params: { ]) } - return from([errorLink, link]) + // SSR req logging link + const loggerLink = new ApolloLink((operation, forward) => { + const startTime = Date.now() + return forward(operation).map((result) => { + const elapsed = new Date().getTime() - startTime + const name = operation.operationName + const success = !!(result.data && !result.errors?.length) + + nuxtApp.$logger.info( + { + operation: name, + elapsed, + success + }, + `Apollo operation {operation} finished in {elapsed}ms` + ) + + return result + }) + }) + + return from([...(process.server ? [loggerLink] : []), errorLink, link]) } const defaultConfigResolver: ApolloConfigResolver = async () => { diff --git a/packages/frontend-2/nuxt.config.ts b/packages/frontend-2/nuxt.config.ts index c639cff665..d0d7f30c4a 100644 --- a/packages/frontend-2/nuxt.config.ts +++ b/packages/frontend-2/nuxt.config.ts @@ -175,5 +175,9 @@ export default defineNuxtConfig({ manifest[key] = oldManifest[key] } } + }, + + prometheus: { + verbose: false } }) diff --git a/packages/frontend-2/plugins/001-logger.ts b/packages/frontend-2/plugins/001-logger.ts index bc5318a093..8806667957 100644 --- a/packages/frontend-2/plugins/001-logger.ts +++ b/packages/frontend-2/plugins/001-logger.ts @@ -1,10 +1,11 @@ /* eslint-disable @typescript-eslint/restrict-template-expressions */ import { isString } from 'lodash-es' +import { useRequestId } from '~/lib/core/composables/server' import { isObjectLike } from '~~/lib/common/helpers/type' import { buildFakePinoLogger } from '~~/lib/core/helpers/observability' /** - * Pino logger in SSR, basic console.log fallback in CSR + * Setting up Pino logger in SSR, basic console.log fallback in CSR */ export default defineNuxtPlugin(async (nuxtApp) => { @@ -20,12 +21,27 @@ export default defineNuxtPlugin(async (nuxtApp) => { } = useRuntimeConfig() const route = useRoute() const router = useRouter() + const reqId = useRequestId() + + const collectMainInfo = (params: { isBrowser: boolean }) => { + return { + browser: params.isBrowser, + speckleServerVersion, + serverName, + frontendType: 'frontend-2', + route: route?.path, + routeDefinition: route.matched?.[route.matched.length - 1]?.path, + req: { id: reqId } + } + } // Set up logger let logger: ReturnType if (process.server) { const { buildLogger } = await import('~/server/lib/core/helpers/observability') - logger = buildLogger(logLevel, logPretty) + logger = buildLogger(logLevel, logPretty).child({ + ...collectMainInfo({ isBrowser: false }) + }) } else { if (logClientApiToken?.length && logClientApiEndpoint?.length) { const seq = await import('seq-logging/browser') @@ -46,17 +62,10 @@ export default defineNuxtPlugin(async (nuxtApp) => { return { userAgent, navigatorPlatform, navigatorVendor, url } } - const collectMainInfo = () => { - return { - browser: true, - speckleServerVersion, - serverName, - frontendType: 'frontend-2', - route: route?.path, - routeDefinition: route.matched?.[route.matched.length - 1]?.path, - ...collectBrowserInfo() - } - } + const collectCoreInfo = () => ({ + ...collectBrowserInfo(), + ...collectMainInfo({ isBrowser: true }) + }) const errorListener = (event: ErrorEvent | PromiseRejectionEvent) => { const isUnhandledRejection = isObjectLike(event) && 'reason' in event @@ -70,7 +79,7 @@ export default defineNuxtPlugin(async (nuxtApp) => { properties: { errorMessage: msg, isUnhandledRejection, - ...collectMainInfo() + ...collectCoreInfo() }, exception: err instanceof Error ? err.stack : `${err}` }) @@ -102,7 +111,7 @@ export default defineNuxtPlugin(async (nuxtApp) => { properties: { errorMessage, extraData: otherData, - ...collectMainInfo() + ...collectCoreInfo() }, exception }) diff --git a/packages/frontend-2/plugins/002-healthMetrics.server.ts b/packages/frontend-2/plugins/002-healthMetrics.server.ts new file mode 100644 index 0000000000..f9470d81b0 --- /dev/null +++ b/packages/frontend-2/plugins/002-healthMetrics.server.ts @@ -0,0 +1,27 @@ +/** + * Sending SSR request health metrics to the logger + */ +export default defineNuxtPlugin((ctx) => { + const router = useRouter() + const logger = useLogger() + + const path = router.currentRoute.value?.matched?.[0]?.path || 'empty' + const name = router.currentRoute.value?.name || 'empty' + + const state = { + start: Date.now(), + path: `${String(name)}: ${path}` + } + + ctx.hook('app:rendered', () => { + const endTime = Date.now() - state.start + logger.info( + { + responseTime: endTime, + routeName: name, + routePath: path + }, + `[{routePath}] SSR rendered in {responseTime}ms` + ) + }) +}) diff --git a/packages/frontend-2/server/middleware/001-logging.ts b/packages/frontend-2/server/middleware/001-logging.ts index d6c1329672..a07cc0a226 100644 --- a/packages/frontend-2/server/middleware/001-logging.ts +++ b/packages/frontend-2/server/middleware/001-logging.ts @@ -69,6 +69,17 @@ export const LoggingMiddleware = pinoHttp({ return `[${path}] ${statusMessage} in ${responseTime}ms` }, + customSuccessMessage(req, res) { + const isCompleted = !req.readableAborted && res.writableEnded + const statusMessage = isCompleted ? 'request completed' : 'request aborted' + + return `[{req.path}] ${statusMessage} in {responseTime}ms` + }, + + customErrorMessage() { + return `[{req.path}] request errored` + }, + // we need to redact any potential sensitive data from being logged. // as we do not know what headers may be sent in a request by a user or client // we have to allow list selected headers diff --git a/packages/server/logging/expressLogging.ts b/packages/server/logging/expressLogging.ts index 2fedbcdb60..256cea7dc9 100644 --- a/packages/server/logging/expressLogging.ts +++ b/packages/server/logging/expressLogging.ts @@ -34,6 +34,17 @@ export const LoggingExpressMiddleware = HttpLogger({ return 'info' }, + customSuccessMessage(req, res) { + const isCompleted = !req.readableAborted && res.writableEnded + const statusMessage = isCompleted ? 'request completed' : 'request aborted' + + return `[{req.path}] ${statusMessage} in {responseTime}ms` + }, + + customErrorMessage() { + return `[{req.path}] request errored` + }, + // we need to redact any potential sensitive data from being logged. // as we do not know what headers may be sent in a request by a user or client // we have to allow list selected headers diff --git a/packages/server/package.json b/packages/server/package.json index 6d4a4240ef..ee2a958587 100644 --- a/packages/server/package.json +++ b/packages/server/package.json @@ -45,7 +45,7 @@ "@speckle/objectloader": "workspace:^", "@speckle/shared": "workspace:^", "@types/mailchimp__mailchimp_marketing": "^3.0.9", - "@types/pino-http": "^5.8.1", + "@types/pino-http": "^5.8.4", "@types/uuid": "^9.0.0", "apollo-server-express": "^3.10.2", "bcrypt": "^5.0.0", @@ -89,7 +89,7 @@ "pg": "^8.7.3", "pg-query-stream": "^4.2.3", "pino": "^8.7.0", - "pino-http": "^8.2.1", + "pino-http": "^8.6.1", "pino-pretty": "^9.1.1", "prom-client": "^14.0.1", "rate-limiter-flexible": "^2.4.1", diff --git a/packages/shared/package.json b/packages/shared/package.json index 100db52306..22f68f5ea0 100644 --- a/packages/shared/package.json +++ b/packages/shared/package.json @@ -39,7 +39,8 @@ "peerDependencies": { "@tiptap/core": "^2.0.0-beta.176", "pino": "^8.7.0", - "pino-http": "^8.0.0" + "pino-http": "^8.0.0", + "pino-pretty": ">=8.0.0" }, "devDependencies": { "@tiptap/core": "^2.0.0-beta.176", diff --git a/packages/shared/pinoPrettyTransport.js b/packages/shared/pinoPrettyTransport.js new file mode 100644 index 0000000000..6be5ff40dc --- /dev/null +++ b/packages/shared/pinoPrettyTransport.js @@ -0,0 +1,25 @@ +const { get, isString, isNumber, isBoolean } = require('lodash') + +// https://github.com/pinojs/pino-pretty?tab=readme-ov-file#handling-non-serializable-options +module.exports = (opts) => + require('pino-pretty')({ + ...opts, + /** + * Custom formatter to enable value interpolation locally + * @param {Record} log + * @param {string} messageKey + */ + messageFormat: (log, messageKey) => { + const msg = log[messageKey] + if (!msg) return undefined + + return msg.replace(/{([^{}]+)}/g, (match, p1) => { + const val = get(log, p1) + if (val === undefined) return match + + const formattedValue = + isString(val) || isNumber(val) || isBoolean(val) ? val : JSON.stringify(val) + return formattedValue + }) + } + }) diff --git a/packages/shared/src/observability/index.ts b/packages/shared/src/observability/index.ts index b88f6b3fe8..c70acd11d4 100644 --- a/packages/shared/src/observability/index.ts +++ b/packages/shared/src/observability/index.ts @@ -31,7 +31,7 @@ export function getLogger(logLevel = 'info', pretty = false): pino.Logger { if (pretty) { pinoOptions.transport = { - target: 'pino-pretty', + target: '../pinoPrettyTransport.js', options: { colorize: true, destination: 2, //stderr diff --git a/yarn.lock b/yarn.lock index 4837dd6e89..ec80aea1e9 100644 --- a/yarn.lock +++ b/yarn.lock @@ -13831,7 +13831,7 @@ __metadata: "@types/node-cron": ^3.0.2 "@types/nodemailer": ^6.4.5 "@types/pg": ^8.6.6 - "@types/pino-http": ^5.8.1 + "@types/pino-http": ^5.8.4 "@types/sanitize-html": ^2.6.2 "@types/supertest": ^2.0.12 "@types/uuid": ^9.0.0 @@ -13897,7 +13897,7 @@ __metadata: pg: ^8.7.3 pg-query-stream: ^4.2.3 pino: ^8.7.0 - pino-http: ^8.2.1 + pino-http: ^8.6.1 pino-pretty: ^9.1.1 prettier: ^2.5.1 prom-client: ^14.0.1 @@ -13947,6 +13947,7 @@ __metadata: "@tiptap/core": ^2.0.0-beta.176 pino: ^8.7.0 pino-http: ^8.0.0 + pino-pretty: ">=8.0.0" languageName: unknown linkType: soft @@ -16993,6 +16994,15 @@ __metadata: languageName: node linkType: hard +"@types/pino-http@npm:^5.8.4": + version: 5.8.4 + resolution: "@types/pino-http@npm:5.8.4" + dependencies: + "@types/pino": 6.3 + checksum: 9520c7ea5e2f4b6950d0635d26d3e37f70ef8199c3f6815e9f8dca887a9e967f81b4f1228b91d63b9506f4e9f3cac921170fd84b07ba62fbbe675b4d2579951a + languageName: node + linkType: hard + "@types/pino-pretty@npm:*": version: 4.7.5 resolution: "@types/pino-pretty@npm:4.7.5" @@ -37667,7 +37677,7 @@ __metadata: languageName: node linkType: hard -"pino-abstract-transport@npm:^1.0.0, pino-abstract-transport@npm:v1.0.0": +"pino-abstract-transport@npm:^1.0.0": version: 1.0.0 resolution: "pino-abstract-transport@npm:1.0.0" dependencies: @@ -37677,6 +37687,16 @@ __metadata: languageName: node linkType: hard +"pino-abstract-transport@npm:v1.1.0": + version: 1.1.0 + resolution: "pino-abstract-transport@npm:1.1.0" + dependencies: + readable-stream: ^4.0.0 + split2: ^4.0.0 + checksum: cc84caabee5647b5753ae484d5f63a1bca0f6e1791845e2db2b6d830a561c2b5dd1177720f68d78994c8a93aecc69f2729e6ac2bc871a1bf5bb4b0ec17210668 + languageName: node + linkType: hard + "pino-http@npm:^8.0.0, pino-http@npm:^8.3.3": version: 8.3.3 resolution: "pino-http@npm:8.3.3" @@ -37702,6 +37722,18 @@ __metadata: languageName: node linkType: hard +"pino-http@npm:^8.6.1": + version: 8.6.1 + resolution: "pino-http@npm:8.6.1" + dependencies: + get-caller-file: ^2.0.5 + pino: ^8.17.1 + pino-std-serializers: ^6.2.2 + process-warning: ^3.0.0 + checksum: 988e3e838a5a68b062e07da96d2c990ea6f60d5d17cee00e97bd7af6cb7a60fc7f15e6aaa682340b63e848796b178a925f625ea54e429e3fa019a9edded25787 + languageName: node + linkType: hard + "pino-pretty@npm:^10.0.1": version: 10.0.1 resolution: "pino-pretty@npm:10.0.1" @@ -37757,45 +37789,31 @@ __metadata: languageName: node linkType: hard -"pino@npm:^8.0.0, pino@npm:^8.7.0": - version: 8.7.0 - resolution: "pino@npm:8.7.0" - dependencies: - atomic-sleep: ^1.0.0 - fast-redact: ^3.1.1 - on-exit-leak-free: ^2.1.0 - pino-abstract-transport: v1.0.0 - pino-std-serializers: ^6.0.0 - process-warning: ^2.0.0 - quick-format-unescaped: ^4.0.3 - real-require: ^0.2.0 - safe-stable-stringify: ^2.3.1 - sonic-boom: ^3.1.0 - thread-stream: ^2.0.0 - bin: - pino: bin.js - checksum: 4aa2e320aa88f4a90fd25884ee4e3b9ef7963b3c59c514f3693b5a5c987b112cf3ab4e39a8c51efe32c861f5c058d7cfa7fcda59d964ed878f842fdbc6ab2876 +"pino-std-serializers@npm:^6.2.2": + version: 6.2.2 + resolution: "pino-std-serializers@npm:6.2.2" + checksum: aeb0662edc46ec926de9961ed4780a4f0586bb7c37d212cd469c069639e7816887a62c5093bc93f260a4e0900322f44fc8ab1343b5a9fa2864a888acccdb22a4 languageName: node linkType: hard -"pino@npm:^8.14.1": - version: 8.14.1 - resolution: "pino@npm:8.14.1" +"pino@npm:^8.0.0, pino@npm:^8.14.1, pino@npm:^8.17.1, pino@npm:^8.7.0": + version: 8.17.2 + resolution: "pino@npm:8.17.2" dependencies: atomic-sleep: ^1.0.0 fast-redact: ^3.1.1 on-exit-leak-free: ^2.1.0 - pino-abstract-transport: v1.0.0 + pino-abstract-transport: v1.1.0 pino-std-serializers: ^6.0.0 - process-warning: ^2.0.0 + process-warning: ^3.0.0 quick-format-unescaped: ^4.0.3 real-require: ^0.2.0 safe-stable-stringify: ^2.3.1 - sonic-boom: ^3.1.0 + sonic-boom: ^3.7.0 thread-stream: ^2.0.0 bin: pino: bin.js - checksum: 72dcae8f550d375695bb8745f11b30c42aaa20d0bcab8f546ca5af0684d784453850949fe1b244206793e813a46d72cbbf0dda8aed2cee86e9491ba44a643e3e + checksum: fc769d3d7b1333de94d51815fbe2abc4a1cc07cb0252a399313e54e26c13da2c0a69b227c296bd95ed52660d7eaa993662a9bf270b7370d0f7553fdd38716b63 languageName: node linkType: hard @@ -38805,6 +38823,13 @@ __metadata: languageName: node linkType: hard +"process-warning@npm:^3.0.0": + version: 3.0.0 + resolution: "process-warning@npm:3.0.0" + checksum: 1fc2eb4524041de3c18423334cc8b4e36bec5ad5472640ca1a936122c6e01da0864c1a4025858ef89aea93eabe7e77db93ccea225b10858617821cb6a8719efe + languageName: node + linkType: hard + "process@npm:^0.11.10": version: 0.11.10 resolution: "process@npm:0.11.10" @@ -41924,7 +41949,7 @@ __metadata: languageName: node linkType: hard -"sonic-boom@npm:^3.0.0, sonic-boom@npm:^3.1.0": +"sonic-boom@npm:^3.0.0": version: 3.2.0 resolution: "sonic-boom@npm:3.2.0" dependencies: @@ -41933,6 +41958,15 @@ __metadata: languageName: node linkType: hard +"sonic-boom@npm:^3.7.0": + version: 3.8.0 + resolution: "sonic-boom@npm:3.8.0" + dependencies: + atomic-sleep: ^1.0.0 + checksum: c21ece61a0cabb78db96547aecb4e9086eba2db2d53030221ed07215bfda2d25bb02906366ea2584cbe73d236dd7dd109122d3d7287914b76a9630e0a36ad819 + languageName: node + linkType: hard + "sort-any@npm:^2.0.0": version: 2.0.0 resolution: "sort-any@npm:2.0.0" From bf46b182b5e430cf56467b75441b28e323deaa83 Mon Sep 17 00:00:00 2001 From: Iain Sproat <68657+iainsproat@users.noreply.github.com> Date: Thu, 11 Jan 2024 14:07:13 +0000 Subject: [PATCH 09/17] fix(fileimport-service): logging was not writing valid log messages directly to std(out|err) --- packages/fileimport-service/src/daemon.js | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/packages/fileimport-service/src/daemon.js b/packages/fileimport-service/src/daemon.js index 36fa15f2d4..02122f5c28 100644 --- a/packages/fileimport-service/src/daemon.js +++ b/packages/fileimport-service/src/daemon.js @@ -240,19 +240,21 @@ function runProcessWithTimeout(processLogger, cmd, cmdArgs, extraEnv, timeoutMs) boundLogger = boundLogger.child({ pid: childProc.pid }) childProc.stdout.on('data', (data) => { try { - JSON.parse(data.toString()) // data is already in JSON format - process.stdout.write(data.string()) + if (typeof data !== 'string') throw new Error('not a string') + JSON.parse(data) // validate that data is already in JSON format + process.stdout.write(data) } catch { - boundLogger.info('Parser: %s', data.toString()) + boundLogger.info('Parser: %s', JSON.stringify(data)) } }) childProc.stderr.on('data', (data) => { try { - JSON.parse(data.toString()) // data is already in JSON format - process.stderr.write(data.string()) + if (typeof data !== 'string') throw new Error('not a string') + JSON.parse(data) // validate that data is already in JSON format + process.stderr.write(data) } catch { - boundLogger.info('Parser: %s', data.toString()) + boundLogger.info('Parser: %s', JSON.stringify(data)) } }) From 5e358cb5629377f7b0e9bcec7776475948db9a44 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gerg=C5=91=20Jedlicska?= <57442769+gjedlicska@users.noreply.github.com> Date: Thu, 11 Jan 2024 16:17:04 +0100 Subject: [PATCH 10/17] fix: request logs (#1964) * fix: request logs * chore: remove comments --- .../plugins/002-healthMetrics.server.ts | 2 +- .../server/middleware/001-logging.ts | 32 ++++++++++++------- packages/server/logging/expressLogging.ts | 27 +++++++++++++--- 3 files changed, 43 insertions(+), 18 deletions(-) diff --git a/packages/frontend-2/plugins/002-healthMetrics.server.ts b/packages/frontend-2/plugins/002-healthMetrics.server.ts index f9470d81b0..6c7d4811e4 100644 --- a/packages/frontend-2/plugins/002-healthMetrics.server.ts +++ b/packages/frontend-2/plugins/002-healthMetrics.server.ts @@ -21,7 +21,7 @@ export default defineNuxtPlugin((ctx) => { routeName: name, routePath: path }, - `[{routePath}] SSR rendered in {responseTime}ms` + '{routePath} SSR rendered in {responseTime} ms' ) }) }) diff --git a/packages/frontend-2/server/middleware/001-logging.ts b/packages/frontend-2/server/middleware/001-logging.ts index a07cc0a226..807276fb53 100644 --- a/packages/frontend-2/server/middleware/001-logging.ts +++ b/packages/frontend-2/server/middleware/001-logging.ts @@ -60,24 +60,32 @@ export const LoggingMiddleware = pinoHttp({ return shouldBeDebug ? 'debug' : 'info' }, - - customSuccessMessage(req, res, responseTime) { - const path = req.url?.split('?')[0] ?? 'unknown' - const isCompleted = !req.readableAborted && res.writableEnded - const statusMessage = isCompleted ? 'request completed' : 'request aborted' - - return `[${path}] ${statusMessage} in ${responseTime}ms` + customSuccessMessage() { + return '{requestPath} request {requestStatus} in {responseTime} ms' }, - customSuccessMessage(req, res) { + customSuccessObject(req, res, val: Record) { const isCompleted = !req.readableAborted && res.writableEnded - const statusMessage = isCompleted ? 'request completed' : 'request aborted' - - return `[{req.path}] ${statusMessage} in {responseTime}ms` + const requestStatus = isCompleted ? 'completed' : 'aborted' + const requestPath = req.url?.split('?')[0] || 'unknown' + return { + ...val, + requestStatus, + requestPath + } }, customErrorMessage() { - return `[{req.path}] request errored` + return '{requestPath} request {requestStatus} in {responseTime} ms' + }, + customErrorObject(req, res, err, val: Record) { + const requestStatus = 'failed' + const requestPath = req.url?.split('?')[0] || 'unknown' + return { + ...val, + requestStatus, + requestPath + } }, // we need to redact any potential sensitive data from being logged. diff --git a/packages/server/logging/expressLogging.ts b/packages/server/logging/expressLogging.ts index 256cea7dc9..21653a74de 100644 --- a/packages/server/logging/expressLogging.ts +++ b/packages/server/logging/expressLogging.ts @@ -34,15 +34,32 @@ export const LoggingExpressMiddleware = HttpLogger({ return 'info' }, - customSuccessMessage(req, res) { - const isCompleted = !req.readableAborted && res.writableEnded - const statusMessage = isCompleted ? 'request completed' : 'request aborted' + customSuccessMessage() { + return '{requestPath} request {requestStatus} in {responseTime} ms' + }, - return `[{req.path}] ${statusMessage} in {responseTime}ms` + customSuccessObject(req, res, val: Record) { + const isCompleted = !req.readableAborted && res.writableEnded + const requestStatus = isCompleted ? 'completed' : 'aborted' + const requestPath = req.url?.split('?')[0] || 'unknown' + return { + ...val, + requestStatus, + requestPath + } }, customErrorMessage() { - return `[{req.path}] request errored` + return '{requestPath} request {requestStatus} in {responseTime} ms' + }, + customErrorObject(req, res, err, val: Record) { + const requestStatus = 'failed' + const requestPath = req.url?.split('?')[0] || 'unknown' + return { + ...val, + requestStatus, + requestPath + } }, // we need to redact any potential sensitive data from being logged. From 6f53da63396f22bec31fc623dbc8547f62956fcd Mon Sep 17 00:00:00 2001 From: Iain Sproat <68657+iainsproat@users.noreply.github.com> Date: Thu, 11 Jan 2024 16:56:49 +0000 Subject: [PATCH 11/17] Use message template format --- packages/fileimport-service/src/daemon.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/fileimport-service/src/daemon.js b/packages/fileimport-service/src/daemon.js index 02122f5c28..511de9059a 100644 --- a/packages/fileimport-service/src/daemon.js +++ b/packages/fileimport-service/src/daemon.js @@ -244,7 +244,7 @@ function runProcessWithTimeout(processLogger, cmd, cmdArgs, extraEnv, timeoutMs) JSON.parse(data) // validate that data is already in JSON format process.stdout.write(data) } catch { - boundLogger.info('Parser: %s', JSON.stringify(data)) + boundLogger.info({ parserLog: data }, 'ParserLog: {parserLog}') } }) @@ -254,7 +254,7 @@ function runProcessWithTimeout(processLogger, cmd, cmdArgs, extraEnv, timeoutMs) JSON.parse(data) // validate that data is already in JSON format process.stderr.write(data) } catch { - boundLogger.info('Parser: %s', JSON.stringify(data)) + boundLogger.info({ parserLog: data }, 'ParserLog: {parserLog}') } }) From a00163c8f4c0d90327eea765f76157e77263f37d Mon Sep 17 00:00:00 2001 From: Iain Sproat <68657+iainsproat@users.noreply.github.com> Date: Fri, 12 Jan 2024 21:51:31 +0000 Subject: [PATCH 12/17] refactor to print data per line --- packages/fileimport-service/src/daemon.js | 32 +++++++++++++---------- 1 file changed, 18 insertions(+), 14 deletions(-) diff --git a/packages/fileimport-service/src/daemon.js b/packages/fileimport-service/src/daemon.js index 511de9059a..a59f5c4b40 100644 --- a/packages/fileimport-service/src/daemon.js +++ b/packages/fileimport-service/src/daemon.js @@ -239,23 +239,11 @@ function runProcessWithTimeout(processLogger, cmd, cmdArgs, extraEnv, timeoutMs) boundLogger = boundLogger.child({ pid: childProc.pid }) childProc.stdout.on('data', (data) => { - try { - if (typeof data !== 'string') throw new Error('not a string') - JSON.parse(data) // validate that data is already in JSON format - process.stdout.write(data) - } catch { - boundLogger.info({ parserLog: data }, 'ParserLog: {parserLog}') - } + handleData(data, boundLogger.info) }) childProc.stderr.on('data', (data) => { - try { - if (typeof data !== 'string') throw new Error('not a string') - JSON.parse(data) // validate that data is already in JSON format - process.stderr.write(data) - } catch { - boundLogger.info({ parserLog: data }, 'ParserLog: {parserLog}') - } + handleData(data, boundLogger.error) }) let timedOut = false @@ -292,6 +280,22 @@ function runProcessWithTimeout(processLogger, cmd, cmdArgs, extraEnv, timeoutMs) }) } +function handleData(data, logFunc) { + try { + if (typeof data !== 'string') throw new Error('Not a string; force writing to log.') + data.split('\n').forEach((line) => { + try { + JSON.parse(line) // validate that data is already in JSON format + process.stdout.write(line) + } catch { + logFunc({ parserLogLine: line }, 'ParserLog: {parserLogLine}') + } + }) + } catch { + logFunc({ parserLogLine: data }, 'ParserLog: {parserLogLine}') + } +} + async function tick() { if (shouldExit) { process.exit(0) From 6aef5cc41b0d490895f781bd76b81ea0ed357f77 Mon Sep 17 00:00:00 2001 From: Iain Sproat <68657+iainsproat@users.noreply.github.com> Date: Fri, 12 Jan 2024 23:10:08 +0000 Subject: [PATCH 13/17] fix(logging): pino expected 'this' to be populated - presuming passing of the functions was the cause --- packages/fileimport-service/src/daemon.js | 18 +++++++++++++----- 1 file changed, 13 insertions(+), 5 deletions(-) diff --git a/packages/fileimport-service/src/daemon.js b/packages/fileimport-service/src/daemon.js index a59f5c4b40..760fc4dda3 100644 --- a/packages/fileimport-service/src/daemon.js +++ b/packages/fileimport-service/src/daemon.js @@ -239,11 +239,11 @@ function runProcessWithTimeout(processLogger, cmd, cmdArgs, extraEnv, timeoutMs) boundLogger = boundLogger.child({ pid: childProc.pid }) childProc.stdout.on('data', (data) => { - handleData(data, boundLogger.info) + handleData(data, false, boundLogger) }) childProc.stderr.on('data', (data) => { - handleData(data, boundLogger.error) + handleData(data, true, boundLogger) }) let timedOut = false @@ -280,7 +280,7 @@ function runProcessWithTimeout(processLogger, cmd, cmdArgs, extraEnv, timeoutMs) }) } -function handleData(data, logFunc) { +function handleData(data, isErr, logger) { try { if (typeof data !== 'string') throw new Error('Not a string; force writing to log.') data.split('\n').forEach((line) => { @@ -288,14 +288,22 @@ function handleData(data, logFunc) { JSON.parse(line) // validate that data is already in JSON format process.stdout.write(line) } catch { - logFunc({ parserLogLine: line }, 'ParserLog: {parserLogLine}') + wrapLogLine(line, isErr, logger) } }) } catch { - logFunc({ parserLogLine: data }, 'ParserLog: {parserLogLine}') + wrapLogLine(JSON.stringify(data), isErr, logger) } } +function wrapLogLine(line, isErr, logger) { + if (isErr) { + logger.error({ parserLogLine: line }, 'ParserLog: {parserLogLine}') + return + } + logger.info({ parserLogLine: line }, 'ParserLog: {parserLogLine}') +} + async function tick() { if (shouldExit) { process.exit(0) From 224298469f9928553e7cb3b6c37738f34186d4e8 Mon Sep 17 00:00:00 2001 From: Iain Sproat <68657+iainsproat@users.noreply.github.com> Date: Fri, 12 Jan 2024 23:32:43 +0000 Subject: [PATCH 14/17] improve handling of buffers --- packages/fileimport-service/src/daemon.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/fileimport-service/src/daemon.js b/packages/fileimport-service/src/daemon.js index 760fc4dda3..2fa44d5c4c 100644 --- a/packages/fileimport-service/src/daemon.js +++ b/packages/fileimport-service/src/daemon.js @@ -282,10 +282,10 @@ function runProcessWithTimeout(processLogger, cmd, cmdArgs, extraEnv, timeoutMs) function handleData(data, isErr, logger) { try { - if (typeof data !== 'string') throw new Error('Not a string; force writing to log.') + Buffer.isBuffer(data) && (data = data.toString()) data.split('\n').forEach((line) => { try { - JSON.parse(line) // validate that data is already in JSON format + JSON.parse(line) // verify if the data is already in JSON format process.stdout.write(line) } catch { wrapLogLine(line, isErr, logger) From 1d00dea314116219a5125b1e7d1928b1d2f3c30d Mon Sep 17 00:00:00 2001 From: Iain Sproat <68657+iainsproat@users.noreply.github.com> Date: Fri, 12 Jan 2024 23:53:26 +0000 Subject: [PATCH 15/17] Handle empty lines --- packages/fileimport-service/src/daemon.js | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/packages/fileimport-service/src/daemon.js b/packages/fileimport-service/src/daemon.js index 2fa44d5c4c..9ada2dbd21 100644 --- a/packages/fileimport-service/src/daemon.js +++ b/packages/fileimport-service/src/daemon.js @@ -67,7 +67,7 @@ async function doTask(task) { let branchMetadata = { streamId: null, branchName: null } try { - taskLogger.info('Doing task.') + taskLogger.info("Doing task '{taskId}'.") const info = await FileUploads().where({ id: taskId }).first() if (!info) { throw new Error('Internal error: DB inconsistent') @@ -284,9 +284,11 @@ function handleData(data, isErr, logger) { try { Buffer.isBuffer(data) && (data = data.toString()) data.split('\n').forEach((line) => { + if (!line) return try { JSON.parse(line) // verify if the data is already in JSON format process.stdout.write(line) + process.stdout.write('\n') } catch { wrapLogLine(line, isErr, logger) } From 44b523510741d0811bb55f934cc39388a695f794 Mon Sep 17 00:00:00 2001 From: Iain Sproat <68657+iainsproat@users.noreply.github.com> Date: Sat, 13 Jan 2024 00:24:49 +0000 Subject: [PATCH 16/17] Use message template in IFC parser log lines --- packages/fileimport-service/ifc/api.js | 18 ++++++++++++------ packages/fileimport-service/ifc/index.js | 14 ++++++++++---- packages/fileimport-service/src/daemon.js | 4 ++-- 3 files changed, 24 insertions(+), 12 deletions(-) diff --git a/packages/fileimport-service/ifc/api.js b/packages/fileimport-service/ifc/api.js index ae80fe839e..246413ba0f 100644 --- a/packages/fileimport-service/ifc/api.js +++ b/packages/fileimport-service/ifc/api.js @@ -125,9 +125,12 @@ module.exports = class ServerAPI { this.prepInsertionObjectBatch(batch) await Objects().insert(batch).onConflict().ignore() this.logger.info( - `Inserted ${batch.length} objects from batch ${index + 1} of ${ - batches.length - }` + { + currentBatchCount: batch.length, + currentBatchId: index + 1, + totalNumberOfBatches: batches.length + }, + 'Inserted {currentBatchCount} objects from batch {currentBatchId} of {totalNumberOfBatches}' ) } } @@ -140,9 +143,12 @@ module.exports = class ServerAPI { this.prepInsertionClosureBatch(batch) await Closures().insert(batch).onConflict().ignore() this.logger.info( - `Inserted ${batch.length} closures from batch ${index + 1} of ${ - batches.length - }` + { + currentBatchCount: batch.length, + currentBatchId: index + 1, + totalNumberOfBatches: batches.length + }, + 'Inserted {currentBatchCount} closures from batch {currentBatchId} of {totalNumberOfBatches}' ) } } diff --git a/packages/fileimport-service/ifc/index.js b/packages/fileimport-service/ifc/index.js index caaae0a548..5981dbeda3 100644 --- a/packages/fileimport-service/ifc/index.js +++ b/packages/fileimport-service/ifc/index.js @@ -25,8 +25,14 @@ async function parseAndCreateCommit({ const start = performance.now() const { id, tCount } = await myParser.parse(data) + logger = logger.child({ objectId: id }) const end = performance.now() - logger.info(`Total processing time V2: ${(end - start).toFixed(2)}ms`) + logger.info( + { + fileProcessingDurationMs: (end - start).toFixed(2) + }, + 'Total processing time V2: {fileProcessingDurationMs}ms' + ) const commit = { streamId, @@ -43,7 +49,7 @@ async function parseAndCreateCommit({ }) if (!branch) { - logger.info('Branch not found, creating it.') + logger.info("Branch '{branchName}' not found, creating it.") await serverApi.createBranch({ name: branchName, streamId, @@ -55,7 +61,7 @@ async function parseAndCreateCommit({ const userToken = process.env.USER_TOKEN const serverBaseUrl = process.env.SPECKLE_SERVER_URL || 'http://127.0.0.1:3000' - logger.info(`Creating commit for object (${id}), with message "${message}"`) + logger.info('Creating commit for object ({objectId}), with message "{message}"') const response = await fetch(serverBaseUrl + '/graphql', { method: 'POST', headers: { @@ -72,7 +78,7 @@ async function parseAndCreateCommit({ }) const json = await response.json() - logger.info(json) + logger.info(json, 'Commit created') return json.data.commitCreate } diff --git a/packages/fileimport-service/src/daemon.js b/packages/fileimport-service/src/daemon.js index 9ada2dbd21..d9895065a8 100644 --- a/packages/fileimport-service/src/daemon.js +++ b/packages/fileimport-service/src/daemon.js @@ -249,7 +249,7 @@ function runProcessWithTimeout(processLogger, cmd, cmdArgs, extraEnv, timeoutMs) let timedOut = false const timeout = setTimeout(() => { - boundLogger.warn('Process timeout. Killing process...') + boundLogger.warn('Process timed out. Killing process...') timedOut = true childProc.kill(9) @@ -263,7 +263,7 @@ function runProcessWithTimeout(processLogger, cmd, cmdArgs, extraEnv, timeoutMs) }, timeoutMs) childProc.on('close', (code) => { - boundLogger.info({ exitCode: code }, `Process exited with code ${code}`) + boundLogger.info({ exitCode: code }, "Process exited with code '{exitCode}'") if (timedOut) { return // ignore `close` calls after killing (the promise was already rejected) From 1adc5612ec96914ff51203788afe29d0e614aab9 Mon Sep 17 00:00:00 2001 From: Iain Sproat <68657+iainsproat@users.noreply.github.com> Date: Sat, 13 Jan 2024 00:38:11 +0000 Subject: [PATCH 17/17] fix broken message template --- packages/fileimport-service/ifc/index.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/fileimport-service/ifc/index.js b/packages/fileimport-service/ifc/index.js index 5981dbeda3..e3c1b9ba7e 100644 --- a/packages/fileimport-service/ifc/index.js +++ b/packages/fileimport-service/ifc/index.js @@ -61,7 +61,7 @@ async function parseAndCreateCommit({ const userToken = process.env.USER_TOKEN const serverBaseUrl = process.env.SPECKLE_SERVER_URL || 'http://127.0.0.1:3000' - logger.info('Creating commit for object ({objectId}), with message "{message}"') + logger.info(`Creating commit for object ({objectId}), with message "${message}"`) const response = await fetch(serverBaseUrl + '/graphql', { method: 'POST', headers: {