diff --git a/api/http/transport.js b/api/http/transport.js index 78c53faa..b0772301 100644 --- a/api/http/transport.js +++ b/api/http/transport.js @@ -101,11 +101,11 @@ function TransportHttpApi (transportModule, app, logger, cache) { function getCommonBlocksMiddleware (req, res, next) { req.sanitize(req.query, schema.commonBlock, function (err, report, query) { if (err) { - logger.debug('Common block request validation failed', { err: err.toString(), req: req.query }); + logger.debug('transport-api', 'Common block request validation failed', { err: err.toString(), req: req.query }); return next(err); } if (!report.isValid) { - logger.debug('Common block request validation failed', { err: report, req: req.query }); + logger.debug('transport-api', 'Common block request validation failed', { err: report, req: req.query }); return res.json({ success: false, error: report.issues }); } diff --git a/api/ws/server.js b/api/ws/server.js index 1237b925..ff65a0f6 100644 --- a/api/ws/server.js +++ b/api/ws/server.js @@ -17,7 +17,7 @@ class WebSocketServer { this.logger = logger; const self = this; - self.logger.info(`[WsNodeServer] Created WebSocketServer`); + self.logger.info('ws-node-server', 'Created WebSocketServer'); } /** @@ -34,12 +34,12 @@ class WebSocketServer { this.io.on('connection', (socket) => { const peerIp = socket.handshake.address || socket.request.socket.remoteAddress; - self.logger.debug(`[WsNodeServer] WebSocket peer ${peerIp} is connecting…`); + self.logger.debug('ws-node-server', `WebSocket peer ${peerIp} is connecting…`); const { nonce } = socket.handshake.auth; if (!nonce) { - self.logger.trace(`[WsNodeServer] WebSocket peer ${peerIp} is not allowed to connect`, 'Wrong peer nonce'); + self.logger.trace('ws-node-server', `WebSocket peer ${peerIp} is not allowed to connect`, 'Wrong peer nonce'); socket.disconnect(true); return; @@ -55,7 +55,7 @@ class WebSocketServer { normalizeIp(peerIp) !== normalizeIp(existingPeer.ip) || existingPeer.state === Peer.STATE.BANNED ) { - self.logger.trace(`[WsNodeServer] WebSocket peer ${peerIp} is not allowed to connect`, 'Unknown or banned peer'); + self.logger.trace('ws-node-server', `WebSocket peer ${peerIp} is not allowed to connect`, 'Unknown or banned peer'); socket.disconnect(true); return; @@ -64,7 +64,7 @@ class WebSocketServer { if (logic.peers.getSocketCount() >= this.max) { const reason = 'Server connection limit exceeded'; - self.logger.trace(`[WsNodeServer] WebSocket peer ${peerIp} is not allowed to connect`, reason); + self.logger.trace('ws-node-server', `WebSocket peer ${peerIp} is not allowed to connect`, reason); socket.emit('disconnect_reason', reason); socket.disconnect(true); @@ -73,12 +73,12 @@ class WebSocketServer { existingPeer.isBroadcastingViaSocket = true; - self.logger.info(`[WsNodeServer] WebSocket peer ${peerIp} is connected to the node`); + self.logger.info('ws-node-server', `WebSocket peer ${peerIp} is connected to the node`); socket.on('disconnect', () => { const disconnectedPeer = logic.peers.getByNonce(nonce); - self.logger.debug(`[WsNodeServer] WebSocket peer ${disconnectedPeer.ip} is disconnecting…`); + self.logger.debug('ws-node-server', `WebSocket peer ${disconnectedPeer.ip} is disconnecting…`); if (disconnectedPeer) { disconnectedPeer.isBroadcastingViaSocket = false; diff --git a/api/ws/transport.js b/api/ws/transport.js index 3b84b202..ae18ef5e 100644 --- a/api/ws/transport.js +++ b/api/ws/transport.js @@ -29,7 +29,7 @@ class TransportWsApi { this.startRotation(); const self = this; - self.logger.info(`[WsNodeClient] Created TransportWsApi`); + self.logger.info('ws-node-client', `Created TransportWsApi`); } /** @@ -38,7 +38,7 @@ class TransportWsApi { initialize() { const self = this; - self.logger.info(`[WsNodeClient] Connecting to random peers via WebSocket…`); + self.logger.info('ws-node-client', `Connecting to random peers via WebSocket…`); // Clear existing connections self.connections.forEach(({ socket }) => { @@ -52,7 +52,7 @@ class TransportWsApi { if (err || !peers.length) { const reason = err ?? 'No suitable peers found'; self.logger.info( - `[WsNodeClient] Unable to initialize peers: ${reason}. Scheduling reconnection…`, + 'ws-node-client', `Unable to initialize peers: ${reason}. Scheduling reconnection…`, ); return self.scheduleReconnect(); } @@ -75,7 +75,7 @@ class TransportWsApi { return; } - self.logger.debug(`[WsNodeClient] Connecting to WebSocket peer ${peerUrl}…`); + self.logger.debug('ws-node-client', `Connecting to WebSocket peer ${peerUrl}…`); const socket = io(peerUrl, { reconnection: false, @@ -89,7 +89,7 @@ class TransportWsApi { socket.on('connect_error', (err) => self.handleConnectError(peer, err)); socket.on('disconnect', (reason) => self.handleDisconnect(peer, reason)); socket.on('disconnect_reason', (reason) => { - this.logger.debug(`[WsNodeClient] ${peer.ip}:${peer.port} rejected connection`, reason); + this.logger.debug('ws-node-client', `${peer.ip}:${peer.port} rejected connection`, reason); }); self.connections.set(peerUrl, { socket, peer }); @@ -101,7 +101,7 @@ class TransportWsApi { * @param {Peer} peer target peer */ handleConnect(socket, peer) { - this.logger.info(`[WsNodeClient] Connected to peer WebSocket at ${peer.ip}:${peer.port}`); + this.logger.info('ws-node-client', `Connected to peer WebSocket at ${peer.ip}:${peer.port}`); this.peers.switchToWs(peer); this.peers.recordRequest(peer.ip, peer.port, null); @@ -115,7 +115,7 @@ class TransportWsApi { * @param {string} err error message */ handleConnectError(peer, err) { - this.logger.debug(`[WsNodeClient] Connection error with ${peer.ip}:${peer.port}`, err.message); + this.logger.debug('ws-node-client', `Connection error with ${peer.ip}:${peer.port}`, err.message); this.peers.switchToHttp(peer); this.peers.recordRequest(peer.ip, peer.port, err); @@ -129,7 +129,7 @@ class TransportWsApi { * @param {string} reason disconnection reason */ handleDisconnect(peer, reason) { - this.logger.info(`[WsNodeClient] Disconnected from ${peer.ip}:${peer.port}`, reason); + this.logger.info('ws-node-client', `Disconnected from ${peer.ip}:${peer.port}`, reason); this.peers.switchToHttp(peer); this.replacePeer(peer); } @@ -149,7 +149,7 @@ class TransportWsApi { self.getRandomPeer((err, newPeer) => { if (err || !newPeer) { const reason = err ?? 'No suitable peers found'; - self.logger.debug(`[WsNodeClient] Failed to find replacement peer for ${disconnectedPeer}. ${reason}`); + self.logger.debug('ws-node-client', `Failed to find replacement peer for ${disconnectedPeer}. ${reason}`); return; } @@ -245,11 +245,11 @@ class TransportWsApi { updatePeers() { const self = this; - self.logger.info('[WsNodeClient] Updating peers…'); + self.logger.info('ws-node-client', 'Updating peers…'); this.connections.forEach(({ peer }) => { if (self.peers.isBanned(peer)) { - self.logger.info(`[WsNodeClient] Disconnecting from banned peer ws://${peer.ip}:${peer.port}…`); + self.logger.info('ws-node-client', `Disconnecting from banned peer ws://${peer.ip}:${peer.port}…`); self.cleanupConnection(peer); } }); @@ -257,14 +257,14 @@ class TransportWsApi { const availableSlots = this.maxConnections - this.connections.size; if (availableSlots <= 0) { - self.logger.info('[WsNodeClient] Max connections reached. No peers updated.'); + self.logger.info('ws-node-client', 'Max connections reached. No peers updated.'); return; } this.getRandomPeers(availableSlots, (err, candidates) => { if (err || !candidates.length) { const reason = err ?? 'Every peer is already connected via WebSocket'; - self.logger.info(`[WsNodeClient] ${reason}. No peers updated.`); + self.logger.info('ws-node-client', `${reason}. No peers updated.`); return; } @@ -295,7 +295,7 @@ class TransportWsApi { rotatePeers() { const self = this; - self.logger.info('[WsNodeClient] Rotating peers…'); + self.logger.info('ws-node-client', 'Rotating peers…'); const totalConnections = self.connections.size; @@ -311,16 +311,16 @@ class TransportWsApi { self.getRandomPeers(countToRotate, (err, newPeers) => { if (err || !newPeers.length) { const reason = err ?? 'No suitable peers found'; - self.logger.info(`[WsNodeClient] Could not rotate peers: ${reason}`); + self.logger.info('ws-node-client', `Could not rotate peers: ${reason}`); return; } - self.logger.info(`[WsNodeClient] Rotating ${newPeers.length} out of ${totalConnections} peers.`); + self.logger.info('ws-node-client', `Rotating ${newPeers.length} out of ${totalConnections} peers.`); const peersToRotate = shuffled.slice(0, newPeers.length).map((connection) => connection.peer); peersToRotate.forEach(peer => { - self.logger.debug(`[WsNodeClient] Rotating peer ${peer.ip}:${peer.port}`); + self.logger.debug('ws-node-client', `Rotating peer ${peer.ip}:${peer.port}`); self.cleanupConnection(peer); }); diff --git a/app.js b/app.js index 2ec0a8c9..b5e1429b 100644 --- a/app.js +++ b/app.js @@ -177,16 +177,17 @@ var config = { * @property {object} - Logger instance. */ var logger = new Logger({ - echo: appConfig.consoleLogLevel, + consoleLogLevel: appConfig.consoleLogLevel, errorLevel: appConfig.fileLogLevel, - filename: appConfig.logFileName + filename: appConfig.logFileName, + debugFilename: appConfig.debugFileName }); // Trying to get last git commit try { lastCommit = git.getLastCommit(); } catch (err) { - logger.debug('Cannot get last git commit', err.message); + logger.debug('system', 'Cannot get last git commit', err.message); } /** @@ -196,7 +197,7 @@ try { var d = require('domain').create(); d.on('error', function (err) { - logger.fatal('Domain master', { + logger.fatal('runtime', 'Domain master', { message: err.message, stack: err.stack }); @@ -218,7 +219,7 @@ d.run(function () { try { appConfig.nethash = Buffer.from(genesisblock.payloadHash, 'hex').toString('hex'); } catch (e) { - logger.error('Failed to assign nethash from genesis block'); + logger.error('genesis', 'Failed to assign nethash from genesis block'); throw Error(e); } @@ -354,7 +355,7 @@ d.run(function () { dbSequence: ['logger', function (scope, cb) { var sequence = new Sequence({ onWarning: function (current, limit) { - scope.logger.warn('DB queue', current); + scope.logger.warn('queue', 'Database queue size is too big. Tasks that queued database changes:', current); } }); cb(null, sequence); @@ -363,7 +364,7 @@ d.run(function () { sequence: ['logger', function (scope, cb) { var sequence = new Sequence({ onWarning: function (current, limit) { - scope.logger.warn('Main queue', current); + scope.logger.warn('queue', 'Main queue size is too big. Jobs in the queue:', current); } }); cb(null, sequence); @@ -372,7 +373,7 @@ d.run(function () { balancesSequence: ['logger', function (scope, cb) { var sequence = new Sequence({ onWarning: function (current, limit) { - scope.logger.warn('Balance queue', current); + scope.logger.warn('queue', 'Balance queue is overloaded. Tasks that require changing balance in the queue:', current); } }); cb(null, sequence); @@ -587,14 +588,14 @@ d.run(function () { var d = require('domain').create(); d.on('error', function (err) { - scope.logger.fatal('Domain ' + name, { + scope.logger.fatal('runtime', 'Domain ' + name, { message: err.message, stack: err.stack }); }); d.run(function () { - logger.debug('Loading module', name); + logger.debug('startup', 'Loading module', name); var Klass = require(config.modules[name]); var obj = new Klass(cb, scope); modules.push(obj); @@ -638,7 +639,7 @@ d.run(function () { var ApiEndpoint = require(apiEndpointPath); new ApiEndpoint(scope.modules[moduleName], scope.network.app, scope.logger, scope.modules.cache); } catch (e) { - scope.logger.error('Unable to load API endpoint for ' + moduleName + ' of ' + protocol, e); + scope.logger.error('startup', 'Unable to load API endpoint for ' + moduleName + ' of ' + protocol, e); } }); }); @@ -665,12 +666,12 @@ d.run(function () { */ listen: ['ready', function (scope, cb) { scope.network.server.listen(scope.config.port, scope.config.address, function (err) { - scope.logger.info('ADAMANT started: ' + scope.config.address + ':' + scope.config.port); + scope.logger.info('startup', 'ADAMANT started: ' + scope.config.address + ':' + scope.config.port); if (!err) { if (scope.config.ssl.enabled) { scope.network.https.listen(scope.config.ssl.options.port, scope.config.ssl.options.address, function (err) { - scope.logger.info('ADAMANT https started: ' + scope.config.ssl.options.address + ':' + scope.config.ssl.options.port); + scope.logger.info('startup', 'ADAMANT https started: ' + scope.config.ssl.options.address + ':' + scope.config.ssl.options.port); cb(err, scope.network); }); @@ -684,7 +685,7 @@ d.run(function () { }] }, function (err, scope) { if (err) { - logger.fatal(err); + logger.fatal('startup', err); } else { /** * Handles app instance (acts as global variable, passed as parameter). @@ -714,7 +715,7 @@ d.run(function () { * @todo logic repeats: bus, ed, genesisblock, logger, schema. * @todo description for nonce and ready */ - scope.logger.info('Modules ready and launched'); + scope.logger.info('startup', 'Modules ready and launched'); /** * Event reporting a cleanup. * @event cleanup @@ -724,7 +725,7 @@ d.run(function () { * @listens cleanup */ process.once('cleanup', function () { - scope.logger.info('Cleaning up...'); + scope.logger.info('exit', 'Cleaning up...'); async.eachSeries(modules, function (module, cb) { if (typeof (module.cleanup) === 'function') { module.cleanup(cb); @@ -733,9 +734,9 @@ d.run(function () { } }, function (err) { if (err) { - scope.logger.error(err); + scope.logger.error('exit', 'An error occurred while cleaning up modules:', err); } else { - scope.logger.info('Cleaned up successfully'); + scope.logger.info('exit', 'Cleaned up successfully'); } process.exit(1); }); @@ -802,7 +803,7 @@ d.run(function () { */ process.on('uncaughtException', function (err) { // Handle error safely - logger.fatal('System error', { + logger.fatal('runtime', 'System error', { message: err.message, stack: err.stack }); diff --git a/config.default.json b/config.default.json index db9b611d..a587bc5b 100644 --- a/config.default.json +++ b/config.default.json @@ -2,6 +2,7 @@ "port": 36666, "address": "0.0.0.0", "fileLogLevel": "warn", + "debugFileName": "logs/adamant_debug.log", "logFileName": "logs/adamant.log", "consoleLogLevel": "info", "trustProxy": false, diff --git a/helpers/cache.js b/helpers/cache.js index 4f063bea..f7cd8b9e 100644 --- a/helpers/cache.js +++ b/helpers/cache.js @@ -25,7 +25,7 @@ module.exports.connect = function (cacheEnabled, config, logger, cb) { client.connect() .then(() => { - logger.info('App connected with redis server'); + logger.info('cache', 'App connected with redis server'); if (!isRedisLoaded) { isRedisLoaded = true; @@ -34,7 +34,7 @@ module.exports.connect = function (cacheEnabled, config, logger, cb) { } }) .catch((err) => { - logger.error('Redis:', err); + logger.error('cache', 'An error occurred while connecting to redis server:', err); // Only throw an error if cache was enabled in config but were unable to load it properly if (!isRedisLoaded) { isRedisLoaded = true; diff --git a/helpers/database.js b/helpers/database.js index 0521e9ab..e6fb698c 100644 --- a/helpers/database.js +++ b/helpers/database.js @@ -109,7 +109,7 @@ function Migrator (pgp, db, logger) { */ this.applyPendingMigrations = function (pendingMigrations, waterCb) { if (pendingMigrations.length) { - logger.info(`Found ${pendingMigrations.length} pending migrations. Start executing, this may take a while…`); + logger.info('migrator', `Found ${pendingMigrations.length} pending migrations. Start executing, this may take a while…`); } var appliedMigrations = []; @@ -125,7 +125,7 @@ function Migrator (pgp, db, logger) { }); }, function (err) { if (pendingMigrations.length && !err) { - logger.info('Migrations have been successfully completed.'); + logger.info('migrator', 'Migrations have been successfully completed.'); } return waterCb(err, appliedMigrations); @@ -199,7 +199,11 @@ module.exports.connect = function (config, logger, cb) { monitor.setTheme('matrix'); monitor.setLog(function (msg, info) { - logger.log(info.event, info.text); + if (info.event === 'error') { + logger.error('pg-monitor', info.text); + } else { + logger.info('pg-monitor', `${info.event}: ${info.text}`); + } info.display = false; }); diff --git a/helpers/httpApi.js b/helpers/httpApi.js index eefe32eb..66f42c37 100644 --- a/helpers/httpApi.js +++ b/helpers/httpApi.js @@ -37,7 +37,7 @@ var middleware = { */ errorLogger: function (logger, err, req, res, next) { if (!err) { return next(); } - logger.error('API error ' + req.url, err.message); + logger.error('http', 'API error ' + req.url, err.message); res.status(500).send({ success: false, error: 'API error: ' + err.message }); }, @@ -50,7 +50,7 @@ var middleware = { */ logClientConnections: function (logger, req, res, next) { // Log client connections - logger.log(req.method + ' ' + req.url + ' from ' + req.ip); + logger.log('http', req.method + ' ' + req.url + ' from ' + req.ip); return next(); }, @@ -163,14 +163,14 @@ var middleware = { var expressSendJson = res.json; res.json = function (response) { if (response.success) { - logger.debug('cached response for key: ', req.url); + logger.debug('cache', 'cached response for key: ', req.url); cache.setJsonForKey(key, response); } expressSendJson.call(res, response); }; next(); } else { - logger.debug(['serving response for url:', req.url, 'from cache'].join(' ')); + logger.debug('cache', ['serving response for url:', req.url, 'from cache'].join(' ')); res.json(cachedValue); } }); diff --git a/logger.js b/logger.js index a622ce97..e161f3ce 100644 --- a/logger.js +++ b/logger.js @@ -1,9 +1,21 @@ -'use strict'; +const fs = require('fs'); +const path = require('path'); +const util = require('util'); -var strftime = require('strftime').utc(); -var fs = require('fs'); -var util = require('util'); -require('colors'); +const colors = require('colors/safe'); + +const DEFAULT_LOG_PATH = path.join(__dirname, 'logs.log'); +const DEFAULT_FILE_LOG_LEVEL = 'log'; + +// minimize debug file size +const debugNamespaces = new Set(['delegates', 'rounds', 'transactions', 'blocks']); + +/** + * Console log levels that should print to `stderr` instead of `stdout`. + * + * @link https://docs.adamant.im/own-node/configuration.html#logging + */ +const stdErrorLogLevels = new Set(['warn', 'error', 'fatal']); const logColors = { none: 'bgGray', @@ -13,95 +25,263 @@ const logColors = { info: 'bgBlue', warn: 'bgYellow', error: 'bgRed', - fatal: 'bgMagenta' + fatal: 'bgMagenta', }; -module.exports = function (config) { - config = config || {}; - var exports = {}; - - config.levels = config.levels || { - none: 99, - trace: 0, - debug: 1, - log: 2, - info: 3, - warn: 4, - error: 5, - fatal: 6 - }; - - config.level_abbr = config.level_abbr || { - trace: 'trc', - debug: 'dbg', - log: 'log', - info: 'inf', - warn: 'WRN', - error: 'ERR', - fatal: 'FTL' - }; - - config.filename = config.filename || __dirname + '/logs.log'; - - config.errorLevel = config.errorLevel || 'log'; - - var log_file = fs.createWriteStream(config.filename, { flags: 'a' }); - - exports.setLevel = function (errorLevel) { - config.errorLevel = errorLevel; - }; - - function snipsecret (data) { - for (var key in data) { - if (key.search(/secret/i) > -1) { - data[key] = 'XXXXXXXXXX'; - } +const namespaceColors = [ + 'black', + 'red', + 'yellow', + 'blue', + 'green', + 'magenta', + 'cyan', + 'white', + 'brightGreen', + 'gray', + 'brightRed', + 'brightYellow', + 'brightBlue', + 'brightMagenta', + 'brightCyan', + 'brightWhite', +]; + +const defaultLogLevels = { + none: 99, + trace: 0, + debug: 1, + log: 2, + info: 3, + warn: 4, + error: 5, + fatal: 6, +}; + +const defaultLogAbbr = { + trace: 'trc', + debug: 'dbg', + log: 'log', + info: 'inf', + warn: 'WRN', + error: 'ERR', + fatal: 'FTL', +}; + +class Logger { + constructor(options) { + this.levels = options.levels ?? defaultLogLevels; + this.levelAbbr = options.level_abbr ?? defaultLogAbbr; + + this.filename = options.filename ?? DEFAULT_LOG_PATH; + this.debugFilename = options.debugFilename; + this.isDebugFileEnabled = !!this.debugFilename; + + this.fileLogLevel = options.errorLevel ?? DEFAULT_FILE_LOG_LEVEL; + this.logLevel = options.consoleLogLevel; + + this.namespaceColorMap = {}; + + this.initWriteStreams(); + + if (this.isDebugFileEnabled) { + const oneDay = 24 * 60 * 60 * 1000; + setInterval(() => this.rotateDebugLogs(), oneDay); + this.rotateDebugLogs(); } - return data; } - Object.keys(config.levels).forEach(function (name) { - function log (message, data) { - var log = { - level: name, - timestamp: strftime('%F %T', new Date()) - }; + initWriteStreams() { + this.loggerWriteStream = fs.createWriteStream(this.filename, { flags: 'a' }); + this.debugWriteStream = this.isDebugFileEnabled + ? fs.createWriteStream(this.debugFilename, { flags: 'a' }) + : null; + } - if (message instanceof Error) { - log.message = message.stack; - } else { - log.message = message; - } + writeToFiles(logLevel, namespace, message, data) { + const timestamp = new Date().toISOString(); + const formatted = this.#formatLog({ + symbol: this.levelAbbr[logLevel], + timestamp, + message: `${namespace} | ${message}`, + data: data ? JSON.stringify(this.#hideSecret({ ...data })) : null, + }); + + if (this.levels[logLevel] >= this.levels[this.fileLogLevel]) { + this.loggerWriteStream.write(formatted + '\n'); + } - if (data && typeof data === 'object') { - log.data = JSON.stringify(snipsecret(data)); - } else { - log.data = data; + if (this.debugWriteStream && debugNamespaces.has(namespace)) { + this.debugWriteStream.write(formatted + '\n'); + } + } + + logMessage(logLevel, namespace, message, data) { + this.writeToFiles(logLevel, namespace, message, data); + this.print(logLevel, namespace, message, data); + } + + fatal(namespace, message, data) { + this.logMessage('fatal', namespace, message, data); + } + + error(namespace, message, data) { + this.logMessage('error', namespace, message, data); + } + + warn(namespace, message, data) { + this.logMessage('warn', namespace, message, data); + } + + info(namespace, message, data) { + this.logMessage('info', namespace, message, data); + } + + log(namespace, message, data) { + this.logMessage('info', namespace, message, data); + } + + debug(namespace, message, data) { + this.logMessage('debug', namespace, message, data); + } + + trace(namespace, message, data) { + this.logMessage('trace', namespace, message, data); + } + + print(logLevel, namespace, message, data) { + if (this.levels[logLevel] < this.levels[this.logLevel]) { + return; + } + + const consoleMethod = stdErrorLogLevels.has(logLevel) ? + 'error' : 'log'; + + const consoleArgs = this.#formatConsoleLog( + logLevel, + namespace, + message, + data, + ); + + console[consoleMethod](...consoleArgs); + } + + async rotateDebugLogs() { + if (!this.debugWriteStream) { + return; + } + + await new Promise((resolve) => this.debugWriteStream.end(resolve)); + + await this.cleanupOldLogs(); + this.initWriteStreams(); + } + + async cleanupOldLogs() { + try { + const retentionDays = 7; + const cutoff = Date.now() - retentionDays * 24 * 60 * 60 * 1000; + + if (!fs.existsSync(this.debugFilename)) { + return; } - log.symbol = config.level_abbr[log.level] ? config.level_abbr[log.level] : '???'; + const fd = fs.openSync(this.debugFilename, 'r'); + const buffer = Buffer.alloc(8192); + let bytesRead; + let offset = 0; + let foundOffset = 0; + let stop = false; + + while (!stop && (bytesRead = fs.readSync(fd, buffer, 0, buffer.length, offset)) > 0) { + const chunk = buffer.toString('utf8', 0, bytesRead); + const lines = chunk.split('\n'); + + for (const line of lines) { + const match = line.match(/(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z)/); + if (!match) { + offset += line.length + 1; + continue; + } - if (config.levels[config.errorLevel] <= config.levels[log.level]) { - if (log.data) { - log_file.write(util.format('[%s] %s | %s - %s\n', log.symbol, log.timestamp, log.message, log.data)); - } else { - log_file.write(util.format('[%s] %s | %s\n', log.symbol, log.timestamp, log.message)); + const timestamp = new Date(match[1]).getTime(); + if (timestamp >= cutoff) { + foundOffset = offset; + stop = true; + break; + } + offset += line.length + 1; } } - if (config.echo && config.levels[config.echo] <= config.levels[log.level]) { - const messageColor = logColors[log.level] ?? 'bgGray'; + fs.closeSync(fd); - if (log.data) { - console.log('[' + log.symbol[messageColor].black + ']', log.timestamp.grey, '|', log.message, '-', log.data); - } else { - console.log('[' + log.symbol[messageColor].black + ']', log.timestamp.grey, '|', log.message); - } + const tempFile = `${this.debugFilename}.tmp`; + + const readStream = fs.createReadStream(this.debugFilename, { start: foundOffset }); + const writeStream = fs.createWriteStream(tempFile, { flags: 'w' }); + + await new Promise((resolve, reject) => { + readStream.pipe(writeStream); + readStream.on('error', reject); + writeStream.on('error', reject); + writeStream.on('close', resolve); + }); + + fs.renameSync(tempFile, this.debugFilename); + } catch (error) { + console.error('cleanupOldLogs failed:', error); + } + } + + #pickColor(namespace) { + if (!this.namespaceColorMap[namespace]) { + let hash = 0; + + for (let i = 0; i < namespace.length; i++) { + hash = ((hash << 5) - hash) + namespace.charCodeAt(i); + hash |= 0; // Convert to 32bit integer } + + this.namespaceColorMap[namespace] = namespaceColors[Math.abs(hash) % namespaceColors.length]; } - exports[name] = log; - }); + return this.namespaceColorMap[namespace]; + } - return exports; -}; + #formatConsoleLog(logLevel, namespace, message, data) { + const symbol = this.levelAbbr[logLevel]; + const symbolColor = logColors[logLevel]; + + const namespaceColor = this.#pickColor(namespace); + + const args = [ + `[${colors[symbolColor](symbol)}]`, + colors[namespaceColor](namespace), + message, + ]; + + if (data) { + args.push(this.#hideSecret(data)); + } + + return args; + } + + #formatLog(log) { + const base = util.format('[%s] %s | %s', log.symbol, log.timestamp, log.message); + return log.data ? `${base} - ${log.data}` : base; + } + + #hideSecret(data) { + for (const key in data) { + if (key.includes('secret')) { + data[key] = 'XXXXXXXXXX'; + } + } + return data; + } +} + +module.exports = Logger; diff --git a/logic/account.js b/logic/account.js index 6ec2d164..f9441d65 100644 --- a/logic/account.js +++ b/logic/account.js @@ -430,12 +430,13 @@ function Account (db, schema, logger, cb) { * @return {setImmediateCallback} cb|error. */ Account.prototype.createTables = function (cb) { - var sql = new pgp.QueryFile(path.join(process.cwd(), 'sql', 'memoryTables.sql'), { minify: true }); + const filename = path.join(process.cwd(), 'sql', 'memoryTables.sql'); + var sql = new pgp.QueryFile(filename, { minify: true }); this.scope.db.query(sql).then(function () { return setImmediate(cb); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('accounts', `An error occurred while trying to create memory tables from ${filename}: ${err?.message || err}.`, err.stack); return setImmediate(cb, 'Account#createTables error'); }); }; @@ -466,7 +467,7 @@ Account.prototype.removeTables = function (cb) { this.scope.db.query(sqles.join('')).then(function () { return setImmediate(cb); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('accounts', `An error occurred while trying to delete memory tables: ${err?.message || err}.`, err.stack); return setImmediate(cb, 'Account#removeTables error'); }); }; @@ -625,7 +626,7 @@ Account.prototype.getAll = function (filter, fields, cb) { this.scope.db.query(query.toString() + ';').then(function (rows) { return setImmediate(cb, null, rows); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('accounts', `An error occurred while trying to query mem_accounts table: ${err?.message || err}.`, err.stack); return setImmediate(cb, 'Account#getAll error'); }); }; @@ -655,7 +656,7 @@ Account.prototype.set = function (address, rawFields, cb) { this.scope.db.none(query, fields.values).then(function () { return setImmediate(cb); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('accounts', `An error occurred while trying to set fields for the mem_accounts table: ${err?.message || err}.`, err.stack); return setImmediate(cb, 'Account#set error'); }); }; @@ -690,7 +691,7 @@ Account.prototype.merge = function (address, diff, cb) { case Number: if (isNaN(trueValue) || trueValue === Infinity) { const error = new Error(`Encountered unsafe number: ${trueValue}`) - library.logger.error(error.stack, diff); + library.logger.error('accounts', `${error.message}; While trying to merge: ${JSON.stringify(diff)}`, error.stack); return setImmediate(cb, error.message); } else if (Math.abs(trueValue) === trueValue && trueValue !== 0) { update[value] = knex.raw('?? + ?', [value, Math.floor(trueValue)]) @@ -897,7 +898,7 @@ Account.prototype.merge = function (address, diff, cb) { this.scope.db.none(queries).then(function () { return done(); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('account', `An error occurred while trying to merge account data: ${err?.message || err}`, err.stack); return done('Account#merge error'); }); }; @@ -917,7 +918,7 @@ Account.prototype.remove = function (address, cb) { this.scope.db.none(sql).then(function () { return setImmediate(cb, null, address); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('account', `An error occurred while trying to remove an account: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Account#remove error'); }); }; diff --git a/logic/broadcaster.js b/logic/broadcaster.js index 4e3b833e..3021b9ee 100644 --- a/logic/broadcaster.js +++ b/logic/broadcaster.js @@ -67,7 +67,7 @@ function Broadcaster (broadcasts, force, peers, transaction, logger) { function nextRelease (cb) { __private.releaseQueue(function (err) { if (err) { - library.logger.log('Broadcaster timer', err); + library.logger.log('broadcaster', 'Broadcaster timer error:', err); } return setImmediate(cb); }); @@ -110,7 +110,7 @@ Broadcaster.prototype.getPeers = function (params, cb) { } if (self.consensus !== undefined && originalLimit === constants.maxPeers) { - library.logger.info(['Broadhash consensus now', consensus, '%'].join(' ')); + library.logger.info('peers', ['Broadhash consensus now', consensus, '%'].join(' ')); self.consensus = consensus; } @@ -151,7 +151,7 @@ Broadcaster.prototype.broadcast = function (params, options, cb) { } }, function getFromPeer (peers, waterCb) { - library.logger.debug('Begin broadcast', options); + library.logger.debug('broadcaster', 'Begin broadcast', options); if (params.limit === self.config.peerLimit) { peers = peers.slice(0, self.config.broadcastLimit); @@ -162,12 +162,12 @@ Broadcaster.prototype.broadcast = function (params, options, cb) { modules.transport.getFromPeer(peer, options, function (err) { if (err) { - library.logger.debug('Failed to broadcast to peer: ' + peer.string, err); + library.logger.debug('broadcaster', 'Failed to broadcast to peer: ' + peer.string, err); } return setImmediate(eachLimitCb); }); }, function (err) { - library.logger.debug('End broadcast'); + library.logger.debug('broadcaster', 'End broadcast'); return setImmediate(waterCb, err, peers); }); } @@ -189,7 +189,7 @@ Broadcaster.prototype.maxRelays = function (object) { } if (Math.abs(object.relays) >= self.config.relayLimit) { - library.logger.debug('Broadcast relays exhausted', object); + library.logger.debug('broadcaster', 'Broadcast relays exhausted', object); return true; } else { object.relays++; // Next broadcast @@ -206,7 +206,7 @@ Broadcaster.prototype.maxRelays = function (object) { * @return {setImmediateCallback} cb */ __private.filterQueue = function (cb) { - library.logger.debug('Broadcasts before filtering: ' + self.queue.length); + library.logger.debug('broadcaster', 'Broadcasts queue size before filtering: ' + self.queue.length); async.filter(self.queue, function (broadcast, filterCb) { if (broadcast.options.immediate) { @@ -220,7 +220,7 @@ __private.filterQueue = function (cb) { }, function (err, broadcasts) { self.queue = broadcasts; - library.logger.debug('Broadcasts after filtering: ' + self.queue.length); + library.logger.debug('broadcaster', 'Broadcasts queue size after filtering: ' + self.queue.length); return setImmediate(cb); }); }; @@ -293,10 +293,10 @@ __private.squashQueue = function (broadcasts) { * @return {setImmediateCallback} cb */ __private.releaseQueue = function (cb) { - library.logger.debug('Releasing enqueued broadcasts'); + library.logger.debug('broadcaster', 'Releasing enqueued broadcasts'); if (!self.queue.length) { - library.logger.debug('Queue empty'); + library.logger.debug('broadcaster', 'Queue empty'); return setImmediate(cb); } @@ -322,9 +322,9 @@ __private.releaseQueue = function (cb) { } ], function (err, broadcasts) { if (err) { - library.logger.debug('Failed to release broadcast queue', err); + library.logger.debug('broadcaster', 'Failed to release broadcast queue', err); } else { - library.logger.debug('Broadcasts released: ' + broadcasts.length); + library.logger.debug('broadcaster', 'Broadcasts released: ' + broadcasts.length); } return setImmediate(cb); }); diff --git a/logic/peers.js b/logic/peers.js index f7eb057d..8006d376 100644 --- a/logic/peers.js +++ b/logic/peers.js @@ -85,9 +85,9 @@ Peers.prototype.upsert = function (peer, insertOnly) { if (!_.isEmpty(modules.peers.acceptable([peer]))) { peer.updated = Date.now(); __private.peers[peer.string] = peer; - library.logger.info('Added new peer', peer.string); + library.logger.info('peers', 'Added new peer', peer.string); } else { - library.logger.debug('Rejecting unacceptable peer', peer.string); + library.logger.debug('peers', 'Rejecting unacceptable peer', peer.string); } }; @@ -108,16 +108,16 @@ Peers.prototype.upsert = function (peer, insertOnly) { __private.peers[peer.string].update(peer); if (Object.keys(diff).length) { - library.logger.debug('Updated peer ' + peer.string, diff); + library.logger.debug('peers', 'Updated peer ' + peer.string, diff); } else { - library.logger.trace('Peer not changed', peer.string); + library.logger.trace('peers', 'Peer not changed', peer.string); } }; peer = self.create(peer); if (!peer.string) { - library.logger.warn('Upsert invalid peer rejected', { peer: peer }); + library.logger.warn('peers', 'Upsert invalid peer rejected', { peer: peer }); return false; } @@ -152,7 +152,7 @@ Peers.prototype.upsert = function (peer, insertOnly) { } }); - library.logger.trace('Peer stats', { total: cnt_total, alive: cnt_active, empty_height: cnt_empty_height, empty_broadhash: cnt_empty_broadhash }); + library.logger.trace('peers', 'Peer stats', { total: cnt_total, alive: cnt_active, empty_height: cnt_empty_height, empty_broadhash: cnt_empty_broadhash }); return true; }; @@ -166,13 +166,13 @@ Peers.prototype.remove = function (peer) { peer = self.create(peer); // Remove peer if exists if (self.exists(peer)) { - library.logger.info('Removed peer', peer.string); - library.logger.debug('Removed peer', { peer: __private.peers[peer.string] }); + library.logger.info('peers', 'Removed peer', peer.string); + library.logger.debug('peers', 'Removed peer', { peer: __private.peers[peer.string] }); __private.peers[peer.string] = null; // Possible memory leak prevention delete __private.peers[peer.string]; return true; } else { - library.logger.debug('Failed to remove peer', { err: 'AREMOVED', peer: peer }); + library.logger.debug('peers', 'Failed to remove peer', { err: 'AREMOVED', peer: peer }); return false; } }; @@ -185,7 +185,7 @@ Peers.prototype.remove = function (peer) { */ Peers.prototype.recordRequest = function (data, error) { if (!self.exists(data)) { - library.logger.debug('Failed to update request success rate for peer', { + library.logger.debug('peers', 'Failed to update request success rate for peer', { peer: data, err: error, }); diff --git a/logic/round.js b/logic/round.js index 2a3653dc..5fadc3c1 100644 --- a/logic/round.js +++ b/logic/round.js @@ -158,7 +158,7 @@ Round.prototype.truncateBlocks = function () { * @return {function} Promise */ Round.prototype.restoreRoundSnapshot = function () { - this.scope.library.logger.debug('Restoring mem_round snapshot...'); + this.scope.library.logger.debug('rounds', 'Restoring mem_round snapshot...'); return this.t.none(sql.restoreRoundSnapshot); }; @@ -168,7 +168,7 @@ Round.prototype.restoreRoundSnapshot = function () { * @return {function} Promise */ Round.prototype.restoreVotesSnapshot = function () { - this.scope.library.logger.debug('Restoring mem_accounts.vote snapshot...'); + this.scope.library.logger.debug('rounds', 'Restoring mem_accounts.vote snapshot...'); return this.t.none(sql.restoreVotesSnapshot); }; @@ -190,7 +190,7 @@ Round.prototype.applyRound = function () { var delegate = this.scope.roundDelegates[i]; var changes = roundChanges.at(i); - this.scope.library.logger.trace('Delegate changes', { delegate: delegate, changes: changes }); + this.scope.library.logger.trace('rounds', 'Delegate changes', { delegate: delegate, changes: changes }); queries.push(this.scope.modules.accounts.mergeAccountAndGet({ publicKey: delegate, @@ -214,7 +214,7 @@ Round.prototype.applyRound = function () { if (changes.feesRemaining > 0) { var feesRemaining = (this.scope.backwards ? -changes.feesRemaining : changes.feesRemaining); - this.scope.library.logger.trace('Fees remaining', { index: remainderIndex, delegate: remainderDelegate, fees: feesRemaining }); + this.scope.library.logger.trace('rounds', 'Fees remaining', { index: remainderIndex, delegate: remainderDelegate, fees: feesRemaining }); queries.push(this.scope.modules.accounts.mergeAccountAndGet({ publicKey: remainderDelegate, @@ -226,7 +226,7 @@ Round.prototype.applyRound = function () { })); } - this.scope.library.logger.trace('Applying round', queries); + this.scope.library.logger.trace('rounds', 'Applying round', queries); if (queries.length > 0) { return this.t.none(queries.join('')); diff --git a/logic/transaction.js b/logic/transaction.js index cb2c0229..cc343190 100644 --- a/logic/transaction.js +++ b/logic/transaction.js @@ -378,7 +378,11 @@ Transaction.prototype.countById = function (trs, cb) { }).then(function (row) { return setImmediate(cb, null, row.count); }).catch(function (err) { - this.scope.logger.error(err.stack); + this.scope.logger.error( + 'transactions', + `An error occurred while fetching transactions count by ID: ${err?.message || err}`, + err.stack, + ); return setImmediate(cb, 'Transaction#countById error'); }); }; @@ -459,7 +463,11 @@ Transaction.prototype.process = function (trs, sender, requester, cb) { try { txId = this.getId(trs); } catch (e) { - this.scope.logger.error(e.stack); + this.scope.logger.error( + 'transactions', + `Failed to get transaction ID: ${err?.message || err}`, + { trs, stack: err.stack }, + ); return setImmediate(cb, 'Failed to get transaction id'); } @@ -537,8 +545,7 @@ Transaction.prototype.verify = function (trs, sender, requester, cb) { err = ['Invalid sender public key:', trs.senderPublicKey, 'expected:', sender.publicKey].join(' '); if (exceptions.senderPublicKey.indexOf(trs.id) > -1) { - this.scope.logger.debug(err); - this.scope.logger.debug(JSON.stringify(trs)); + this.scope.logger.debug('transactions', err, trs); } else { return setImmediate(cb, err); } @@ -584,7 +591,11 @@ Transaction.prototype.verify = function (trs, sender, requester, cb) { valid = false; valid = this.verifySignature(trs, (trs.requesterPublicKey || trs.senderPublicKey), trs.signature); } catch (e) { - this.scope.logger.error(e.stack); + this.scope.logger.error( + 'transactions', + 'An error occurred while trying to verify signature for a transaction.', + { trs, stack: e.stack }, + ); return setImmediate(cb, e.toString()); } @@ -592,8 +603,7 @@ Transaction.prototype.verify = function (trs, sender, requester, cb) { err = 'Failed to verify signature'; if (exceptions.signatures.indexOf(trs.id) > -1) { - this.scope.logger.debug(err); - this.scope.logger.debug(JSON.stringify(trs)); + this.scope.logger.debug('transactions', err, trs); valid = true; err = null; } else { @@ -654,8 +664,7 @@ Transaction.prototype.verify = function (trs, sender, requester, cb) { var fee = __private.types[trs.type].calculateFee.call(this, trs, sender) || false; if (!fee || trs.fee !== fee) { if (exceptions.fee.indexOf(trs.id) > -1) { - this.scope.logger.debug('Invalid transaction fee'); - this.scope.logger.debug(JSON.stringify(trs)); + this.scope.logger.debug('transactions', 'Invalid transaction fee', trs); } else { return setImmediate(cb, 'Invalid transaction fee'); } @@ -822,17 +831,15 @@ Transaction.prototype.apply = function (trs, block, sender, cb) { amount = amount.toNumber(); - this.scope.logger.trace('Logic/Transaction->apply', { - sender: sender.address, + const diff = { balance: -amount, blockId: block.id, round: modules.rounds.calc(block.height) - }); - this.scope.account.merge(sender.address, { - balance: -amount, - blockId: block.id, - round: modules.rounds.calc(block.height) - }, function (err, sender) { + }; + + this.scope.logger.trace('transactions', 'Logic/Transaction->apply', diff); + + this.scope.account.merge(sender.address, diff, function (err, sender) { if (err) { return setImmediate(cb, err); } @@ -872,17 +879,15 @@ Transaction.prototype.undo = function (trs, block, sender, cb) { var amount = new bignum(trs.amount.toString()); amount = amount.plus(trs.fee.toString()).toNumber(); - this.scope.logger.trace('Logic/Transaction->undo', { - sender: sender.address, + const diff = { balance: amount, blockId: block.id, round: modules.rounds.calc(block.height) - }); - this.scope.account.merge(sender.address, { - balance: amount, - blockId: block.id, - round: modules.rounds.calc(block.height) - }, function (err, sender) { + }; + + this.scope.logger.trace('transactions', 'Logic/Transaction->undo', diff); + + this.scope.account.merge(sender.address, diff, function (err, sender) { if (err) { return setImmediate(cb, err); } @@ -943,7 +948,11 @@ Transaction.prototype.applyUnconfirmed = function (trs, sender, requester, cb) { } this.scope.clientWs.emit(new_trs); }).catch((err) => { - this.scope.logger.error(err.stack); + this.scope.logger.error( + 'ws-client-server', + 'An error occurred while trying to retrieve publicKey for a recipient', + { new_trs, stack: err.stack } + ); }); } else { this.scope.clientWs.emit(new_trs); @@ -1297,7 +1306,7 @@ Transaction.prototype.dbRead = function (raw) { * @param {Object} __modules */ Transaction.prototype.bindModules = function (__modules) { - this.scope.logger.trace('Logic/Transaction->bindModules'); + this.scope.logger.trace('transactions', 'Logic/Transaction->bindModules'); modules = { rounds: __modules.rounds }; diff --git a/logic/transactionPool.js b/logic/transactionPool.js index efb03bc1..73f82828 100644 --- a/logic/transactionPool.js +++ b/logic/transactionPool.js @@ -55,7 +55,7 @@ function TransactionPool (broadcastInterval, releaseLimit, maxTxsPerQueue, trans function nextBundle (cb) { self.processBundled(function (err) { if (err) { - library.logger.log('Bundled transaction timer', err); + library.logger.log('transaction-pool', 'Bundled transaction timer', err); } return setImmediate(cb); }); @@ -67,7 +67,7 @@ function TransactionPool (broadcastInterval, releaseLimit, maxTxsPerQueue, trans function nextExpiry (cb) { self.expireTransactions(function (err) { if (err) { - library.logger.log('Transaction expiry timer', err); + library.logger.log('transaction-pool', 'Transaction expiry timer', err); } return setImmediate(cb); }); @@ -377,13 +377,13 @@ TransactionPool.prototype.processBundled = function (cb) { __private.processVerifyTransaction(transaction, true, function (err, sender) { if (err) { - library.logger.debug('Failed to process / verify bundled transaction: ' + transaction.id, err); + library.logger.debug('transaction-pool', 'Failed to process / verify bundled transaction: ' + transaction.id, err); self.removeUnconfirmedTransaction(transaction); return setImmediate(eachSeriesCb); } else { self.queueTransaction(transaction, function (err) { if (err) { - library.logger.debug('Failed to queue bundled transaction: ' + transaction.id, err); + library.logger.debug('transaction-pool', 'Failed to queue bundled transaction: ' + transaction.id, err); } return setImmediate(eachSeriesCb); }); @@ -500,7 +500,7 @@ TransactionPool.prototype.undoUnconfirmedList = function (cb) { ids.push(transaction.id); modules.transactions.undoUnconfirmed(transaction, function (err) { if (err) { - library.logger.error('Failed to undo unconfirmed transaction: ' + transaction.id, err); + library.logger.error('transaction-pool', 'Failed to undo unconfirmed transaction: ' + transaction.id, err); self.removeUnconfirmedTransaction(transaction.id); } return setImmediate(eachSeriesCb); @@ -556,7 +556,7 @@ TransactionPool.prototype.fillPool = function (cb) { if (modules.loader.syncing()) { return setImmediate(cb); } var unconfirmedCount = self.countUnconfirmed(); - library.logger.debug('Transaction pool size: ' + unconfirmedCount); + library.logger.debug('transaction-pool', 'Transaction pool size: ' + unconfirmedCount); if (unconfirmedCount >= constants.maxTxsPerBlock) { return setImmediate(cb); @@ -700,13 +700,13 @@ __private.applyUnconfirmedList = function (transactions, cb) { } __private.processVerifyTransaction(transaction, false, function (err, sender) { if (err) { - library.logger.error('Failed to process / verify unconfirmed transaction: ' + transaction.id, err); + library.logger.error('transaction-pool', 'Failed to process / verify unconfirmed transaction: ' + transaction.id, err); self.removeUnconfirmedTransaction(transaction.id); return setImmediate(eachSeriesCb); } modules.transactions.applyUnconfirmed(transaction, sender, function (err) { if (err) { - library.logger.error('Failed to apply unconfirmed transaction: ' + transaction.id, err); + library.logger.error('transaction-pool', 'Failed to apply unconfirmed transaction: ' + transaction.id, err); self.removeUnconfirmedTransaction(transaction.id); } return setImmediate(eachSeriesCb); @@ -757,7 +757,7 @@ __private.expireTransactions = function (transactions, parentIds, cb) { if (seconds > timeOut) { ids.push(transaction.id); self.removeUnconfirmedTransaction(transaction.id); - library.logger.info('Expired transaction: ' + transaction.id + ' received at: ' + transaction.receivedAt.toUTCString()); + library.logger.info('transaction-pool', 'Expired transaction: ' + transaction.id + ' received at: ' + transaction.receivedAt.toUTCString()); return setImmediate(eachSeriesCb); } else { return setImmediate(eachSeriesCb); diff --git a/logic/vote.js b/logic/vote.js index eb04cfdb..9cc6f066 100644 --- a/logic/vote.js +++ b/logic/vote.js @@ -173,8 +173,7 @@ Vote.prototype.verifyVote = function (vote, cb) { Vote.prototype.checkConfirmedDelegates = function (trs, cb) { modules.delegates.checkConfirmedDelegates(trs.senderPublicKey, trs.asset.votes, function (err) { if (err && exceptions.votes.indexOf(trs.id) > -1) { - library.logger.debug(err); - library.logger.debug(JSON.stringify(trs)); + library.logger.debug('votes', `Ignored known vote exception for transaction ${trs.id}: ${err}`, trs); err = null; } @@ -193,8 +192,7 @@ Vote.prototype.checkConfirmedDelegates = function (trs, cb) { Vote.prototype.checkUnconfirmedDelegates = function (trs, cb) { modules.delegates.checkUnconfirmedDelegates(trs.senderPublicKey, trs.asset.votes, function (err) { if (err && exceptions.votes.indexOf(trs.id) > -1) { - library.logger.debug(err); - library.logger.debug(JSON.stringify(trs)); + library.logger.debug('votes', `Ignored known vote exception for unconfirmed transaction ${trs.id}: ${err}`, trs); err = null; } diff --git a/modules/blocks.js b/modules/blocks.js index 086696cf..14b65f28 100644 --- a/modules/blocks.js +++ b/modules/blocks.js @@ -191,7 +191,7 @@ Blocks.prototype.cleanup = function (cb) { // Module is not ready, repeat setImmediate(function nextWatch () { if (__private.isActive) { - library.logger.info('Waiting for block processing to finish...'); + library.logger.info('cleanup', 'Waiting for block processing to finish...'); setTimeout(nextWatch, 10000); // 10 sec } else { return setImmediate(cb); diff --git a/modules/blocks/api.js b/modules/blocks/api.js index 2c164c4d..b802e62a 100644 --- a/modules/blocks/api.js +++ b/modules/blocks/api.js @@ -35,7 +35,7 @@ function API (logger, db, block, schema, dbSequence) { }; self = this; - library.logger.trace('Blocks->API: Submodule initialized.'); + library.logger.trace('api-blocks', 'Blocks->API: Submodule initialized.'); return self; } @@ -62,7 +62,7 @@ __private.getById = function (id, cb) { return setImmediate(cb, null, block); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-blocks', `Failed to get block ${id} from database: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Blocks#getById error'); }); }; @@ -168,7 +168,7 @@ __private.list = function (filter, cb) { return setImmediate(cb, null, { blocks }); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-blocks', `Failed to get blocks from database: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Blocks#list error'); }); }; @@ -314,7 +314,7 @@ API.prototype.getStatus = function (req, cb) { * @param {modules} scope Exposed modules */ API.prototype.onBind = function (scope) { - library.logger.trace('Blocks->API: Shared modules bind.'); + library.logger.trace('api-blocks', 'Blocks->API: Shared modules bind.'); modules = { blocks: scope.blocks, system: scope.system diff --git a/modules/blocks/chain.js b/modules/blocks/chain.js index 09539e1e..f1654ef6 100644 --- a/modules/blocks/chain.js +++ b/modules/blocks/chain.js @@ -37,7 +37,7 @@ function Chain (logger, block, transaction, db, genesisblock, bus, balancesSeque }; self = this; - library.logger.trace('Blocks->Chain: Submodule initialized.'); + library.logger.trace('blocks', 'Blocks->Chain: Submodule initialized.'); return self; } @@ -65,7 +65,7 @@ Chain.prototype.saveGenesisBlock = function (cb) { return setImmediate(cb); } }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('blocks', `An error occurred while trying to get genesis block id: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Blocks#saveGenesisBlock error'); }); }; @@ -102,7 +102,7 @@ Chain.prototype.saveBlock = function (block, cb) { // Execute afterSave for transactions return __private.afterSave(block, cb); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('blocks', `An error occurred while trying to save block ${block?.id || block}: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Blocks#saveBlock error'); }); }; @@ -203,7 +203,7 @@ Chain.prototype.deleteBlock = function (blockId, cb) { library.db.none(sql.deleteBlock, { id: blockId }).then(function () { return setImmediate(cb); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('blocks', `An error occurred while trying to delete block ${blockId}: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Blocks#deleteBlock error'); }); }; @@ -224,7 +224,7 @@ Chain.prototype.deleteAfterBlock = function (blockId, cb) { library.db.query(sql.deleteAfterBlock, { id: blockId }).then(function (res) { return setImmediate(cb, null, res); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('blocks', `An error occurred while trying to delete all blocks with heigh greater than ${blockId} block: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Blocks#deleteAfterBlock error'); }); }; @@ -353,7 +353,7 @@ Chain.prototype.applyBlock = function (block, broadcast, cb, saveBlock) { modules.transactions.undoUnconfirmedList(function (err, ids) { if (err) { // Fatal error, memory tables will be inconsistent - library.logger.error('Failed to undo unconfirmed list', err); + library.logger.error('transactions', 'Failed to undo unconfirmed list', err); return process.exit(0); } else { @@ -371,8 +371,7 @@ Chain.prototype.applyBlock = function (block, broadcast, cb, saveBlock) { modules.transactions.applyUnconfirmed(transaction, sender, function (err) { if (err) { err = ['Failed to apply transaction:', transaction.id, '-', err].join(' '); - library.logger.error(err); - library.logger.error('Transaction', transaction); + library.logger.error('transactions', err, transaction); return setImmediate(eachSeriesCb, err); } @@ -420,8 +419,7 @@ Chain.prototype.applyBlock = function (block, broadcast, cb, saveBlock) { if (err) { // Fatal error, memory tables will be inconsistent err = ['Failed to apply transaction:', transaction.id, '-', err].join(' '); - library.logger.error(err); - library.logger.error('Transaction', transaction); + library.logger.error('transactions', err, transaction); return process.exit(0); } @@ -430,8 +428,7 @@ Chain.prototype.applyBlock = function (block, broadcast, cb, saveBlock) { if (err) { // Fatal error, memory tables will be inconsistent err = ['Failed to apply transaction:', transaction.id, '-', err].join(' '); - library.logger.error(err); - library.logger.error('Transaction', transaction); + library.logger.error('transactions', err, transaction); return process.exit(0); } @@ -453,13 +450,12 @@ Chain.prototype.applyBlock = function (block, broadcast, cb, saveBlock) { self.saveBlock(block, function (err) { if (err) { // Fatal error, memory tables will be inconsistent - library.logger.error('Failed to save block...'); - library.logger.error('Block', block); + library.logger.error('blocks', 'Failed to save a block.', block); return process.exit(0); } - library.logger.debug('Block applied correctly with ' + block.transactions.length + ' transactions'); + library.logger.debug('blocks', 'Block applied correctly with ' + block.transactions.length + ' transactions'); library.bus.message('newBlock', block, broadcast); // DATABASE write. Update delegates accounts @@ -491,7 +487,7 @@ Chain.prototype.applyBlock = function (block, broadcast, cb, saveBlock) { // Finish here if snapshotting. // FIXME: Not the best place to do that if (err === 'Snapshot finished') { - library.logger.info(err); + library.logger.info('snapshot', err); process.emit('SIGTERM'); } @@ -546,7 +542,7 @@ __private.popLastBlock = function (oldLastBlock, cb) { }, function (err) { if (err) { // Fatal error, memory tables will be inconsistent - library.logger.error('Failed to undo transactions', err); + library.logger.error('transactions', 'Failed to undo transactions', err); return process.exit(0); } @@ -556,7 +552,7 @@ __private.popLastBlock = function (oldLastBlock, cb) { modules.rounds.backwardTick(oldLastBlock, previousBlock, function (err) { if (err) { // Fatal error, memory tables will be inconsistent - library.logger.error('Failed to perform backwards tick', err); + library.logger.error('transactions', 'Failed to perform backwards tick', err); return process.exit(0); } @@ -566,7 +562,7 @@ __private.popLastBlock = function (oldLastBlock, cb) { self.deleteBlock(oldLastBlock.id, function (err) { if (err) { // Fatal error, memory tables will be inconsistent - library.logger.error('Failed to delete block', err); + library.logger.error('blocks', 'Failed to delete block', err); return process.exit(0); } @@ -592,7 +588,7 @@ __private.popLastBlock = function (oldLastBlock, cb) { */ Chain.prototype.deleteLastBlock = function (cb) { var lastBlock = modules.blocks.lastBlock.get(); - library.logger.warn('Deleting last block', lastBlock); + library.logger.warn('blocks', 'Deleting last block', lastBlock); if (lastBlock.height === 1) { return setImmediate(cb, 'Cannot delete genesis block'); @@ -601,7 +597,7 @@ Chain.prototype.deleteLastBlock = function (cb) { // Delete last block, replace last block with previous block, undo things __private.popLastBlock(lastBlock, function (err, newLastBlock) { if (err) { - library.logger.error('Error deleting last block', lastBlock); + library.logger.error('blocks', 'An error occurred while deleting last block', lastBlock); } else { // Replace last block with previous lastBlock = modules.blocks.lastBlock.set(newLastBlock); @@ -621,12 +617,12 @@ Chain.prototype.deleteLastBlock = function (cb) { * @return {Object} cb.err Error if occurred */ Chain.prototype.recoverChain = function (cb) { - library.logger.warn('Chain comparison failed, starting recovery'); + library.logger.warn('blocks', 'Chain comparison failed, deleting last block'); self.deleteLastBlock(function (err, newLastBlock) { if (err) { - library.logger.error('Recovery failed'); + library.logger.error('blocks', 'Recovery failed'); } else { - library.logger.info('Recovery complete, new last block', newLastBlock.id); + library.logger.info('blocks', 'Last block deleted, new last block', newLastBlock.id); } return setImmediate(cb, err); }); @@ -641,7 +637,7 @@ Chain.prototype.recoverChain = function (cb) { * @param {modules} scope Exposed modules */ Chain.prototype.onBind = function (scope) { - library.logger.trace('Blocks->Chain: Shared modules bind.'); + library.logger.trace('blocks', 'Blocks->Chain: Shared modules bind.'); modules = { accounts: scope.accounts, blocks: scope.blocks, diff --git a/modules/blocks/process.js b/modules/blocks/process.js index b0e02349..a2716871 100644 --- a/modules/blocks/process.js +++ b/modules/blocks/process.js @@ -41,7 +41,7 @@ function Process (logger, block, peers, transaction, schema, db, dbSequence, seq }; self = this; - library.logger.trace('Blocks->Process: Submodule initialized.'); + library.logger.trace('blocks', 'Blocks->Process: Submodule initialized.'); return self; } @@ -115,7 +115,7 @@ Process.prototype.getCommonBlock = function (peer, height, cb) { } }).catch(function (err) { // SQL error occurred - library.logger.error(err.stack); + library.logger.error('blocks', `Failed to get common block: ${err?.message || err}`, err.stack); return setImmediate(waterCb, 'Blocks#getCommonBlock error'); }); } @@ -150,7 +150,7 @@ Process.prototype.loadBlocksOffset = function (limit, offset, verify, cb) { var newLimit = limit + (offset || 0); var params = { limit: newLimit, offset: offset || 0 }; - library.logger.debug('Loading blocks offset', { limit: limit, offset: offset, verify: verify }); + library.logger.debug('loader', 'Loading blocks offset', { limit: limit, offset: offset, verify: verify }); // Execute in sequence via dbSequence library.dbSequence.add(function (cb) { // Loads full blocks from database @@ -165,14 +165,14 @@ Process.prototype.loadBlocksOffset = function (limit, offset, verify, cb) { return setImmediate(cb); } - library.logger.debug('Processing block', block.id); + library.logger.debug('loader', 'Processing block', block.id); if (verify && block.id !== library.genesisblock.block.id) { // Sanity check of the block, if values are coherent. // No access to database. var check = modules.blocks.verify.verifyBlock(block); if (!check.verified) { - library.logger.error(['Block', block.id, 'verification failed'].join(' '), check.errors.join(', ')); + library.logger.error('loader', ['Block', block.id, 'verification failed'].join(' '), check.errors.join(', ')); // Return first error from checks return setImmediate(cb, check.errors[0]); } @@ -191,7 +191,7 @@ Process.prototype.loadBlocksOffset = function (limit, offset, verify, cb) { return setImmediate(cb, err, modules.blocks.lastBlock.get()); }); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('loader', `Failed to get blocks offset: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Blocks#loadBlocksOffset error'); }); }, cb); @@ -215,7 +215,7 @@ Process.prototype.loadBlocksFromPeer = function (peer, cb) { // Normalize peer peer = library.logic.peers.create(peer); - library.logger.info('Loading blocks from: ' + peer.string); + library.logger.info('loader', 'Loading blocks from: ' + peer.string); function getFromPeer (seriesCb) { // Ask remote peer for blocks @@ -270,11 +270,11 @@ Process.prototype.loadBlocksFromPeer = function (peer, cb) { if (!err) { // Update last valid block lastValidBlock = block; - library.logger.info(['Block', block.id, 'loaded from:', peer.string].join(' '), 'height: ' + block.height); + library.logger.info('loader', ['Block', block.id, 'loaded from:', peer.string].join(' '), 'height: ' + block.height); } else { var id = (block ? block.id : 'null'); - library.logger.debug('Block processing failed', { id: id, err: err.toString(), module: 'blocks', block: block }); + library.logger.debug('loader', 'Block processing failed', { id: id, err: err.toString(), module: 'blocks', block: block }); } return seriesCb(err); }, true); @@ -340,7 +340,7 @@ Process.prototype.generateBlock = function (keypair, timestamp, cb) { transactions: ready }); } catch (e) { - library.logger.error(e.stack); + library.logger.error('loader', `Failed to generate a new block: ${e?.message || e}`, e.stack); return setImmediate(cb, e); } @@ -370,7 +370,7 @@ Process.prototype.onReceiveBlock = function (block) { // Do not receive new blocks as client is not ready const syncPending = !modules.loader.isReadyToSync() || modules.loader.syncing(); if (!__private.loaded || syncPending || modules.rounds.ticking()) { - library.logger.debug('Client not ready to receive block', block.id); + library.logger.debug('loader', 'Client not ready to receive block', block.id); return setImmediate(cb); } @@ -389,11 +389,11 @@ Process.prototype.onReceiveBlock = function (block) { return __private.receiveForkFive(block, lastBlock, cb); } else { if (block.id === lastBlock.id) { - library.logger.debug('Block already processed', block.id); + library.logger.debug('loader', 'Block already processed', block.id); } else if (block.height < lastBlock.height) { - library.logger.debug('Received old block', block.id); + library.logger.debug('loader', 'Received old block', block.id); } else { - library.logger.warn([ + library.logger.warn('loader', [ 'Discarded the received block because it does not match the current chain.', 'Blockchain Last Block:', @@ -427,7 +427,7 @@ Process.prototype.onReceiveBlock = function (block) { * @param {Function} cb Callback function */ __private.receiveBlock = function (block, cb) { - library.logger.info([ + library.logger.info('loader', [ 'Received new block id:', block.id, 'height:', block.height, 'round:', modules.rounds.calc(block.height), @@ -458,10 +458,10 @@ __private.receiveForkOne = function (block, lastBlock, cb) { // Keep the oldest block, or if both have same age, keep block with lower id if (block.timestamp > lastBlock.timestamp || (block.timestamp === lastBlock.timestamp && block.id > lastBlock.id)) { - library.logger.info('Last block stands'); + library.logger.info('loader', 'Last block stands after processing fork cause 1'); return setImmediate(cb); // Discard received block } else { - library.logger.info('Last block and parent loses'); + library.logger.info('loader', 'Last block and parent loses after processing fork cause 1'); async.series([ function (seriesCb) { try { @@ -476,7 +476,7 @@ __private.receiveForkOne = function (block, lastBlock, cb) { var check = modules.blocks.verify.verifyReceipt(tmp_block); if (!check.verified) { - library.logger.error(['Block', tmp_block.id, 'verification failed'].join(' '), check.errors.join(', ')); + library.logger.error('loader', ['Block', tmp_block.id, 'verification failed'].join(' '), check.errors.join(', ')); // Return first error from checks return setImmediate(seriesCb, check.errors[0]); } else { @@ -488,7 +488,7 @@ __private.receiveForkOne = function (block, lastBlock, cb) { modules.blocks.chain.deleteLastBlock ], function (err) { if (err) { - library.logger.error('Fork recovery failed', err); + library.logger.error('loader', 'Fork cause 1 recovery failed', err); } return setImmediate(cb, err); }); @@ -512,15 +512,15 @@ __private.receiveForkFive = function (block, lastBlock, cb) { // Check if delegate forged on more than one node if (block.generatorPublicKey === lastBlock.generatorPublicKey) { - library.logger.warn('Delegate forging on multiple nodes', block.generatorPublicKey); + library.logger.warn('loader', 'Delegate forging on multiple nodes', block.generatorPublicKey); } // Keep the oldest block, or if both have same age, keep block with lower id if (block.timestamp > lastBlock.timestamp || (block.timestamp === lastBlock.timestamp && block.id > lastBlock.id)) { - library.logger.info('Last block stands'); + library.logger.info('loader', 'Last block stands after processing fork 5'); return setImmediate(cb); // Discard received block } else { - library.logger.info('Last block loses'); + library.logger.info('loader', 'Last block loses after processing fork 5'); async.series([ function (seriesCb) { try { @@ -535,7 +535,7 @@ __private.receiveForkFive = function (block, lastBlock, cb) { var check = modules.blocks.verify.verifyReceipt(tmp_block); if (!check.verified) { - library.logger.error(['Block', tmp_block.id, 'verification failed'].join(' '), check.errors.join(', ')); + library.logger.error('loader', ['Block', tmp_block.id, 'verification failed'].join(' '), check.errors.join(', ')); // Return first error from checks return setImmediate(seriesCb, check.errors[0]); } else { @@ -552,7 +552,7 @@ __private.receiveForkFive = function (block, lastBlock, cb) { } ], function (err) { if (err) { - library.logger.error('Fork recovery failed', err); + library.logger.error('loader', 'Fork cause 5 recovery failed', err); } return setImmediate(cb, err); }); @@ -571,7 +571,7 @@ __private.receiveForkFive = function (block, lastBlock, cb) { * @param {modules} scope Exposed modules */ Process.prototype.onBind = function (scope) { - library.logger.trace('Blocks->Process: Shared modules bind.'); + library.logger.trace('loader', 'Blocks->Process: Shared modules bind.'); modules = { accounts: scope.accounts, blocks: scope.blocks, diff --git a/modules/blocks/utils.js b/modules/blocks/utils.js index 7d3f8e27..7b76b422 100644 --- a/modules/blocks/utils.js +++ b/modules/blocks/utils.js @@ -33,7 +33,7 @@ function Utils (logger, block, transaction, db, dbSequence, genesisblock) { }; self = this; - library.logger.trace('Blocks->Utils: Submodule initialized.'); + library.logger.trace('blocks', 'Blocks->Utils: Submodule initialized.'); return self; } @@ -160,7 +160,7 @@ Utils.prototype.loadLastBlock = function (cb) { modules.blocks.lastBlock.set(block); return setImmediate(cb, null, block); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('blocks', `Failed to get last block: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Blocks#loadLastBlock error'); }); }, cb); @@ -221,7 +221,7 @@ Utils.prototype.getIdSequence = function (height, cb) { return setImmediate(cb, null, { firstHeight: rows[0].height, ids: ids.join(',') }); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('blocks', `Failed to get id sequence ${height}: ${err?.message || err}`,err.stack); return setImmediate(cb, 'Blocks#getIdSequence error'); }); }; @@ -278,7 +278,7 @@ Utils.prototype.loadBlocksData = function (filter, options, cb) { return setImmediate(cb, null, rows); }); }).catch(function (err ) { - library.logger.error(err.stack); + library.logger.error('blocks', `Failed to get height by last id ${filter.lastid}: ${err?.message || err}`,err.stack); return setImmediate(cb, 'Blocks#loadBlockData error'); }); }, cb); @@ -325,7 +325,7 @@ Utils.prototype.getBlockProgressLogger = function (transactionsCount, logsFreque * Logs the progress */ this.log = function () { - library.logger.info(msg, ((this.applied / this.target) * 100).toPrecision(4) + ' %' + ': applied ' + this.applied + ' of ' + this.target + ' transactions' ); + library.logger.info('blocks', msg, ((this.applied / this.target) * 100).toPrecision(4) + ' %' + ': applied ' + this.applied + ' of ' + this.target + ' transactions' ); }; } @@ -373,7 +373,7 @@ Utils.prototype.aggregateBlocksReward = function (filter, cb) { data = { fees: data.fees || '0', rewards: data.rewards || '0', count: data.count || 0 }; return setImmediate(cb, null, data); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('blocks', `Failed to aggregate blocks reward: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Blocks#aggregateBlocksReward error'); }); }; @@ -384,7 +384,7 @@ Utils.prototype.aggregateBlocksReward = function (filter, cb) { * @param {modules} scope Exposed modules */ Utils.prototype.onBind = function (scope) { - library.logger.trace('Blocks->Utils: Shared modules bind.'); + library.logger.trace('blocks', 'Blocks->Utils: Shared modules bind.'); modules = { blocks: scope.blocks }; diff --git a/modules/blocks/verify.js b/modules/blocks/verify.js index 12420e63..d1628f38 100644 --- a/modules/blocks/verify.js +++ b/modules/blocks/verify.js @@ -23,7 +23,7 @@ function Verify (logger, block, transaction, db) { }; self = this; - library.logger.trace('Blocks->Verify: Submodule initialized.'); + library.logger.trace('blocks', 'Blocks->Verify: Submodule initialized.'); return self; } @@ -431,7 +431,7 @@ Verify.prototype.processBlock = function (block, broadcast, cb, saveBlock) { var check = self.verifyBlock(block); if (!check.verified) { - library.logger.error(['Block', block.id, 'verification failed'].join(' '), check.errors.join(', ')); + library.logger.error('blocks', ['Block', block.id, 'verification failed'].join(' '), check.errors.join(', ')); return setImmediate(seriesCb, check.errors[0]); } @@ -492,7 +492,7 @@ Verify.prototype.processBlock = function (block, broadcast, cb, saveBlock) { * @param {modules} scope Exposed modules */ Verify.prototype.onBind = function (scope) { - library.logger.trace('Blocks->Verify: Shared modules bind.'); + library.logger.trace('blocks', 'Blocks->Verify: Shared modules bind.'); modules = { accounts: scope.accounts, blocks: scope.blocks, diff --git a/modules/cache.js b/modules/cache.js index b6eec8c8..4c9da7f1 100644 --- a/modules/cache.js +++ b/modules/cache.js @@ -182,9 +182,9 @@ Cache.prototype.onNewBlock = function (block, broadcast, cb) { async.map(['/api/blocks*', '/api/transactions*'], function (pattern, mapCb) { self.removeByPattern(pattern, function (err) { if (err) { - logger.error(['Error clearing keys with pattern:', pattern, ' on new block'].join(' ')); + logger.error('cache', ['Error clearing keys with pattern:', pattern, ' on new block'].join(' ')); } else { - logger.debug(['keys with pattern:', pattern, 'cleared from cache on new block'].join(' ')); + logger.debug('cache', ['keys with pattern:', pattern, 'cleared from cache on new block'].join(' ')); } mapCb(err); }); @@ -203,9 +203,9 @@ Cache.prototype.onFinishRound = function (round, cb) { var pattern = '/api/delegates*'; self.removeByPattern(pattern, function (err) { if (err) { - logger.error(['Error clearing keys with pattern:', pattern, ' round finish'].join(' ')); + logger.error('cache', ['Error clearing keys with pattern:', pattern, ' round finish'].join(' ')); } else { - logger.debug(['keys with pattern: ', pattern, 'cleared from cache new Round'].join(' ')); + logger.debug('cache', ['keys with pattern: ', pattern, 'cleared from cache new Round'].join(' ')); } return cb(err); }); @@ -230,9 +230,9 @@ Cache.prototype.onTransactionsSaved = function (transactions, cb) { if (!!delegateTransaction) { self.removeByPattern(pattern, function (err) { if (err) { - logger.error(['Error clearing keys with pattern:', pattern, ' on delegate trs'].join(' ')); + logger.error('cache', ['Error clearing keys with pattern:', pattern, ' on delegate trs'].join(' ')); } else { - logger.debug(['keys with pattern:', pattern, 'cleared from cache on delegate trs'].join(' ')); + logger.debug('cache', ['keys with pattern:', pattern, 'cleared from cache on delegate trs'].join(' ')); } return cb(err); }); diff --git a/modules/chatrooms.js b/modules/chatrooms.js index 8c793ec8..f2844106 100644 --- a/modules/chatrooms.js +++ b/modules/chatrooms.js @@ -193,11 +193,11 @@ __private.listChats = function (filter, cb) { }; return setImmediate(cb, null, data); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-chatrooms', `An error occurred while getting list of chats: ${err?.message || err}`, err.stack); return setImmediate(cb, err); }); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-chatrooms', `An error occurred while getting chats count: ${err?.message || err}`, err.stack); return setImmediate(cb, err); }); }; @@ -335,11 +335,11 @@ __private.listMessages = function (filter, cb) { }; return setImmediate(cb, null, data); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-chatrooms', `An error occurred while getting list of messages: ${err?.message || err}`, err.stack); return setImmediate(cb, err); }); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-chatrooms', `An error occurred while getting messages count: ${err?.message || err}`, err.stack); return setImmediate(cb, err); }); }; diff --git a/modules/chats.js b/modules/chats.js index e7986ed5..7d9561dd 100644 --- a/modules/chats.js +++ b/modules/chats.js @@ -82,12 +82,12 @@ function Chats (cb, scope) { __private.get = function (id, cb) { library.db.query(sql.get, { id: id }).then(function (rows) { if (rows.length === 0) { - return setImmediate(cb, 'Application not found'); + return setImmediate(cb, 'Message not found'); } else { return setImmediate(cb, null, rows[0]); } }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-chats', `An error occurred while getting a message ${id}: ${err?.message || err}`, err.stack); return setImmediate(cb, 'CHAT#get error'); }); }; @@ -104,7 +104,7 @@ __private.getByIds = function (ids, cb) { library.db.query(sql.getByIds, [ids]).then(function (rows) { return setImmediate(cb, null, rows); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-chats', `An error occurred while getting messages ${ids.join(', ')}: ${err?.message || err}`, err.stack); return setImmediate(cb, 'CHAT#getByIds error'); }); }; @@ -254,11 +254,11 @@ __private.list = function (filter, cb) { return setImmediate(cb, null, data); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-chats', `An error occurred while getting messages: ${err?.message || err}`, err.stack); return setImmediate(cb, err); }); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-chats', `An error occurred while getting messages count: ${err?.message || err}`, err.stack); return setImmediate(cb, err); }); }; diff --git a/modules/clientWs.js b/modules/clientWs.js index 23018f26..b9d9bc66 100644 --- a/modules/clientWs.js +++ b/modules/clientWs.js @@ -49,7 +49,7 @@ class ClientWs { delete this.describes[socket.id]; }); } catch (e) { - logger.debug('Error Connection socket: ' + e); + logger.debug('ws-client-server', `Error Connection socket: ${e?.message || e}`, e.stack); } }); @@ -69,7 +69,7 @@ class ClientWs { s.socket.emit('newTrans', t); }); } catch (e) { - this.logger.debug('Socket error emit ' + e); + logger.debug('ws-client-server', `Socker error emit: ${e?.message || e}`, e.stack); } } } diff --git a/modules/delegates.js b/modules/delegates.js index fd2cf3d5..b5831118 100644 --- a/modules/delegates.js +++ b/modules/delegates.js @@ -152,7 +152,7 @@ __private.getBlockSlotData = function (slot, height, cb) { */ __private.forge = function (cb) { if (!Object.keys(__private.keypairs).length) { - library.logger.debug('No delegates enabled'); + library.logger.debug('delegates', 'No delegates enabled'); return __private.loadDelegates(cb); } @@ -160,7 +160,7 @@ __private.forge = function (cb) { // Do not try to forge new blocks as client is not ready const syncPending = !modules.loader.isReadyToSync() || modules.loader.syncing(); if (!__private.loaded || syncPending || !modules.rounds.loaded() || modules.rounds.ticking()) { - library.logger.debug('Client not ready to forge'); + library.logger.debug('delegates', 'Client not ready to forge'); return setImmediate(cb); } @@ -168,18 +168,18 @@ __private.forge = function (cb) { var lastBlock = modules.blocks.lastBlock.get(); if (currentSlot === slots.getSlotNumber(lastBlock.timestamp)) { - library.logger.debug('Waiting for next delegate slot'); + library.logger.debug('delegates', 'Waiting for next delegate slot'); return setImmediate(cb); } __private.getBlockSlotData(currentSlot, lastBlock.height + 1, function (err, currentBlockData) { if (err || currentBlockData === null) { - library.logger.warn('Skipping delegate slot', err); + library.logger.warn('delegates', 'Skipping delegate slot', err); return setImmediate(cb); } if (slots.getSlotNumber(currentBlockData.time) !== slots.getSlotNumber()) { - library.logger.debug('Delegate slot', slots.getSlotNumber()); + library.logger.debug('delegates', 'Delegate slot', slots.getSlotNumber()); return setImmediate(cb); } @@ -197,7 +197,7 @@ __private.forge = function (cb) { } }, function (err) { if (err) { - library.logger.warn(err); + library.logger.warn('delegates', err); return setImmediate(cb, err); } else { return modules.blocks.process.generateBlock(currentBlockData.keypair, currentBlockData.time, cb); @@ -205,12 +205,12 @@ __private.forge = function (cb) { }); }, function (err) { if (err) { - library.logger.error('Failed to generate block within delegate slot', err); + library.logger.error('delegates', 'Failed to generate block within delegate slot', err); } else { var forgedBlock = modules.blocks.lastBlock.get(); modules.blocks.lastReceipt.update(); - library.logger.info([ + library.logger.info('delegates', [ 'Forged new block id:', forgedBlock.id, 'height:', forgedBlock.height, 'round:', modules.rounds.calc(forgedBlock.height), @@ -269,7 +269,7 @@ __private.checkDelegates = function (publicKey, votes, state, cb) { try { Buffer.from(publicKey, 'hex'); } catch (e) { - library.logger.error(e.stack); + library.logger.error('delegates', `Invalid public key: ${publicKey}`, e.stack); return setImmediate(cb, 'Invalid public key'); } @@ -330,7 +330,7 @@ __private.loadDelegates = function (cb) { if (!secrets || !secrets.length) { return setImmediate(cb); } else { - library.logger.info(['Loading', secrets.length, 'delegates from config'].join(' ')); + library.logger.info('delegates', ['Loading', secrets.length, 'delegates from config'].join(' ')); } async.eachSeries(secrets, function (secret, cb) { @@ -350,9 +350,9 @@ __private.loadDelegates = function (cb) { if (account.isDelegate) { __private.keypairs[keypair.publicKey.toString('hex')] = keypair; - library.logger.info(['Forging enabled on account:', account.address].join(' ')); + library.logger.info('delegates', ['Forging enabled on account:', account.address].join(' ')); } else { - library.logger.warn(['Account with public key:', keypair.publicKey.toString('hex'), 'is not a delegate'].join(' ')); + library.logger.warn('delegates', ['Account with public key:', keypair.publicKey.toString('hex'), 'is not a delegate'].join(' ')); } return setImmediate(cb); @@ -516,7 +516,7 @@ Delegates.prototype.checkUnconfirmedDelegates = function (publicKey, votes, cb) * @param {string} cause */ Delegates.prototype.fork = function (block, cause) { - library.logger.info('Fork', { + library.logger.info('delegates', 'Fork', { delegate: block.generatorPublicKey, block: { id: block.id, timestamp: block.timestamp, height: block.height, previousBlock: block.previousBlock }, cause: cause @@ -555,7 +555,7 @@ Delegates.prototype.validateBlockSlot = function (block, cb) { if (delegate_id && block.generatorPublicKey === delegate_id) { return setImmediate(cb); } else { - library.logger.error('Expected generator: ' + delegate_id + ' Received generator: ' + block.generatorPublicKey); + library.logger.error('delegates', 'Expected generator: ' + delegate_id + ' Received generator: ' + block.generatorPublicKey); return setImmediate(cb, 'Failed to verify slot: ' + currentSlot); } }); @@ -604,7 +604,7 @@ Delegates.prototype.onBlockchainReady = function () { __private.loadDelegates(function (err) { function nextForge (cb) { if (err) { - library.logger.error('Failed to load delegates', err); + library.logger.error('delegates', 'Failed to load delegates', err); } async.series([ @@ -672,7 +672,7 @@ Delegates.prototype.internal = { } if (account && account.isDelegate) { __private.keypairs[keypair.publicKey.toString('hex')] = keypair; - library.logger.info('Forging enabled on account: ' + account.address); + library.logger.info('delegates', 'Forging enabled on account: ' + account.address); return setImmediate(cb, null, { address: account.address }); } else { return setImmediate(cb, 'Delegate not found'); @@ -710,7 +710,7 @@ Delegates.prototype.internal = { } if (account && account.isDelegate) { delete __private.keypairs[keypair.publicKey.toString('hex')]; - library.logger.info('Forging disabled on account: ' + account.address); + library.logger.info('delegates', 'Forging disabled on account: ' + account.address); return setImmediate(cb, null, { address: account.address }); } else { return setImmediate(cb, 'Delegate not found'); @@ -853,7 +853,7 @@ Delegates.prototype.shared = { })).then(function (rows) { return setImmediate(cb, null, { delegates: rows }); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-delegates', `An error occurred while trying to find a delegate "${req.body.q}": ${err?.message || err}`, err.stack); return setImmediate(cb, 'Database search failed'); }); }); @@ -863,7 +863,7 @@ Delegates.prototype.shared = { library.db.one(sql.count).then(function (row) { return setImmediate(cb, null, { count: row.count }); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-delegates', `An error occurred while trying to count delegates: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Failed to count delegates'); }); }, @@ -888,7 +888,7 @@ Delegates.prototype.shared = { } }); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-delegates', `An error occurred while trying to get a delegate's voters ${req.body.publicKey}: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Failed to get voters for delegate: ' + req.body.publicKey); }); }); diff --git a/modules/loader.js b/modules/loader.js index d40347dc..723dc3d5 100644 --- a/modules/loader.js +++ b/modules/loader.js @@ -88,14 +88,14 @@ __private.initialize = function () { */ __private.syncTrigger = function (turnOn) { if (turnOn === false && __private.syncIntervalId) { - library.logger.trace('Clearing sync interval'); + library.logger.trace('loader', 'Clearing sync interval'); clearTimeout(__private.syncIntervalId); __private.syncIntervalId = null; } if (turnOn === true && !__private.syncIntervalId) { - library.logger.trace('Setting sync interval'); + library.logger.trace('loader', 'Setting sync interval'); setImmediate(function nextSyncTrigger () { - library.logger.trace('Sync trigger'); + library.logger.trace('loader', 'Sync trigger'); library.network.wsServer.emit('loader/sync', { blocks: __private.blocksToSync, height: modules.blocks.lastBlock.get().height @@ -116,17 +116,17 @@ __private.syncTrigger = function (turnOn) { * @implements {__private.initialize} */ __private.syncTimer = function () { - library.logger.trace('Setting sync timer'); + library.logger.trace('loader', 'Setting sync timer'); function nextSync (cb) { - library.logger.trace('Sync timer trigger', { loaded: __private.loaded, syncing: self.syncing(), last_receipt: modules.blocks.lastReceipt.get() }); + library.logger.trace('loader', 'Sync timer trigger', { loaded: __private.loaded, syncing: self.syncing(), last_receipt: modules.blocks.lastReceipt.get() }); if (__private.loaded && !self.syncing() && modules.blocks.lastReceipt.isStale()) { library.sequence.add(function (sequenceCb) { async.retry(__private.retries, __private.sync, sequenceCb); }, function (err) { if (err) { - library.logger.error('Sync timer', err); + library.logger.error('loader', 'Sync timer error:', err); __private.initialize(); } return setImmediate(cb); @@ -165,7 +165,7 @@ __private.loadSignatures = function (cb) { }); }, function (peer, waterCb) { - library.logger.log('Loading signatures from: ' + peer.string); + library.logger.log('loader', 'Loading signatures from: ' + peer.string); modules.transport.getFromPeer(peer, { api: '/signatures', @@ -229,7 +229,7 @@ __private.loadTransactions = function (cb) { }); }, function (peer, waterCb) { - library.logger.log('Loading transactions from: ' + peer.string); + library.logger.log('loader', 'Loading transactions from: ' + peer.string); modules.transport.getFromPeer(peer, { api: '/transactions', @@ -255,9 +255,9 @@ __private.loadTransactions = function (cb) { try { transaction = library.logic.transaction.objectNormalize(transaction); } catch (e) { - library.logger.debug('Transaction normalization failed', { id: id, err: e.toString(), module: 'loader', tx: transaction }); + library.logger.debug('loader', 'Transaction normalization failed', { id: id, err: e.toString(), module: 'loader', tx: transaction }); - library.logger.warn(['Transaction', id, 'is not valid, peer removed'].join(' '), peer.string); + library.logger.warn('peers', ['Transaction', id, 'is not valid, peer removed'].join(' '), peer.string); modules.peers.remove(peer.ip, peer.port); return setImmediate(eachSeriesCb, e); @@ -276,7 +276,7 @@ __private.loadTransactions = function (cb) { }, function (err) { if (err) { // TODO: Validate if must include error propagation. - library.logger.debug(err); + library.logger.debug('loader', `Failed to process transaction ${transaction.id}. Error: ${err?.message || err}`); } return setImmediate(eachSeriesCb); }); @@ -355,7 +355,7 @@ __private.loadBlockChain = function () { return testCb(null, count < offset); }, function (cb) { if (count > 1) { - library.logger.info('Rebuilding blockchain, current block height: ' + (offset + 1)); + library.logger.info('loader', 'Rebuilding blockchain, current block height: ' + (offset + 1)); } modules.blocks.process.loadBlocksOffset(limit, offset, verify, function (err, lastBlock) { if (err) { @@ -374,16 +374,16 @@ __private.loadBlockChain = function () { } }, function (err) { if (err) { - library.logger.error(err); + library.logger.error('loader', err); if (err.block) { - library.logger.error('Blockchain failed at: ' + err.block.height); + library.logger.error('loader', 'Blockchain failed at: ' + err.block.height); modules.blocks.chain.deleteAfterBlock(err.block.id, function (err, res) { - library.logger.error('Blockchain clipped'); + library.logger.error('loader', 'Blockchain clipped'); library.bus.message('blockchainReady'); }); } } else { - library.logger.info('Blockchain ready'); + library.logger.info('loader', 'Blockchain ready'); library.bus.message('blockchainReady'); } }); @@ -391,8 +391,8 @@ __private.loadBlockChain = function () { function reload (count, message) { if (message) { - library.logger.warn(message); - library.logger.warn('Recreating memory tables'); + library.logger.warn('loader', message); + library.logger.warn('loader', 'Recreating memory tables'); } return load(count); @@ -418,7 +418,7 @@ __private.loadBlockChain = function () { row.blockSignature.toString('hex') === __private.genesisBlock.block.blockSignature ); if (matched) { - library.logger.info('Genesis block matched with database'); + library.logger.info('loader', 'Genesis block matched with database'); } else { throw 'Failed to match genesis block with database'; } @@ -427,7 +427,7 @@ __private.loadBlockChain = function () { function verifySnapshot (count, round) { if (library.config.loading.snapshot !== undefined || library.config.loading.snapshot > 0) { - library.logger.info('Snapshot mode enabled'); + library.logger.info('loader', 'Snapshot mode enabled'); if (isNaN(library.config.loading.snapshot) || library.config.loading.snapshot >= round) { library.config.loading.snapshot = round; @@ -439,7 +439,7 @@ __private.loadBlockChain = function () { modules.rounds.setSnapshotRounds(library.config.loading.snapshot); } - library.logger.info('Snapshotting to end of round: ' + library.config.loading.snapshot); + library.logger.info('loader', 'Snapshotting to end of round: ' + library.config.loading.snapshot); return true; } else { return false; @@ -449,7 +449,7 @@ __private.loadBlockChain = function () { library.db.task(checkMemTables).then(function (results) { var count = results[0].count; - library.logger.info('Blocks ' + count); + library.logger.info('loader', 'Blocks count in database: ' + count); var round = modules.rounds.calc(count); @@ -482,7 +482,7 @@ __private.loadBlockChain = function () { var duplicatedDelegates = +results[4][0].count; if (duplicatedDelegates > 0) { - library.logger.error('Delegates table corrupted with duplicated entries'); + library.logger.error('loader', 'Delegates table corrupted with duplicated entries'); return process.emit('exit'); } @@ -510,13 +510,13 @@ __private.loadBlockChain = function () { return reload(count, err || 'Failed to load last block'); } else { __private.lastBlock = block; - library.logger.info('Blockchain ready'); + library.logger.info('loader', 'Blockchain ready'); library.bus.message('blockchainReady'); } }); }); }).catch(function (err) { - library.logger.error(err.stack || err); + library.logger.error('loader', `Failed to load blockchain: ${err?.message || err}`, err.stack); return process.emit('exit'); }); }; @@ -553,8 +553,7 @@ __private.loadBlocksFromNetwork = function (cb) { modules.blocks.process.loadBlocksFromPeer(peer, function (err, lastValidBlock) { if (err) { - library.logger.error(err.toString()); - library.logger.error('Failed to load blocks from: ' + peer.string); + library.logger.error('loader', `Failed to load blocks from ${peer.string}: ${err?.message || err}`, err.stack); errorCount += 1; } loaded = lastValidBlock.id === lastBlock.id; @@ -564,15 +563,15 @@ __private.loadBlocksFromNetwork = function (cb) { } function getCommonBlock (cb) { - library.logger.info('Looking for common block with: ' + peer.string); + library.logger.info('loader', 'Looking for common block with: ' + peer.string); modules.blocks.process.getCommonBlock(peer, lastBlock.height, function (err, commonBlock) { if (!commonBlock) { - if (err) { library.logger.error(err.toString()); } - library.logger.error('Failed to find common block with: ' + peer.string); + if (err) { library.logger.error('loader', err.toString()); } + library.logger.error('loader', 'Failed to find common block with: ' + peer.string); errorCount += 1; return next(); } else { - library.logger.info(['Found common block:', commonBlock.id, 'with:', peer.string].join(' ')); + library.logger.info('loader', ['Found common block:', commonBlock.id, 'with:', peer.string].join(' ')); return setImmediate(cb); } }); @@ -586,7 +585,7 @@ __private.loadBlocksFromNetwork = function (cb) { }, function (err) { if (err) { - library.logger.error('Failed to load blocks from network', err); + library.logger.error('loader', 'Failed to load blocks from network', err); return setImmediate(cb, err); } else { return setImmediate(cb); @@ -614,7 +613,7 @@ __private.loadBlocksFromNetwork = function (cb) { * @todo check err actions */ __private.sync = function (cb) { - library.logger.info('Starting sync'); + library.logger.info('loader', 'Starting sync'); library.bus.message('syncStarted'); __private.isActive = true; @@ -622,11 +621,11 @@ __private.sync = function (cb) { async.series({ undoUnconfirmedList: function (seriesCb) { - library.logger.debug('Undoing unconfirmed transactions before sync'); + library.logger.debug('loader', 'Undoing unconfirmed transactions before sync'); return modules.transactions.undoUnconfirmedList(seriesCb); }, getPeersBefore: function (seriesCb) { - library.logger.debug('Establishing broadhash consensus before sync'); + library.logger.debug('loader', 'Establishing broadhash consensus before sync'); return modules.transport.getPeers({ limit: constants.maxPeers }, seriesCb); }, loadBlocksFromNetwork: function (seriesCb) { @@ -636,11 +635,11 @@ __private.sync = function (cb) { return modules.system.update(seriesCb); }, getPeersAfter: function (seriesCb) { - library.logger.debug('Establishing broadhash consensus after sync'); + library.logger.debug('loader', 'Establishing broadhash consensus after sync'); return modules.transport.getPeers({ limit: constants.maxPeers }, seriesCb); }, applyUnconfirmedList: function (seriesCb) { - library.logger.debug('Applying unconfirmed transactions after sync'); + library.logger.debug('loader', 'Applying unconfirmed transactions after sync'); return modules.transactions.applyUnconfirmedList(seriesCb); } }, function (err) { @@ -648,7 +647,7 @@ __private.sync = function (cb) { __private.syncTrigger(false); __private.blocksToSync = 0; - library.logger.info('Finished sync'); + library.logger.info('loader', 'Finished sync'); library.bus.message('syncFinished'); return setImmediate(cb, err); }); @@ -671,14 +670,14 @@ __private.sync = function (cb) { */ __private.findGoodPeers = function (heights) { var lastBlockHeight = modules.blocks.lastBlock.get().height; - library.logger.trace('Good peers - received', { count: heights.length }); + library.logger.trace('loader', 'Good peers - received', { count: heights.length }); heights = heights.filter(function (item) { // Removing unreachable peers or heights below last block height return item != null && item.height >= lastBlockHeight; }); - library.logger.trace('Good peers - filtered', { count: heights.length }); + library.logger.trace('loader', 'Good peers - filtered', { count: heights.length }); // No peers found if (heights.length === 0) { @@ -714,8 +713,8 @@ __private.findGoodPeers = function (heights) { return library.logic.peers.create(item); }); - library.logger.trace('Good peers - accepted', { count: peers.length }); - library.logger.debug('Good peers', peers); + library.logger.trace('loader', 'Good peers - accepted', { count: peers.length }); + library.logger.debug('loader', 'Good peers', peers); return { height: height, peers: peers }; } @@ -840,7 +839,7 @@ Loader.prototype.isLoaded = function () { * @return {function} calls to __private.syncTimer() */ Loader.prototype.onPeersReady = function () { - library.logger.trace('Peers ready', { module: 'loader' }); + library.logger.trace('loader', 'Peers ready'); // Enforce sync early __private.syncTimer(); @@ -852,7 +851,7 @@ Loader.prototype.onPeersReady = function () { if (__private.loaded) { async.retry(__private.retries, __private.loadTransactions, function (err) { if (err) { - library.logger.log('Unconfirmed transactions loader', err); + library.logger.log('loader', 'Unconfirmed transactions loader', err); } return setImmediate(seriesCb); @@ -865,7 +864,7 @@ Loader.prototype.onPeersReady = function () { if (__private.loaded) { async.retry(__private.retries, __private.loadSignatures, function (err) { if (err) { - library.logger.log('Signatures loader', err); + library.logger.error('loader', 'Failed to load signatures:', err); } return setImmediate(seriesCb); @@ -875,7 +874,7 @@ Loader.prototype.onPeersReady = function () { } } }, function (err) { - library.logger.trace('Transactions and signatures pulled'); + library.logger.trace('loader', 'Transactions and signatures pulled'); if (err) { __private.initialize(); diff --git a/modules/peers.js b/modules/peers.js index 6470b0cf..c3b2d0ff 100644 --- a/modules/peers.js +++ b/modules/peers.js @@ -163,16 +163,16 @@ __private.getByFilter = function (filter, cb) { */ __private.insertSeeds = function (cb) { var updated = 0; - library.logger.trace('Peers->insertSeeds'); + library.logger.trace('peers', 'Peers->insertSeeds'); async.each(library.config.peers.list, function (peer, eachCb) { peer = library.logic.peers.create(peer); - library.logger.trace('Processing seed peer: ' + peer.string); + library.logger.trace('peers', 'Processing seed peer: ' + peer.string); self.ping(peer, function (err) { ++updated; return setImmediate(eachCb); }); }, function (err) { - library.logger.trace('Peers->insertSeeds - Peers discovered', { updated: updated, total: library.config.peers.list.length }); + library.logger.trace('peers', 'Peers->insertSeeds - Peers discovered', { updated: updated, total: library.config.peers.list.length }); return setImmediate(cb); }); }; @@ -187,9 +187,9 @@ __private.insertSeeds = function (cb) { */ __private.dbLoad = function (cb) { var updated = 0; - library.logger.trace('Importing peers from database'); + library.logger.trace('peers', 'Importing peers from database'); library.db.any(sql.getAll).then(function (rows) { - library.logger.info('Imported peers from database', { count: rows.length }); + library.logger.info('peers', 'Imported peers from database', { count: rows.length }); async.each(rows, function (peer, eachCb) { peer = library.logic.peers.create(peer); @@ -210,11 +210,11 @@ __private.dbLoad = function (cb) { }); } }, function (err) { - library.logger.trace('Peers->dbLoad Peers discovered', { updated: updated, total: rows.length }); + library.logger.trace('peers', 'Peers->dbLoad Peers discovered', { updated: updated, total: rows.length }); return setImmediate(cb); }); }).catch(function (err) { - library.logger.error('Import peers from database failed', { error: err.message || err }); + library.logger.error('peers', 'Import peers from database failed', { error: err.message || err }); return setImmediate(cb); }); }; @@ -232,7 +232,7 @@ __private.dbSave = function (cb) { // Do nothing when peers list is empty if (!peers.length) { - library.logger.debug('Export peers to database failed: Peers list empty'); + library.logger.debug('peers', 'Export peers to database failed: Peers list empty'); return setImmediate(cb); } @@ -272,10 +272,10 @@ __private.dbSave = function (cb) { return t.batch(queries); }).then(function (data) { - library.logger.info('Peers exported to database'); + library.logger.info('peers', 'Peers exported to database'); return setImmediate(cb); }).catch(function (err) { - library.logger.error('Export peers to database failed', { error: err.message || err }); + library.logger.error('peers', 'Export peers to database failed', { error: err.message || err }); return setImmediate(cb); }); }; @@ -380,13 +380,13 @@ Peers.prototype.recordRequest = function (ip, port, error) { * @returns {setImmediateCallback} cb | error when ping peer fails */ Peers.prototype.ping = function (peer, cb) { - library.logger.trace('Pinging peer: ' + peer.string); + library.logger.trace('peers', 'Pinging peer: ' + peer.string); modules.transport.getFromPeer(peer, { api: '/height', method: 'GET' }, function (err, res) { if (err) { - library.logger.trace('Ping peer failed: ' + peer.string, err); + library.logger.trace('peers', 'Ping peer failed: ' + peer.string, err); return setImmediate(cb, err); } else { return setImmediate(cb); @@ -400,7 +400,7 @@ Peers.prototype.ping = function (peer, cb) { * @return {setImmediateCallback} cb | error */ Peers.prototype.discover = function (cb) { - library.logger.trace('Peers->discover'); + library.logger.trace('peers', 'Peers->discover'); function getFromRandomPeer (waterCb) { modules.transport.getFromRandomPeer({ api: '/list', @@ -418,7 +418,7 @@ Peers.prototype.discover = function (cb) { function pickPeers (peers, waterCb) { var picked = self.acceptable(peers); - library.logger.debug(['Picked', picked.length, 'of', peers.length, 'peers'].join(' ')); + library.logger.debug('peers', ['Picked', picked.length, 'of', peers.length, 'peers'].join(' ')); return setImmediate(waterCb, null, picked); } @@ -429,7 +429,7 @@ Peers.prototype.discover = function (cb) { library.schema.validate(peer, schema.discover.peer, function (err) { if (err) { - library.logger.warn(['Rejecting invalid peer:', peer.string].join(' '), { err: err }); + library.logger.warn('peers', ['Rejecting invalid peer:', peer.string].join(' '), { err: err }); return setImmediate(eachCb); } @@ -440,7 +440,7 @@ Peers.prototype.discover = function (cb) { return setImmediate(eachCb); }); }, function (err) { - library.logger.trace('Peers discovered', peers.length); + library.logger.trace('peers', 'Peers discovered', peers.length); return setImmediate(waterCb); }); } @@ -530,7 +530,7 @@ Peers.prototype.list = function (options, cb) { peersList = peersList.slice(0, options.limit); picked = peersList.length; accepted = self.acceptable(peers.concat(peersList)); - library.logger.debug('Listing peers', { attempt: options.attempts[options.attempt], found: found, matched: matched, picked: picked, accepted: accepted.length }); + library.logger.debug('peers', 'Listing peers', { attempt: options.attempts[options.attempt], found: found, matched: matched, picked: picked, accepted: accepted.length }); return setImmediate(cb, null, accepted); }); } @@ -556,7 +556,7 @@ Peers.prototype.list = function (options, cb) { var consensus = Math.round(options.matched / peers.length * 100 * 1e2) / 1e2; consensus = isNaN(consensus) ? 0 : consensus; - library.logger.debug(['Listing', peers.length, 'total peers'].join(' ')); + library.logger.debug('peers', ['Listing', peers.length, 'total peers'].join(' ')); return setImmediate(cb, err, peers, consensus); }); }; @@ -605,14 +605,14 @@ Peers.prototype.onBlockchainReady = function () { * Discovers peers and updates them in 10sec intervals loop. */ Peers.prototype.onPeersReady = function () { - library.logger.trace('Peers ready'); + library.logger.trace('peers', 'Peers ready'); function peersDiscoveryAndUpdate (cb) { async.series({ discoverPeers: function (seriesCb) { - library.logger.trace('Discovering new peers...'); + library.logger.trace('peers', 'Discovering new peers...'); self.discover(function (err) { if (err) { - library.logger.error('Discovering new peers failed', err); + library.logger.error('peers', 'Discovering new peers failed.', err); } return setImmediate(seriesCb); }); @@ -621,12 +621,12 @@ Peers.prototype.onPeersReady = function () { var updated = 0; var peers = library.logic.peers.list(); - library.logger.trace('Updating peers', { count: peers.length }); + library.logger.trace('peers', 'Updating peers', { count: peers.length }); async.each(peers, function (peer, eachCb) { // If peer is not banned and not been updated during last 3 sec - ping if (peer && peer.state > 0 && (!peer.updated || Date.now() - peer.updated > 3000)) { - library.logger.trace('Updating peer', peer); + library.logger.trace('peers', 'Updating peer', peer); self.ping(peer, function (err) { ++updated; return setImmediate(eachCb); @@ -635,7 +635,7 @@ Peers.prototype.onPeersReady = function () { return setImmediate(eachCb); } }, function () { - library.logger.trace('Peers updated', { updated: updated, total: peers.length }); + library.logger.trace('peers', 'Peers updated', { updated: updated, total: peers.length }); if (updated) { self.events.emit('peers:update'); } diff --git a/modules/rounds.js b/modules/rounds.js index 19b36f58..29729a59 100644 --- a/modules/rounds.js +++ b/modules/rounds.js @@ -77,7 +77,7 @@ Rounds.prototype.flush = function (round, cb) { library.db.none(sql.flush, { round: round }).then(function () { return setImmediate(cb); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('rounds', `Failed to flush mem_round: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Rounds#flush error'); }); }; @@ -116,8 +116,7 @@ Rounds.prototype.backwardTick = function (block, previousBlock, done) { function BackwardTick (t) { var promised = new Round(scope, t); - library.logger.debug('Performing backward tick'); - library.logger.trace(scope); + library.logger.debug('rounds', 'Performing backward tick'); return promised.mergeBlockGenerator().then(function () { if (scope.finishRound) { @@ -155,7 +154,7 @@ Rounds.prototype.backwardTick = function (block, previousBlock, done) { library.db.tx(BackwardTick).then(function () { return setImmediate(cb); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('rounds', `Failed to perform a backward tick: ${err?.message || err}`, err.stack); return setImmediate(cb, err); }); } @@ -211,8 +210,7 @@ Rounds.prototype.tick = function (block, done) { function Tick (t) { var promised = new Round(scope, t); - library.logger.debug('Performing forward tick'); - library.logger.trace(scope); + library.logger.debug('rounds', 'Performing forward tick'); return promised.mergeBlockGenerator().then(function () { if (scope.finishRound) { @@ -253,14 +251,14 @@ Rounds.prototype.tick = function (block, done) { library.db.tx(Tick).then(function () { return setImmediate(cb); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('rounds', err.stack); return setImmediate(cb, err); }); }, function (cb) { // Check if we are one block before last block of round, if yes - perform round snapshot if ((block.height + 1) % slots.delegates === 0) { - library.logger.debug('Performing round snapshot...'); + library.logger.debug('rounds', 'Performing round snapshot...'); library.db.tx(function (t) { return t.batch([ @@ -270,10 +268,10 @@ Rounds.prototype.tick = function (block, done) { t.none(sql.performVotesSnapshot) ]); }).then(function () { - library.logger.trace('Round snapshot done'); + library.logger.trace('rounds', 'Round snapshot done'); return setImmediate(cb); }).catch(function (err) { - library.logger.error('Round snapshot failed', err); + library.logger.error('rounds', 'Round snapshot failed', err); return setImmediate(cb, err); }); } else { @@ -375,7 +373,7 @@ __private.getOutsiders = function (scope, cb) { } return setImmediate(eachCb); }, function (err) { - library.logger.trace('Got outsiders', scope.roundOutsiders); + library.logger.trace('rounds', 'Got outsiders', scope.roundOutsiders); return setImmediate(cb, err); }); }); @@ -391,7 +389,7 @@ __private.getOutsiders = function (scope, cb) { * @return {setImmediateCallback} err When failed to sum round | cb */ __private.sumRound = function (scope, cb) { - library.logger.debug('Summing round', scope.round); + library.logger.debug('rounds', 'Summing round', scope.round); library.db.query(sql.summedRound, { round: scope.round, activeDelegates: constants.activeDelegates }).then(function (rows) { var rewards = []; @@ -404,14 +402,14 @@ __private.sumRound = function (scope, cb) { scope.roundRewards = rewards; scope.roundDelegates = rows[0].delegates; - library.logger.trace('roundFees', scope.roundFees); - library.logger.trace('roundRewards', scope.roundRewards); - library.logger.trace('roundDelegates', scope.roundDelegates); + library.logger.trace('rounds', 'roundFees', scope.roundFees); + library.logger.trace('rounds', 'roundRewards', scope.roundRewards); + library.logger.trace('rounds', 'roundDelegates', scope.roundDelegates); return setImmediate(cb); }).catch(function (err) { - library.logger.error('Failed to sum round', scope.round); - library.logger.error(err.stack); + library.logger.error('rounds', 'Failed to sum round', scope.round); + library.logger.error('rounds', err.stack); return setImmediate(cb, err); }); }; diff --git a/modules/sql.js b/modules/sql.js index 43b64789..035730fb 100644 --- a/modules/sql.js +++ b/modules/sql.js @@ -153,7 +153,7 @@ __private.query = function (action, config, cb) { break; } - library.logger.trace('sql.query:', sql); + library.logger.trace('sql', 'sql.query:', sql); } catch (e) { return done(e); } @@ -161,7 +161,7 @@ __private.query = function (action, config, cb) { library.db.query(sql.toString() + ';').then(function (rows) { return done(null, rows); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('sql', err.stack); return done('Sql#query error'); }); } else { @@ -183,7 +183,7 @@ __private.query = function (action, config, cb) { library.db.none(sql).then(function () { return setImmediate(cb); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('sql', err.stack); return setImmediate(cb, 'Sql#query error'); }); }, done); @@ -272,14 +272,14 @@ Sql.prototype.dropTables = function (dappid, config, cb) { library.db.none('DROP TABLE IF EXISTS ' + table.name + ' CASCADE').then(function () { return setImmediate(cb, null); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('sql', err.stack); return setImmediate(cb, 'Sql#dropTables error'); }); } else if (table.type === 'index') { library.db.none('DROP INDEX IF EXISTS ' + table.name).then(function () { return setImmediate(cb, null); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('sql', err.stack); return setImmediate(cb, 'Sql#dropTables error'); }); } else { diff --git a/modules/states.js b/modules/states.js index 79ce049a..89928f60 100644 --- a/modules/states.js +++ b/modules/states.js @@ -82,7 +82,7 @@ __private.get = function (id, cb) { return setImmediate(cb, null, rows[0]); } }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('states', `An error occurred while trying to get a state ${id}: ${err?.message || err}`, err.stack); return setImmediate(cb, 'STATE#get error'); }); }; @@ -99,7 +99,8 @@ __private.getByIds = function (ids, cb) { library.db.query(sql.getByIds, [ids]).then(function (rows) { return setImmediate(cb, null, rows); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('states', `An error occurred while trying to get states ${ids.join(', ')}: ${err?.message || err}`, err.stack); + return setImmediate(cb, 'STATE#getByIds error'); }); }; @@ -238,11 +239,11 @@ __private.list = function (filter, cb) { return setImmediate(cb, null, data); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('states', `An error occurred while trying to get list of states: ${err?.message || err}`, err.stack); return setImmediate(cb, err); }); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('states', `An error occurred while trying to get states count: ${err?.message || err}`, err.stack); return setImmediate(cb, err); }); }; diff --git a/modules/system.js b/modules/system.js index 036478db..c96c96bd 100644 --- a/modules/system.js +++ b/modules/system.js @@ -181,7 +181,7 @@ System.prototype.getBroadhash = function (cb) { return setImmediate(cb, null, hash.toString('hex')); } }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('system', `Failed to get broadhash from database: ${err?.message || err}`, err.stack); return setImmediate(cb, err); }); }; @@ -211,7 +211,7 @@ System.prototype.update = function (cb) { return setImmediate(seriesCb); } }, function (err) { - library.logger.debug('System headers', __private); + library.logger.debug('system', 'System headers', __private); modules.transport.headers(__private); return setImmediate(cb, err); }); diff --git a/modules/transactions.js b/modules/transactions.js index 5e6927ae..368a254e 100644 --- a/modules/transactions.js +++ b/modules/transactions.js @@ -287,11 +287,11 @@ __private.list = function (filter, cb) { return setImmediate(cb, null, data); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-transactions', `An error occurred while trying to get list of transactions: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Transactions#list error'); }); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-transactions', `An error occurred while trying to get transactions count: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Transactions#list error'); }); }; @@ -313,7 +313,7 @@ __private.getById = function (id, cb) { return setImmediate(cb, null, transacton); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-transactions', `An error occurred while trying to get transaction ${id}: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Transactions#getById error'); }); }; @@ -335,7 +335,7 @@ __private.getByIdFullAsset = function (id, cb) { return setImmediate(cb, null, transacton); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-transactions', `An error occurred while trying to get transaction ${id} from 'trs_list_full' table: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Transactions#getById error'); }); }; @@ -368,7 +368,7 @@ __private.getVotesById = function (transaction, cb) { return setImmediate(cb, null, transaction); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-transactions', `An error occurred while trying to get votes for a transaction ${transaction.id}: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Transactions#getVotesById error'); }); }; @@ -769,7 +769,7 @@ Transactions.prototype.undoUnconfirmedList = function (cb) { * @param {function} cb - Callback function */ Transactions.prototype.apply = function (transaction, block, sender, cb) { - library.logger.debug('Applying confirmed transaction', transaction.id); + library.logger.debug('transactions', 'Applying confirmed transaction', transaction.id); library.logic.transaction.apply(transaction, block, sender, cb); }; @@ -782,7 +782,7 @@ Transactions.prototype.apply = function (transaction, block, sender, cb) { * @param {function} cb - Callback function */ Transactions.prototype.undo = function (transaction, block, sender, cb) { - library.logger.debug('Undoing confirmed transaction', transaction.id); + library.logger.debug('transactions', 'Undoing confirmed transaction', transaction.id); library.logic.transaction.undo(transaction, block, sender, cb); }; @@ -796,7 +796,7 @@ Transactions.prototype.undo = function (transaction, block, sender, cb) { * @return {setImmediateCallback} for errors */ Transactions.prototype.applyUnconfirmed = function (transaction, sender, cb) { - library.logger.debug('Applying unconfirmed transaction', transaction.id); + library.logger.debug('transactions', 'Applying unconfirmed transaction', transaction.id); if (!sender && transaction.blockId !== library.genesisblock.block.id) { return setImmediate(cb, 'Invalid block id'); @@ -828,7 +828,7 @@ Transactions.prototype.applyUnconfirmed = function (transaction, sender, cb) { * @return {setImmediateCallback} For error */ Transactions.prototype.undoUnconfirmed = function (transaction, cb) { - library.logger.debug('Undoing unconfirmed transaction', transaction.id); + library.logger.debug('transactions', 'Undoing unconfirmed transaction', transaction.id); modules.accounts.getAccount({ publicKey: transaction.senderPublicKey }, function (err, sender) { if (err) { diff --git a/modules/transport.js b/modules/transport.js index e5c61d7e..c0d750fc 100644 --- a/modules/transport.js +++ b/modules/transport.js @@ -94,7 +94,7 @@ __private.hashsum = function (obj) { * @param {string} extraMessage */ __private.removePeer = function (options, extraMessage) { - library.logger.debug([options.code, 'Removing peer', options.peer.string, extraMessage].join(' ')); + library.logger.debug('peers', [options.code, 'Removing peer', options.peer.string, extraMessage].join(' ')); modules.peers.remove(options.peer.ip, options.peer.port); }; @@ -141,7 +141,7 @@ __private.receiveSignatures = function (query, cb) { async.eachSeries(signatures, function (signature, eachSeriesCb) { __private.receiveSignature(signature, function (err) { if (err) { - library.logger.debug(err, signature); + library.logger.debug('transport', `Failed to verify signature ${signature}: ${err?.message || err}`, err.stack); } return setImmediate(eachSeriesCb); @@ -210,7 +210,7 @@ __private.receiveTransactions = function (query, peer, extraLogMessage, cb) { __private.receiveTransaction(transaction, peer, extraLogMessage, function (err) { if (err) { - library.logger.debug(err, transaction); + library.logger.debug('transactions', err, transaction); } return setImmediate(eachSeriesCb); @@ -243,7 +243,7 @@ __private.receiveTransaction = function (transaction, peer, extraLogMessage, cb) try { transaction = library.logic.transaction.objectNormalize(transaction); } catch (e) { - library.logger.debug('Transaction normalization failed', { id: id, err: e.toString(), module: 'transport', tx: transaction }); + library.logger.debug('transport', 'Transaction normalization failed', { id: id, err: e.toString(), module: 'transport', tx: transaction }); __private.removePeer({ peer: peer, code: 'ETRANSACTION' }, extraLogMessage); @@ -251,11 +251,11 @@ __private.receiveTransaction = function (transaction, peer, extraLogMessage, cb) } library.balancesSequence.add(function (cb) { - library.logger.debug('Received transaction ' + transaction.id + ' from peer ' + peer.string); + library.logger.debug('transactions', 'Received transaction ' + transaction.id + ' from peer ' + peer.string); modules.transactions.processUnconfirmedTransaction(transaction, true, function (err) { if (err) { - library.logger.debug(['Transaction', id].join(' '), err.toString()); - if (transaction) { library.logger.debug('Transaction', transaction); } + library.logger.debug('transactions', ['Transaction', id].join(' '), err.toString()); + if (transaction) { library.logger.debug('transport', 'Transaction', transaction); } return setImmediate(cb, err.toString()); } else { @@ -574,7 +574,7 @@ Transport.prototype.internal = { }); if (!escapedIds.length) { - library.logger.debug('Common block request validation failed', { err: 'ESCAPE', req: ids }); + library.logger.debug('transport', 'Common block request validation failed', { err: 'ESCAPE', req: ids }); __private.removePeer({ peer: peer, code: 'ECOMMON' }, extraLogMessage); @@ -584,7 +584,7 @@ Transport.prototype.internal = { library.db.query(sql.getCommonBlock, escapedIds).then(function (rows) { return setImmediate(cb, null, { success: true, common: rows[0] || null }); }).catch(function (err) { - library.logger.error(err.stack); + library.logger.error('api-transport', `Failed to get common block: ${err?.message || err}`, err.stack); return setImmediate(cb, 'Failed to get common block'); }); }, @@ -610,7 +610,7 @@ Transport.prototype.internal = { try { block = library.logic.block.objectNormalize(block); } catch (e) { - library.logger.debug('Block normalization failed', { err: e.toString(), module: 'transport', block: block }); + library.logger.debug('api-transport', 'Block normalization failed', { err: e.toString(), module: 'transport', block: block }); __private.removePeer({ peer: peer, code: 'EBLOCK' }, extraLogMessage); @@ -714,7 +714,7 @@ Transport.prototype.internal = { return setImmediate(cb, null, { success: false, message: 'Invalid hash sum' }); } } catch (e) { - library.logger.error(e.stack); + library.logger.error('api-transport', e.stack); return setImmediate(cb, null, { success: false, message: e.toString() }); } @@ -752,7 +752,7 @@ Transport.prototype.internal = { return setImmediate(cb, null, { success: false, message: 'Invalid hash sum' }); } } catch (e) { - library.logger.error(e.stack); + library.logger.error('api-transport', e.stack); return setImmediate(cb, null, { success: false, message: e.toString() }); } diff --git a/test/config.default.json b/test/config.default.json index f539fd08..be9d9d96 100644 --- a/test/config.default.json +++ b/test/config.default.json @@ -3,6 +3,7 @@ "address": "0.0.0.0", "fileLogLevel": "info", "logFileName": "logs/adamant_testnet.log", + "debugFileName": "logs/adamant_testnet_debug.log", "consoleLogLevel": "info", "trustProxy": false, "topAccounts": true,