From 3d69e7abcbad45e6756965cca402aaf8072243d7 Mon Sep 17 00:00:00 2001 From: Luis Fernando Molina Date: Tue, 4 Feb 2020 09:29:10 +0100 Subject: [PATCH] Improving console logging plus bug fixes --- DebugLog.js | 6 ++++-- IndicatorBotProcessMainLoop.js | 4 ++-- MultiPeriod.js | 2 -- MultiPeriodDaily.js | 4 +--- ProcessExecutionEvents.js | 8 ++++---- Root.js | 11 +---------- SensorBotProcessMainLoop.js | 6 +++--- TradingBotProcessMainLoop.js | 4 ++-- server.js | 15 ++++++++------- 9 files changed, 25 insertions(+), 35 deletions(-) diff --git a/DebugLog.js b/DebugLog.js index ebc3e6d39..ba2c83788 100644 --- a/DebugLog.js +++ b/DebugLog.js @@ -37,10 +37,12 @@ exports.newDebugLog = function newDebugLog() { } } - function newInternalLoop(pBot, pProcess) { + function newInternalLoop(pBot, pProcess, date) { + if (date === undefined) { date = thisObject.bot.processDatetime } - console.log(new Date().toISOString() + " " + strPad(pBot, 20) + " " + strPad(pProcess, 30) + " Entered into Internal Loop # " + strPad(internalLoopCounter + 1, 4) + " bot.processDatetime = " + thisObject.bot.processDatetime.toISOString()); + console.log(new Date().toISOString() + " " + strPad(pBot, 20) + " " + strPad(pProcess, 30) + " " + strPad(thisObject.bot.exchange, 20) + " " + strPad(thisObject.bot.market.baseAsset + '/' + thisObject.bot.market.quotedAsset, 10) + + " Entered into Internal Loop # " + strPad(internalLoopCounter + 1, 8) + " " + strPad(date.toISOString(), 30)) persist(); diff --git a/IndicatorBotProcessMainLoop.js b/IndicatorBotProcessMainLoop.js index 00c6974dc..aa2cd6ac2 100644 --- a/IndicatorBotProcessMainLoop.js +++ b/IndicatorBotProcessMainLoop.js @@ -145,8 +145,8 @@ /* High level log entry */ - console.log(new Date().toISOString() + " " + pad(bot.codeName, 20) + " " + pad(bot.process, 30) - + " Entered into Main Loop # " + pad(Number(bot.loopCounter), 8)); + console.log(new Date().toISOString() + " " + pad(bot.codeName, 20) + " " + pad(bot.process, 30) + " " + pad(bot.exchange, 20) + " " + pad(bot.market.baseAsset + '/' + bot.market.quotedAsset, 10) + + " Entered into Main Loop # " + pad(Number(bot.loopCounter), 8)); /* We will prepare first the infraestructure needed for the bot to run. There are 3 modules we need to sucessfullly initialize first. */ diff --git a/MultiPeriod.js b/MultiPeriod.js index 62141ce01..94a1cd318 100644 --- a/MultiPeriod.js +++ b/MultiPeriod.js @@ -453,8 +453,6 @@ bot.multiPeriodProcessDatetime = new Date(bot.multiPeriodProcessDatetime.valueOf() + ONE_DAY_IN_MILISECONDS); previousDay = new Date(bot.multiPeriodProcessDatetime.valueOf() - ONE_DAY_IN_MILISECONDS); - console.log(new Date().toISOString() + " " + pad(bot.codeName, 20) + " " + pad(bot.process, 30) + " " + "bot.multiPeriodProcessDatetime = " + bot.multiPeriodProcessDatetime.toISOString()); - if (global.WRITE_LOGS_TO_FILES === 'true') { logger.newInternalLoop(bot.codeName, bot.process); } diff --git a/MultiPeriodDaily.js b/MultiPeriodDaily.js index b50e975c0..1e87a91a5 100644 --- a/MultiPeriodDaily.js +++ b/MultiPeriodDaily.js @@ -306,9 +306,7 @@ bot.multiPeriodDailyProcessDatetime = new Date(bot.multiPeriodDailyProcessDatetime.valueOf() + ONE_DAY_IN_MILISECONDS); previousDay = new Date(bot.multiPeriodDailyProcessDatetime.valueOf() - ONE_DAY_IN_MILISECONDS); - - console.log(new Date().toISOString() + " " + pad(bot.codeName, 20) + " " + pad(bot.process, 30) + " " + "bot.multiPeriodDailyProcessDatetime = " + bot.multiPeriodDailyProcessDatetime.toISOString()); - + if (global.WRITE_LOGS_TO_FILES === 'true') { logger.newInternalLoop(bot.codeName, bot.process); } diff --git a/ProcessExecutionEvents.js b/ProcessExecutionEvents.js index 3aa7486ee..ed79e1be7 100644 --- a/ProcessExecutionEvents.js +++ b/ProcessExecutionEvents.js @@ -32,7 +32,8 @@ if (bot.processNode.referenceParent !== undefined) { - currentProcessKey = bot.processNode.referenceParent.name + "-" + bot.processNode.referenceParent.type + "-" + bot.processNode.referenceParent.id + let market = bot.market.baseAsset + '/' + bot.market.quotedAsset + currentProcessKey = bot.processNode.referenceParent.name + "-" + bot.processNode.referenceParent.type + "-" + bot.processNode.referenceParent.id + "-" + bot.exchange + "-" + market if (bot.processNode.referenceParent.executionStartedEvent !== undefined) { if (bot.processNode.referenceParent.executionStartedEvent.referenceParent !== undefined) { @@ -70,7 +71,8 @@ let extraCallerId = '-' + Math.trunc(Math.random() * 10000) + '-' - let key = processThisDependsOn.name + "-" + processThisDependsOn.type + "-" + processThisDependsOn.id + let market = bot.market.baseAsset + '/' + bot.market.quotedAsset + let key = processThisDependsOn.name + "-" + processThisDependsOn.type + "-" + processThisDependsOn.id + "-" + bot.exchange + "-" + market let callerId = bot.dataMine + "-" + bot.codeName + "-" + bot.process + extraCallerId let subscriptionId @@ -80,7 +82,6 @@ if (global.LOG_CONTROL[MODULE_NAME].logInfo === true) { logger.write(MODULE_NAME, "[INFO] start -> waitForDependantProcess -> callerId = " + callerId); } global.SYSTEM_EVENT_HANDLER.listenToEvent(key, 'Process Execution Finished', undefined, callerId, responseCallBack, eventsCallBack) - console.log("LISTENING TO EVENT:", 'Process Execution Finished', key) function responseCallBack(message) { if (message.result !== global.DEFAULT_OK_RESPONSE.result) { @@ -146,7 +147,6 @@ global.SYSTEM_EVENT_HANDLER.createEventHandler(currentProcessKey, 'Process Execution Finished') global.SYSTEM_EVENT_HANDLER.raiseEvent(currentProcessKey, 'Process Execution Finished', event) - console.log("RAISING EVENT:", 'Process Execution Finished', currentProcessKey) if (global.LOG_CONTROL[MODULE_NAME].logInfo === true) { logger.write(MODULE_NAME, "[INFO] finish -> " + currentProcessKey + " Process Execution Finished " ); } diff --git a/Root.js b/Root.js index c960da47f..41e18541b 100644 --- a/Root.js +++ b/Root.js @@ -53,7 +53,6 @@ function initialize(callBackFunction) { try { - console.log(logDisplace + "Root : [INFO] initialize -> Entering function. "); /* Global control of logging. */ @@ -159,7 +158,6 @@ function getBotConfigFromFile() { try { - console.log(logDisplace + "Root : [INFO] start -> getBotConfigFromFile -> Entering function. "); const FILE_STORAGE = require('./FileStorage.js'); let fileStorage = FILE_STORAGE.newFileStorage(); @@ -196,7 +194,6 @@ function bootingBot(processIndex) { try { - if (FULL_LOG === true) { console.log(logDisplace + "Root : [INFO] start -> bootingBot -> Entering function. "); } botConfig.process = global.TASK_NODE.bot.processes[processIndex].referenceParent.code.codeName botConfig.debug = {}; @@ -252,9 +249,6 @@ } } - if (FULL_LOG === true) { console.log(logDisplace + "Root : [INFO] start -> bootingBot -> filePathRoot = " + botConfig.filePathRoot); } - if (FULL_LOG === true) { console.log(logDisplace + "Root : [INFO] start -> bootingBot -> Process found at the bot configuration file. -> process = " + global.TASK_NODE.bot.processes[processIndex].referenceParent.code.codeName); } - let processConfig = global.TASK_NODE.bot.processes[processIndex].referenceParent.code if (processConfig.framework !== undefined) { @@ -335,7 +329,6 @@ if (processConfig.startMode.userDefined.run === "true") { botConfig.startMode = "User Defined"; - console.log(logDisplace + "Root : [INFO] start -> bootingBot -> Process found at the bot configuration file. -> Start Mode = " + botConfig.startMode); if (processConfig.startMode.userDefined.resumeExecution === true) { botConfig.hasTheBotJustStarted = false; @@ -393,7 +386,6 @@ logger.write(MODULE_NAME, "[INFO] start -> bootingBot -> runSensorBot -> onInitializeReady -> whenStartFinishes -> Bot execution finished sucessfully."); logger.write(MODULE_NAME, "[INFO] start -> bootingBot -> runSensorBot -> onInitializeReady -> whenStartFinishes -> Bot Id = " + botId); - console.log(logDisplace + "Root : [INFO] start -> bootingBot -> runSensorBot -> onInitializeReady -> whenStartFinishes -> botId = " + botId); console.log(logDisplace + "Root : [INFO] start -> bootingBot -> runSensorBot -> onInitializeReady -> whenStartFinishes -> Bot execution finished sucessfully."); logger.persist(); @@ -404,7 +396,6 @@ logger.write(MODULE_NAME, "[ERROR] start -> bootingBot -> runSensorBot -> onInitializeReady -> whenStartFinishes -> Bye."); logger.write(MODULE_NAME, "[ERROR] start -> bootingBot -> runSensorBot -> onInitializeReady -> whenStartFinishes -> Bot Id = " + botId); - console.log(logDisplace + "Root : [ERROR] start -> bootingBot -> runSensorBot -> onInitializeReady -> whenStartFinishes -> botId = " + botId); console.log(logDisplace + "Root : [ERROR] start -> bootingBot -> runSensorBot -> onInitializeReady -> whenStartFinishes -> Bot execution was aborted."); logger.persist(); } @@ -460,7 +451,7 @@ logger.write(MODULE_NAME, "[INFO] start -> bootingBot -> runIndicatorBot -> onInitializeReady -> whenStartFinishes -> Bot execution finished sucessfully."); logger.write(MODULE_NAME, "[INFO] start -> bootingBot -> runIndicatorBot -> onInitializeReady -> whenStartFinishes -> Bot Id = " + botId); - console.log(logDisplace + "Root : [INFO] start -> bootingBot -> runIndicatorBot -> onInitializeReady -> whenStartFinishes -> botId = " + botId); + console.log(logDisplace + "Root : [INFO] start -> bootingBot -> runIndicatorBot -> onInitializeReady -> whenStartFinishes -> Bot execution finished sucessfully."); logger.persist(); diff --git a/SensorBotProcessMainLoop.js b/SensorBotProcessMainLoop.js index 0a443faf9..b8e2c49fc 100644 --- a/SensorBotProcessMainLoop.js +++ b/SensorBotProcessMainLoop.js @@ -148,10 +148,10 @@ bot.processDatetime = new Date(); // This will be considered the process date and time, so as to have it consistenly all over the execution. - /* High level log entry */ + /* High level log entry */ - console.log(new Date().toISOString() + " " + pad(bot.codeName, 20) + " " + pad(bot.process, 30) + " " - + " Entered into Main Loop # " + pad(Number(bot.loopCounter), 8) + " bot.processDatetime = " + bot.processDatetime.toISOString()); + console.log(new Date().toISOString() + " " + pad(bot.codeName, 20) + " " + pad(bot.process, 30) + " " + pad(bot.exchange, 20) + " " + pad(bot.market.baseAsset + '/' + bot.market.quotedAsset, 10) + + " Entered into Main Loop # " + pad(Number(bot.loopCounter), 8) ) /* We will prepare first the infraestructure needed for the bot to run. There are 4 modules we need to sucessfullly initialize first. */ diff --git a/TradingBotProcessMainLoop.js b/TradingBotProcessMainLoop.js index e83ff955d..01a0ce2dc 100644 --- a/TradingBotProcessMainLoop.js +++ b/TradingBotProcessMainLoop.js @@ -161,8 +161,8 @@ /* High level log entry */ - console.log(new Date().toISOString() + " " + pad(bot.codeName, 20) + " " + pad(bot.process, 30) + " " + bot.sessionKey - + " Loop # " + pad(Number(bot.loopCounter), 8)); + console.log(new Date().toISOString() + " " + pad(bot.codeName, 20) + " " + pad(bot.process, 30) + " " + pad(bot.exchange, 20) + " " + pad(bot.market.baseAsset + '/' + bot.market.quotedAsset, 10) + + " Entered into Main Loop # " + pad(Number(bot.loopCounter), 8) + " " + bot.sessionKey ) /* Checking if we need to need to emit any event */ diff --git a/server.js b/server.js index 49a63094f..700940611 100644 --- a/server.js +++ b/server.js @@ -50,7 +50,7 @@ process.on('exit', function (code) { global.SYSTEM_EVENT_HANDLER.finalize() global.SYSTEM_EVENT_HANDLER = undefined - console.log('[INFO] Task Server -> server -> process.on.exit -> About to exit -> code = ' + code) + //console.log('[INFO] Task Server -> server -> process.on.exit -> About to exit -> code = ' + code) }) /* Here we listen for the message to stop this Task / Process comming from the Task Manager, which is the paret of this node js process. */ @@ -63,7 +63,8 @@ process.on('message', message => { There are some process that might no be able to end grafully, for example the ones schedulle to process information in a future day or month. In order to be sure that the process will be terminated, we schedulle one forced exit in 2 minutes from now. */ - console.log('[INFO] Task Server -> server -> process.on -> Executing order received from Task Manager to Stop this Task. Nodejs process will be exited in less than 1 minute.') + let key = global.TASK_NODE.name + '-' + global.TASK_NODE.type + '-' + global.TASK_NODE.id + console.log('[INFO] Task Server -> server -> process.on -> Stopping Task ' + key + '. Nodejs process will be exited in less than 1 minute.') setTimeout(global.EXIT_NODE_PROCESS, 60000); } }); @@ -81,7 +82,7 @@ global.EXIT_NODE_PROCESS = function exitProcess() { global.SYSTEM_EVENT_HANDLER.raiseEvent(key, 'Stopped') // Meaning Process Stopped } - console.log("[INFO] Task Server -> " + global.TASK_NODE.name + " -> EXIT_NODE_PROCESS -> Task Server will stop in 10 seconds."); + //console.log("[INFO] Task Server -> " + global.TASK_NODE.name + " -> EXIT_NODE_PROCESS -> Task Server will stop in 10 seconds."); setTimeout(process.exit, 10000) // We will give 10 seconds to logs be written on file } @@ -119,7 +120,7 @@ function preLoader() { if (taskId !== undefined) { /* The Task Manager sent the info via a process argument. In this case we listen to an event with the Task Info that should be emitted at the UI */ try { - console.log('[INFO] Task Server -> server -> preLoader -> Listening to starting event -> key = ' + 'Task Server - ' + taskId) + //console.log('[INFO] Task Server -> server -> preLoader -> Listening to starting event -> key = ' + 'Task Server - ' + taskId) global.SYSTEM_EVENT_HANDLER.listenToEvent('Task Server - ' + taskId, 'Run Task', undefined, undefined, undefined, eventReceived) function eventReceived(message) { global.TASK_NODE = message @@ -133,7 +134,7 @@ function preLoader() { } else { /* This process was started not by the Task Manager, but independently (most likely for debugging purposes). In this case we listen to an event with the Task Info that should be emitted at the UI */ try { - console.log('[INFO] Task Server -> server -> preLoader -> Waiting for event to start debugging...') + //console.log('[INFO] Task Server -> server -> preLoader -> Waiting for event to start debugging...') global.SYSTEM_EVENT_HANDLER.listenToEvent('Task Server', 'Debug Task Started', undefined, undefined, undefined, startDebugging) function startDebugging(message) { global.TASK_NODE = message @@ -247,7 +248,7 @@ function bootLoader() { function startRoot(processIndex) { - console.log('[INFO] Task Server -> server -> startRoot -> Entering function. ') + // console.log('[INFO] Task Server -> server -> startRoot -> Entering function. ') const ROOT_MODULE = require('./Root') let root = ROOT_MODULE.newRoot() @@ -255,7 +256,7 @@ function startRoot(processIndex) { root.initialize(onInitialized) function onInitialized() { - console.log('[INFO] Task Server -> server -> startRoot -> onInitialized -> Entering function. ') + //console.log('[INFO] Task Server -> server -> startRoot -> onInitialized -> Entering function. ') root.start(processIndex) } }