feat(core): Allow logging JSON to stdout (#15766)

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

@@ -37,6 +37,200 @@ describe('Logger', () => {
 		});
 	});
 
+	describe('formats', () => {
+		afterEach(() => {
+			jest.resetAllMocks();
+		});
+
+		test('log text, if `config.logging.format` is set to `text`', () => {
+			// ARRANGE
+			const stdoutSpy = jest.spyOn(process.stdout, 'write').mockReturnValue(true);
+			const globalConfig = mock<GlobalConfig>({
+				logging: {
+					format: 'text',
+					level: 'info',
+					outputs: ['console'],
+					scopes: [],
+				},
+			});
+			const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
+			const testMessage = 'Test Message';
+			const testMetadata = { test: 1 };
+
+			// ACT
+			logger.info(testMessage, testMetadata);
+
+			// ASSERT
+			expect(stdoutSpy).toHaveBeenCalledTimes(1);
+
+			const output = stdoutSpy.mock.lastCall?.[0];
+			if (typeof output !== 'string') {
+				fail(`expected 'output' to be of type 'string', got ${typeof output}`);
+			}
+
+			expect(output).toEqual(`${testMessage}\n`);
+		});
+
+		test('log json, if `config.logging.format` is set to `json`', () => {
+			// ARRANGE
+			const stdoutSpy = jest.spyOn(process.stdout, 'write').mockReturnValue(true);
+			const globalConfig = mock<GlobalConfig>({
+				logging: {
+					format: 'json',
+					level: 'info',
+					outputs: ['console'],
+					scopes: [],
+				},
+			});
+			const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
+			const testMessage = 'Test Message';
+			const testMetadata = { test: 1 };
+
+			// ACT
+			logger.info(testMessage, testMetadata);
+
+			// ASSERT
+			expect(stdoutSpy).toHaveBeenCalledTimes(1);
+			const output = stdoutSpy.mock.lastCall?.[0];
+			if (typeof output !== 'string') {
+				fail(`expected 'output' to be of type 'string', got ${typeof output}`);
+			}
+
+			expect(() => JSON.parse(output)).not.toThrow();
+			const parsedOutput = JSON.parse(output);
+
+			expect(parsedOutput).toMatchObject({
+				message: testMessage,
+				level: 'info',
+				metadata: {
+					...testMetadata,
+					timestamp: expect.any(String),
+				},
+			});
+		});
+
+		test('apply scope filters, if `config.logging.format` is set to `json`', () => {
+			// ARRANGE
+			const stdoutSpy = jest.spyOn(process.stdout, 'write').mockReturnValue(true);
+			const globalConfig = mock<GlobalConfig>({
+				logging: {
+					format: 'json',
+					level: 'info',
+					outputs: ['console'],
+					scopes: ['push'],
+				},
+			});
+			const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
+			const redisLogger = logger.scoped('redis');
+			const pushLogger = logger.scoped('push');
+			const testMessage = 'Test Message';
+			const testMetadata = { test: 1 };
+
+			// ACT
+			redisLogger.info(testMessage, testMetadata);
+			pushLogger.info(testMessage, testMetadata);
+
+			// ASSERT
+			expect(stdoutSpy).toHaveBeenCalledTimes(1);
+		});
+
+		test('log errors in metadata with stack trace, if `config.logging.format` is set to `json`', () => {
+			// ARRANGE
+			const stdoutSpy = jest.spyOn(process.stdout, 'write').mockReturnValue(true);
+			const globalConfig = mock<GlobalConfig>({
+				logging: {
+					format: 'json',
+					level: 'info',
+					outputs: ['console'],
+					scopes: [],
+				},
+			});
+			const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
+			const testMessage = 'Test Message';
+			const parentError = new Error('Parent', { cause: 'just a string' });
+			const testError = new Error('Test', { cause: parentError });
+			const testMetadata = { error: testError };
+
+			// ACT
+			logger.info(testMessage, testMetadata);
+
+			// ASSERT
+			expect(stdoutSpy).toHaveBeenCalledTimes(1);
+			const output = stdoutSpy.mock.lastCall?.[0];
+			if (typeof output !== 'string') {
+				fail(`expected 'output' to be of type 'string', got ${typeof output}`);
+			}
+
+			expect(() => JSON.parse(output)).not.toThrow();
+			const parsedOutput = JSON.parse(output);
+
+			expect(parsedOutput).toMatchObject({
+				message: testMessage,
+				metadata: {
+					error: {
+						name: testError.name,
+						message: testError.message,
+						stack: testError.stack,
+						cause: {
+							name: parentError.name,
+							message: parentError.message,
+							stack: parentError.stack,
+							cause: parentError.cause,
+						},
+					},
+				},
+			});
+		});
+
+		test('do not recurse indefinitely when `cause` contains circular references', () => {
+			// ARRANGE
+			const stdoutSpy = jest.spyOn(process.stdout, 'write').mockReturnValue(true);
+			const globalConfig = mock<GlobalConfig>({
+				logging: {
+					format: 'json',
+					level: 'info',
+					outputs: ['console'],
+					scopes: [],
+				},
+			});
+			const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
+			const testMessage = 'Test Message';
+			const parentError = new Error('Parent', { cause: 'just a string' });
+			const childError = new Error('Test', { cause: parentError });
+			parentError.cause = childError;
+			const testMetadata = { error: childError };
+
+			// ACT
+			logger.info(testMessage, testMetadata);
+
+			// ASSERT
+			expect(stdoutSpy).toHaveBeenCalledTimes(1);
+			const output = stdoutSpy.mock.lastCall?.[0];
+			if (typeof output !== 'string') {
+				fail(`expected 'output' to be of type 'string', got ${typeof output}`);
+			}
+
+			expect(() => JSON.parse(output)).not.toThrow();
+			const parsedOutput = JSON.parse(output);
+
+			expect(parsedOutput).toMatchObject({
+				message: testMessage,
+				metadata: {
+					error: {
+						name: childError.name,
+						message: childError.message,
+						stack: childError.stack,
+						cause: {
+							name: parentError.name,
+							message: parentError.message,
+							stack: parentError.stack,
+						},
+					},
+				},
+			});
+		});
+	});
+
 	describe('transports', () => {
 		afterEach(() => {
 			jest.restoreAllMocks();

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

@@ -81,6 +81,27 @@ export class Logger implements LoggerType {
 		return scopedLogger;
 	}
 
+	private serializeError(
+		error: unknown,
+		seen: Set<unknown> = new Set(),
+	): { name: string; message: string; stack?: string; cause: unknown } | string {
+		if (!(error instanceof Error)) return String(error);
+
+		// prevent infinite recursion
+		let cause: unknown;
+		if (error.cause && !seen.has(error.cause)) {
+			seen.add(error.cause);
+			cause = this.serializeError(error.cause, seen);
+		}
+
+		return {
+			name: error.name,
+			message: error.message,
+			stack: error.stack,
+			cause,
+		};
+	}
+
 	private log(level: LogLevel, message: string, metadata: LogMetadata) {
 		const location: LogLocationMetadata = {};
 
@@ -92,6 +113,13 @@ export class Logger implements LoggerType {
 			if (fnName) location.function = fnName;
 		}
 
+		for (const key of Object.keys(metadata)) {
+			const value = metadata[key];
+			if (value instanceof Error) {
+				metadata[key] = this.serializeError(value);
+			}
+		}
+
 		this.internalLogger.log(level, message, { ...metadata, ...location });
 	}
 
@@ -107,13 +135,29 @@ export class Logger implements LoggerType {
 		}
 	}
 
+	private jsonConsoleFormat() {
+		return winston.format.combine(
+			winston.format.timestamp(),
+			winston.format.metadata(),
+			winston.format.json(),
+			this.scopeFilter(),
+		);
+	}
+
+	private pickConsoleTransportFormat() {
+		if (this.globalConfig.logging.format === 'json') {
+			return this.jsonConsoleFormat();
+		} else if (this.level === 'debug' && inDevelopment) {
+			return this.debugDevConsoleFormat();
+		} else if (this.level === 'debug' && inProduction) {
+			return this.debugProdConsoleFormat();
+		} else {
+			return winston.format.printf(({ message }: { message: string }) => message);
+		}
+	}
+
 	private setConsoleTransport() {
-		const format =
-			this.level === 'debug' && inDevelopment
-				? this.debugDevConsoleFormat()
-				: this.level === 'debug' && inProduction
-					? this.debugProdConsoleFormat()
-					: winston.format.printf(({ message }: { message: string }) => message);
+		const format = this.pickConsoleTransportFormat();
 
 		this.internalLogger.add(new winston.transports.Console({ format }));
 	}
@@ -189,12 +233,6 @@ export class Logger implements LoggerType {
 	}
 
 	private setFileTransport() {
-		const format = winston.format.combine(
-			winston.format.timestamp(),
-			winston.format.metadata(),
-			winston.format.json(),
-		);
-
 		const filename = path.isAbsolute(this.globalConfig.logging.file.location)
 			? this.globalConfig.logging.file.location
 			: path.join(this.instanceSettingsConfig.n8nFolder, this.globalConfig.logging.file.location);
@@ -204,7 +242,7 @@ export class Logger implements LoggerType {
 		this.internalLogger.add(
 			new winston.transports.File({
 				filename,
-				format,
+				format: this.jsonConsoleFormat(),
 				maxsize: fileSizeMax * 1_048_576, // config * 1 MiB in bytes
 				maxFiles: fileCountMax,
 			}),

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

@@ -66,6 +66,15 @@ export class LoggingConfig {
 	@Env('N8N_LOG_OUTPUT')
 	outputs: CommaSeparatedStringArray<'console' | 'file'> = ['console'];
 
+	/**
+	 * What format the logs should have.
+	 * `text` is only printing the human readable messages.
+	 * `json` is printing one JSON object per line containing the message, level,
+	 * timestamp and all the metadata.
+	 */
+	@Env('N8N_LOG_FORMAT')
+	format: 'text' | 'json' = 'text';
+
 	@Nested
 	file: FileLoggingConfig;
 

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

@@ -241,6 +241,7 @@ describe('GlobalConfig', () => {
 		},
 		logging: {
 			level: 'info',
+			format: 'text',
 			outputs: ['console'],
 			file: {
 				fileCountMax: 100,

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

@@ -425,9 +425,7 @@ export class ActiveWorkflowManager {
 		if (dbWorkflowIds.length === 0) return;
 
 		if (this.instanceSettings.isLeader) {
-			this.logger.info(' ================================');
-			this.logger.info('   Start Active Workflows:');
-			this.logger.info(' ================================');
+			this.logger.info('Start Active Workflows:');
 		}
 
 		const batches = chunk(dbWorkflowIds, this.workflowsConfig.activationBatchSize);
@@ -456,23 +454,18 @@ export class ActiveWorkflowManager {
 			});
 
 			if (added.webhooks || added.triggersAndPollers) {
-				this.logger.info(`   - ${formatWorkflow(dbWorkflow)})`);
-				this.logger.info('     => Started');
-				this.logger.debug(`Activated workflow ${formatWorkflow(dbWorkflow)}`, {
+				this.logger.info(`Activated workflow ${formatWorkflow(dbWorkflow)}`, {
 					workflowName: dbWorkflow.name,
 					workflowId: dbWorkflow.id,
 				});
 			}
 		} catch (error) {
 			this.errorReporter.error(error);
-			this.logger.info(
-				`     => ERROR: Workflow ${formatWorkflow(dbWorkflow)} could not be activated on first try, keep on trying if not an auth issue`,
-			);
-
-			this.logger.info(`               ${error.message}`);
 			this.logger.error(
 				`Issue on initial workflow activation try of ${formatWorkflow(dbWorkflow)} (startup)`,
 				{
+					// eslint-disable-next-line @typescript-eslint/no-unsafe-assignment
+					error,
 					workflowName: dbWorkflow.name,
 					workflowId: dbWorkflow.id,
 				},
@@ -723,10 +716,12 @@ export class ActiveWorkflowManager {
 				}
 
 				this.logger.info(
-					` -> Activation of workflow "${workflowName}" (${workflowId}) did fail with error: "${
+					`Activation of workflow "${workflowName}" (${workflowId}) did fail with error: "${
 						error.message as string
 					}" | retry in ${Math.floor(lastTimeout / 1000)} seconds`,
 					{
+						// eslint-disable-next-line @typescript-eslint/no-unsafe-assignment
+						error,
 						workflowId,
 						workflowName,
 					},
@@ -736,13 +731,10 @@ export class ActiveWorkflowManager {
 				this.queuedActivations[workflowId].timeout = setTimeout(retryFunction, lastTimeout);
 				return;
 			}
-			this.logger.info(
-				` -> Activation of workflow "${workflowName}" (${workflowId}) was successful!`,
-				{
-					workflowId,
-					workflowName,
-				},
-			);
+			this.logger.info(`Activation of workflow "${workflowName}" (${workflowId}) was successful!`, {
+				workflowId,
+				workflowName,
+			});
 		};
 
 		// Just to be sure that there is not chance that for any reason

packages/core/src/instance-settings/instance-settings.ts

@@ -186,7 +186,7 @@ export class InstanceSettings {
 				errorMessage: `Error parsing n8n-config file "${this.settingsFile}". It does not seem to be valid JSON.`,
 			});
 
-			if (!inTest) console.info(`User settings loaded from: ${this.settingsFile}`);
+			if (!inTest) this.logger.info(`User settings loaded from: ${this.settingsFile}`);
 
 			const { encryptionKey, tunnelSubdomain } = settings;