houseassassin/twenty
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat(upgrade): emit structured logfmt logs for upgrade flow (#20539)

Browse Source 
## 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:

```
<humanMessage as-is, may span multiple lines>
[upgrade] event=<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<string,             // short structured key=value tail
    string | number | boolean | null | undefined
  >,
});
```

- `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
This commit is contained in:
Charles Bochet
2026-05-13 21:31:22 +02:00
committed by GitHub
parent 0dc8426727
commit 2a9fef2341
5 changed files with 297 additions and 25 deletions
Download Patch File Download Diff File Expand all files Collapse all files
packages/twenty-server/src/database/commands/upgrade-version-command/upgrade.command.ts
+42 -15
View File
@@ -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<string>;
@@ -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;
}
}
packages/twenty-server/src/engine/core-modules/upgrade/services/upgrade-sequence-runner.service.ts
+22 -5
View File
@@ -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 };
packages/twenty-server/src/engine/core-modules/upgrade/services/workspace-command-runner.service.ts
+35 -5
View File
@@ -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<void> {
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,
},
}),
);
}
}
packages/twenty-server/src/engine/core-modules/upgrade/utils/__tests__/format-upgrade-log.util.spec.ts
+149
View File
@@ -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=<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""
`);
});
});
packages/twenty-server/src/engine/core-modules/upgrade/utils/format-upgrade-log.util.ts
+49
View File
@@ -0,0 +1,49 @@
import { isDefined } from 'twenty-shared/utils';
type UpgradeLogScalar = string | number | boolean;
type UpgradeLogFields = Record<string, UpgradeLogScalar | null | undefined>;
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(' ')}`;
};