From 2a9fef23419cb964261c4e9ed216dda3493c3d87 Mon Sep 17 00:00:00 2001 From: Charles Bochet Date: Wed, 13 May 2026 21:31:22 +0200 Subject: [PATCH] feat(upgrade): emit structured logfmt logs for upgrade flow (#20539) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Summary Adds a small helper that lets every log line in the upgrade flow stay human-readable while emitting a structured tail that Loki / the upgrade-status Grafana dashboard can filter on. Output shape per `logger.log()` call: ``` [upgrade] event= key=value … ← always single line ``` Same call produces **one** structured Loki event regardless of how chatty the human-readable part gets — the dashboard's `|= "[upgrade]"` filter only matches the trailing line. ## Helper API ```ts formatUpgradeLog({ humanMessage: string, // free-form, multi-line OK, for engineers scrolling raw pod logs event: string, // required anchor for Loki filtering / dashboards logFields?: Record, }); ``` - `humanMessage` is preserved as-is. A thrown `new Error('line one\nline two')` surfacing through `humanMessage` stays human-readable across multiple lines. - `logFields` values are logfmt-escaped: whitespace / `=` / `"` get quoted, embedded `\` / `"` / `\n` / `\r` / `\t` are escaped, `null` / `undefined` emit literally (`key=null`, `key=undefined`) instead of being silently dropped — caught via `isDefined` from `twenty-shared/utils`. - `event` itself runs through the same escape so an event name with whitespace or `=` can't break parsing. ## Example output ``` Initialized upgrade sequence: 8 step(s) [upgrade] event=sequence.initialized stepCount=8 dryRun=false Upgrading workspace abc-123 1/10 [upgrade] event=workspace.start workspaceId=abc-123 index=1 total=10 dryRun=false Upgrade for workspace abc-123 completed. [upgrade] event=workspace.success workspaceId=abc-123 executedByVersion=1.4.0 dryRun=false Upgrade summary: 42 workspace(s) succeeded, 1 workspace(s) failed [upgrade] event=summary totalSuccesses=42 totalFailures=1 dryRun=false Upgrade failed: Workspace migration runner failed: - Option id is required - Option id is invalid [upgrade] event=aborted totalSuccesses=41 totalFailures=2 dryRun=false ``` Loki query for the dashboard: `{namespace="twenty"} |= "[upgrade]" | logfmt event, workspaceId, command, executedByVersion` ## Scope Only the **upgrade-specific** call sites carry the tag: - `upgrade.command.ts` — `sequence.initialized`, `sequence.step` (verbose), `summary`, `aborted` - `upgrade-sequence-runner.service.ts` — `sequence.stopped`, `sequence.aborted` - `workspace-command-runner.service.ts` — `workspace.start`, `workspace.success`, `cache.invalidate.failed` `instance-command-runner.service.ts` is intentionally **not** tagged — `runFastInstanceCommand` / `runSlowInstanceCommand` are also invoked from `RunInstanceCommandsCommand` (DB init / `run-instance-commands`), so an `[upgrade]` tag there would mislead at init time. Those lines stay plain-text; stacks still flow on their own via NestJS `logger.error(message, error.stack)`. `chalk` is dropped from `upgrade.command.ts` — ANSI escapes break log parsers and chalk is a no-op without a TTY anyway. ## Tests 9 inline-snapshot tests in `format-upgrade-log.util.spec.ts` surface the actual output of every interesting shape (summary call site, multi-line humanMessage, quoted / escaped / control-character logField values, null/undefined fields, event name escaping). Snapshots double as documentation of what a real upgrade log line looks like. ## Test plan - [x] Unit tests green (`jest format-upgrade-log`) - [x] oxlint + prettier clean - [x] tsgo typecheck clean on the upgrade module - [x] CI green - [ ] Smoke test on staging: run `upgrade` command, confirm `[upgrade]` structured lines surface in Loki and `| logfmt` extracts fields --- .../upgrade.command.ts | 57 +++++-- .../upgrade-sequence-runner.service.ts | 27 +++- .../workspace-command-runner.service.ts | 40 ++++- .../__tests__/format-upgrade-log.util.spec.ts | 149 ++++++++++++++++++ .../upgrade/utils/format-upgrade-log.util.ts | 49 ++++++ 5 files changed, 297 insertions(+), 25 deletions(-) create mode 100644 packages/twenty-server/src/engine/core-modules/upgrade/utils/__tests__/format-upgrade-log.util.spec.ts create mode 100644 packages/twenty-server/src/engine/core-modules/upgrade/utils/format-upgrade-log.util.ts diff --git a/packages/twenty-server/src/database/commands/upgrade-version-command/upgrade.command.ts b/packages/twenty-server/src/database/commands/upgrade-version-command/upgrade.command.ts index 0cc931af78..81ecc58820 100644 --- a/packages/twenty-server/src/database/commands/upgrade-version-command/upgrade.command.ts +++ b/packages/twenty-server/src/database/commands/upgrade-version-command/upgrade.command.ts @@ -1,10 +1,10 @@ -import chalk from 'chalk'; import { Command, CommandRunner, Option } from 'nest-commander'; import { isDefined } from 'twenty-shared/utils'; import { CommandLogger } from 'src/database/commands/logger'; import { UpgradeSequenceReaderService } from 'src/engine/core-modules/upgrade/services/upgrade-sequence-reader.service'; import { UpgradeSequenceRunnerService } from 'src/engine/core-modules/upgrade/services/upgrade-sequence-runner.service'; +import { formatUpgradeLog } from 'src/engine/core-modules/upgrade/utils/format-upgrade-log.util'; type RawUpgradeCommandOptions = { workspaceId?: Set; @@ -126,18 +126,31 @@ export class UpgradeCommand extends CommandRunner { const sequence = this.upgradeSequenceReaderService.getUpgradeSequence(); this.logger.log( - chalk.blue( - [ - 'Initialized upgrade sequence:', - `- ${sequence.length} step(s)`, - ...sequence.map( - (step, index) => - ` [${index}] ${step.kind} — ${step.name} (${step.version})`, - ), - ].join('\n '), - ), + formatUpgradeLog({ + humanMessage: `Initialized upgrade sequence: ${sequence.length} step(s)`, + event: 'sequence.initialized', + logFields: { + stepCount: sequence.length, + dryRun: options.dryRun ?? false, + }, + }), ); + for (const [index, step] of sequence.entries()) { + this.logger.verbose( + formatUpgradeLog({ + humanMessage: ` [${index}] ${step.kind} — ${step.name} (${step.version})`, + event: 'sequence.step', + logFields: { + index, + kind: step.kind, + name: step.name, + version: step.version, + }, + }), + ); + } + const { totalSuccesses, totalFailures } = await this.upgradeSequenceRunnerService.run({ sequence, @@ -150,9 +163,15 @@ export class UpgradeCommand extends CommandRunner { }); this.logger.log( - chalk.blue( - `Upgrade summary: ${totalSuccesses} workspace(s) succeeded, ${totalFailures} workspace(s) failed`, - ), + formatUpgradeLog({ + humanMessage: `Upgrade summary: ${totalSuccesses} workspace(s) succeeded, ${totalFailures} workspace(s) failed`, + event: 'summary', + logFields: { + totalSuccesses, + totalFailures, + dryRun: options.dryRun ?? false, + }, + }), ); if (totalFailures > 0) { @@ -161,7 +180,15 @@ export class UpgradeCommand extends CommandRunner { ); } } catch (error) { - this.logger.error(chalk.red(`Upgrade failed: ${error.message}`)); + const errorMessage = + error instanceof Error ? error.message : String(error); + + this.logger.error( + formatUpgradeLog({ + humanMessage: `Upgrade failed: ${errorMessage}`, + event: 'aborted', + }), + ); throw error; } } diff --git a/packages/twenty-server/src/engine/core-modules/upgrade/services/upgrade-sequence-runner.service.ts b/packages/twenty-server/src/engine/core-modules/upgrade/services/upgrade-sequence-runner.service.ts index 0fd848f6d5..5e370e6e65 100644 --- a/packages/twenty-server/src/engine/core-modules/upgrade/services/upgrade-sequence-runner.service.ts +++ b/packages/twenty-server/src/engine/core-modules/upgrade/services/upgrade-sequence-runner.service.ts @@ -17,6 +17,7 @@ import { UpgradeSequenceReaderService, } from 'src/engine/core-modules/upgrade/services/upgrade-sequence-reader.service'; import { WorkspaceCommandRunnerService } from 'src/engine/core-modules/upgrade/services/workspace-command-runner.service'; +import { formatUpgradeLog } from 'src/engine/core-modules/upgrade/utils/format-upgrade-log.util'; import { WorkspaceVersionService } from 'src/engine/workspace-manager/workspace-version/services/workspace-version.service'; import { assertUnreachable, isDefined } from 'twenty-shared/utils'; @@ -75,9 +76,17 @@ export class UpgradeSequenceRunnerService { isDefined(options.workspaceCountLimit) ) { this.logger.log( - `Stopping before instance step "${step.name}": ` + - 'upgrade was run with a workspace filter (-w, --start-from-workspace-id, or --workspace-count-limit). ' + - 'Instance commands require all workspaces to be aligned.', + formatUpgradeLog({ + humanMessage: + `Stopping before instance step "${step.name}": ` + + 'upgrade was run with a workspace filter (-w, --start-from-workspace-id, or --workspace-count-limit). ' + + 'Instance commands require all workspaces to be aligned.', + event: 'sequence.stopped', + logFields: { + before: step.name, + reason: 'workspace-filter-active', + }, + }), ); break; @@ -120,8 +129,16 @@ export class UpgradeSequenceRunnerService { if (report.fail.length > 0) { this.logger.error( - `Workspace steps ended with ${report.fail.length} failure(s). ` + - 'Aborting — cannot proceed to next instance step.', + formatUpgradeLog({ + humanMessage: + `Workspace steps ended with ${report.fail.length} failure(s). ` + + 'Aborting — cannot proceed to next instance step.', + event: 'sequence.aborted', + logFields: { + failures: report.fail.length, + reason: 'workspace-failures', + }, + }), ); return { totalSuccesses, totalFailures }; diff --git a/packages/twenty-server/src/engine/core-modules/upgrade/services/workspace-command-runner.service.ts b/packages/twenty-server/src/engine/core-modules/upgrade/services/workspace-command-runner.service.ts index 798bf3f902..5041143ba7 100644 --- a/packages/twenty-server/src/engine/core-modules/upgrade/services/workspace-command-runner.service.ts +++ b/packages/twenty-server/src/engine/core-modules/upgrade/services/workspace-command-runner.service.ts @@ -6,6 +6,7 @@ import { TwentyConfigService } from 'src/engine/core-modules/twenty-config/twent import { type RegisteredWorkspaceCommand } from 'src/engine/core-modules/upgrade/services/upgrade-command-registry.service'; import { UpgradeMigrationService } from 'src/engine/core-modules/upgrade/services/upgrade-migration.service'; import { UpgradeStatusService } from 'src/engine/core-modules/upgrade/services/upgrade-status.service'; +import { formatUpgradeLog } from 'src/engine/core-modules/upgrade/utils/format-upgrade-log.util'; type WorkspaceCommandEntry = Pick< RegisteredWorkspaceCommand, @@ -35,8 +36,19 @@ export class WorkspaceCommandRunnerService { }: RunWorkspaceCommandsArgs): Promise { const { workspaceId, index, total } = iteratorContext; + const dryRunPrefix = options.dryRun ? '(dry run) ' : ''; + this.logger.log( - `${options.dryRun ? '(dry run) ' : ''}Upgrading workspace ${workspaceId} ${index + 1}/${total}`, + formatUpgradeLog({ + humanMessage: `${dryRunPrefix}Upgrading workspace ${workspaceId} ${index + 1}/${total}`, + event: 'workspace.start', + logFields: { + workspaceId, + index: index + 1, + total, + dryRun: options.dryRun ?? false, + }, + }), ); const executedByVersion = @@ -53,7 +65,17 @@ export class WorkspaceCommandRunnerService { }); } - this.logger.log(`Upgrade for workspace ${workspaceId} completed.`); + this.logger.log( + formatUpgradeLog({ + humanMessage: `Upgrade for workspace ${workspaceId} completed.`, + event: 'workspace.success', + logFields: { + workspaceId, + executedByVersion, + dryRun: options.dryRun ?? false, + }, + }), + ); } finally { if (!options.dryRun) { await this.safeInvalidateWorkspace(workspaceId); @@ -65,10 +87,18 @@ export class WorkspaceCommandRunnerService { try { await this.upgradeStatusService.invalidateInstanceAndAllWorkspacesStatus(); } catch (error) { + const errorMessage = + error instanceof Error ? error.message : String(error); + this.logger.warn( - `Failed to invalidate upgrade-status cache for workspace ${workspaceId}: ${ - error instanceof Error ? error.message : String(error) - }`, + formatUpgradeLog({ + humanMessage: `Failed to invalidate upgrade-status cache (triggered by workspace ${workspaceId}): ${errorMessage}`, + event: 'cache.invalidate.failed', + logFields: { + scope: 'instance-and-all-workspaces', + triggeredByWorkspaceId: workspaceId, + }, + }), ); } } diff --git a/packages/twenty-server/src/engine/core-modules/upgrade/utils/__tests__/format-upgrade-log.util.spec.ts b/packages/twenty-server/src/engine/core-modules/upgrade/utils/__tests__/format-upgrade-log.util.spec.ts new file mode 100644 index 0000000000..3e301aaa10 --- /dev/null +++ b/packages/twenty-server/src/engine/core-modules/upgrade/utils/__tests__/format-upgrade-log.util.spec.ts @@ -0,0 +1,149 @@ +import { formatUpgradeLog } from 'src/engine/core-modules/upgrade/utils/format-upgrade-log.util'; + +describe('formatUpgradeLog', () => { + it('emits humanMessage on its own lines followed by a single-line "[upgrade] event=" tail', () => { + expect( + formatUpgradeLog({ + humanMessage: 'Upgrade for workspace abc-123 completed.', + event: 'workspace.success', + }), + ).toMatchInlineSnapshot(` +"Upgrade for workspace abc-123 completed. +[upgrade] event=workspace.success" +`); + }); + + it('serializes numeric, boolean and string logFields after the humanMessage', () => { + expect( + formatUpgradeLog({ + humanMessage: 'Upgrading workspace abc-123 1/10', + event: 'workspace.start', + logFields: { + workspaceId: 'abc-123', + index: 1, + total: 10, + dryRun: false, + }, + }), + ).toMatchInlineSnapshot(` +"Upgrading workspace abc-123 1/10 +[upgrade] event=workspace.start workspaceId=abc-123 index=1 total=10 dryRun=false" +`); + }); + + it('matches the summary call site emitted by UpgradeCommand at the end of a run', () => { + expect( + formatUpgradeLog({ + humanMessage: + 'Upgrade summary: 42 workspace(s) succeeded, 1 workspace(s) failed', + event: 'summary', + logFields: { + totalSuccesses: 42, + totalFailures: 1, + dryRun: false, + }, + }), + ).toMatchInlineSnapshot(` +"Upgrade summary: 42 workspace(s) succeeded, 1 workspace(s) failed +[upgrade] event=summary totalSuccesses=42 totalFailures=1 dryRun=false" +`); + }); + + it('preserves a multi-line humanMessage as-is and keeps the structured tail on its own single line', () => { + const errorMessage = + 'Workspace migration runner failed:\n - Option id is required\n - Option id is invalid'; + + expect( + formatUpgradeLog({ + humanMessage: `Upgrade failed: ${errorMessage}`, + event: 'aborted', + logFields: { + totalSuccesses: 41, + totalFailures: 2, + dryRun: false, + }, + }), + ).toMatchInlineSnapshot(` +"Upgrade failed: Workspace migration runner failed: + - Option id is required + - Option id is invalid +[upgrade] event=aborted totalSuccesses=41 totalFailures=2 dryRun=false" +`); + }); + + it('emits null and undefined logFields explicitly', () => { + expect( + formatUpgradeLog({ + humanMessage: 'migration-foo executed successfully', + event: 'instance.success', + logFields: { + command: 'migration-foo', + error: undefined, + executedByVersion: null, + }, + }), + ).toMatchInlineSnapshot(` +"migration-foo executed successfully +[upgrade] event=instance.success command=migration-foo error=undefined executedByVersion=null" +`); + }); + + it('quotes values containing whitespace, quotes or equals signs', () => { + expect( + formatUpgradeLog({ + humanMessage: + 'Workspace abc failed on migrate-foo: Connection timed out', + event: 'workspace.failed', + logFields: { + workspaceId: 'abc', + command: 'migrate-foo', + }, + }), + ).toMatchInlineSnapshot(` +"Workspace abc failed on migrate-foo: Connection timed out +[upgrade] event=workspace.failed workspaceId=abc command=migrate-foo" +`); + }); + + it('escapes embedded quotes and backslashes in logField values', () => { + expect( + formatUpgradeLog({ + humanMessage: 'Workspace abc failed', + event: 'workspace.failed', + logFields: { + reason: 'bad "quote" and \\ backslash', + }, + }), + ).toMatchInlineSnapshot(` +"Workspace abc failed +[upgrade] event=workspace.failed reason="bad \\"quote\\" and \\\\ backslash"" +`); + }); + + it('keeps multi-line logField values on a single log line via \\n / \\r / \\t escaping', () => { + expect( + formatUpgradeLog({ + humanMessage: 'Workspace abc failed', + event: 'workspace.failed', + logFields: { + reason: 'line one\nline two\rline three\ttab', + }, + }), + ).toMatchInlineSnapshot(` +"Workspace abc failed +[upgrade] event=workspace.failed reason="line one\\nline two\\rline three\\ttab"" +`); + }); + + it('escapes an event name containing whitespace or =', () => { + expect( + formatUpgradeLog({ + humanMessage: 'Something happened', + event: 'weird event=with-equals', + }), + ).toMatchInlineSnapshot(` +"Something happened +[upgrade] event="weird event=with-equals"" +`); + }); +}); diff --git a/packages/twenty-server/src/engine/core-modules/upgrade/utils/format-upgrade-log.util.ts b/packages/twenty-server/src/engine/core-modules/upgrade/utils/format-upgrade-log.util.ts new file mode 100644 index 0000000000..490db9ccc3 --- /dev/null +++ b/packages/twenty-server/src/engine/core-modules/upgrade/utils/format-upgrade-log.util.ts @@ -0,0 +1,49 @@ +import { isDefined } from 'twenty-shared/utils'; + +type UpgradeLogScalar = string | number | boolean; + +type UpgradeLogFields = Record; + +type FormatUpgradeLogParams = { + humanMessage: string; + event: string; + logFields?: UpgradeLogFields; +}; + +const UPGRADE_LOG_PREFIX = '[upgrade]'; + +const NEEDS_QUOTING = /[\s"=]/; +const CONTROL_CHARACTERS = /[\n\r\t]/; + +const escapeLogValue = (value: UpgradeLogScalar): string => { + const raw = String(value); + + if (!NEEDS_QUOTING.test(raw) && !CONTROL_CHARACTERS.test(raw)) { + return raw; + } + + const escaped = raw + .replace(/\\/g, '\\\\') + .replace(/"/g, '\\"') + .replace(/\n/g, '\\n') + .replace(/\r/g, '\\r') + .replace(/\t/g, '\\t'); + + return `"${escaped}"`; +}; + +export const formatUpgradeLog = ({ + humanMessage, + event, + logFields = {}, +}: FormatUpgradeLogParams): string => { + const tailParts: string[] = [`event=${escapeLogValue(event)}`]; + + for (const [key, value] of Object.entries(logFields)) { + tailParts.push( + `${key}=${isDefined(value) ? escapeLogValue(value) : String(value)}`, + ); + } + + return `${humanMessage}\n${UPGRADE_LOG_PREFIX} ${tailParts.join(' ')}`; +};