refactor(core): Move Logger to @n8n/backend-common (#15721)

packages/@n8n/backend-common/package.json

@@ -21,10 +21,14 @@
     "dist/**/*"
   ],
   "dependencies": {
+    "@n8n/config": "workspace:^",
     "@n8n/constants": "workspace:^",
     "@n8n/di": "workspace:^",
+    "callsites": "catalog:",
     "n8n-workflow": "workspace:^",
-    "reflect-metadata": "catalog:"
+    "picocolors": "catalog:",
+    "reflect-metadata": "catalog:",
+    "winston": "3.14.2"
   },
   "devDependencies": {
     "@n8n/typescript-config": "workspace:*"

packages/@n8n/backend-common/src/environment.ts

@@ -0,0 +1,5 @@
+const { NODE_ENV } = process.env;
+
+export const inTest = NODE_ENV === 'test';
+export const inProduction = NODE_ENV === 'production';
+export const inDevelopment = !NODE_ENV || NODE_ENV === 'development';

packages/@n8n/backend-common/src/index.ts

@@ -1,10 +1,6 @@
 export * from './license-state';
 export * from './types';
 
-const { NODE_ENV } = process.env;
-
-export const inTest = NODE_ENV === 'test';
-export const inProduction = NODE_ENV === 'production';
-export const inDevelopment = !NODE_ENV || NODE_ENV === 'development';
-
+export { inDevelopment, inProduction, inTest } from './environment';
 export { isObjectLiteral } from './utils/is-object-literal';
+export { Logger } from './logging/logger';

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

@@ -0,0 +1,183 @@
+jest.mock('n8n-workflow', () => ({
+	...jest.requireActual('n8n-workflow'),
+	LoggerProxy: { init: jest.fn() },
+}));
+
+import type { GlobalConfig, InstanceSettingsConfig } from '@n8n/config';
+import { mock } from 'jest-mock-extended';
+import { LoggerProxy } from 'n8n-workflow';
+
+import { Logger } from '../logger';
+
+describe('Logger', () => {
+	beforeEach(() => {
+		jest.resetAllMocks();
+	});
+
+	describe('constructor', () => {
+		const globalConfig = mock<GlobalConfig>({
+			logging: {
+				level: 'info',
+				outputs: ['console'],
+				scopes: [],
+			},
+		});
+
+		test('if root, should initialize `LoggerProxy` with instance', () => {
+			const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>(), { isRoot: true });
+
+			expect(LoggerProxy.init).toHaveBeenCalledWith(logger);
+		});
+
+		test('if scoped, should not initialize `LoggerProxy`', () => {
+			new Logger(globalConfig, mock<InstanceSettingsConfig>(), { isRoot: false });
+
+			expect(LoggerProxy.init).not.toHaveBeenCalled();
+		});
+	});
+
+	describe('transports', () => {
+		test('if `console` selected, should set console transport', () => {
+			const globalConfig = mock<GlobalConfig>({
+				logging: {
+					level: 'info',
+					outputs: ['console'],
+					scopes: [],
+				},
+			});
+
+			const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
+
+			const { transports } = logger.getInternalLogger();
+
+			expect(transports).toHaveLength(1);
+
+			const [transport] = transports;
+
+			expect(transport.constructor.name).toBe('Console');
+		});
+
+		test('if `file` selected, should set file transport', () => {
+			const globalConfig = mock<GlobalConfig>({
+				logging: {
+					level: 'info',
+					outputs: ['file'],
+					scopes: [],
+					file: {
+						fileSizeMax: 100,
+						fileCountMax: 16,
+						location: 'logs/n8n.log',
+					},
+				},
+			});
+
+			const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>({ n8nFolder: '/tmp' }));
+
+			const { transports } = logger.getInternalLogger();
+
+			expect(transports).toHaveLength(1);
+
+			const [transport] = transports;
+
+			expect(transport.constructor.name).toBe('File');
+		});
+	});
+
+	describe('levels', () => {
+		test('if `error` selected, should enable `error` level', () => {
+			const globalConfig = mock<GlobalConfig>({
+				logging: {
+					level: 'error',
+					outputs: ['console'],
+					scopes: [],
+				},
+			});
+
+			const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
+
+			const internalLogger = logger.getInternalLogger();
+
+			expect(internalLogger.isErrorEnabled()).toBe(true);
+			expect(internalLogger.isWarnEnabled()).toBe(false);
+			expect(internalLogger.isInfoEnabled()).toBe(false);
+			expect(internalLogger.isDebugEnabled()).toBe(false);
+		});
+
+		test('if `warn` selected, should enable `error` and `warn` levels', () => {
+			const globalConfig = mock<GlobalConfig>({
+				logging: {
+					level: 'warn',
+					outputs: ['console'],
+					scopes: [],
+				},
+			});
+
+			const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
+
+			const internalLogger = logger.getInternalLogger();
+
+			expect(internalLogger.isErrorEnabled()).toBe(true);
+			expect(internalLogger.isWarnEnabled()).toBe(true);
+			expect(internalLogger.isInfoEnabled()).toBe(false);
+			expect(internalLogger.isDebugEnabled()).toBe(false);
+		});
+
+		test('if `info` selected, should enable `error`, `warn`, and `info` levels', () => {
+			const globalConfig = mock<GlobalConfig>({
+				logging: {
+					level: 'info',
+					outputs: ['console'],
+					scopes: [],
+				},
+			});
+
+			const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
+
+			const internalLogger = logger.getInternalLogger();
+
+			expect(internalLogger.isErrorEnabled()).toBe(true);
+			expect(internalLogger.isWarnEnabled()).toBe(true);
+			expect(internalLogger.isInfoEnabled()).toBe(true);
+			expect(internalLogger.isDebugEnabled()).toBe(false);
+		});
+
+		test('if `debug` selected, should enable all levels', () => {
+			const globalConfig = mock<GlobalConfig>({
+				logging: {
+					level: 'debug',
+					outputs: ['console'],
+					scopes: [],
+				},
+			});
+
+			const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
+
+			const internalLogger = logger.getInternalLogger();
+
+			expect(internalLogger.isErrorEnabled()).toBe(true);
+			expect(internalLogger.isWarnEnabled()).toBe(true);
+			expect(internalLogger.isInfoEnabled()).toBe(true);
+			expect(internalLogger.isDebugEnabled()).toBe(true);
+		});
+
+		test('if `silent` selected, should disable all levels', () => {
+			const globalConfig = mock<GlobalConfig>({
+				logging: {
+					level: 'silent',
+					outputs: ['console'],
+					scopes: [],
+				},
+			});
+
+			const logger = new Logger(globalConfig, mock<InstanceSettingsConfig>());
+
+			const internalLogger = logger.getInternalLogger();
+
+			expect(internalLogger.isErrorEnabled()).toBe(false);
+			expect(internalLogger.isWarnEnabled()).toBe(false);
+			expect(internalLogger.isInfoEnabled()).toBe(false);
+			expect(internalLogger.isDebugEnabled()).toBe(false);
+			expect(internalLogger.silent).toBe(true);
+		});
+	});
+});

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

