⚡ Some logging improvements

packages/cli/config/index.ts

@@ -576,7 +576,7 @@ const config = convict({
 			env: 'N8N_LOG_LEVEL',
 		},
 		output: {
-			doc: 'Where to output logs. Options are: console, file.',
+			doc: 'Where to output logs. Options are: console, file. Multiple can be separated by comma (",")',
 			format: String,
 			default: 'console',
 			env: 'N8N_LOG_OUTPUT',

packages/cli/src/Logger.ts

@@ -1,5 +1,5 @@
-import * as winston from 'winston';
 import config = require('../config');
+import * as winston from 'winston';
 
 import {
 	ILogger,
@@ -10,20 +10,39 @@ class Logger implements ILogger {
 	private logger: winston.Logger;
 
 	constructor() {
-
+		const level = config.get('logs.level');
-		const logFormat = winston.format.printf(({ message }) => message) as winston.Logform.Format;
+		const output = (config.get('logs.output') as string).split(',').map(output => output.trim());
 
 		this.logger = winston.createLogger({
-			level: config.get('logs.level'),
+			level,
-			format: logFormat,
-			transports: [
-				new winston.transports.Console(),
-			],
 		});
 
-		if (config.get('logs.output') === 'file') {
+		if (output.includes('console')) {
+			let format: winston.Logform.Format;
+			if (['debug', 'verbose'].includes(level)) {
+				format = winston.format.combine(
+					winston.format.metadata(),
+					winston.format.timestamp(),
+					winston.format.colorize({ all: true }),
+					winston.format.printf(({ level, message, timestamp, metadata }) => {
+						return `${timestamp} | ${level.padEnd(18)} | ${message}` + (Object.keys(metadata).length ? ` ${JSON.stringify(metadata)}` : '');
+					}) as winston.Logform.Format,
+				);
+			} else {
+				format = winston.format.printf(({ message }) => message) as winston.Logform.Format;
+			}
+
+			this.logger.add(
+				new winston.transports.Console({
+					format,
+				})
+			);
+		}
+
+		if (output.includes('file')) {
 			const fileLogFormat = winston.format.combine(
 				winston.format.timestamp(),
+				winston.format.metadata(),
 				winston.format.json()
 			);
 			this.logger.add(
@@ -35,7 +54,6 @@ class Logger implements ILogger {
 				})
 			);
 		}
-			
 	}
 
 	log(type: LogTypes, message: string, meta: object = {}) {

packages/cli/src/WorkflowExecuteAdditionalData.ts

@@ -289,7 +289,7 @@ export function hookFunctionsPreExecute(parentProcessMode?: string): IWorkflowEx
 					// For busy machines, we may get "Database is locked" errors.
 
 					// We do this to prevent crashes and executions ending in `unknown` state.
-					console.log(`Failed saving execution progress to database for execution ID ${this.executionId}`, err);
+					Logger.error(`Failed saving execution progress to database for execution ID ${this.executionId}`, err);
 				}
 
 			},
@@ -325,8 +325,7 @@ function hookFunctionsSave(parentProcessMode?: string): IWorkflowExecuteHooks {
 						try {
 							await WorkflowHelpers.saveStaticDataById(this.workflowData.id as string, newStaticData);
 						} catch (e) {
-							// TODO: Add proper logging!
+							Logger.error(`There was a problem saving the workflow with id "${this.workflowData.id}" to save changed staticData: ${e.message}`);
-							console.error(`There was a problem saving the workflow with id "${this.workflowData.id}" to save changed staticData: ${e.message}`);
 						}
 					}
 
@@ -424,8 +423,7 @@ function hookFunctionsSaveWorker(): IWorkflowExecuteHooks {
 						try {
 							await WorkflowHelpers.saveStaticDataById(this.workflowData.id as string, newStaticData);
 						} catch (e) {
-							// TODO: Add proper logging!
+							Logger.error(`There was a problem saving the workflow with id "${this.workflowData.id}" to save changed staticData: ${e.message}`);
-							console.error(`There was a problem saving the workflow with id "${this.workflowData.id}" to save changed staticData: ${e.message}`);
 						}
 					}
 

packages/cli/src/WorkflowHelpers.ts

@@ -17,6 +17,7 @@ import {
 	IRun,
 	IRunExecutionData,
 	ITaskData,
+	LoggerProxy as Logger,
 	IWorkflowCredentials,
 	Workflow,
 } from 'n8n-workflow';
@@ -86,7 +87,7 @@ export async function executeErrorWorkflow(workflowId: string, workflowErrorData
 
 		if (workflowData === undefined) {
 			// The error workflow could not be found
-			console.error(`ERROR: Calling Error Workflow for "${workflowErrorData.workflow.id}". Could not find error workflow "${workflowId}"`);
+			Logger.error(`Calling Error Workflow for "${workflowErrorData.workflow.id}". Could not find error workflow "${workflowId}"`, { workflowId });
 			return;
 		}
 
@@ -105,7 +106,7 @@ export async function executeErrorWorkflow(workflowId: string, workflowErrorData
 		}
 
 		if (workflowStartNode === undefined) {
-			console.error(`ERROR: Calling Error Workflow for "${workflowErrorData.workflow.id}". Could not find "${ERROR_TRIGGER_TYPE}" in workflow "${workflowId}"`);
+			Logger.error(`Calling Error Workflow for "${workflowErrorData.workflow.id}". Could not find "${ERROR_TRIGGER_TYPE}" in workflow "${workflowId}"`);
 			return;
 		}
 
@@ -153,7 +154,7 @@ export async function executeErrorWorkflow(workflowId: string, workflowErrorData
 		const workflowRunner = new WorkflowRunner();
 		await workflowRunner.run(runData);
 	} catch (error) {
-		console.error(`ERROR: Calling Error Workflow for "${workflowErrorData.workflow.id}": ${error.message}`);
+		Logger.error(`Calling Error Workflow for "${workflowErrorData.workflow.id}": ${error.message}`, { workflowId: workflowErrorData.workflow.id });
 	}
 }
 
@@ -315,8 +316,7 @@ export async function saveStaticData(workflow: Workflow): Promise <void> {
 				await saveStaticDataById(workflow.id!, workflow.staticData);
 				workflow.staticData.__dataChanged = false;
 			} catch (e) {
-				// TODO: Add proper logging!
+				Logger.error(`There was a problem saving the workflow with id "${workflow.id}" to save changed staticData: ${e.message}`, { workflowId: workflow.id });
-				console.error(`There was a problem saving the workflow with id "${workflow.id}" to save changed staticData: ${e.message}`);
 			}
 		}
 	}

packages/cli/src/WorkflowRunnerProcess.ts

@@ -17,25 +17,30 @@ import {
 
 import {
 	IDataObject,
-	IExecuteData,
 	IExecuteWorkflowInfo,
 	IExecutionError,
+	ILogger,
 	INodeExecutionData,
 	INodeType,
 	INodeTypeData,
 	IRun,
-	IRunExecutionData,
 	ITaskData,
 	IWorkflowExecuteAdditionalData,
 	IWorkflowExecuteHooks,
+	LoggerProxy,
 	Workflow,
 	WorkflowHooks,
 } from 'n8n-workflow';
 
+import {
+	getLogger,
+} from '../src/Logger';
+
 import * as config from '../config';
 
 export class WorkflowRunnerProcess {
 	data: IWorkflowExecutionDataProcessWithExecution | undefined;
+	logger: ILogger;
 	startedAt = new Date();
 	workflow: Workflow | undefined;
 	workflowExecute: WorkflowExecute | undefined;
@@ -53,6 +58,10 @@ export class WorkflowRunnerProcess {
 		process.on('SIGTERM', WorkflowRunnerProcess.stopProcess);
 		process.on('SIGINT', WorkflowRunnerProcess.stopProcess);
 
+		const logger = this.logger = getLogger();
+		LoggerProxy.init(logger);
+		logger.info('Initializing n8n sub-process', { pid: process.pid });
+
 		this.data = inputData;
 		let className: string;
 		let tempNode: INodeType;
@@ -167,12 +176,7 @@ export class WorkflowRunnerProcess {
 				parameters,
 			});
 		} catch (error) {
-			// TODO: Add proper logging
+			this.logger.error(`There was a problem sending hook: "${hook}"`, { parameters, error});
-			console.error(`There was a problem sending hook: "${hook}"`);
-			console.error('Parameters:');
-			console.error(parameters);
-			console.error('Error:');
-			console.error(error);
 		}
 	}
 

packages/core/src/WorkflowExecute.ts

@@ -15,6 +15,7 @@ import {
 	ITaskDataConnections,
 	IWaitingForExecution,
 	IWorkflowExecuteAdditionalData,
+	LoggerProxy as Logger,
 	Workflow,
 	WorkflowExecuteMode,
 } from 'n8n-workflow';
@@ -500,7 +501,7 @@ export class WorkflowExecute {
 		if (this.runExecutionData.startData === undefined) {
 			this.runExecutionData.startData = {};
 		}
-
+		Logger.debug(`Workflow execution (start)`);
 
 		let currentExecutionTry = '';
 		let lastExecutionTry = '';
@@ -557,6 +558,7 @@ export class WorkflowExecute {
 					executionData = this.runExecutionData.executionData!.nodeExecutionStack.shift() as IExecuteData;
 					executionNode = executionData.node;
 
+					Logger.debug(`Process node: "${executionNode.name}" (Start)`);
 					await this.executeHook('nodeExecuteBefore', [executionNode.name]);
 
 					// Get the index of the current run
@@ -654,7 +656,9 @@ export class WorkflowExecute {
 								}
 							}
 
+							Logger.debug(`Process node: "${executionNode.name}" (before: runNode)`);
 							nodeSuccessData = await workflow.runNode(executionData.node, executionData.data, this.runExecutionData, runIndex, this.additionalData, NodeExecuteFunctions, this.mode);
+							Logger.debug(`Process node: "${executionNode.name}" (after: runNode - success)`);
 
 							if (nodeSuccessData === undefined) {
 								// Node did not get executed
@@ -689,6 +693,8 @@ export class WorkflowExecute {
 								message: error.message,
 								stack: error.stack,
 							};
+
+							Logger.debug(`Process node: "${executionNode.name}" (after: runNode - error)`);
 						}
 					}
 
@@ -819,8 +825,10 @@ export class WorkflowExecute {
 		const fullRunData = this.getFullRunData(startedAt);
 
 		if (executionError !== undefined) {
+			Logger.debug(`Workflow execution (end: error)`, { error: executionError });
 			fullRunData.data.resultData.error = executionError;
 		} else {
+			Logger.debug(`Workflow execution (end: success)`);
 			fullRunData.finished = true;
 		}