Skip to content

Commit 8abd556

Browse files
despairbluedespairblue
authored
feat(core): Allow logging JSON to stdout (#15766)
1 parent 5bc4e5d commit 8abd556

File tree

6 files changed

+267
-33
lines changed

6 files changed

+267
-33
lines changed

‎packages/@n8n/backend-common/src/logging/__tests__/logger.test.ts

Lines changed: 194 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -37,6 +37,200 @@ describe('Logger', () => {
3737
});
3838
});
3939

40+
describe('formats', () => {
41+
afterEach(() => {
42+
jest.resetAllMocks();
43+
});
44+
45+
test('log text, if `config.logging.format` is set to `text`', () => {
46+
// ARRANGE
47+
const stdoutSpy = jest.spyOn(process.stdout, 'write').mockReturnValue(true);
48+
const globalConfig = mock<GlobalConfig>({
49+
logging: {
50+
format: 'text',
51+
level: 'info',
52+
outputs: ['console'],
53+
scopes: [],
54+
},
55+
});
56+
const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
57+
const testMessage = 'Test Message';
58+
const testMetadata = { test: 1 };
59+
60+
// ACT
61+
logger.info(testMessage, testMetadata);
62+
63+
// ASSERT
64+
expect(stdoutSpy).toHaveBeenCalledTimes(1);
65+
66+
const output = stdoutSpy.mock.lastCall?.[0];
67+
if (typeof output !== 'string') {
68+
fail(`expected 'output' to be of type 'string', got ${typeof output}`);
69+
}
70+
71+
expect(output).toEqual(`${testMessage}\n`);
72+
});
73+
74+
test('log json, if `config.logging.format` is set to `json`', () => {
75+
// ARRANGE
76+
const stdoutSpy = jest.spyOn(process.stdout, 'write').mockReturnValue(true);
77+
const globalConfig = mock<GlobalConfig>({
78+
logging: {
79+
format: 'json',
80+
level: 'info',
81+
outputs: ['console'],
82+
scopes: [],
83+
},
84+
});
85+
const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
86+
const testMessage = 'Test Message';
87+
const testMetadata = { test: 1 };
88+
89+
// ACT
90+
logger.info(testMessage, testMetadata);
91+
92+
// ASSERT
93+
expect(stdoutSpy).toHaveBeenCalledTimes(1);
94+
const output = stdoutSpy.mock.lastCall?.[0];
95+
if (typeof output !== 'string') {
96+
fail(`expected 'output' to be of type 'string', got ${typeof output}`);
97+
}
98+
99+
expect(() => JSON.parse(output)).not.toThrow();
100+
const parsedOutput = JSON.parse(output);
101+
102+
expect(parsedOutput).toMatchObject({
103+
message: testMessage,
104+
level: 'info',
105+
metadata: {
106+
...testMetadata,
107+
timestamp: expect.any(String),
108+
},
109+
});
110+
});
111+
112+
test('apply scope filters, if `config.logging.format` is set to `json`', () => {
113+
// ARRANGE
114+
const stdoutSpy = jest.spyOn(process.stdout, 'write').mockReturnValue(true);
115+
const globalConfig = mock<GlobalConfig>({
116+
logging: {
117+
format: 'json',
118+
level: 'info',
119+
outputs: ['console'],
120+
scopes: ['push'],
121+
},
122+
});
123+
const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
124+
const redisLogger = logger.scoped('redis');
125+
const pushLogger = logger.scoped('push');
126+
const testMessage = 'Test Message';
127+
const testMetadata = { test: 1 };
128+
129+
// ACT
130+
redisLogger.info(testMessage, testMetadata);
131+
pushLogger.info(testMessage, testMetadata);
132+
133+
// ASSERT
134+
expect(stdoutSpy).toHaveBeenCalledTimes(1);
135+
});
136+
137+
test('log errors in metadata with stack trace, if `config.logging.format` is set to `json`', () => {
138+
// ARRANGE
139+
const stdoutSpy = jest.spyOn(process.stdout, 'write').mockReturnValue(true);
140+
const globalConfig = mock<GlobalConfig>({
141+
logging: {
142+
format: 'json',
143+
level: 'info',
144+
outputs: ['console'],
145+
scopes: [],
146+
},
147+
});
148+
const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
149+
const testMessage = 'Test Message';
150+
const parentError = new Error('Parent', { cause: 'just a string' });
151+
const testError = new Error('Test', { cause: parentError });
152+
const testMetadata = { error: testError };
153+
154+
// ACT
155+
logger.info(testMessage, testMetadata);
156+
157+
// ASSERT
158+
expect(stdoutSpy).toHaveBeenCalledTimes(1);
159+
const output = stdoutSpy.mock.lastCall?.[0];
160+
if (typeof output !== 'string') {
161+
fail(`expected 'output' to be of type 'string', got ${typeof output}`);
162+
}
163+
164+
expect(() => JSON.parse(output)).not.toThrow();
165+
const parsedOutput = JSON.parse(output);
166+
167+
expect(parsedOutput).toMatchObject({
168+
message: testMessage,
169+
metadata: {
170+
error: {
171+
name: testError.name,
172+
message: testError.message,
173+
stack: testError.stack,
174+
cause: {
175+
name: parentError.name,
176+
message: parentError.message,
177+
stack: parentError.stack,
178+
cause: parentError.cause,
179+
},
180+
},
181+
},
182+
});
183+
});
184+
185+
test('do not recurse indefinitely when `cause` contains circular references', () => {
186+
// ARRANGE
187+
const stdoutSpy = jest.spyOn(process.stdout, 'write').mockReturnValue(true);
188+
const globalConfig = mock<GlobalConfig>({
189+
logging: {
190+
format: 'json',
191+
level: 'info',
192+
outputs: ['console'],
193+
scopes: [],
194+
},
195+
});
196+
const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
197+
const testMessage = 'Test Message';
198+
const parentError = new Error('Parent', { cause: 'just a string' });
199+
const childError = new Error('Test', { cause: parentError });
200+
parentError.cause = childError;
201+
const testMetadata = { error: childError };
202+
203+
// ACT
204+
logger.info(testMessage, testMetadata);
205+
206+
// ASSERT
207+
expect(stdoutSpy).toHaveBeenCalledTimes(1);
208+
const output = stdoutSpy.mock.lastCall?.[0];
209+
if (typeof output !== 'string') {
210+
fail(`expected 'output' to be of type 'string', got ${typeof output}`);
211+
}
212+
213+
expect(() => JSON.parse(output)).not.toThrow();
214+
const parsedOutput = JSON.parse(output);
215+
216+
expect(parsedOutput).toMatchObject({
217+
message: testMessage,
218+
metadata: {
219+
error: {
220+
name: childError.name,
221+
message: childError.message,
222+
stack: childError.stack,
223+
cause: {
224+
name: parentError.name,
225+
message: parentError.message,
226+
stack: parentError.stack,
227+
},
228+
},
229+
},
230+
});
231+
});
232+
});
233+
40234
describe('transports', () => {
41235
afterEach(() => {
42236
jest.restoreAllMocks();

‎packages/@n8n/backend-common/src/logging/logger.ts

Lines changed: 51 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -81,6 +81,27 @@ export class Logger implements LoggerType {
8181
return scopedLogger;
8282
}
8383

84+
private serializeError(
85+
error: unknown,
86+
seen: Set<unknown> = new Set(),
87+
): { name: string; message: string; stack?: string; cause: unknown } | string {
88+
if (!(error instanceof Error)) return String(error);
89+
90+
// prevent infinite recursion
91+
let cause: unknown;
92+
if (error.cause && !seen.has(error.cause)) {
93+
seen.add(error.cause);
94+
cause = this.serializeError(error.cause, seen);
95+
}
96+
97+
return {
98+
name: error.name,
99+
message: error.message,
100+
stack: error.stack,
101+
cause,
102+
};
103+
}
104+
84105
private log(level: LogLevel, message: string, metadata: LogMetadata) {
85106
const location: LogLocationMetadata = {};
86107

@@ -92,6 +113,13 @@ export class Logger implements LoggerType {
92113
if (fnName) location.function = fnName;
93114
}
94115

116+
for (const key of Object.keys(metadata)) {
117+
const value = metadata[key];
118+
if (value instanceof Error) {
119+
metadata[key] = this.serializeError(value);
120+
}
121+
}
122+
95123
this.internalLogger.log(level, message, { ...metadata, ...location });
96124
}
97125

@@ -107,13 +135,29 @@ export class Logger implements LoggerType {
107135
}
108136
}
109137

138+
private jsonConsoleFormat() {
139+
return winston.format.combine(
140+
winston.format.timestamp(),
141+
winston.format.metadata(),
142+
winston.format.json(),
143+
this.scopeFilter(),
144+
);
145+
}
146+
147+
private pickConsoleTransportFormat() {
148+
if (this.globalConfig.logging.format === 'json') {
149+
return this.jsonConsoleFormat();
150+
} else if (this.level === 'debug' && inDevelopment) {
151+
return this.debugDevConsoleFormat();
152+
} else if (this.level === 'debug' && inProduction) {
153+
return this.debugProdConsoleFormat();
154+
} else {
155+
return winston.format.printf(({ message }: { message: string }) => message);
156+
}
157+
}
158+
110159
private setConsoleTransport() {
111-
const format =
112-
this.level === 'debug' && inDevelopment
113-
? this.debugDevConsoleFormat()
114-
: this.level === 'debug' && inProduction
115-
? this.debugProdConsoleFormat()
116-
: winston.format.printf(({ message }: { message: string }) => message);
160+
const format = this.pickConsoleTransportFormat();
117161

118162
this.internalLogger.add(new winston.transports.Console({ format }));
119163
}
@@ -189,12 +233,6 @@ export class Logger implements LoggerType {
189233
}
190234

191235
private setFileTransport() {
192-
const format = winston.format.combine(
193-
winston.format.timestamp(),
194-
winston.format.metadata(),
195-
winston.format.json(),
196-
);
197-
198236
const filename = path.isAbsolute(this.globalConfig.logging.file.location)
199237
? this.globalConfig.logging.file.location
200238
: path.join(this.instanceSettingsConfig.n8nFolder, this.globalConfig.logging.file.location);
@@ -204,7 +242,7 @@ export class Logger implements LoggerType {
204242
this.internalLogger.add(
205243
new winston.transports.File({
206244
filename,
207-
format,
245+
format: this.jsonConsoleFormat(),
208246
maxsize: fileSizeMax * 1_048_576, // config * 1 MiB in bytes
209247
maxFiles: fileCountMax,
210248
}),

‎packages/@n8n/config/src/configs/logging.config.ts

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -66,6 +66,15 @@ export class LoggingConfig {
6666
@Env('N8N_LOG_OUTPUT')
6767
outputs: CommaSeparatedStringArray<'console' | 'file'> = ['console'];
6868

69+
/**
70+
* What format the logs should have.
71+
* `text` is only printing the human readable messages.
72+
* `json` is printing one JSON object per line containing the message, level,
73+
* timestamp and all the metadata.
74+
*/
75+
@Env('N8N_LOG_FORMAT')
76+
format: 'text' | 'json' = 'text';
77+
6978
@Nested
7079
file: FileLoggingConfig;
7180

‎packages/@n8n/config/test/config.test.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -241,6 +241,7 @@ describe('GlobalConfig', () => {
241241
},
242242
logging: {
243243
level: 'info',
244+
format: 'text',
244245
outputs: ['console'],
245246
file: {
246247
fileCountMax: 100,

‎packages/cli/src/active-workflow-manager.ts

Lines changed: 11 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -425,9 +425,7 @@ export class ActiveWorkflowManager {
425425
if (dbWorkflowIds.length === 0) return;
426426

427427
if (this.instanceSettings.isLeader) {
428-
this.logger.info(' ================================');
429-
this.logger.info(' Start Active Workflows:');
430-
this.logger.info(' ================================');
428+
this.logger.info('Start Active Workflows:');
431429
}
432430

433431
const batches = chunk(dbWorkflowIds, this.workflowsConfig.activationBatchSize);
@@ -456,23 +454,18 @@ export class ActiveWorkflowManager {
456454
});
457455

458456
if (added.webhooks || added.triggersAndPollers) {
459-
this.logger.info(` - ${formatWorkflow(dbWorkflow)})`);
460-
this.logger.info(' => Started');
461-
this.logger.debug(`Activated workflow ${formatWorkflow(dbWorkflow)}`, {
457+
this.logger.info(`Activated workflow ${formatWorkflow(dbWorkflow)}`, {
462458
workflowName: dbWorkflow.name,
463459
workflowId: dbWorkflow.id,
464460
});
465461
}
466462
} catch (error) {
467463
this.errorReporter.error(error);
468-
this.logger.info(
469-
` => ERROR: Workflow ${formatWorkflow(dbWorkflow)} could not be activated on first try, keep on trying if not an auth issue`,
470-
);
471-
472-
this.logger.info(` ${error.message}`);
473464
this.logger.error(
474465
`Issue on initial workflow activation try of ${formatWorkflow(dbWorkflow)} (startup)`,
475466
{
467+
// eslint-disable-next-line @typescript-eslint/no-unsafe-assignment
468+
error,
476469
workflowName: dbWorkflow.name,
477470
workflowId: dbWorkflow.id,
478471
},
@@ -723,10 +716,12 @@ export class ActiveWorkflowManager {
723716
}
724717

725718
this.logger.info(
726-
` -> Activation of workflow "${workflowName}" (${workflowId}) did fail with error: "${
719+
`Activation of workflow "${workflowName}" (${workflowId}) did fail with error: "${
727720
error.message as string
728721
}" | retry in ${Math.floor(lastTimeout / 1000)} seconds`,
729722
{
723+
// eslint-disable-next-line @typescript-eslint/no-unsafe-assignment
724+
error,
730725
workflowId,
731726
workflowName,
732727
},
@@ -736,13 +731,10 @@ export class ActiveWorkflowManager {
736731
this.queuedActivations[workflowId].timeout = setTimeout(retryFunction, lastTimeout);
737732
return;
738733
}
739-
this.logger.info(
740-
` -> Activation of workflow "${workflowName}" (${workflowId}) was successful!`,
741-
{
742-
workflowId,
743-
workflowName,
744-
},
745-
);
734+
this.logger.info(`Activation of workflow "${workflowName}" (${workflowId}) was successful!`, {
735+
workflowId,
736+
workflowName,
737+
});
746738
};
747739

748740
// Just to be sure that there is not chance that for any reason

0 commit comments

Comments
 (0)