✨ Added logging to n8n (#1381)

* Added logging to n8n

This commit adds logging to n8n using the Winston library.

For now, this commit only allows logging to console (default behavior)
or file (need to pass in config via environment variables).

Other logging methods can be further implemented using hooks. These were
skipped for now as it would require adding more dependencies.

Logging level is notice by default, meaning no additional messages would
be displayed at the moment. Logging level can be set to info or debug as
well to enrich the generated logs.

The ILogger interface was added to the workflow project as it would make
it available for all other projects but the implementation was done on
the cli project.

* Lint fixes and logging level naming. Also fixed the way we use the logger as it was not working previously

* Improvements to logging framework

Using appropriate single quotes
Improving the way the logger is declared

* Improved naming for Log Types

* Removed logger global variable, replacing it by a proxy

* Add logging to CLI commands

* Remove unused GenericHelpers

* Changed back some messages to console instead of logger and added npm
shortcuts for worker and webhook

* Fix typos

* Adding basic file rotation to logs as suggested by @mutdmour

* Fixed linting issues

* Correcting comment to correctly reflect space usage

* Added settings for log files rotation

* Correcting config type from String to Number

* Changed default file settings to number

To reflect previous changes to the type

* Changed the way log messages are added to be called statically. Also minor naming improvements

* Applying latest corrections sent by @ivov

* ⚡ Some logging improvements

* Saving logs to a folder inside n8n home instead of root

* Fixed broken tests and linting

* Changed some log messages to improve formatting

* Adding quotes to names  on log messages

* Added execution and session IDs to logs. Also removed unnecessary line breaks

* ⚡ Added file caller to log messages (#1657)

This is done using callsites library which already existed
in the project as another library's dependency. So in fact
it does not add any new dependency.

* Adding logs to help debug Salesforce node

* ⚡ Add function name to logs and add more logs

* ⚡ Improve some error messages

* ⚡ Improve some more log messages

* ⚡ Rename logging env variables to match others

Co-authored-by: dali <servfrdali@yahoo.fr>
Co-authored-by: Jan Oberhauser <jan.oberhauser@gmail.com>

packages/cli/src/ActiveWorkflowRunner.ts

@@ -35,6 +35,9 @@ import {
 } from 'n8n-workflow';
 
 import * as express from 'express';
+import { 
+	LoggerProxy as Logger,
+} from 'n8n-workflow';
 
 export class ActiveWorkflowRunner {
 	private activeWorkflows: ActiveWorkflows | null = null;
@@ -43,7 +46,6 @@ export class ActiveWorkflowRunner {
 		[key: string]: IActivationError;
 	} = {};
 
-
 	async init() {
 
 		// Get the active workflows from database
@@ -59,20 +61,24 @@ export class ActiveWorkflowRunner {
 		this.activeWorkflows = new ActiveWorkflows();
 
 		if (workflowsData.length !== 0) {
-			console.log('\n ================================');
-			console.log('   Start Active Workflows:');
-			console.log(' ================================');
+			console.info(' ================================');
+			console.info('   Start Active Workflows:');
+			console.info(' ================================');
 
 			for (const workflowData of workflowsData) {
 				console.log(`   - ${workflowData.name}`);
+				Logger.debug(`Initializing active workflow "${workflowData.name}" (startup)`, {workflowName: workflowData.name, workflowId: workflowData.id});
 				try {
 					await this.add(workflowData.id.toString(), 'init', workflowData);
+					Logger.verbose(`Successfully started workflow "${workflowData.name}"`, {workflowName: workflowData.name, workflowId: workflowData.id});
 					console.log(`     => Started`);
 				} catch (error) {
 					console.log(`     => ERROR: Workflow could not be activated:`);
 					console.log(`               ${error.message}`);
+					Logger.error(`Unable to initialize workflow "${workflowData.name}" (startup)`, {workflowName: workflowData.name, workflowId: workflowData.id});
 				}
 			}
+			Logger.verbose('Finished initializing active workflows (startup)');
 		}
 	}
 
@@ -88,6 +94,7 @@ export class ActiveWorkflowRunner {
 	 */
 	async removeAll(): Promise<void> {
 		const activeWorkflowId: string[] = [];
+		Logger.verbose('Call to remove all active workflows received (removeAll)');
 
 		if (this.activeWorkflows !== null) {
 			// TODO: This should be renamed!
@@ -117,6 +124,7 @@ export class ActiveWorkflowRunner {
 	 * @memberof ActiveWorkflowRunner
 	 */
 	async executeWebhook(httpMethod: WebhookHttpMethod, path: string, req: express.Request, res: express.Response): Promise<IResponseCallbackData> {
+		Logger.debug(`Received webhoook "${httpMethod}" for path "${path}"`);
 		if (this.activeWorkflows === null) {
 			throw new ResponseHelper.ResponseError('The "activeWorkflows" instance did not get initialized yet.', 404, 404);
 		}
@@ -437,6 +445,7 @@ export class ActiveWorkflowRunner {
 		return ((workflow: Workflow, node: INode) => {
 			const returnFunctions = NodeExecuteFunctions.getExecutePollFunctions(workflow, node, additionalData, mode, activation);
 			returnFunctions.__emit = (data: INodeExecutionData[][]): void => {
+				Logger.debug(`Received event to trigger execution for workflow "${workflow.name}"`);
 				this.runWorkflow(workflowData, node, data, additionalData, mode);
 			};
 			return returnFunctions;
@@ -458,6 +467,7 @@ export class ActiveWorkflowRunner {
 		return ((workflow: Workflow, node: INode) => {
 			const returnFunctions = NodeExecuteFunctions.getExecuteTriggerFunctions(workflow, node, additionalData, mode, activation);
 			returnFunctions.emit = (data: INodeExecutionData[][]): void => {
+				Logger.debug(`Received trigger for workflow "${workflow.name}"`);
 				WorkflowHelpers.saveStaticData(workflow);
 				this.runWorkflow(workflowData, node, data, additionalData, mode).catch((err) => console.error(err));
 			};
@@ -492,6 +502,7 @@ export class ActiveWorkflowRunner {
 
 			const canBeActivated = workflowInstance.checkIfWorkflowCanBeActivated(['n8n-nodes-base.start']);
 			if (canBeActivated === false) {
+				Logger.error(`Unable to activate workflow "${workflowData.name}"`);
 				throw new Error(`The workflow can not be activated because it does not contain any nodes which could start the workflow. Only workflows which have trigger or webhook nodes can be activated.`);
 			}
 
@@ -507,6 +518,7 @@ export class ActiveWorkflowRunner {
 			if (workflowInstance.getTriggerNodes().length !== 0
 				|| workflowInstance.getPollNodes().length !== 0) {
 					await this.activeWorkflows.add(workflowId, workflowInstance, additionalData, mode, activation, getTriggerFunctions, getPollFunctions);
+				Logger.info(`Successfully activated workflow "${workflowData.name}"`);
 			}
 
 			if (this.activationErrors[workflowId] !== undefined) {

packages/cli/src/Logger.ts

@@ -0,0 +1,114 @@
+import config = require('../config');
+import * as winston from 'winston';
+
+import {
+	IDataObject,
+	ILogger,
+	LogTypes,
+} from 'n8n-workflow';
+
+import * as callsites from 'callsites';
+import { basename } from 'path';
+
+class Logger implements ILogger {
+	private logger: winston.Logger;
+
+	constructor() {
+		const level = config.get('logs.level');
+		const output = (config.get('logs.output') as string).split(',').map(output => output.trim());
+
+		this.logger = winston.createLogger({
+			level,
+		});
+
+		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(
+				new winston.transports.File({
+					filename: config.get('logs.file.location'),
+					format: fileLogFormat,
+					maxsize: config.get('logs.file.fileSizeMax') as number * 1048576, // config * 1mb
+					maxFiles: config.get('logs.file.fileCountMax'),
+				})
+			);
+		}
+	}
+
+	log(type: LogTypes, message: string, meta: object = {}) {
+		const callsite = callsites();
+		// We are using the third array element as the structure is as follows:
+		// [0]: this file
+		// [1]: Should be LoggerProxy
+		// [2]: Should point to the caller.
+		// Note: getting line number is useless because at this point
+		// We are in runtime, so it means we are looking at compiled js files
+		const logDetails = {} as IDataObject;
+		if (callsite[2] !== undefined) {
+			logDetails.file = basename(callsite[2].getFileName() || '');
+			const functionName = callsite[2].getFunctionName();
+			if (functionName) {
+				logDetails.function = functionName;
+			}
+		}
+		this.logger.log(type, message, {...meta, ...logDetails});
+	}
+
+	// Convenience methods below
+
+	debug(message: string, meta: object = {}) {
+		this.log('debug', message, meta);
+	}
+
+	info(message: string, meta: object = {}) {
+		this.log('info', message, meta);
+	}
+
+	error(message: string, meta: object = {}) {
+		this.log('error', message, meta);
+	}
+
+	verbose(message: string, meta: object = {}) {
+		this.log('verbose', message, meta);
+	}
+
+	warn(message: string, meta: object = {}) {
+		this.log('warn', message, meta);
+	}
+
+}
+
+let activeLoggerInstance: Logger | undefined;
+
+export function getLogger() {
+	if (activeLoggerInstance === undefined) {
+		activeLoggerInstance = new Logger();
+	}
+
+	return activeLoggerInstance;
+}

packages/cli/src/Push.ts

@@ -7,6 +7,10 @@ import {
 	IPushDataType,
 } from '.';
 
+import {
+	LoggerProxy as Logger,
+} from 'n8n-workflow';
+
 export class Push {
 	private channel: sseChannel;
 	private connections: {
@@ -24,6 +28,7 @@ export class Push {
 
 		this.channel.on('disconnect', (channel: string, res: express.Response) => {
 			if (res.req !== undefined) {
+				Logger.debug(`Remove editor-UI session`, { sessionId: res.req.query.sessionId });
 				delete this.connections[res.req.query.sessionId as string];
 			}
 		});
@@ -39,6 +44,8 @@ export class Push {
 	 * @memberof Push
 	 */
 	add(sessionId: string, req: express.Request, res: express.Response) {
+		Logger.debug(`Add editor-UI session`, { sessionId });
+
 		if (this.connections[sessionId] !== undefined) {
 			// Make sure to remove existing connection with the same session
 			// id if one exists already
@@ -64,11 +71,12 @@ export class Push {
 
 	send(type: IPushDataType, data: any, sessionId?: string) { // tslint:disable-line:no-any
 		if (sessionId !== undefined && this.connections[sessionId] === undefined) {
-			// TODO: Log that properly!
-			console.error(`The session "${sessionId}" is not registred.`);
+			Logger.error(`The session "${sessionId}" is not registred.`, { sessionId });
 			return;
 		}
 
+		Logger.debug(`Send data of type "${type}" to editor-UI`, { dataType: type, sessionId });
+
 		const sendData: IPushData = {
 			type,
 			data,

packages/cli/src/WebhookHelpers.ts

@@ -30,13 +30,14 @@ import {
 	IWebhookData,
 	IWebhookResponseData,
 	IWorkflowExecuteAdditionalData,
+	LoggerProxy as Logger,
 	NodeHelpers,
 	Workflow,
 	WorkflowExecuteMode,
 } from 'n8n-workflow';
 
-const activeExecutions = ActiveExecutions.getInstance();
 
+const activeExecutions = ActiveExecutions.getInstance();
 
 /**
  * Returns all the webhooks which should be created for the give workflow
@@ -286,6 +287,8 @@ export function getWorkflowWebhooksBasic(workflow: Workflow): IWebhookData[] {
 		const workflowRunner = new WorkflowRunner();
 		const executionId = await workflowRunner.run(runData, true, !didSendResponse);
 
+		Logger.verbose(`Started execution of workflow "${workflow.name}" from webhook with execution ID ${executionId}`, { executionId });
+
 		// Get a promise which resolves when the workflow did execute and send then response
 		const executePromise = activeExecutions.getPostExecutePromise(executionId) as Promise<IExecutionDb | undefined>;
 		executePromise.then((data) => {

packages/cli/src/WorkflowExecuteAdditionalData.ts

@@ -37,6 +37,7 @@ import {
 	IWorkflowExecuteAdditionalData,
 	IWorkflowExecuteHooks,
 	IWorkflowHooksOptionalParameters,
+	LoggerProxy as Logger,
 	Workflow,
 	WorkflowExecuteMode,
 	WorkflowHooks,
@@ -44,11 +45,10 @@ import {
 
 import * as config from '../config';
 
-import { LessThanOrEqual } from "typeorm";
+import { LessThanOrEqual } from 'typeorm';
 
 const ERROR_TRIGGER_TYPE = config.get('nodes.errorTriggerType') as string;
 
-
 /**
  * Checks if there was an error and if errorWorkflow or a trigger is defined. If so it collects
  * all the data and executes it
@@ -85,9 +85,11 @@ function executeErrorWorkflow(workflowData: IWorkflowBase, fullRunData: IRun, mo
 		// Run the error workflow
 		// To avoid an infinite loop do not run the error workflow again if the error-workflow itself failed and it is its own error-workflow.
 		if (workflowData.settings !== undefined && workflowData.settings.errorWorkflow && !(mode === 'error' && workflowData.id && workflowData.settings.errorWorkflow.toString() === workflowData.id.toString())) {
+			Logger.verbose(`Start external error workflow`, { executionId: this.executionId, errorWorkflowId: workflowData.settings.errorWorkflow.toString(), workflowId: this.workflowData.id });
 			// If a specific error workflow is set run only that one
 			WorkflowHelpers.executeErrorWorkflow(workflowData.settings.errorWorkflow as string, workflowErrorData);
 		} else if (mode !== 'error' && workflowData.id !== undefined && workflowData.nodes.some((node) => node.type === ERROR_TRIGGER_TYPE)) {
+			Logger.verbose(`Start internal error workflow`, { executionId: this.executionId, workflowId: this.workflowData.id });
 			// If the workflow contains
 			WorkflowHelpers.executeErrorWorkflow(workflowData.id.toString(), workflowErrorData);
 		}
@@ -102,6 +104,8 @@ function executeErrorWorkflow(workflowData: IWorkflowBase, fullRunData: IRun, mo
 let throttling = false;
 function pruneExecutionData(): void {
 	if (!throttling) {
+		Logger.verbose('Pruning execution data from database');
+
 		throttling = true;
 		const timeout = config.get('executions.pruneDataTimeout') as number; // in seconds
 		const maxAge = config.get('executions.pruneDataMaxAge') as number; // in h
@@ -133,6 +137,7 @@ function hookFunctionsPush(): IWorkflowExecuteHooks {
 				if (this.sessionId === undefined) {
 					return;
 				}
+				Logger.debug(`Executing hook on node "${nodeName}" (hookFunctionsPush)`, { executionId: this.executionId, sessionId: this.sessionId, workflowId: this.workflowData.id });
 
 				const pushInstance = Push.getInstance();
 				pushInstance.send('nodeExecuteBefore', {
@@ -147,6 +152,7 @@ function hookFunctionsPush(): IWorkflowExecuteHooks {
 				if (this.sessionId === undefined) {
 					return;
 				}
+				Logger.debug(`Executing hook on node "${nodeName}" (hookFunctionsPush)`, { executionId: this.executionId, sessionId: this.sessionId, workflowId: this.workflowData.id });
 
 				const pushInstance = Push.getInstance();
 				pushInstance.send('nodeExecuteAfter', {
@@ -158,6 +164,7 @@ function hookFunctionsPush(): IWorkflowExecuteHooks {
 		],
 		workflowExecuteBefore: [
 			async function (this: WorkflowHooks): Promise<void> {
+				Logger.debug(`Executing hook (hookFunctionsPush)`, { executionId: this.executionId, sessionId: this.sessionId, workflowId: this.workflowData.id });
 				// Push data to session which started the workflow
 				if (this.sessionId === undefined) {
 					return;
@@ -168,13 +175,14 @@ function hookFunctionsPush(): IWorkflowExecuteHooks {
 					mode: this.mode,
 					startedAt: new Date(),
 					retryOf: this.retryOf,
-					workflowId: this.workflowData.id as string,
+					workflowId: this.workflowData.id, sessionId: this.sessionId as string,
 					workflowName: this.workflowData.name,
 				}, this.sessionId);
 			},
 		],
 		workflowExecuteAfter: [
 			async function (this: WorkflowHooks, fullRunData: IRun, newStaticData: IDataObject): Promise<void> {
+				Logger.debug(`Executing hook (hookFunctionsPush)`, { executionId: this.executionId, sessionId: this.sessionId, workflowId: this.workflowData.id });
 				// Push data to session which started the workflow
 				if (this.sessionId === undefined) {
 					return;
@@ -195,6 +203,7 @@ function hookFunctionsPush(): IWorkflowExecuteHooks {
 				};
 
 				// Push data to editor-ui once workflow finished
+				Logger.debug(`Save execution progress to database for execution ID ${this.executionId} `, { executionId: this.executionId, workflowId: this.workflowData.id });
 				// TODO: Look at this again
 				const sendData: IPushDataExecutionFinished = {
 					executionId: this.executionId,
@@ -232,6 +241,8 @@ export function hookFunctionsPreExecute(parentProcessMode?: string): IWorkflowEx
 				}
 
 				try {
+					Logger.debug(`Save execution progress to database for execution ID ${this.executionId} `, { executionId: this.executionId, nodeName });
+
 					const execution = await Db.collections.Execution!.findOne(this.executionId);
 
 					if (execution === undefined) {
@@ -286,7 +297,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} (hookFunctionsPreExecute, nodeExecuteAfter)`, { ...err, executionId: this.executionId, sessionId: this.sessionId, workflowId: this.workflowData.id });
 				}
 
 			},
@@ -307,6 +318,7 @@ function hookFunctionsSave(parentProcessMode?: string): IWorkflowExecuteHooks {
 		workflowExecuteBefore: [],
 		workflowExecuteAfter: [
 			async function (this: WorkflowHooks, fullRunData: IRun, newStaticData: IDataObject): Promise<void> {
+				Logger.debug(`Executing hook (hookFunctionsSave)`, { executionId: this.executionId, workflowId: this.workflowData.id });
 
 				// Prune old execution data
 				if (config.get('executions.pruneData')) {
@@ -321,8 +333,7 @@ function hookFunctionsSave(parentProcessMode?: string): IWorkflowExecuteHooks {
 						try {
 							await WorkflowHelpers.saveStaticDataById(this.workflowData.id as string, newStaticData);
 						} catch (e) {
-							// TODO: Add proper logging!
-							console.error(`There was a problem saving the workflow with id "${this.workflowData.id}" to save changed staticData: ${e.message}`);
+							Logger.error(`There was a problem saving the workflow with id "${this.workflowData.id}" to save changed staticData: "${e.message}" (hookFunctionsSave)`, { executionId: this.executionId, workflowId: this.workflowData.id });
 						}
 					}
 
@@ -375,6 +386,9 @@ function hookFunctionsSave(parentProcessMode?: string): IWorkflowExecuteHooks {
 						fullExecutionData.workflowId = this.workflowData.id.toString();
 					}
 
+					// Leave log message before flatten as that operation increased memory usage a lot and the chance of a crash is highest here
+					Logger.debug(`Save execution data to database for execution ID ${this.executionId}`, { executionId: this.executionId, workflowId: this.workflowData.id });
+
 					const executionData = ResponseHelper.flattenExecutionData(fullExecutionData);
 
 					// Save the Execution in DB
@@ -420,8 +434,7 @@ function hookFunctionsSaveWorker(): IWorkflowExecuteHooks {
 						try {
 							await WorkflowHelpers.saveStaticDataById(this.workflowData.id as string, newStaticData);
 						} catch (e) {
-							// TODO: Add proper logging!
-							console.error(`There was a problem saving the workflow with id "${this.workflowData.id}" to save changed staticData: ${e.message}`);
+							Logger.error(`There was a problem saving the workflow with id "${this.workflowData.id}" to save changed staticData: "${e.message}" (workflowExecuteAfter)`, { sessionId: this.sessionId, workflowId: this.workflowData.id });
 						}
 					}
 

packages/cli/src/WorkflowHelpers.ts

@@ -18,8 +18,8 @@ import {
 	IRunExecutionData,
 	ITaskData,
 	IWorkflowCredentials,
-	Workflow,
-} from 'n8n-workflow';
+	LoggerProxy as Logger,
+	Workflow,} from 'n8n-workflow';
 
 import * as config from '../config';
 
@@ -86,7 +86,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 +105,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 +153,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 +315,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!
-				console.error(`There was a problem saving the workflow with id "${workflow.id}" to save changed staticData: ${e.message}`);
+				Logger.error(`There was a problem saving the workflow with id "${workflow.id}" to save changed staticData: "${e.message}"`, { workflowId: workflow.id });
 			}
 		}
 	}

packages/cli/src/WorkflowRunner.ts

@@ -29,6 +29,7 @@ import {
 import {
 	ExecutionError,
 	IRun,
+	LoggerProxy as Logger,
 	Workflow,
 	WorkflowExecuteMode,
 	WorkflowHooks,
@@ -177,20 +178,24 @@ export class WorkflowRunner {
 
 		// Register the active execution
 		const executionId = await this.activeExecutions.add(data, undefined);
+		Logger.verbose(`Execution for workflow ${data.workflowData.name} was assigned id ${executionId}`, {executionId});
 
 		additionalData.hooks = WorkflowExecuteAdditionalData.getWorkflowHooksMain(data, executionId, true);
 
 		let workflowExecution: PCancelable<IRun>;
 		if (data.executionData !== undefined) {
+			Logger.debug(`Execution ID ${executionId} had Execution data. Running with payload.`, {executionId});
 			const workflowExecute = new WorkflowExecute(additionalData, data.executionMode, data.executionData);
 			workflowExecution = workflowExecute.processRunExecutionData(workflow);
 		} else if (data.runData === undefined || data.startNodes === undefined || data.startNodes.length === 0 || data.destinationNode === undefined) {
+			Logger.debug(`Execution ID ${executionId} will run executing all nodes.`, {executionId});
 			// Execute all nodes
 
 			// Can execute without webhook so go on
 			const workflowExecute = new WorkflowExecute(additionalData, data.executionMode);
 			workflowExecution = workflowExecute.run(workflow, undefined, data.destinationNode);
 		} else {
+			Logger.debug(`Execution ID ${executionId} is a partial execution.`, {executionId});
 			// Execute only the nodes between start and destination nodes
 			const workflowExecute = new WorkflowExecute(additionalData, data.executionMode);
 			workflowExecution = workflowExecute.runPartialWorkflow(workflow, data.runData, data.startNodes, data.destinationNode);
@@ -450,6 +455,7 @@ export class WorkflowRunner {
 
 		// Listen to data from the subprocess
 		subprocess.on('message', async (message: IProcessMessage) => {
+			Logger.debug(`Received child process message of type ${message.type} for execution ID ${executionId}.`, {executionId});
 			if (message.type === 'start') {
 				// Now that the execution actually started set the timeout again so that does not time out to early.
 				startedAt = new Date();
@@ -491,11 +497,13 @@ export class WorkflowRunner {
 		// Also get informed when the processes does exit especially when it did crash or timed out
 		subprocess.on('exit', async (code, signal) => {
 			if (signal === 'SIGTERM'){
+				Logger.debug(`Subprocess for execution ID ${executionId} timed out.`, {executionId});
 				// Execution timed out and its process has been terminated
 				const timeoutError = new WorkflowOperationError('Workflow execution timed out!');
 
 				this.processError(timeoutError, startedAt, data.executionMode, executionId);
 			} else if (code !== 0) {
+				Logger.debug(`Subprocess for execution ID ${executionId} finished with error code ${code}.`, {executionId});
 				// Process did exit with error code, so something went wrong.
 				const executionError = new WorkflowOperationError('Workflow execution process did crash for an unknown reason!');
 

packages/cli/src/WorkflowRunnerProcess.ts

@@ -20,23 +20,29 @@ import {
 	ExecutionError,
 	IDataObject,
 	IExecuteWorkflowInfo,
+	ILogger,
 	INodeExecutionData,
 	INodeType,
 	INodeTypeData,
 	IRun,
-	IRunExecutionData,
 	ITaskData,
 	IWorkflowExecuteAdditionalData,
 	IWorkflowExecuteHooks,
+	LoggerProxy,
 	Workflow,
 	WorkflowHooks,
 	WorkflowOperationError,
 } 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;
@@ -57,7 +63,13 @@ export class WorkflowRunnerProcess {
 		process.on('SIGTERM', WorkflowRunnerProcess.stopProcess);
 		process.on('SIGINT', WorkflowRunnerProcess.stopProcess);
 
+		const logger = this.logger = getLogger();
+		LoggerProxy.init(logger);
+
 		this.data = inputData;
+
+		logger.verbose('Initializing n8n sub-process', { pid: process.pid, workflowId: this.data.workflowData.id });
+
 		let className: string;
 		let tempNode: INodeType;
 		let filePath: string;
@@ -152,6 +164,8 @@ export class WorkflowRunnerProcess {
 				throw e;
 			}
 
+			await sendToParentProcess('finishExecution', { executionId, result });
+
 			const returnData = WorkflowHelpers.getDataLastExecutedNodeData(result);
 			return returnData!.data!.main;
 		};
@@ -187,12 +201,7 @@ export class WorkflowRunnerProcess {
 				parameters,
 			});
 		} catch (error) {
-			// TODO: Add proper logging
-			console.error(`There was a problem sending hook: "${hook}"`);
-			console.error('Parameters:');
-			console.error(parameters);
-			console.error('Error:');
-			console.error(error);
+			this.logger.error(`There was a problem sending hook: "${hook}"`, { parameters, error});
 		}
 	}