From 3627e8036965514a9f7f78ca845d5442b03dd79a Mon Sep 17 00:00:00 2001 From: Uladzislau Hubar Date: Fri, 27 Oct 2023 13:47:58 +0200 Subject: [PATCH] Added command name / id to logs inside commands, unified some logs format --- index.js | 2 +- ot-node.js | 98 +++++++++++-------- scripts/copy-assertions.js | 18 ++-- src/commands/cleaners/cleaner-command.js | 14 ++- .../cleaners/operation-id-cleaner-command.js | 21 ++-- src/commands/command-executor.js | 65 +++++++----- src/commands/command-resolver.js | 10 +- src/commands/command.js | 18 ++-- src/commands/common/dial-peers-command.js | 11 ++- src/commands/common/otnode-update-command.js | 40 +++++--- src/commands/common/send-telemetry-command.js | 23 +++-- src/commands/common/validate-asset-command.js | 21 ++-- .../local-store/local-store-command.js | 2 +- .../protocols/common/epoch-check-command.js | 41 +++++--- .../protocols/common/find-nodes-command.js | 13 ++- .../common/handle-protocol-message-command.js | 50 ++++++---- .../protocol-schedule-messages-command.js | 5 +- .../protocols/common/submit-commit-command.js | 30 +++--- .../protocols/common/submit-proofs-command.js | 40 +++++--- .../v1.0.0/v1-0-0-handle-get-init-command.js | 9 +- .../v1-0-0-handle-get-request-command.js | 4 +- .../get/sender/get-assertion-id-command.js | 16 +-- .../protocols/get/sender/local-get-command.js | 4 - .../v1.0.0/v1-0-0-get-request-command.js | 3 +- .../v1-0-0-handle-store-init-command.js | 10 +- .../v1-0-0-handle-store-request-command.js | 4 +- .../sender/publish-validate-asset-command.js | 4 - .../receiver/delete-pending-state-command.js | 6 +- .../receiver/submit-update-commit-command.js | 28 +++--- .../v1-0-0-handle-update-init-command.js | 14 ++- .../v1-0-0-handle-update-request-command.js | 20 ++-- .../sender/update-validate-asset-command.js | 4 - src/commands/query/query-command.js | 4 +- src/logger/logger.js | 46 ++++++--- .../private-assets-metadata-migration.js | 2 +- .../service-agreements-metadata-migration.js | 20 ++-- .../triple-store-metadata-migration.js | 40 ++++---- .../implementation/ot-auto-updater.js | 8 +- src/modules/base-module-manager.js | 2 +- src/service/sharding-table-service.js | 2 +- src/service/validation-service.js | 26 +++-- 41 files changed, 470 insertions(+), 328 deletions(-) diff --git a/index.js b/index.js index 7a6cda7eef..113684b32a 100644 --- a/index.js +++ b/index.js @@ -55,6 +55,6 @@ process.env.NODE_ENV = })(); process.on('uncaughtException', (err) => { - console.error('Something went really wrong! OT-node shutting down...', err); + console.error(`Something went really wrong! Error: ${err.message}. OT-node shutting down...`); process.exit(1); }); diff --git a/ot-node.js b/ot-node.js index fa68cfc2af..3241b04f8f 100644 --- a/ot-node.js +++ b/ot-node.js @@ -80,7 +80,8 @@ class OTNode { this.logger.warn(`Using node.js version: ${process.versions.node}`); if (nodeMajorVersion < MIN_NODE_VERSION) { this.logger.warn( - `This node was tested with node.js version 16. To make sure that your node is running properly please update your node version!`, + `This node was tested with node.js version 16. ` + + `To make sure that your node is running properly please update your node version!`, ); } this.logger.warn('======================================================'); @@ -88,10 +89,14 @@ class OTNode { initializeLogger() { this.logger = new Logger(this.config.logLevel); + + this.logger.info('Logger has been successfully initialized.'); } initializeFileService() { this.fileService = new FileService({ config: this.config, logger: this.logger }); + + this.logger.info('File Service has been successfully initialized.'); } initializeAutoUpdaterModule() { @@ -100,6 +105,8 @@ class OTNode { this.config.modules.autoUpdater.implementation['ot-auto-updater'].config, this.logger, ); + + this.logger.info('Auto Updater has been successfully initialized.'); } initializeConfiguration(userConfig) { @@ -121,7 +128,7 @@ class OTNode { DependencyInjection.registerValue(this.container, 'config', this.config); DependencyInjection.registerValue(this.container, 'logger', this.logger); - this.logger.info('Dependency injection module is initialized'); + this.logger.info('Dependency Injection Module has been successfully initialized.'); } async initializeModules() { @@ -134,18 +141,22 @@ class OTNode { } try { await Promise.all(initializationPromises); - this.logger.info(`All modules initialized!`); } catch (e) { - this.logger.error(`Module initialization failed. Error message: ${e.message}`); + this.logger.error( + `Module initialization failed. Error: ${e.message}. ` + + `OT-Node is shutting down...`, + ); this.stop(1); } + + this.logger.info(`All modules have been successfully initialized.`); } initializeEventEmitter() { const eventEmitter = new EventEmitter(); DependencyInjection.registerValue(this.container, 'eventEmitter', eventEmitter); - this.logger.info('Event emitter initialized'); + this.logger.info('Event Emitter has been successfully initialized.'); } async initializeBlockchainEventListenerService() { @@ -153,40 +164,35 @@ class OTNode { const eventListenerService = this.container.resolve('blockchainEventListenerService'); await eventListenerService.initialize(); eventListenerService.startListeningOnEvents(); - this.logger.info('Event Listener Service initialized successfully'); } catch (error) { this.logger.error( - `Unable to initialize event listener service. Error message: ${error.message} OT-node shutting down...`, + `Unable to initialize Event Listener Service. Error: ${error.message}. ` + + `OT-Node is shutting down...`, ); this.stop(1); } + + this.logger.info('Event Listener Service has been successfully initialized.'); } async initializeRouters() { - try { - this.logger.info('Initializing http api and rpc router'); - - const routerNames = ['httpApiRouter', 'rpcRouter']; - await Promise.all( - routerNames.map(async (routerName) => { - const router = this.container.resolve(routerName); - try { - await router.initialize(); - } catch (error) { - this.logger.error( - `${routerName} initialization failed. Error message: ${error.message}, ${error.stackTrace}`, - ); - this.stop(1); - } - }), - ); - this.logger.info('Routers initialized successfully'); - } catch (error) { - this.logger.error( - `Failed to initialize routers: ${error.message}, ${error.stackTrace}`, - ); - this.stop(1); - } + const routerNames = ['httpApiRouter', 'rpcRouter']; + await Promise.all( + routerNames.map(async (routerName) => { + const router = this.container.resolve(routerName); + try { + await router.initialize(); + } catch (error) { + this.logger.error( + `${routerName} initialization failed. Error: ${error.message}. ` + + `OT-Node is shutting down...`, + ); + this.stop(1); + } + }), + ); + + this.logger.info('HTTP API and RPC Routers are successfully initialized.'); } async createProfiles() { @@ -196,7 +202,7 @@ class OTNode { .map(async (blockchain) => { try { if (!(await blockchainModuleManager.identityIdExists(blockchain))) { - this.logger.info(`Creating profile on network: ${blockchain}`); + this.logger.info(`Creating profile on ${blockchain} network.`); const networkModuleManager = this.container.resolve('networkModuleManager'); const peerId = networkModuleManager.getPeerId().toB58String(); await blockchainModuleManager.createProfile(blockchain, peerId); @@ -225,10 +231,10 @@ class OTNode { } } const identityId = await blockchainModuleManager.getIdentityId(blockchain); - this.logger.info(`Identity ID: ${identityId}`); + this.logger.info(`Identity ID: ${identityId}.`); } catch (error) { this.logger.warn( - `Unable to create ${blockchain} blockchain profile. Removing implementation. Error: ${error.message}`, + `Unable to create ${blockchain} blockchain profile. Error: ${error.message}. Removing implementation...`, ); blockchainModuleManager.removeImplementation(blockchain); } @@ -237,7 +243,7 @@ class OTNode { await Promise.all(createProfilesPromises); if (!blockchainModuleManager.getImplementationNames().length) { - this.logger.error(`Unable to create blockchain profiles. OT-node shutting down...`); + this.logger.error(`Unable to create blockchain profiles. OT-Node is shutting down...`); this.stop(1); } } @@ -249,10 +255,11 @@ class OTNode { await commandExecutor.addDefaultCommands(); commandExecutor .replayOldCommands() - .then(() => this.logger.info('Finished replaying old commands')); + .then(() => this.logger.info('Finished replaying old commands.')); } catch (e) { this.logger.error( - `Command executor initialization failed. Error message: ${e.message}`, + `Command executor initialization failed. Error: ${e.message}. ` + + `OT-Node is shutting down...`, ); this.stop(1); } @@ -273,6 +280,8 @@ class OTNode { async startNetworkModule() { const networkModuleManager = this.container.resolve('networkModuleManager'); await networkModuleManager.start(); + + this.logger.info('Network Module has been successfully started.'); } async executePrivateAssetsMetadataMigration() { @@ -465,13 +474,15 @@ class OTNode { try { const shardingTableService = this.container.resolve('shardingTableService'); await shardingTableService.initialize(); - this.logger.info('Sharding Table Service initialized successfully'); } catch (error) { this.logger.error( - `Unable to initialize sharding table service. Error message: ${error.message} OT-node shutting down...`, + `Unable to initialize sharding table service. Error: ${error.message} ` + + `OT-Node is shutting down...`, ); this.stop(1); } + + this.logger.info('Sharding Table Service has been successfully initialized.'); } async initializeTelemetryInjectionService() { @@ -481,19 +492,20 @@ class OTNode { 'telemetryInjectionService', ); telemetryHubModuleManager.initialize(); - this.logger.info('Telemetry Injection Service initialized successfully'); } catch (e) { this.logger.error( - `Telemetry hub module initialization failed. Error message: ${e.message}`, + `Telemetry hub module initialization failed. Error: ${e.message}`, ); } + + this.logger.info('Telemetry Injection Service has been successfully initialized.'); } } async removeUpdateFile() { const updateFilePath = this.fileService.getUpdateFilePath(); await this.fileService.removeFile(updateFilePath).catch((error) => { - this.logger.warn(`Unable to remove update file. Error: ${error}`); + this.logger.warn(`Unable to remove update file. Error: ${error}.`); }); this.config.otNodeUpdated = true; } @@ -510,7 +522,7 @@ class OTNode { } stop(code = 0) { - this.logger.info('Stopping node...'); + this.logger.info('Stopping the node...'); process.exit(code); } diff --git a/scripts/copy-assertions.js b/scripts/copy-assertions.js index a107f6a88b..b1edae3af8 100644 --- a/scripts/copy-assertions.js +++ b/scripts/copy-assertions.js @@ -61,20 +61,20 @@ function logPercentage(index, max) { if (Math.floor(currentPercentage) - Math.floor(previousPercentage) < 1) return; - logger.debug(`Migration at ${Math.floor(currentPercentage * 10) / 10}%`); + logger.debug(`Migration at ${Math.floor(currentPercentage * 10) / 10}%.`); } let toRepositoryAssertions = await getAssertions(toImplementation, toRepository); logger.info( - `${toRepositoryAssertions.length} assertions found in ${toRepository} repository before migration`, + `${toRepositoryAssertions.length} assertions found in ${toRepository} repository before migration.`, ); logger.info( - `Starting to copy assertions from ${fromImplementation} repository ${fromRepository} with name ${fromRepositoryName} to repository ${toImplementation} repository ${toRepository} with name ${toRepositoryName}`, + `Starting to copy assertions from ${fromImplementation} repository ${fromRepository} ``with name ${fromRepositoryName} to repository ${toImplementation} repository ${toRepository} ``with name ${toRepositoryName}.`, ); const fromRepositoryAssertions = await getAssertions(fromImplementation, fromRepository); -logger.info(`${fromRepositoryAssertions.length} assertions found in ${fromRepository}`); +logger.info(`${fromRepositoryAssertions.length} assertions found in ${fromRepository}.`); let completed = 0; const copyAssertion = async (g) => { @@ -101,9 +101,9 @@ const copyAssertion = async (g) => { logger.error( `Error while getting assertion ${g.substring( 'assertion:'.length, - )} from ${fromImplementation} repository ${fromRepository} with name ${fromRepositoryName}. Error: ${ + )} from ${fromImplementation} repository ${fromRepository} with name ${fromRepositoryName}; Error: ${ error.message - }`, + }.`, ); process.exit(1); } @@ -119,9 +119,9 @@ const copyAssertion = async (g) => { logger.error( `Error while inserting assertion ${g.substring( 'assertion:'.length, - )} with nquads: ${nquads} in ${toImplementation} repository ${toRepository} with name ${toRepositoryName}. Error: ${ + )} with nquads: ${nquads} in ${toImplementation} repository ${toRepository} with name ${toRepositoryName}; Error: ${ error.message - }`, + }.`, ); process.exit(1); } @@ -150,5 +150,5 @@ logger.info(`Migration completed! Lasted ${(end - start) / 1000} seconds.`); toRepositoryAssertions = await getAssertions(toImplementation, toRepository); logger.info( - `${toRepositoryAssertions.length} assertions found in ${toRepository} repository after migration`, + `${toRepositoryAssertions.length} assertions found in ${toRepository} repository after migration.`, ); diff --git a/src/commands/cleaners/cleaner-command.js b/src/commands/cleaners/cleaner-command.js index 38dc0685f2..ef8af69ff1 100644 --- a/src/commands/cleaners/cleaner-command.js +++ b/src/commands/cleaners/cleaner-command.js @@ -4,13 +4,13 @@ import Command from '../command.js'; class CleanerCommand extends Command { constructor(ctx) { super(ctx); + this.logger = ctx.logger; this.repositoryModuleManager = ctx.repositoryModuleManager; this.archiveService = ctx.archiveService; } /** * Executes command and produces one or more events - * @param command */ async execute() { const nowTimestamp = Date.now(); @@ -49,16 +49,16 @@ class CleanerCommand extends Command { // eslint-disable-next-line no-unused-vars async findRowsForRemoval(nowTimestamp) { - throw Error('findRowsForRemoval not implemented'); + throw Error('findRowsForRemoval is not implemented.'); } getArchiveFolderName() { - throw Error('getArchiveFolderName not implemented'); + throw Error('getArchiveFolderName is not implemented.'); } // eslint-disable-next-line no-unused-vars async deleteRows(ids) { - throw Error('deleteRows not implemented'); + throw Error('deleteRows is not implemented.'); } /** @@ -67,7 +67,11 @@ class CleanerCommand extends Command { * @param error */ async recover(command, error) { - this.logger.warn(`Failed to clean operational db data: error: ${error.message}`); + this.logger.warn( + `Error occurred during the command execution; ` + + `Error Message: ${error.message}. Repeating the command...`, + command, + ); return Command.repeat(); } } diff --git a/src/commands/cleaners/operation-id-cleaner-command.js b/src/commands/cleaners/operation-id-cleaner-command.js index d1816e7d4c..768d574dea 100644 --- a/src/commands/cleaners/operation-id-cleaner-command.js +++ b/src/commands/cleaners/operation-id-cleaner-command.js @@ -19,10 +19,8 @@ class OperationIdCleanerCommand extends Command { /** * Executes command and produces one or more events - * @param command */ - async execute() { - this.logger.debug('Starting command for removal of expired cache files'); + async execute(command) { const timeToBeDeleted = Date.now() - OPERATION_ID_COMMAND_CLEANUP_TIME_MILLS; await this.repositoryModuleManager.removeOperationIdRecord(timeToBeDeleted, [ OPERATION_ID_STATUS.COMPLETED, @@ -33,9 +31,9 @@ class OperationIdCleanerCommand extends Command { ); if (removed) { this.logger.debug( - `Successfully removed ${ - removed / BYTES_IN_KILOBYTE - } Kbs expired cached operation entries from memory`, + `Successfully removed ${removed / BYTES_IN_KILOBYTE} KBs ` + + `of expired cached operation entries from the memory.`, + command, ); } removed = await this.operationIdService.removeExpiredOperationIdFileCache( @@ -43,7 +41,10 @@ class OperationIdCleanerCommand extends Command { OPERATION_ID_FILES_FOR_REMOVAL_MAX_NUMBER, ); if (removed) { - this.logger.debug(`Successfully removed ${removed} expired cached operation files`); + this.logger.debug( + `Successfully removed ${removed} expired cached operation files.`, + command, + ); } return Command.repeat(); @@ -55,7 +56,11 @@ class OperationIdCleanerCommand extends Command { * @param error */ async recover(command, error) { - this.logger.warn(`Failed to clean operation ids table: error: ${error.message}`); + this.logger.warn( + `Error occurred during the command execution; ` + + `Error Message: ${error.message}. Repeating the command...`, + command, + ); return Command.repeat(); } diff --git a/src/commands/command-executor.js b/src/commands/command-executor.js index 9f2a85933a..3dc0eb53e4 100644 --- a/src/commands/command-executor.js +++ b/src/commands/command-executor.js @@ -27,7 +27,7 @@ class CommandExecutor { }) .catch((error) => { this.logger.error( - `Something went really wrong! OT-node shutting down... ${error}`, + `Something went really wrong! Message: ${error}. OT-node is shutting down...`, ); process.exit(1); }); @@ -42,7 +42,7 @@ class CommandExecutor { await Promise.all(PERMANENT_COMMANDS.map((command) => this._addDefaultCommand(command))); if (this.verboseLoggingEnabled) { - this.logger.trace('Command executor has been initialized...'); + this.logger.trace('Command Executor has been initialized.'); } } @@ -51,7 +51,7 @@ class CommandExecutor { */ resumeQueue() { if (this.verboseLoggingEnabled) { - this.logger.trace('Command executor queue has been resumed...'); + this.logger.trace('Command Executor queue has been resumed.'); } this.queue.resume(); } @@ -61,7 +61,7 @@ class CommandExecutor { */ pauseQueue() { if (this.verboseLoggingEnabled) { - this.logger.trace('Command executor queue has been paused...'); + this.logger.trace('Command Executor queue has been paused.'); } this.queue.pause(); } @@ -78,19 +78,23 @@ class CommandExecutor { }); if (this.verboseLoggingEnabled) { - this.logger.trace(`Command ${command.name} and ID ${command.id} started.`); + this.logger.trace('Command has been started.', command); } const handler = this.commandResolver.resolve(command.name); if (!handler) { - this.logger.warn(`Command '${command.name}' will not be executed.`); + this.logger.warn(`Command won't be executed.`, command); await this._update(command, { status: COMMAND_STATUS.UNKNOWN, }); return; } if (command.deadlineAt && now > command.deadlineAt) { - this.logger.warn(`Command ${command.name} and ID ${command.id} is too late...`); + this.logger.warn( + `Command has exceeded the deadline. ` + + `Time now: ${now}. Deadline: ${command.deadlineAt}.`, + command, + ); await this._update(command, { status: COMMAND_STATUS.EXPIRED, }); @@ -99,9 +103,10 @@ class CommandExecutor { if (result?.commands) { await Promise.all(result.commands.map((c) => this.add(c, c.delay, true))); } - } catch (e) { + } catch (err) { this.logger.warn( - `Failed to handle expired callback for command ${command.name} and ID ${command.id}`, + `Failed to handle expired callback; Error Message: ${err.message}.`, + command, ); } return; @@ -110,9 +115,7 @@ class CommandExecutor { const waitMs = command.readyAt + command.delay - now; if (waitMs > 0) { if (this.verboseLoggingEnabled) { - this.logger.trace( - `Command ${command.name} with ID ${command.id} should be delayed`, - ); + this.logger.trace(`Command will be delayed.`, command); } await this.add(command, Math.min(waitMs, MAX_COMMAND_DELAY_IN_MILLS), false); return; @@ -174,7 +177,7 @@ class CommandExecutor { if (!processResult.repeat && !processResult.retry) { if (this.verboseLoggingEnabled) { - this.logger.trace(`Command ${command.name} and ID ${command.id} processed.`); + this.logger.trace(`Command is being processed.`, command); } const addPromises = []; processResult.children.forEach((e) => @@ -182,15 +185,17 @@ class CommandExecutor { ); await Promise.all(addPromises); } - } catch (e) { + } catch (err) { if (this.verboseLoggingEnabled) { this.logger.trace( - `Failed to process command ${command.name} and ID ${command.id}. ${e}.\n${e.stack}`, + `Command is failed to process; ` + + `Error Message: ${err.message}; Error Stack: ${err.stack}.`, + command, ); } try { - const result = await this._handleError(command, handler, e); + const result = await this._handleError(command, handler, err); if (result && result.repeat) { await this._update(command, { status: COMMAND_STATUS.REPEATING, @@ -206,7 +211,8 @@ class CommandExecutor { } } catch (error) { this.logger.warn( - `Failed to handle error callback for command ${command.name} and ID ${command.id}, error: ${error.message}`, + `Failed to handle error callback; Error Message: ${error.message}.`, + command, ); } } @@ -228,20 +234,20 @@ class CommandExecutor { /** * Starts the default command by name - * @param name - Command name + * @param commandName - Command name * @return {Promise} * @private */ - async _addDefaultCommand(name) { - await this._delete(name); - const handler = this.commandResolver.resolve(name); + async _addDefaultCommand(commandName) { + await this._delete(commandName); + const handler = this.commandResolver.resolve(commandName); if (!handler) { - this.logger.warn(`Command '${name}' will not be executed.`); + this.logger.warn(`Failed to resolve ${commandName}, skipping execution.`); return; } await this.add(handler.default(), DEFAULT_COMMAND_DELAY_IN_MILLS, true); if (this.verboseLoggingEnabled) { - this.logger.trace(`Permanent command ${name} created.`); + this.logger.trace(`Permanent ${commandName} has been created.`); } } @@ -324,10 +330,16 @@ class CommandExecutor { status: COMMAND_STATUS.FAILED, message: err.message, }); - this.logger.warn(`Error in command: ${command.name}, error: ${err.message}`); + this.logger.warn( + `Error occurred during command execution; Error Message: ${err.message}.`, + command, + ); return await handler.recover(command, err); - } catch (e) { - this.logger.warn(`Failed to recover command ${command.name} and ID ${command.id}`); + } catch (error) { + this.logger.warn( + `Failed to recover the command; Error Message: ${error.message}.`, + command, + ); } } } @@ -407,7 +419,6 @@ class CommandExecutor { * @returns {Promise} */ async replayOldCommands() { - this.logger.info('Replay pending/started commands from the database...'); const pendingCommands = await this.repositoryModuleManager.getCommandsWithStatus( [COMMAND_STATUS.PENDING, COMMAND_STATUS.STARTED, COMMAND_STATUS.REPEATING], PERMANENT_COMMANDS, diff --git a/src/commands/command-resolver.js b/src/commands/command-resolver.js index 881afdc8a0..b4918f6ae0 100644 --- a/src/commands/command-resolver.js +++ b/src/commands/command-resolver.js @@ -12,12 +12,12 @@ class CommandResolver { * @param name * @return {*} */ - resolve(name) { - try { - return this.ctx[`${name}`]; - } catch (e) { - this.logger.warn(`No handler defined for command '${name}'`); + resolve(commandName) { + const handler = this.ctx[`${commandName}`]; + if (handler === undefined) { + this.logger.warn(`No handler defined for the ${commandName}.`); } + return handler; } } diff --git a/src/commands/command.js b/src/commands/command.js index 9190fc7005..3b65ec673e 100644 --- a/src/commands/command.js +++ b/src/commands/command.js @@ -25,7 +25,7 @@ class Command { */ async recover(command, err) { const { operationId } = command.data; - await this.handleError(operationId, err.message, this.errorType, true, command.data); + await this.handleError(operationId, command, this.errorType, err.message, true); return Command.empty(); } @@ -104,19 +104,23 @@ class Command { } async retryFinished(command) { - this.logger.trace(`Max retry count for command: ${command.name} reached!`); + this.logger.trace(`Max retries have been exceeded!`, command); } /** * Error handler for command - * @param operationId - Operation operation id - * @param error - Error object - * @param errorName - Name of error + * @param operationId - Operation operation ID + * @param command - Command object + * @param error - Error object * @param markFailed - Update operation status to failed * @returns {*} */ - async handleError(operationId, errorMessage, errorName, markFailed) { - this.logger.error(`Command error (${errorName}): ${errorMessage}`); + async handleError(operationId, command, errorName, errorMessage, markFailed = false) { + this.logger.error( + `Error occurred during ${operationId} operation in the command; ` + + `Error: ${errorName}; Error Message: ${errorMessage}.`, + command, + ); if (markFailed) { await this.operationIdService.updateOperationIdStatus( operationId, diff --git a/src/commands/common/dial-peers-command.js b/src/commands/common/dial-peers-command.js index 41a728f342..9c4f67b028 100644 --- a/src/commands/common/dial-peers-command.js +++ b/src/commands/common/dial-peers-command.js @@ -14,16 +14,15 @@ class DialPeersCommand extends Command { /** * Executes command and produces one or more events - * @param command */ - async execute() { + async execute(command) { const peersToDial = await this.repositoryModuleManager.getPeersToDial( DIAL_PEERS_CONCURRENCY, MIN_DIAL_FREQUENCY_MILLIS, ); if (peersToDial.length) { - this.logger.trace(`Dialing ${peersToDial.length} remote peers`); + this.logger.trace(`Dialing ${peersToDial.length} remote peers.`, command); await Promise.all( peersToDial.map(({ peerId }) => this.shardingTableService.dial(peerId)), ); @@ -38,7 +37,11 @@ class DialPeersCommand extends Command { * @param error */ async recover(command, error) { - this.logger.warn(`Failed to dial peers: error: ${error.message}`); + this.logger.warn( + `Error occurred during the command execution; ` + + `Error Message: ${error.message}. Repeating the command...`, + command, + ); return Command.repeat(); } diff --git a/src/commands/common/otnode-update-command.js b/src/commands/common/otnode-update-command.js index 46b391bd71..d3ca95a1ed 100644 --- a/src/commands/common/otnode-update-command.js +++ b/src/commands/common/otnode-update-command.js @@ -12,26 +12,29 @@ class OtnodeUpdateCommand extends Command { /** * Performs code update by fetching new code from github repo - * @param command */ - async execute() { + async execute(command) { if (!this.config.modules.autoUpdater.enabled) { return Command.empty(); } try { - this.logger.info('Checking for new updates...'); + this.logger.info('Checking for new updates...', command); const { upToDate, currentVersion, remoteVersion } = await this.autoUpdaterModuleManager.compareVersions(); if (!upToDate) { if (semver.major(currentVersion) < semver.major(remoteVersion)) { this.logger.info( - `New major update available. Please run update to version ${remoteVersion} manually.`, + `A new major update is available. ` + + `Please run the update to version ${remoteVersion} manually.`, + command, ); return Command.repeat(); } if (semver.lt(semver.valid(remoteVersion), semver.valid(currentVersion))) { this.logger.info( - 'Remote version less than current version, update will be skipped', + 'The remote version is older than the current version; ' + + 'therefore, the update will be skipped.', + command, ); return Command.repeat(); } @@ -44,27 +47,34 @@ class OtnodeUpdateCommand extends Command { 'UPDATED', 'UPDATED', ); - this.logger.info('Node will now restart!'); + this.logger.info('OtnodeUpdateCommand: Node will now restart!'); process.exit(1); } - this.logger.info('Unable to update ot-node to new version.'); + this.logger.info('Unable to update ot-node to the new version.', command); } else { - this.logger.info('Your node is running on the latest version!'); + this.logger.info('Your node is running on the latest version!', command); } - } catch (e) { - await this.handleError(e); + } catch (err) { + await this.handleError(command, err); } return Command.repeat(); } - async recover(command, err) { - await this.handleError(err); - + async recover(command, error) { + this.logger.error( + `Error occurred during the command execution; ` + + `Error Message: ${error.message}. Repeating the command...`, + command, + ); return Command.repeat(); } - async handleError(error) { - this.logger.error(`Error in update command: ${error}. ${error.stack}`); + async handleError(command, error) { + this.logger.error( + `Error occurred during the command execution; ` + + `Error Message: ${error.message}; Error Stack: ${error.stack}.`, + command, + ); } /** diff --git a/src/commands/common/send-telemetry-command.js b/src/commands/common/send-telemetry-command.js index 03fa2ff128..b96cdcbc3a 100644 --- a/src/commands/common/send-telemetry-command.js +++ b/src/commands/common/send-telemetry-command.js @@ -20,7 +20,7 @@ class SendTelemetryCommand extends Command { * Performs code update by fetching new code from github repo * @param command */ - async execute() { + async execute(command) { if (!this.config.telemetry.enabled || !this.config.telemetry.sendTelemetryData) { return Command.empty(); } @@ -51,20 +51,27 @@ class SendTelemetryCommand extends Command { if (response.status === 200 && events?.length > 0) { await this.telemetryInjectionService.removePublishedEvents(events); } - } catch (e) { - await this.handleError(e); + } catch (err) { + await this.handleError(command, err); } return Command.repeat(); } - async recover(command, err) { - await this.handleError(err); - + async recover(command, error) { + this.logger.error( + `Error occurred during the command execution; ` + + `Error Message: ${error.message}. Repeating the command...`, + command, + ); return Command.repeat(); } - async handleError(error) { - this.logger.error(`Error in send telemetry command: ${error}. ${error.stack}`); + async handleError(command, error) { + this.logger.error( + `Error occurred during the command execution; ` + + `Error Message: ${error.message}. Error Stack: ${error.stack}.`, + command, + ); } /** diff --git a/src/commands/common/validate-asset-command.js b/src/commands/common/validate-asset-command.js index 458396d630..e4d445e1d8 100644 --- a/src/commands/common/validate-asset-command.js +++ b/src/commands/common/validate-asset-command.js @@ -49,13 +49,18 @@ class ValidateAssetCommand extends Command { const cachedData = await this.operationIdService.getCachedOperationIdData(operationId); const ual = this.ualService.deriveUAL(blockchain, contract, tokenId); this.logger.info( - `Validating asset's public assertion with id: ${cachedData.public.assertionId} ual: ${ual}`, + `Validating Knowledge Asset's Public Assertion ` + + `with ID: ${cachedData.public.assertionId}, UAL: ${ual}.`, + command, ); if (blockchainAssertionId !== cachedData.public.assertionId) { await this.handleError( operationId, - `Invalid assertion id for asset ${ual}. Received value from blockchain: ${blockchainAssertionId}, received value from request: ${cachedData.public.assertionId}`, + command, this.errorType, + `Invalid Assertion ID for the Knowledge Asset with the UAL: ${ual}. ` + + `Value from the blockchain: ${blockchainAssertionId}; ` + + `Value from the request: ${cachedData.public.assertionId}`, true, ); return Command.empty(); @@ -69,16 +74,19 @@ class ValidateAssetCommand extends Command { if (cachedData.private?.assertionId && cachedData.private?.assertion) { this.logger.info( - `Validating asset's private assertion with id: ${cachedData.private.assertionId} ual: ${ual}`, + `Validating Knowledge Asset's Private Assertion ` + + `with ID: ${cachedData.private.assertionId}, UAL: ${ual}`, + command, ); try { this.validationService.validateAssertionId( - cachedData.private.assertion, + blockchain, cachedData.private.assertionId, + cachedData.private.assertion, ); } catch (error) { - await this.handleError(operationId, error.message, this.errorType, true); + await this.handleError(operationId, command, this.errorType, error.message, true); return Command.empty(); } } @@ -98,8 +106,9 @@ class ValidateAssetCommand extends Command { const ual = this.ualService.deriveUAL(blockchain, contract, tokenId); await this.handleError( operationId, - `Max retry count for command: ${command.name} reached! Unable to validate ual: ${ual}`, + command, this.errorType, + `Max retries exceeded! Unable to validate the Knowledge Asset with the UAL: ${ual}`, true, ); } diff --git a/src/commands/local-store/local-store-command.js b/src/commands/local-store/local-store-command.js index 5bf84abc00..f7a855ec03 100644 --- a/src/commands/local-store/local-store-command.js +++ b/src/commands/local-store/local-store-command.js @@ -112,7 +112,7 @@ class LocalStoreCommand extends Command { OPERATION_ID_STATUS.COMPLETED, ); } catch (e) { - await this.handleError(operationId, e.message, this.errorType, true); + await this.handleError(operationId, command, this.errorType, e.message, true); return Command.empty(); } diff --git a/src/commands/protocols/common/epoch-check-command.js b/src/commands/protocols/common/epoch-check-command.js index 3d674f498b..6eb41ca2d8 100644 --- a/src/commands/protocols/common/epoch-check-command.js +++ b/src/commands/protocols/common/epoch-check-command.js @@ -18,6 +18,10 @@ class EpochCheckCommand extends Command { this.serviceAgreementService = ctx.serviceAgreementService; } + /** + * Executes Command, schedules Commit/Proof Commands + * @param command + */ async execute(command) { const operationId = this.operationIdService.generateId(); this.operationIdService.emitChangeEvent( @@ -55,6 +59,7 @@ class EpochCheckCommand extends Command { await Promise.all([ this.scheduleSubmitCommitCommands( + command, blockchain, Math.floor(totalTransactions / 2), commitWindowDurationPerc, @@ -62,6 +67,7 @@ class EpochCheckCommand extends Command { r2, ), this.scheduleCalculateProofsCommands( + command, blockchain, Math.ceil(totalTransactions / 2), proofWindowDurationPerc, @@ -80,6 +86,7 @@ class EpochCheckCommand extends Command { } async scheduleSubmitCommitCommands( + command, blockchain, maxTransactions, commitWindowDurationPerc, @@ -115,24 +122,28 @@ class EpochCheckCommand extends Command { if (rank == null) { this.logger.trace( - `Node not in R2: ${r2} for agreement id: ${serviceAgreement.agreementId}. Skipping scheduling submit commit command.`, + `Node not in R2 (${r2}) for the Service Agreement with ID: ${serviceAgreement.agreementId}. ` + + `Skipping scheduling SubmitCommitCommand.`, + command, ); continue; } if (rank >= r0) { this.logger.trace( - `Calculated rank: ${rank + 1}. Node not in R0: ${r0} for agreement id: ${ - serviceAgreement.agreementId - }. Skipping scheduling submit commit command.`, + `Calculated rank in the neighborhood: ${rank + 1}. ` + + `Node not in R0 (${r0}) for the Service Agreement with ID: ${serviceAgreement.agreementId}. ` + + `Skipping scheduling SubmitCommitCommand.`, + command, ); continue; } this.logger.trace( - `Calculated rank: ${rank + 1}. Node in R0: ${r0} for agreement id: ${ - serviceAgreement.agreementId - }. Scheduling submit commit command.`, + `Calculated rank in the neighborhood: ${rank + 1}. ` + + `Node in R0 (${r0}) for the Service Agreement with ID: ${serviceAgreement.agreementId}. ` + + `Scheduling SubmitCommitCommand.`, + command, ); scheduleSubmitCommitCommands.push(this.scheduleSubmitCommitCommand(serviceAgreement)); @@ -144,6 +155,7 @@ class EpochCheckCommand extends Command { } async scheduleCalculateProofsCommands( + command, blockchain, maxTransactions, proofWindowDurationPerc, @@ -170,7 +182,9 @@ class EpochCheckCommand extends Command { ); if (eligibleForReward) { this.logger.trace( - `Node is eligible for rewards for agreement id: ${serviceAgreement.agreementId}. Scheduling submit proof command.`, + `Node is eligible for the reward for the Service Agreement with ID: ${serviceAgreement.agreementId}. ` + + `Scheduling SubmitProofCommand.`, + command, ); scheduleSubmitProofCommands.push( @@ -178,7 +192,9 @@ class EpochCheckCommand extends Command { ); } else { this.logger.trace( - `Node is not eligible for rewards for agreement id: ${serviceAgreement.agreementId}. Skipping scheduling submit proof command.`, + `Node is not eligible for the reward for the Service Agreement with ID: ${serviceAgreement.agreementId}. ` + + `Skipping scheduling SubmitProofCommand.`, + command, ); } updateServiceAgreementsLastProofEpoch.push( @@ -326,8 +342,11 @@ class EpochCheckCommand extends Command { * @param error */ async recover(command, error) { - this.logger.warn(`Failed to execute ${command.name}: error: ${error.message}`); - + this.logger.warn( + `Error occurred during the command execution; ` + + `Error Message: ${error.message}. Repeating the command...`, + command, + ); return Command.repeat(); } diff --git a/src/commands/protocols/common/find-nodes-command.js b/src/commands/protocols/common/find-nodes-command.js index 400a0a6ef5..c8de5399cb 100644 --- a/src/commands/protocols/common/find-nodes-command.js +++ b/src/commands/protocols/common/find-nodes-command.js @@ -25,7 +25,7 @@ class FindNodesCommand extends Command { } = command.data; this.errorType = errorType; - this.logger.debug(`Searching for closest node(s) for keyword ${keyword}`); + this.logger.debug(`Searching for the closest node(s) for the keyword ${keyword}.`, command); // TODO: protocol selection const closestNodes = []; @@ -36,20 +36,25 @@ class FindNodesCommand extends Command { } } - this.logger.debug(`Found ${closestNodes.length} node(s) for keyword ${keyword}`); + this.logger.debug( + `Found ${closestNodes.length} node(s) for the keyword ${keyword}.`, + command, + ); this.logger.trace( - `Found neighbourhood: ${JSON.stringify( + `Found the neighbourhood: ${JSON.stringify( closestNodes.map((node) => node.id), null, 2, )}`, + command, ); if (closestNodes.length < minAckResponses) { this.handleError( operationId, - `Unable to find enough nodes for ${operationId}. Minimum number of nodes required: ${minAckResponses}`, + command, this.errorType, + `Unable to find enough nodes. Minimum number of nodes required: ${minAckResponses}.`, true, ); return Command.empty(); diff --git a/src/commands/protocols/common/handle-protocol-message-command.js b/src/commands/protocols/common/handle-protocol-message-command.js index 79400fda6e..1fa6a16eb1 100644 --- a/src/commands/protocols/common/handle-protocol-message-command.js +++ b/src/commands/protocols/common/handle-protocol-message-command.js @@ -21,7 +21,7 @@ class HandleProtocolMessageCommand extends Command { const { remotePeerId, operationId, keywordUuid, protocol } = command.data; try { - const { messageType, messageData } = await this.prepareMessage(command.data); + const { messageType, messageData } = await this.prepareMessage(command); await this.networkModuleManager.sendMessageResponse( protocol, remotePeerId, @@ -32,10 +32,14 @@ class HandleProtocolMessageCommand extends Command { ); } catch (error) { if (command.retries) { - this.logger.warn(error.message); + this.logger.warn( + `Error occurred during the command execution; ` + + `Error Message: ${error.message}. Retrying the command...`, + command, + ); return Command.retry(); } - await this.handleError(error.message, command); + await this.handleError(command, error.message); } this.networkModuleManager.removeCachedSession(operationId, keywordUuid, remotePeerId); @@ -44,7 +48,7 @@ class HandleProtocolMessageCommand extends Command { } async prepareMessage() { - throw Error('prepareMessage not implemented'); + throw Error('prepareMessage is not implemented.'); } async validateNeighborhood(blockchain, keyword, hashFunctionId, ual) { @@ -61,7 +65,8 @@ class HandleProtocolMessageCommand extends Command { return true; } } - this.logger.warn(`Invalid neighborhood for ual: ${ual}`); + + this.logger.warn(`Invalid neighborhood for the UAL: ${ual}`); return false; } @@ -74,7 +79,9 @@ class HandleProtocolMessageCommand extends Command { ); if (blockchainAssertionId !== assertionId) { throw Error( - `Invalid assertion id for asset ${ual}. Received value from blockchain: ${blockchainAssertionId}, received value from request: ${assertionId}`, + `Invalid Assertion ID for the Knowledge Asset with the UAL: ${ual}. ` + + `Value from the blockchain: ${blockchainAssertionId}; ` + + `Value from the request: ${assertionId}.`, ); } } @@ -88,7 +95,7 @@ class HandleProtocolMessageCommand extends Command { assertionId, operationId, ) { - const geAgreementData = async () => { + const getAgreementData = async () => { const agreementId = await this.serviceAgreementService.generateId( blockchain, contract, @@ -96,9 +103,6 @@ class HandleProtocolMessageCommand extends Command { keyword, hashFunctionId, ); - this.logger.info( - `Calculated agreement id: ${agreementId} for contract: ${contract}, token id: ${tokenId}, keyword: ${keyword}, hash function id: ${hashFunctionId}, operationId: ${operationId}`, - ); return { agreementId, @@ -122,7 +126,7 @@ class HandleProtocolMessageCommand extends Command { const [{ agreementId, agreementData }, blockchainAssertionSize, r0, ask] = await Promise.all([ - geAgreementData(), + getAgreementData(), this.blockchainModuleManager.getAssertionSize(blockchain, assertionId), this.blockchainModuleManager.getR0(blockchain), getAsk(), @@ -130,11 +134,15 @@ class HandleProtocolMessageCommand extends Command { const blockchainAssertionSizeInKb = blockchainAssertionSize / BYTES_IN_KILOBYTE; if (blockchainAssertionSizeInKb > this.config.maximumAssertionSizeInKb) { this.logger.warn( - `The size of the received assertion exceeds the maximum limit allowed.. Maximum allowed assertion size in kb: ${this.config.maximumAssertionSizeInKb}, assertion size read from blockchain in kb: ${blockchainAssertionSizeInKb}`, + `The size of the received Assertion for the Service Agreement ` + + `with ID: ${agreementId} exceeds the maximum limit allowed. ` + + `Maximum allowed assertion size: ${this.config.maximumAssertionSizeInKb} KB; ` + + `Assertion size read from blockchain: ${blockchainAssertionSizeInKb} KB.`, ); return { errorMessage: - 'The size of the received assertion exceeds the maximum limit allowed.', + `The size of the received Assertion for the Service Agreement ` + + `with ID: ${agreementId} exceeds the maximum limit allowed.`, agreementId, agreementData, }; @@ -161,7 +169,7 @@ class HandleProtocolMessageCommand extends Command { .div(divisor) .add(1); // add 1 wei because of the precision loss - const bidAskLog = `Service agreement bid: ${serviceAgreementBid}, ask: ${ask}, operationId: ${operationId}`; + const bidAskLog = `Operation ID: ${operationId}; Service Agreement Bid: ${serviceAgreementBid}; Node Ask: ${ask}.`; this.logger.trace(bidAskLog); return { @@ -182,17 +190,19 @@ class HandleProtocolMessageCommand extends Command { ) { const ual = this.ualService.deriveUAL(blockchain, contract, tokenId); - this.logger.trace(`Validating neighborhood for ual: ${ual}`); + this.logger.trace(`Validating neighborhood for the Knowledge Asset with the UAL: ${ual}.`); if (!(await this.validateNeighborhood(blockchain, keyword, hashFunctionId, ual))) { return { messageType: NETWORK_MESSAGE_TYPES.RESPONSES.NACK, - messageData: { errorMessage: 'Invalid neighbourhood' }, + messageData: { + errorMessage: `Invalid neighbourhood for the Knowledge Asset with the UAL: ${ual}.`, + }, }; } - this.logger.trace(`Validating assertion with ual: ${ual}`); + this.logger.trace(`Validating Assertion for the Knowledge Asset with the UAL: ${ual}.`); await this.validateAssertionId(blockchain, contract, tokenId, assertionId, ual); - this.logger.trace(`Validating bid for asset with ual: ${ual}`); + this.logger.trace(`Validating Bid for the Knowledge Asset with the UAL: ${ual}.`); const { errorMessage, agreementId, agreementData } = await this.validateBid( contract, tokenId, @@ -224,10 +234,10 @@ class HandleProtocolMessageCommand extends Command { return { messageType: NETWORK_MESSAGE_TYPES.RESPONSES.ACK, messageData: {} }; } - async handleError(errorMessage, command) { + async handleError(command, errorMessage) { const { operationId, remotePeerId, keywordUuid, protocol } = command.data; - await super.handleError(operationId, errorMessage, this.errorType, true); + await super.handleError(operationId, command, this.errorType, errorMessage, true); await this.networkModuleManager.sendMessageResponse( protocol, remotePeerId, diff --git a/src/commands/protocols/common/protocol-schedule-messages-command.js b/src/commands/protocols/common/protocol-schedule-messages-command.js index bc9d1af115..e04f4bf1c9 100644 --- a/src/commands/protocols/common/protocol-schedule-messages-command.js +++ b/src/commands/protocols/common/protocol-schedule-messages-command.js @@ -31,9 +31,10 @@ class ProtocolScheduleMessagesCommand extends Command { this.logger.debug( `Trying to ${this.operationService.getOperationName()} to batch of ${ currentBatchNodes.length - } nodes for keyword : ${keyword}, leftover for retry: ${ + } nodes for the Keyword: ${keyword}, leftover for retry: ${ currentBatchLeftoverNodes.length - }`, + }.`, + command, ); const addCommandPromises = currentBatchNodes.map(async (node) => { diff --git a/src/commands/protocols/common/submit-commit-command.js b/src/commands/protocols/common/submit-commit-command.js index 7c9cfba13a..49805c24b5 100644 --- a/src/commands/protocols/common/submit-commit-command.js +++ b/src/commands/protocols/common/submit-commit-command.js @@ -25,11 +25,12 @@ class SubmitCommitCommand extends Command { } = command.data; this.logger.trace( - `Started ${command.name} for agreement id: ${agreementId} ` + - `blockchain: ${blockchain}, contract: ${contract}, token id: ${tokenId},` + - `keyword: ${keyword}, hash function id: ${hashFunctionId}, epoch: ${epoch}, ` + - `stateIndex: ${stateIndex}, operationId: ${operationId}, ` + - ` Retry number ${COMMAND_RETRIES.SUBMIT_COMMIT - command.retries + 1}`, + `Started the command for the Blockchain: ${blockchain}, ` + + `Contract: ${contract}, Token ID: ${tokenId}, Service Agreement ID: ${agreementId}, ` + + `Keyword: ${keyword}, Hash Function ID: ${hashFunctionId}, Epoch: ${epoch}, ` + + `State Index: ${stateIndex}, Operation ID: ${operationId}, ` + + `Retry number: ${COMMAND_RETRIES.SUBMIT_COMMIT - command.retries + 1}.`, + command, ); if (command.retries === COMMAND_RETRIES.SUBMIT_COMMIT) { @@ -50,7 +51,11 @@ class SubmitCommitCommand extends Command { ); if (alreadySubmitted) { this.logger.trace( - `Commit already submitted for blockchain: ${blockchain} agreement id: ${agreementId}, epoch: ${epoch}, state index: ${stateIndex}`, + `Commit has been already submitted for the Blockchain: ${blockchain}, ` + + `Contract: ${contract}, Token ID: ${tokenId}, Service Agreement ID: ${agreementId}, ` + + `Keyword: ${keyword}, Hash Function ID: ${hashFunctionId}, Epoch: ${epoch}, ` + + `State Index: ${stateIndex}, Operation ID: ${operationId}.`, + command, ); return Command.empty(); } @@ -76,11 +81,12 @@ class SubmitCommitCommand extends Command { await transactionCompletePromise; this.logger.trace( - `Successfully executed ${command.name} for agreement id: ${agreementId} ` + - `contract: ${contract}, token id: ${tokenId}, keyword: ${keyword}, ` + - `hash function id: ${hashFunctionId}. Retry number ${ - COMMAND_RETRIES.SUBMIT_COMMIT - command.retries + 1 - }`, + `Successfully executed the command for for the Blockchain: ${blockchain}, ` + + `Contract: ${contract}, Token ID: ${tokenId}, Service Agreement ID: ${agreementId}, ` + + `Keyword: ${keyword}, Hash Function ID: ${hashFunctionId}, Epoch: ${epoch}, ` + + `State Index: ${stateIndex}, Operation ID: ${operationId}, ` + + `Retry number: ${COMMAND_RETRIES.SUBMIT_COMMIT - command.retries + 1}.`, + command, ); this.operationIdService.emitChangeEvent( OPERATION_ID_STATUS.COMMIT_PROOF.SUBMIT_COMMIT_END, @@ -111,7 +117,7 @@ class SubmitCommitCommand extends Command { } async retryFinished(command) { - this.recover(command, `Max retry count for command: ${command.name} reached!`); + this.recover(command, Error('Max retries have been exceeded!')); } /** diff --git a/src/commands/protocols/common/submit-proofs-command.js b/src/commands/protocols/common/submit-proofs-command.js index 8348480f84..d38bab9f7e 100644 --- a/src/commands/protocols/common/submit-proofs-command.js +++ b/src/commands/protocols/common/submit-proofs-command.js @@ -35,11 +35,12 @@ class SubmitProofsCommand extends Command { } = command.data; this.logger.trace( - `Started ${command.name} for agreement id: ${agreementId} ` + - `blockchain: ${blockchain}, contract: ${contract}, token id: ${tokenId},` + - `keyword: ${keyword}, hash function id: ${hashFunctionId}, epoch: ${epoch}, ` + - `stateIndex: ${stateIndex}, operationId: ${operationId}, ` + - ` Retry number ${COMMAND_RETRIES.SUBMIT_PROOFS - command.retries + 1}`, + `Started the command for the Blockchain: ${blockchain}, ` + + `Contract: ${contract}, Token ID: ${tokenId}, Service Agreement ID: ${agreementId}, ` + + `Keyword: ${keyword}, Hash Function ID: ${hashFunctionId}, Epoch: ${epoch}, ` + + `State Index: ${stateIndex}, Operation ID: ${operationId}, ` + + `Retry number: ${COMMAND_RETRIES.SUBMIT_PROOFS - command.retries + 1}.`, + command, ); if (command.retries === COMMAND_RETRIES.SUBMIT_PROOFS) { @@ -51,7 +52,10 @@ class SubmitProofsCommand extends Command { ); } - this.logger.trace(`Calculating proofs for agreement id : ${agreementId}`); + this.logger.trace( + `Calculating proofs for the Service Agreement ID: ${agreementId}.`, + command, + ); const { challenge } = await this.blockchainModuleManager.getChallenge( blockchain, contract, @@ -66,7 +70,10 @@ class SubmitProofsCommand extends Command { ); if (!assertion.length) { - this.logger.trace(`Assertion with id: ${assertionId} not found in triple store.`); + this.logger.trace( + `Assertion with the ID: ${assertionId} not found in the triple store.`, + command, + ); return Command.empty(); } @@ -98,7 +105,11 @@ class SubmitProofsCommand extends Command { ); if (alreadySubmitted) { this.logger.trace( - `Proofs already submitted for blockchain: ${blockchain} agreement id: ${agreementId}, epoch: ${epoch}, state index: ${stateIndex}`, + `Proof has been already submitted for the Blockchain: ${blockchain}, ` + + `Contract: ${contract}, Token ID: ${tokenId}, Service Agreement ID: ${agreementId}, ` + + `Keyword: ${keyword}, Hash Function ID: ${hashFunctionId}, Epoch: ${epoch}, ` + + `State Index: ${stateIndex}, Operation ID: ${operationId}.`, + command, ); return Command.empty(); } @@ -126,11 +137,12 @@ class SubmitProofsCommand extends Command { await transactionCompletePromise; this.logger.trace( - `Successfully executed ${command.name} for agreement id: ${agreementId} ` + - `contract: ${contract}, token id: ${tokenId}, keyword: ${keyword}, ` + - `hash function id: ${hashFunctionId}. Retry number ${ - COMMAND_RETRIES.SUBMIT_PROOFS - command.retries + 1 - }`, + `Successfully executed the command for the Blockchain: ${blockchain}, ` + + `Contract: ${contract}, Token ID: ${tokenId}, Service Agreement ID: ${agreementId}, ` + + `Keyword: ${keyword}, Hash Function ID: ${hashFunctionId}, Epoch: ${epoch}, ` + + `State Index: ${stateIndex}, Operation ID: ${operationId}, ` + + `Retry number: ${COMMAND_RETRIES.SUBMIT_PROOFS - command.retries + 1}.`, + command, ); this.operationIdService.emitChangeEvent( @@ -162,7 +174,7 @@ class SubmitProofsCommand extends Command { } async retryFinished(command) { - this.recover(command, `Max retry count for command: ${command.name} reached!`); + this.recover(command, Error('Max retries have been exceeded!')); } /** diff --git a/src/commands/protocols/get/receiver/v1.0.0/v1-0-0-handle-get-init-command.js b/src/commands/protocols/get/receiver/v1.0.0/v1-0-0-handle-get-init-command.js index 8dbef0a104..e565eda452 100644 --- a/src/commands/protocols/get/receiver/v1.0.0/v1-0-0-handle-get-init-command.js +++ b/src/commands/protocols/get/receiver/v1.0.0/v1-0-0-handle-get-init-command.js @@ -18,8 +18,8 @@ class HandleGetInitCommand extends HandleProtocolMessageCommand { this.errorType = ERROR_TYPE.GET.GET_INIT_REMOTE_ERROR; } - async prepareMessage(commandData) { - const { operationId, blockchain, contract, tokenId, assertionId, state } = commandData; + async prepareMessage(command) { + const { operationId, blockchain, contract, tokenId, assertionId, state } = command.data; await this.operationIdService.updateOperationIdStatus( operationId, @@ -27,7 +27,10 @@ class HandleGetInitCommand extends HandleProtocolMessageCommand { ); this.logger.trace( - `Checking if assertion ${assertionId} exists for state ${state}, on blockchain: ${blockchain}, contract: ${contract}, and tokenId: ${tokenId}`, + `Checking if Assertion with ID: ${assertionId} exists on the Blockchain: ${blockchain}, ` + + `within the Contract: ${contract}, for the Knowledge Asset with the Token ID: ${tokenId} ` + + `and State: ${state}.`, + command, ); let assertionExists; diff --git a/src/commands/protocols/get/receiver/v1.0.0/v1-0-0-handle-get-request-command.js b/src/commands/protocols/get/receiver/v1.0.0/v1-0-0-handle-get-request-command.js index 576dbe8a5a..a72798a758 100644 --- a/src/commands/protocols/get/receiver/v1.0.0/v1-0-0-handle-get-request-command.js +++ b/src/commands/protocols/get/receiver/v1.0.0/v1-0-0-handle-get-request-command.js @@ -19,8 +19,8 @@ class HandleGetRequestCommand extends HandleProtocolMessageCommand { this.errorType = ERROR_TYPE.GET.GET_REQUEST_REMOTE_ERROR; } - async prepareMessage(commandData) { - const { operationId, blockchain, contract, tokenId, assertionId, state } = commandData; + async prepareMessage(command) { + const { operationId, blockchain, contract, tokenId, assertionId, state } = command.data; await this.operationIdService.updateOperationIdStatus( operationId, OPERATION_ID_STATUS.GET.GET_REMOTE_START, diff --git a/src/commands/protocols/get/sender/get-assertion-id-command.js b/src/commands/protocols/get/sender/get-assertion-id-command.js index cf40c8d681..f7c1f10b7c 100644 --- a/src/commands/protocols/get/sender/get-assertion-id-command.js +++ b/src/commands/protocols/get/sender/get-assertion-id-command.js @@ -23,8 +23,10 @@ class GetAssertionIdCommand extends Command { if (state === ZERO_BYTES32) { await this.handleError( operationId, - `The provided state: ${state}. State hash cannot be 0x0.`, + command, this.errorType, + `State hash cannot be 0x0.`, + true, ); return Command.empty(); @@ -47,8 +49,11 @@ class GetAssertionIdCommand extends Command { ) { await this.handleError( operationId, - `The provided state: ${state} does not exist on the ${blockchain} blockchain, ``within contract: ${contract}, for the Knowledge Asset with tokenId: ${tokenId}.`, + command, this.errorType, + `Provided State: ${state} does not exist on the Blockchain: ${blockchain}, ` + + `within the Contract: ${contract}, for the Knowledge Asset with the token ID: ${tokenId}.`, + true, ); return Command.empty(); @@ -57,7 +62,8 @@ class GetAssertionIdCommand extends Command { assertionId = state; } else { this.logger.debug( - `Searching for latest assertion id on ${blockchain} on contract: ${contract} with tokenId: ${tokenId}`, + `Searching for the latest Assertion ID on the Blockchain: ${blockchain}, ` + + `within the Contract: ${contract}, for the Knowledge Asset with the Token ID: ${tokenId}.`, ); if (state === GET_STATES.LATEST) { @@ -78,10 +84,6 @@ class GetAssertionIdCommand extends Command { return this.continueSequence({ ...command.data, state, assertionId }, command.sequence); } - async handleError(operationId, errorMessage, errorType) { - await this.operationService.markOperationAsFailed(operationId, errorMessage, errorType); - } - /** * Builds default getStateIdConditionalCommand * @param map diff --git a/src/commands/protocols/get/sender/local-get-command.js b/src/commands/protocols/get/sender/local-get-command.js index 8d64f8186e..4c263abfbb 100644 --- a/src/commands/protocols/get/sender/local-get-command.js +++ b/src/commands/protocols/get/sender/local-get-command.js @@ -107,10 +107,6 @@ class LocalGetCommand extends Command { return this.continueSequence(command.data, command.sequence); } - async handleError(operationId, errorMessage, errorType) { - await this.operationService.markOperationAsFailed(operationId, errorMessage, errorType); - } - /** * Builds default localGetCommand * @param map diff --git a/src/commands/protocols/get/sender/v1.0.0/v1-0-0-get-request-command.js b/src/commands/protocols/get/sender/v1.0.0/v1-0-0-get-request-command.js index 7c6d6e1cfc..2763e401ed 100644 --- a/src/commands/protocols/get/sender/v1.0.0/v1-0-0-get-request-command.js +++ b/src/commands/protocols/get/sender/v1.0.0/v1-0-0-get-request-command.js @@ -24,7 +24,8 @@ class GetRequestCommand extends ProtocolRequestCommand { return true; } this.logger.trace( - `${command.name} skipped for operationId: ${operationId} with status ${status}`, + `Command skipped for the operation ID: ${operationId} with the status ${status}.`, + command, ); return false; diff --git a/src/commands/protocols/publish/receiver/v1.0.0/v1-0-0-handle-store-init-command.js b/src/commands/protocols/publish/receiver/v1.0.0/v1-0-0-handle-store-init-command.js index 36cb8e407c..268a124500 100644 --- a/src/commands/protocols/publish/receiver/v1.0.0/v1-0-0-handle-store-init-command.js +++ b/src/commands/protocols/publish/receiver/v1.0.0/v1-0-0-handle-store-init-command.js @@ -10,9 +10,9 @@ class HandleStoreInitCommand extends HandleProtocolMessageCommand { this.errorType = ERROR_TYPE.PUBLISH.PUBLISH_REMOTE_ERROR; } - async prepareMessage(commandData) { + async prepareMessage(command) { const { operationId, assertionId, blockchain, contract, tokenId, keyword, hashFunctionId } = - commandData; + command.data; await this.operationIdService.updateOperationIdStatus( operationId, @@ -38,11 +38,7 @@ class HandleStoreInitCommand extends HandleProtocolMessageCommand { } async retryFinished(command) { - const { operationId } = command.data; - this.handleError( - `Retry count for command: ${command.name} reached! Unable to validate data for operation id: ${operationId}`, - command, - ); + this.handleError(command, `Max retries exceeded! Unable to validate the data.`); } /** diff --git a/src/commands/protocols/publish/receiver/v1.0.0/v1-0-0-handle-store-request-command.js b/src/commands/protocols/publish/receiver/v1.0.0/v1-0-0-handle-store-request-command.js index 0caa031c63..60d1a6d8c5 100644 --- a/src/commands/protocols/publish/receiver/v1.0.0/v1-0-0-handle-store-request-command.js +++ b/src/commands/protocols/publish/receiver/v1.0.0/v1-0-0-handle-store-request-command.js @@ -21,7 +21,7 @@ class HandleStoreRequestCommand extends HandleProtocolMessageCommand { this.errorType = ERROR_TYPE.PUBLISH.PUBLISH_LOCAL_STORE_REMOTE_ERROR; } - async prepareMessage(commandData) { + async prepareMessage(command) { const { blockchain, keyword, @@ -32,7 +32,7 @@ class HandleStoreRequestCommand extends HandleProtocolMessageCommand { assertionId, agreementId, agreementData, - } = commandData; + } = command.data; await this.operationIdService.updateOperationIdStatus( operationId, diff --git a/src/commands/protocols/publish/sender/publish-validate-asset-command.js b/src/commands/protocols/publish/sender/publish-validate-asset-command.js index 4ff4edc453..6870c3b80a 100644 --- a/src/commands/protocols/publish/sender/publish-validate-asset-command.js +++ b/src/commands/protocols/publish/sender/publish-validate-asset-command.js @@ -6,10 +6,6 @@ class PublishValidateAssetCommand extends ValidateAssetCommand { this.operationService = ctx.publishService; } - async handleError(operationId, errorMessage, errorType) { - await this.operationService.markOperationAsFailed(operationId, errorMessage, errorType); - } - /** * Builds default publishValidateAssetCommand * @param map diff --git a/src/commands/protocols/update/receiver/delete-pending-state-command.js b/src/commands/protocols/update/receiver/delete-pending-state-command.js index defa18d8d2..3588b28c26 100644 --- a/src/commands/protocols/update/receiver/delete-pending-state-command.js +++ b/src/commands/protocols/update/receiver/delete-pending-state-command.js @@ -14,8 +14,9 @@ class DeletePendingStateCommand extends Command { const { blockchain, contract, tokenId, assertionId, operationId } = command.data; this.logger.trace( - `Started ${command.name} for blockchain: ${blockchain} contract: ${contract}, ` + - `token id: ${tokenId}, assertion id: ${assertionId}`, + `Started the command for the Blockchain: ${blockchain}, Contract: ${contract}, ` + + `Token ID: ${tokenId}, Assertion ID: ${assertionId}.`, + command, ); const assetStates = await this.blockchainModuleManager.getAssertionIds( @@ -27,6 +28,7 @@ class DeletePendingStateCommand extends Command { if (assetStates.includes(assertionId)) { this.logger.trace( `Not clearing the pending storage as state was finalized and clearing is triggered by StateFinalized event.`, + command, ); return Command.empty(); } diff --git a/src/commands/protocols/update/receiver/submit-update-commit-command.js b/src/commands/protocols/update/receiver/submit-update-commit-command.js index bf5289600a..a9f7ea4e14 100644 --- a/src/commands/protocols/update/receiver/submit-update-commit-command.js +++ b/src/commands/protocols/update/receiver/submit-update-commit-command.js @@ -28,11 +28,11 @@ class SubmitUpdateCommitCommand extends Command { } = command.data; this.logger.trace( - `Started ${command.name} for agreement id: ${agreementId} ` + - `blockchain: ${blockchain} contract: ${contract}, token id: ${tokenId}, ` + - `keyword: ${keyword}, hash function id: ${hashFunctionId}. Retry number ${ - COMMAND_RETRIES.SUBMIT_UPDATE_COMMIT - command.retries + 1 - }`, + `Started the command the for the Blockchain: ${blockchain}, ` + + `Contract: ${contract}, Token ID: ${tokenId}, Agreement ID: ${agreementId}, ` + + `Keyword: ${keyword}, Hash Function ID: ${hashFunctionId}. ` + + `Retry number: ${COMMAND_RETRIES.SUBMIT_UPDATE_COMMIT - command.retries + 1}.`, + command, ); const epoch = await this.calculateCurrentEpoch( @@ -56,7 +56,7 @@ class SubmitUpdateCommitCommand extends Command { ); if (!hasPendingUpdate) { - this.logger.trace(`Not submitting as state is already finalized for update.`); + this.logger.trace(`Not submitting as state is already finalized for update.`, command); return Command.empty(); } @@ -75,10 +75,10 @@ class SubmitUpdateCommitCommand extends Command { agreementId, epoch, ); - this.logger.info('Successfully executed submit update commit'); + this.logger.info('Successfully executed submit update commit', command); } else if (command.retries - 1 === 0) { const errorMessage = `Failed executing submit update commit command, maximum number of retries reached. Error: ${result.error.message}`; - this.logger.error(errorMessage); + this.logger.error(errorMessage, command); this.operationIdService.emitChangeEvent( OPERATION_ID_STATUS.FAILED, operationId, @@ -90,6 +90,7 @@ class SubmitUpdateCommitCommand extends Command { const blockTime = this.blockchainModuleManager.getBlockTimeMillis(blockchain); this.logger.warn( `Failed executing submit update commit command, retrying in ${blockTime}ms. Error: ${result.error.message}`, + command, ); await this.commandExecutor.add({ name: 'submitUpdateCommitCommand', @@ -106,10 +107,11 @@ class SubmitUpdateCommitCommand extends Command { this.blockchainModuleManager.getTransactionQueueLength(blockchain); this.logger.trace( - `Scheduled submit update commit transaction for agreement id: ${agreementId} ` + - `blockchain: ${blockchain} contract: ${contract}, token id: ${tokenId}, ` + - `keyword: ${keyword}, hash function id: ${hashFunctionId}, operationId ${operationId}. ` + - `Transaction queue length: ${transactionQueueLength}.`, + `Scheduled submitUpdateCommitCommand for the Blockchain: ${blockchain}, ` + + `Contract: ${contract}, Token ID: ${tokenId}, Agreement ID: ${agreementId}, ` + + `Keyword: ${keyword}, Hash Function ID: ${hashFunctionId}, Operation ID ${operationId}. ` + + `Transaction Queue Length: ${transactionQueueLength}.`, + command, ); return Command.empty(); @@ -121,7 +123,7 @@ class SubmitUpdateCommitCommand extends Command { } async retryFinished(command) { - this.recover(command, `Max retry count for command: ${command.name} reached!`); + this.recover(command, `Max retry count for the command has been reached!`); } /** diff --git a/src/commands/protocols/update/receiver/v1.0.0/v1-0-0-handle-update-init-command.js b/src/commands/protocols/update/receiver/v1.0.0/v1-0-0-handle-update-init-command.js index 9882288b20..3a93cc1e6c 100644 --- a/src/commands/protocols/update/receiver/v1.0.0/v1-0-0-handle-update-init-command.js +++ b/src/commands/protocols/update/receiver/v1.0.0/v1-0-0-handle-update-init-command.js @@ -13,9 +13,9 @@ class HandleUpdateInitCommand extends HandleProtocolMessageCommand { this.errorType = ERROR_TYPE.UPDATE.UPDATE_REMOTE_ERROR; } - async prepareMessage(commandData) { + async prepareMessage(command) { const { operationId, assertionId, blockchain, contract, tokenId, keyword, hashFunctionId } = - commandData; + command.data; await this.operationIdService.updateOperationIdStatus( operationId, OPERATION_ID_STATUS.VALIDATE_ASSET_REMOTE_START, @@ -54,17 +54,15 @@ class HandleUpdateInitCommand extends HandleProtocolMessageCommand { ); if (blockchainAssertionId !== assertionId) { throw Error( - `Invalid assertion id for asset ${ual}. Received value from blockchain: ${blockchainAssertionId}, received value from request: ${assertionId}`, + `Invalid Assertion ID for the Knowledge Asset with the UAL: ${ual}. ` + + `Assertion ID from the request: ${assertionId}. ` + + `Received value from the Blockchain (${blockchain}): ${blockchainAssertionId}.`, ); } } async retryFinished(command) { - const { operationId } = command.data; - this.handleError( - `Retry count for command: ${command.name} reached! Unable to validate data for operation id: ${operationId}`, - command, - ); + this.handleError(command, `Max retries exceeded! Unable to validate the data.`); } /** diff --git a/src/commands/protocols/update/receiver/v1.0.0/v1-0-0-handle-update-request-command.js b/src/commands/protocols/update/receiver/v1.0.0/v1-0-0-handle-update-request-command.js index 0429b3c1f3..89b7202afa 100644 --- a/src/commands/protocols/update/receiver/v1.0.0/v1-0-0-handle-update-request-command.js +++ b/src/commands/protocols/update/receiver/v1.0.0/v1-0-0-handle-update-request-command.js @@ -25,7 +25,7 @@ class HandleUpdateRequestCommand extends HandleProtocolMessageCommand { this.errorType = ERROR_TYPE.UPDATE.UPDATE_LOCAL_STORE_REMOTE_ERROR; } - async prepareMessage(commandData) { + async prepareMessage(command) { const { blockchain, contract, @@ -35,7 +35,7 @@ class HandleUpdateRequestCommand extends HandleProtocolMessageCommand { keyword, hashFunctionId, agreementData, - } = commandData; + } = command.data; await this.operationIdService.updateOperationIdStatus( operationId, @@ -67,7 +67,10 @@ class HandleUpdateRequestCommand extends HandleProtocolMessageCommand { const rank = await this.calculateRank(blockchain, keyword, hashFunctionId, r2); if (rank != null) { - this.logger.trace(`Calculated rank: ${rank + 1} for agreement id: ${agreementId}`); + this.logger.trace( + `Calculated rank: ${rank + 1} for the Service Agreement ID: ${agreementId}.`, + command, + ); const finalizationCommitsNumber = await this.blockchainModuleManager.getFinalizationCommitsNumber(blockchain); @@ -84,7 +87,7 @@ class HandleUpdateRequestCommand extends HandleProtocolMessageCommand { delay: updateCommitDelay, retries: COMMAND_RETRIES.SUBMIT_UPDATE_COMMIT, data: { - ...commandData, + ...command.data, agreementData, agreementId, r0, @@ -102,7 +105,7 @@ class HandleUpdateRequestCommand extends HandleProtocolMessageCommand { sequence: [], delay: (updateCommitWindowDuration + 60) * 1000, data: { - ...commandData, + ...command.data, assertionId: cachedData.assertionId, }, transactional: false, @@ -138,9 +141,10 @@ class HandleUpdateRequestCommand extends HandleProtocolMessageCommand { blockTime; const delay = commitsBlockDuration * commitBlock + r0OffsetPeriod + nextNodeDelay; this.logger.info( - `Calculated update commit delay: ${Math.floor( - delay / 1000, - )}s, commitsBlockDuration: ${commitsBlockDuration}, commitBlock: ${commitBlock}, r0OffsetPeriod:${r0OffsetPeriod}, updateCommitWindowDuration ${updateCommitWindowDuration}s, finalizationCommitsNumber: ${finalizationCommitsNumber}, r0: ${r0}, rank: ${rank}`, + `Calculated UpdateCommitCommand delay: ${Math.floor(delay / 1000)}s, ` + + `commitsBlockDuration: ${commitsBlockDuration}, commitBlock: ${commitBlock}, ` + + `r0OffsetPeriod:${r0OffsetPeriod}, updateCommitWindowDuration ${updateCommitWindowDuration}s, ` + + `finalizationCommitsNumber: ${finalizationCommitsNumber}, r0: ${r0}, rank: ${rank}`, ); return delay; diff --git a/src/commands/protocols/update/sender/update-validate-asset-command.js b/src/commands/protocols/update/sender/update-validate-asset-command.js index 581f3cf671..14121cf287 100644 --- a/src/commands/protocols/update/sender/update-validate-asset-command.js +++ b/src/commands/protocols/update/sender/update-validate-asset-command.js @@ -6,10 +6,6 @@ class UpdateValidateAssetCommand extends ValidateAssetCommand { this.operationService = ctx.updateService; } - async handleError(operationId, errorMessage, errorType) { - await this.operationService.markOperationAsFailed(operationId, errorMessage, errorType); - } - /** * Builds default updateValidateAssetCommand * @param map diff --git a/src/commands/query/query-command.js b/src/commands/query/query-command.js index 68860027ec..ea98051bdd 100644 --- a/src/commands/query/query-command.js +++ b/src/commands/query/query-command.js @@ -56,8 +56,8 @@ class QueryCommand extends Command { operationId, OPERATION_ID_STATUS.COMPLETED, ); - } catch (e) { - await this.handleError(operationId, e.message, this.errorType, true); + } catch (err) { + await this.handleError(operationId, command, this.errorType, err.message, true); } return Command.empty(); diff --git a/src/logger/logger.js b/src/logger/logger.js index d98978426c..f6f6f5563b 100644 --- a/src/logger/logger.js +++ b/src/logger/logger.js @@ -33,46 +33,60 @@ class Logger { } } + log(level, obj, commandMetadata = {}) { + const commandMetadataStr = commandMetadata.name + ? this._formatCommandMetadata(commandMetadata) + : ''; + const objStr = typeof obj === 'object' ? JSON.stringify(obj) : obj; + const logStr = `${commandMetadataStr}${objStr}`; + this.pinoLogger[level](logStr); + } + restart() { this.initialize(this.logLevel, true); } - fatal(obj) { - this.pinoLogger.fatal(obj); + fatal(obj, commandMetadata = {}) { + this.log('fatal', obj, commandMetadata); } - error(obj) { - this.pinoLogger.error(obj); + error(obj, commandMetadata = {}) { + this.log('error', obj, commandMetadata); } - warn(obj) { - this.pinoLogger.warn(obj); + warn(obj, commandMetadata = {}) { + this.log('warn', obj, commandMetadata); } - info(obj) { - this.pinoLogger.info(obj); + info(obj, commandMetadata = {}) { + this.log('info', obj, commandMetadata); } - debug(obj) { - this.pinoLogger.debug(obj); + debug(obj, commandMetadata = {}) { + this.log('debug', obj, commandMetadata); } - emit(obj) { - this.pinoLogger.emit(obj); + emit(obj, commandMetadata = {}) { + this.log('emit', obj, commandMetadata); } - trace(obj) { - this.pinoLogger.trace(obj); + trace(obj, commandMetadata = {}) { + this.log('trace', obj, commandMetadata); } - api(obj) { - this.pinoLogger.api(obj); + api(obj, commandMetadata = {}) { + this.log('api', obj, commandMetadata); } closeLogger(closingMessage) { const finalLogger = pino.final(this.pinoLogger); finalLogger.info(closingMessage); } + + _formatCommandMetadata(commandMetadata) { + const commandIdStr = commandMetadata.id ? ` (${commandMetadata.id})` : ''; + return `${commandMetadata.name}${commandIdStr}: `; + } } export default Logger; diff --git a/src/migration/private-assets-metadata-migration.js b/src/migration/private-assets-metadata-migration.js index b9e4617283..6304d707a7 100644 --- a/src/migration/private-assets-metadata-migration.js +++ b/src/migration/private-assets-metadata-migration.js @@ -98,7 +98,7 @@ class PrivateAssetsMetadataMigration extends BaseMigration { tokenId, ); } catch (error) { - this.logger.warn(`Unable to find assertion id for token id: ${tokenId}`); + this.logger.warn(`Unable to find assertion id for token id: ${tokenId}.`); return; } if (!assertionIds.includes(assertionId)) return; diff --git a/src/migration/service-agreements-metadata-migration.js b/src/migration/service-agreements-metadata-migration.js index 8c29a8771c..d0aec7b323 100644 --- a/src/migration/service-agreements-metadata-migration.js +++ b/src/migration/service-agreements-metadata-migration.js @@ -99,7 +99,8 @@ class ServiceAgreementsMetadataMigration extends BaseMigration { attempt += 1; if (attempt >= maxAttempts) throw Error( - `Error while trying to get assertion ids for asset with ual: ${ual}. Max attempts reached`, + `Failed to get assertion IDs for asset with UAL: ${ual}. ` + + `Max attempts reached.`, ); if (attempt > 1) { await setTimeout(sleepTimeSeconds * 1000); @@ -112,13 +113,14 @@ class ServiceAgreementsMetadataMigration extends BaseMigration { ); } catch (error) { this.logger.warn( - `Error while trying to get assertion ids for asset with ual: ${ual}. Retrying in ${sleepTimeSeconds} seconds. Attempt number: ${attempt}.`, + `Filed to get assertion IDs for asset with UAL: ${ual}. ` + + `Retrying in ${sleepTimeSeconds} seconds. Attempt number: ${attempt}.`, ); } } if (!assertionIds?.length) { - this.logger.warn(`Unable to find assertion ids for asset with ual: ${ual}`); + this.logger.warn(`Unable to find assertion IDs for asset with UAL: ${ual}`); return; } const stateIndex = assertionIds.length - 1; @@ -146,7 +148,8 @@ class ServiceAgreementsMetadataMigration extends BaseMigration { attempt += 1; if (attempt >= maxAttempts) throw Error( - `Error while trying to get agreement data for asset with ual: ${ual}. Max attempts reached`, + `Error while trying to get agreement data for asset with ual: ${ual}. ` + + `Max attempts reached`, ); if (attempt > 1) { await setTimeout(sleepTimeSeconds * 1000); @@ -158,7 +161,8 @@ class ServiceAgreementsMetadataMigration extends BaseMigration { ); } catch (error) { this.logger.warn( - `Error while trying to get agreement data for asset with ual: ${ual}. Retrying in ${sleepTimeSeconds} seconds. Attempt number: ${attempt}.`, + `Failed to get agreement data for asset with UAL: ${ual}. ` + + `Retrying in ${sleepTimeSeconds} seconds. Attempt number: ${attempt}.`, ); } } @@ -177,7 +181,8 @@ class ServiceAgreementsMetadataMigration extends BaseMigration { attempt += 1; if (attempt >= maxAttempts) throw Error( - `Error while trying to get top commit submissions for asset with ual: ${ual}. Max attempts reached`, + `Failed to get top commit submissions for asset with UAL: ${ual}. ` + + `Max attempts reached`, ); if (attempt > 1) { await setTimeout(sleepTimeSeconds * 1000); @@ -191,7 +196,8 @@ class ServiceAgreementsMetadataMigration extends BaseMigration { ); } catch (error) { this.logger.warn( - `Error while trying to get top commit submissions for asset with ual: ${ual}. Retrying in ${sleepTimeSeconds} seconds. Attempt number: ${attempt}.`, + `Failed to get top commit submissions for asset with UAL: ${ual}. ` + + `Retrying in ${sleepTimeSeconds} seconds. Attempt number: ${attempt}.`, ); } } diff --git a/src/migration/triple-store-metadata-migration.js b/src/migration/triple-store-metadata-migration.js index dc087689d8..78c66b9c53 100644 --- a/src/migration/triple-store-metadata-migration.js +++ b/src/migration/triple-store-metadata-migration.js @@ -125,7 +125,7 @@ class TripleStoreMetadataMigration extends BaseMigration { try { resolvedUAL = this.ualService.resolveUAL(ual); } catch (error) { - this.logger.warn(`Unable to resolve UAL: ${error}`); + this.logger.warn(`Unable to resolve UAL: ${error}.`); continue; } @@ -140,14 +140,14 @@ class TripleStoreMetadataMigration extends BaseMigration { ); migrationInfo.processedUals[ual].assertionIds = assertionIds; } catch (error) { - this.logger.warn(`Unable to find assertion ids for asset with ual: ${ual}`); + this.logger.warn(`Unable to find assertion IDs for asset with UAL: ${ual}.`); migrationInfo.ualsToProcess.splice(i, 1); await this._updateMigrationInfoFile(currentRepository, migrationInfo); continue; } if (!assertionIds?.length) { - this.logger.warn(`Unable to find assertion ids for asset with ual: ${ual}`); + this.logger.warn(`Unable to find assertion IDs for asset with UAL: ${ual}.`); migrationInfo.ualsToProcess.splice(i, 1); await this._updateMigrationInfoFile(currentRepository, migrationInfo); continue; @@ -209,7 +209,7 @@ class TripleStoreMetadataMigration extends BaseMigration { ); this.logger.debug( - `found ${assetsQueryResult.length} assets with missing blockchain metadata`, + `Found ${assetsQueryResult.length} assets with missing blockchain metadata.`, ); let triples = ''; @@ -221,7 +221,7 @@ class TripleStoreMetadataMigration extends BaseMigration { try { resolvedUAL = this.ualService.resolveUAL(ual); } catch (error) { - this.logger.warn(`Unable to resolve UAL: ${error}`); + this.logger.warn(`Unable to resolve UAL: ${error}.`); continue; } @@ -265,7 +265,7 @@ class TripleStoreMetadataMigration extends BaseMigration { ); this.logger.debug( - `found ${assetsQueryResult.length} assets with missing contract metadata`, + `Found ${assetsQueryResult.length} assets with missing contract metadata.`, ); let triples = ''; @@ -277,7 +277,7 @@ class TripleStoreMetadataMigration extends BaseMigration { try { resolvedUAL = this.ualService.resolveUAL(ual); } catch (error) { - this.logger.warn(`Unable to resolve UAL: ${error}`); + this.logger.warn(`Unable to resolve UAL: ${error}.`); continue; } @@ -320,7 +320,9 @@ class TripleStoreMetadataMigration extends BaseMigration { }`, ); - this.logger.debug(`found ${assetsQueryResult.length} assets with missing keyword metadata`); + this.logger.debug( + `Found ${assetsQueryResult.length} assets with missing keyword metadata.`, + ); let triples = ''; const processedAssets = []; @@ -330,7 +332,7 @@ class TripleStoreMetadataMigration extends BaseMigration { try { resolvedUAL = this.ualService.resolveUAL(ual); } catch (error) { - this.logger.warn(`Unable to resolve UAL: ${error}`); + this.logger.warn(`Unable to resolve UAL: ${error}.`); continue; } @@ -344,12 +346,12 @@ class TripleStoreMetadataMigration extends BaseMigration { tokenId, ); } catch (error) { - this.logger.warn(`Unable to find assertion ids for asset with ual: ${ual}`); + this.logger.warn(`Unable to find assertion IDs for asset with UAL: ${ual}`); continue; } if (!assertionIds?.length) { - this.logger.warn(`Unable to find assertion ids for asset with ual: ${ual}`); + this.logger.warn(`Unable to find assertion IDs for asset with UAL: ${ual}`); continue; } @@ -404,7 +406,7 @@ class TripleStoreMetadataMigration extends BaseMigration { ); this.logger.debug( - `found ${assetsQueryResult.length} assets not containing exactly one assertion id in metadata`, + `Found ${assetsQueryResult.length} assets not containing exactly one assertion ID in metadata.`, ); let migrationInfoCopy = migrationInfo; @@ -414,7 +416,7 @@ class TripleStoreMetadataMigration extends BaseMigration { try { resolvedUAL = this.ualService.resolveUAL(ual); } catch (error) { - this.logger.warn(`Unable to resolve UAL: ${error}`); + this.logger.warn(`Unable to resolve UAL: ${error}.`); continue; } @@ -429,12 +431,12 @@ class TripleStoreMetadataMigration extends BaseMigration { ); migrationInfoCopy.processedUals[ual].assertionIds = assertionIds; } catch (error) { - this.logger.warn(`Unable to find assertion ids for asset with ual: ${ual}`); + this.logger.warn(`Unable to find assertion IDs for asset with UAL: ${ual}.`); continue; } if (!assertionIds?.length) { - this.logger.warn(`Unable to find assertion ids for asset with ual: ${ual}`); + this.logger.warn(`Unable to find assertion IDs for asset with UAL: ${ual}.`); continue; } @@ -668,7 +670,7 @@ class TripleStoreMetadataMigration extends BaseMigration { assetsQueryResult = assetsQueryResult.filter(({ g }) => g.startsWith('assertion:')); } this.logger.debug( - `found ${assetsQueryResult.length} assertions not linked to any asset.`, + `Found ${assetsQueryResult.length} assertions not linked to any asset.`, ); let deleteQuery = ''; if (!migrationInfoCopy.deletedAssertions) migrationInfoCopy.deletedAssertions = []; @@ -706,13 +708,13 @@ class TripleStoreMetadataMigration extends BaseMigration { ); let stats = this.dataService.parseBindings(allAssetsResult)[0]; - let log = `metadata stats for ${repository} repository: `; - log += `\n\t\t\t\tdistinct number of uals: ${stats.all}`; + let log = `Metadata stats for ${repository} repository: `; + log += `\n\t\t\t\tdistinct number of UALs: ${stats.all}`; const predicates = ['blockchain', 'contract', 'tokenId', 'keyword', 'assertion']; for (const predicate of predicates) { stats = await this._getPredicateStats(repository, predicate); - log += `\n\t\t\t\tdistinct number of uals with predicate ${predicate}: ${stats}`; + log += `\n\t\t\t\tdistinct number of UALs with predicate ${predicate}: ${stats}`; } this.logger.debug(log); } diff --git a/src/modules/auto-updater/implementation/ot-auto-updater.js b/src/modules/auto-updater/implementation/ot-auto-updater.js index e272597d78..7fa6f21e05 100644 --- a/src/modules/auto-updater/implementation/ot-auto-updater.js +++ b/src/modules/auto-updater/implementation/ot-auto-updater.js @@ -139,11 +139,11 @@ class OTAutoUpdater { }); res.on('end', () => { if (res.statusCode === 200) return resolve(body); - this.logger.warn(`AutoUpdater - Bad Response ${res.statusCode}`); + this.logger.warn(`AutoUpdater - Bad Response ${res.statusCode}.`); reject(res.statusCode); }); }); - this.logger.debug(`AutoUpdater - Sending request to ${url}`); + this.logger.debug(`AutoUpdater - Sending request to ${url}.`); req.on('error', reject); req.end(); }); @@ -156,7 +156,7 @@ class OTAutoUpdater { const options = {}; let url = `${REPOSITORY_URL}/${this.config.branch}/package.json`; if (url.includes('github')) url = url.replace('github.com', 'raw.githubusercontent.com'); - this.logger.debug(`AutoUpdater - Reading remote version from ${url}`); + this.logger.debug(`AutoUpdater - Reading remote version from ${url}.`); try { const body = await this.promiseHttpsRequest(url, options); @@ -173,7 +173,7 @@ class OTAutoUpdater { downloadUpdate(destination) { return new Promise((resolve, reject) => { const url = `https://${path.join(ARCHIVE_REPOSITORY_URL, this.config.branch)}.zip`; - this.logger.debug(`AutoUpdater - Downloading ot-node .zip file from url: ${url}`); + this.logger.debug(`AutoUpdater - Downloading ot-node .zip file from url: ${url}.`); axios({ method: 'get', url, responseType: 'stream' }) .then((response) => { const fileStream = fs.createWriteStream(destination); diff --git a/src/modules/base-module-manager.js b/src/modules/base-module-manager.js index e96161999c..98632b4aa0 100644 --- a/src/modules/base-module-manager.js +++ b/src/modules/base-module-manager.js @@ -30,7 +30,7 @@ class BaseModuleManager { } if (!implementationConfig.package) { - this.logger.warn(`Package for ${this.getName()} module is not defined`); + this.logger.warn(`Package for ${this.getName()} module is not defined.`); return false; } diff --git a/src/service/sharding-table-service.js b/src/service/sharding-table-service.js index 87688c0a42..bffedce55d 100644 --- a/src/service/sharding-table-service.js +++ b/src/service/sharding-table-service.js @@ -31,7 +31,7 @@ class ShardingTableService { ); this.updatePeerRecordLastSeenAndLastDialed(connection.remotePeer.toB58String()).catch( (error) => { - this.logger.warn(`Unable to update connected peer, error: ${error.message}`); + this.logger.warn(`Unable to update connected peer. Error: ${error.message}`); }, ); }); diff --git a/src/service/validation-service.js b/src/service/validation-service.js index 0786db76d0..c3c3cfbccc 100644 --- a/src/service/validation-service.js +++ b/src/service/validation-service.js @@ -11,7 +11,7 @@ class ValidationService { async validateUal(blockchain, contract, tokenId) { this.logger.info( - `Validating UAL: did:dkg:${blockchain.toLowerCase()}/${contract.toLowerCase()}/${tokenId}`, + `Validating the UAL: did:dkg:${blockchain.toLowerCase()}/${contract.toLowerCase()}/${tokenId}.`, ); let isValid = true; @@ -29,16 +29,16 @@ class ValidationService { } async validateAssertion(assertionId, blockchain, assertion) { - this.logger.info(`Validating assertionId: ${assertionId}`); + this.logger.info(`Validating Assertion with the ID: ${assertionId}.`); - this.validateAssertionId(assertion, assertionId); + this.validateAssertionId(blockchain, assertionId, assertion); // TODO: get assertion data in one call await this.validateAssertionSize(blockchain, assertionId, assertion); await this.validateTriplesNumber(blockchain, assertionId, assertion); await this.validateChunkSize(blockchain, assertionId, assertion); - this.logger.info(`Assertion integrity validated!`); + this.logger.info(`Assertion integrity has been validated!`); } async validateAssertionSize(blockchain, assertionId, assertion) { @@ -50,14 +50,17 @@ class ValidationService { const blockchainAssertionSizeInKb = blockchainAssertionSize / BYTES_IN_KILOBYTE; if (blockchainAssertionSizeInKb > this.config.maximumAssertionSizeInKb) { throw Error( - `The size of the received assertion exceeds the maximum limit allowed.. Maximum allowed assertion size in kb: ${this.config.maximumAssertionSizeInKb}, assertion size read from blockchain in kb: ${blockchainAssertionSizeInKb}`, + `The size of the received assertion exceeds the maximum limit allowed. ` + + `Maximum allowed Assertion Size in KB: ${this.config.maximumAssertionSizeInKb}. ` + + `Assertion Size read from the Blockchain: ${blockchain} in KB: ${blockchainAssertionSizeInKb}.`, ); } const assertionSize = assertionMetadata.getAssertionSizeInBytes(assertion); if (blockchainAssertionSize !== assertionSize) { // todo after corrective component is implemented, update this logic this.logger.warn( - `Invalid assertion size, value read from blockchain: ${blockchainAssertionSize}, calculated: ${assertionSize}`, + `Invalid Assertion Size. Calculated Assertion Size in KB: ${assertionSize}. ` + + `Value read from the Blockchain (${blockchain}) in KB: ${blockchainAssertionSize}.`, ); } } @@ -68,7 +71,8 @@ class ValidationService { const triplesNumber = assertionMetadata.getAssertionTriplesNumber(assertion); if (blockchainTriplesNumber !== triplesNumber) { throw Error( - `Invalid triples number, value read from blockchain: ${blockchainTriplesNumber}, calculated: ${triplesNumber}`, + `Invalid triples number. Calculated Assertion Triples Number: ${triplesNumber}. ` + + `Value read from the Blockchain (${blockchain}): ${blockchainTriplesNumber}.`, ); } } @@ -81,18 +85,20 @@ class ValidationService { const chunksNumber = assertionMetadata.getAssertionChunksNumber(assertion); if (blockchainChunksNumber !== chunksNumber) { throw Error( - `Invalid chunks number, value read from blockchain: ${blockchainChunksNumber}, calculated size: ${chunksNumber}`, + `Invalid chunks number. Calculated Assertion Chunks Number: ${chunksNumber}. ` + + `Value read from the Blockchain (${blockchain}): ${blockchainChunksNumber}.`, ); } } - validateAssertionId(assertion, assertionId) { + validateAssertionId(blockchain, assertionId, assertion) { const calculatedAssertionId = this.validationModuleManager.calculateRoot(assertion); if (assertionId !== calculatedAssertionId) { // todo after corrective component is implemented, update this logic this.logger.warn( - `Invalid assertion id. Received value: ${assertionId}, calculated: ${calculatedAssertionId}`, + `Invalid Assertion ID. Calculated Assertion ID: ${calculatedAssertionId}. ` + + `Value read from the Blockchain (${blockchain}): ${assertionId}.`, ); } }