@@ -0,0 +1 @@
+export { Logger } from './logger';

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

@@ -0,0 +1,242 @@
+import type { LogScope } from '@n8n/config';
+import { GlobalConfig, InstanceSettingsConfig } from '@n8n/config';
+import { Service } from '@n8n/di';
+import callsites from 'callsites';
+import type { TransformableInfo } from 'logform';
+import { LoggerProxy, LOG_LEVELS } from 'n8n-workflow';
+import type {
+	Logger as LoggerType,
+	LogLocationMetadata,
+	LogLevel,
+	LogMetadata,
+} from 'n8n-workflow';
+import path, { basename } from 'node:path';
+import pc from 'picocolors';
+import winston from 'winston';
+
+import { inDevelopment, inProduction } from '../environment';
+import { isObjectLiteral } from '../utils/is-object-literal';
+
+const noOp = () => {};
+
+@Service()
+export class Logger implements LoggerType {
+	private internalLogger: winston.Logger;
+
+	private readonly level: LogLevel;
+
+	private readonly scopes: Set<LogScope>;
+
+	private get isScopingEnabled() {
+		return this.scopes.size > 0;
+	}
+
+	/** https://no-color.org/ */
+	private readonly noColor = process.env.NO_COLOR !== undefined && process.env.NO_COLOR !== '';
+
+	constructor(
+		private readonly globalConfig: GlobalConfig,
+		private readonly instanceSettingsConfig: InstanceSettingsConfig,
+		{ isRoot }: { isRoot?: boolean } = { isRoot: true },
+	) {
+		this.level = this.globalConfig.logging.level;
+
+		const isSilent = this.level === 'silent';
+
+		this.internalLogger = winston.createLogger({
+			level: this.level,
+			silent: isSilent,
+		});
+
+		if (!isSilent) {
+			this.setLevel();
+
+			const { outputs, scopes } = this.globalConfig.logging;
+
+			if (outputs.includes('console')) this.setConsoleTransport();
+			if (outputs.includes('file')) this.setFileTransport();
+
+			this.scopes = new Set(scopes);
+		} else {
+			this.scopes = new Set();
+		}
+
+		if (isRoot) LoggerProxy.init(this);
+	}
+
+	private setInternalLogger(internalLogger: winston.Logger) {
+		this.internalLogger = internalLogger;
+	}
+
+	/** Create a logger that injects the given scopes into its log metadata. */
+	scoped(scopes: LogScope | LogScope[]) {
+		scopes = Array.isArray(scopes) ? scopes : [scopes];
+		const scopedLogger = new Logger(this.globalConfig, this.instanceSettingsConfig, {
+			isRoot: false,
+		});
+		const childLogger = this.internalLogger.child({ scopes });
+
+		scopedLogger.setInternalLogger(childLogger);
+
+		return scopedLogger;
+	}
+
+	private log(level: LogLevel, message: string, metadata: LogMetadata) {
+		const location: LogLocationMetadata = {};
+
+		const caller = callsites().at(2); // zeroth and first are this file, second is caller
+
+		if (caller !== undefined) {
+			location.file = basename(caller.getFileName() ?? '');
+			const fnName = caller.getFunctionName();
+			if (fnName) location.function = fnName;
+		}
+
+		this.internalLogger.log(level, message, { ...metadata, ...location });
+	}
+
+	private setLevel() {
+		const { levels } = this.internalLogger;
+
+		for (const logLevel of LOG_LEVELS) {
+			if (levels[logLevel] > levels[this.level]) {
+				// numerically higher (less severe) log levels become no-op
+				// to prevent overhead from `callsites` calls
+				Object.defineProperty(this, logLevel, { value: noOp });
+			}
+		}
+	}
+
+	private setConsoleTransport() {
+		const format =
+			this.level === 'debug' && inDevelopment
+				? this.debugDevConsoleFormat()
+				: this.level === 'debug' && inProduction
+					? this.debugProdConsoleFormat()
+					: winston.format.printf(({ message }: { message: string }) => message);
+
+		this.internalLogger.add(new winston.transports.Console({ format }));
+	}
+
+	private scopeFilter() {
+		return winston.format((info: TransformableInfo) => {
+			if (!this.isScopingEnabled) return info;
+
+			const { scopes } = (info as unknown as { metadata: LogMetadata }).metadata;
+
+			const shouldIncludeScope =
+				scopes && scopes?.length > 0 && scopes.some((s) => this.scopes.has(s));
+
+			return shouldIncludeScope ? info : false;
+		})();
+	}
+
+	private color() {
+		return this.noColor ? winston.format.uncolorize() : winston.format.colorize({ all: true });
+	}
+
+	private debugDevConsoleFormat() {
+		return winston.format.combine(
+			winston.format.metadata(),
+			winston.format.timestamp({ format: () => this.devTsFormat() }),
+			this.color(),
+			this.scopeFilter(),
+			winston.format.printf(({ level: rawLevel, message, timestamp, metadata: rawMetadata }) => {
+				const separator = ' '.repeat(3);
+				const logLevelColumnWidth = this.noColor ? 5 : 15; // when colorizing, account for ANSI color codes
+				const level = rawLevel.toLowerCase().padEnd(logLevelColumnWidth, ' ');
+				const metadata = this.toPrintable(rawMetadata);
+				return [timestamp, level, message + ' ' + pc.dim(metadata)].join(separator);
+			}),
+		);
+	}
+
+	private debugProdConsoleFormat() {
+		return winston.format.combine(
+			winston.format.metadata(),
+			winston.format.timestamp(),
+			this.color(),
+			this.scopeFilter(),
+			winston.format.printf(({ level, message, timestamp, metadata: rawMetadata }) => {
+				const metadata = this.toPrintable(rawMetadata);
+				return `${timestamp} | ${level.padEnd(5)} | ${message}${metadata ? ' ' + metadata : ''}`;
+			}),
+		);
+	}
+
+	private devTsFormat() {
+		const now = new Date();
+		const pad = (num: number, digits: number = 2) => num.toString().padStart(digits, '0');
+		const hours = pad(now.getHours());
+		const minutes = pad(now.getMinutes());
+		const seconds = pad(now.getSeconds());
+		const milliseconds = pad(now.getMilliseconds(), 3);
+		return `${hours}:${minutes}:${seconds}.${milliseconds}`;
+	}
+
+	private toPrintable(metadata: unknown) {
+		if (isObjectLiteral(metadata) && Object.keys(metadata).length > 0) {
+			return inProduction
+				? JSON.stringify(metadata)
+				: JSON.stringify(metadata)
+						.replace(/{"/g, '{ "')
+						.replace(/,"/g, ', "')
+						.replace(/:/g, ': ')
+						.replace(/}/g, ' }'); // spacing for readability
+		}
+
+		return '';
+	}
+
+	private setFileTransport() {
+		const format = winston.format.combine(
+			winston.format.timestamp(),
+			winston.format.metadata(),
+			winston.format.json(),
+		);
+
+		const filename = path.join(
+			this.instanceSettingsConfig.n8nFolder,
+			this.globalConfig.logging.file.location,
+		);
+
+		const { fileSizeMax, fileCountMax } = this.globalConfig.logging.file;
+
+		this.internalLogger.add(
+			new winston.transports.File({
+				filename,
+				format,
+				maxsize: fileSizeMax * 1_048_576, // config * 1 MiB in bytes
+				maxFiles: fileCountMax,
+			}),
+		);
+	}
+
+	// #region Convenience methods
+
+	error(message: string, metadata: LogMetadata = {}) {
+		this.log('error', message, metadata);
+	}
+
+	warn(message: string, metadata: LogMetadata = {}) {
+		this.log('warn', message, metadata);
+	}
+
+	info(message: string, metadata: LogMetadata = {}) {
+		this.log('info', message, metadata);
+	}
+
+	debug(message: string, metadata: LogMetadata = {}) {
+		this.log('debug', message, metadata);
+	}
+
+	// #endregion
+
+	// #region For testing only
+
+	getInternalLogger() {
+		return this.internalLogger;
+	}
+
+	// #endregion
+}