From e5f4dc951d4792b22b6dbc9dfdf398b4a8afbb72 Mon Sep 17 00:00:00 2001 From: Jan Oberhauser Date: Sun, 4 Apr 2021 13:58:05 +0200 Subject: [PATCH] :zap: Some logging improvements --- packages/cli/config/index.ts | 2 +- packages/cli/src/Logger.ts | 62 ++++++++++++------- .../cli/src/WorkflowExecuteAdditionalData.ts | 8 +-- packages/cli/src/WorkflowHelpers.ts | 10 +-- packages/cli/src/WorkflowRunnerProcess.ts | 26 ++++---- packages/core/src/WorkflowExecute.ts | 10 ++- 6 files changed, 73 insertions(+), 45 deletions(-) diff --git a/packages/cli/config/index.ts b/packages/cli/config/index.ts index f8cec84d10..d2994a71d2 100644 --- a/packages/cli/config/index.ts +++ b/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', diff --git a/packages/cli/src/Logger.ts b/packages/cli/src/Logger.ts index f385a43009..7ea5529b15 100644 --- a/packages/cli/src/Logger.ts +++ b/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, @@ -8,22 +8,41 @@ import { class Logger implements ILogger { private logger: winston.Logger; - - constructor() { - const logFormat = winston.format.printf(({ message }) => message) as winston.Logform.Format; - + 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: config.get('logs.level'), - format: logFormat, - transports: [ - new winston.transports.Console(), - ], + level, }); - - 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,31 +54,30 @@ class Logger implements ILogger { }) ); } - } - + log(type: LogTypes, message: string, meta: object = {}) { this.logger.log(type, message, meta); } - + // Convenience methods below - + debug(message: string, meta: object = {}) { this.logger.log('debug', message, meta); } - + info(message: string, meta: object = {}) { this.logger.log('info', message, meta); } - + error(message: string, meta: object = {}) { this.logger.log('error', message, meta); } - + verbose(message: string, meta: object = {}) { this.logger.log('verbose', message, meta); } - + warn(message: string, meta: object = {}) { this.logger.log('warn', message, meta); } @@ -72,6 +90,6 @@ export function getLogger() { if (activeLoggerInstance === undefined) { activeLoggerInstance = new Logger(); } - + return activeLoggerInstance; -} \ No newline at end of file +} diff --git a/packages/cli/src/WorkflowExecuteAdditionalData.ts b/packages/cli/src/WorkflowExecuteAdditionalData.ts index d0687d28f5..f63189a9d3 100644 --- a/packages/cli/src/WorkflowExecuteAdditionalData.ts +++ b/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! - 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}`); } } @@ -424,8 +423,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}`); } } diff --git a/packages/cli/src/WorkflowHelpers.ts b/packages/cli/src/WorkflowHelpers.ts index 7071c1b715..398ed547cb 100644 --- a/packages/cli/src/WorkflowHelpers.ts +++ b/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 { 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 }); } } } diff --git a/packages/cli/src/WorkflowRunnerProcess.ts b/packages/cli/src/WorkflowRunnerProcess.ts index 70c140a7e3..93f7f30ebe 100644 --- a/packages/cli/src/WorkflowRunnerProcess.ts +++ b/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; @@ -126,10 +135,10 @@ export class WorkflowRunnerProcess { result = await executeWorkflowFunction(workflowInfo, additionalData, inputData, executionId, workflowData, runData); } catch (e) { await sendToParentProcess('finishExecution', { executionId }); - // Throw same error we had - throw e; + // Throw same error we had + throw e; } - + await sendToParentProcess('finishExecution', { executionId, result }); const returnData = WorkflowHelpers.getDataLastExecutedNodeData(result); @@ -167,12 +176,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}); } } diff --git a/packages/core/src/WorkflowExecute.ts b/packages/core/src/WorkflowExecute.ts index a71bc3bfa3..fed3098c1e 100644 --- a/packages/core/src/WorkflowExecute.ts +++ b/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; }