From 420fc718f7c35e414435f1e4493a1c94f094a26b Mon Sep 17 00:00:00 2001 From: Kevin Leyow Date: Thu, 22 Aug 2024 11:00:07 -0500 Subject: [PATCH] chore: add logging for admin api, proxy lookup, participant domain (#1080) * feat: initial commit * fix: int tests * fix: int tests * chore: skip coverage check for snapshots * chore(snapshot): 17.8.0-snapshot.8 * fix: proxy cluster * chore: dep update * chore(snapshot): 17.8.0-snapshot.9 * chore: add logging for admin api, proxy lookup, participant domain * fix tests * address comments * ignore --------- Co-authored-by: Vijay --- .nycrc.yml | 1 + package-lock.json | 101 +++++++++++------ package.json | 2 +- src/domain/participant/index.js | 107 ++++++++++++++++++ src/handlers/transfers/prepare.js | 6 + src/lib/proxyCache.js | 7 ++ src/shared/logger/Logger.js | 101 ----------------- src/shared/logger/index.js | 6 +- src/shared/loggingPlugin.js | 43 +++++++ src/shared/plugins.js | 6 + .../transfers/FxFulfilService.test.js | 4 +- 11 files changed, 241 insertions(+), 143 deletions(-) delete mode 100644 src/shared/logger/Logger.js create mode 100644 src/shared/loggingPlugin.js diff --git a/.nycrc.yml b/.nycrc.yml index fa84bd3ac..d028a91ca 100644 --- a/.nycrc.yml +++ b/.nycrc.yml @@ -19,6 +19,7 @@ exclude: [ '**/ddl/**', '**/bulk*/**', 'src/shared/logger/**', + 'src/shared/loggingPlugin.js', 'src/shared/constants.js', 'src/domain/position/index.js', 'src/domain/position/binProcessor.js', diff --git a/package-lock.json b/package-lock.json index 5e81f49d0..ba8f9c01b 100644 --- a/package-lock.json +++ b/package-lock.json @@ -18,7 +18,7 @@ "@hapi/vision": "7.0.3", "@mojaloop/central-services-error-handling": "13.0.1", "@mojaloop/central-services-health": "15.0.0", - "@mojaloop/central-services-logger": "11.5.0", + "@mojaloop/central-services-logger": "11.5.1", "@mojaloop/central-services-metrics": "12.0.8", "@mojaloop/central-services-shared": "18.6.3", "@mojaloop/central-services-stream": "11.3.1", @@ -556,6 +556,14 @@ "node": ">=6.9.0" } }, + "node_modules/@colors/colors": { + "version": "1.6.0", + "resolved": "https://registry.npmjs.org/@colors/colors/-/colors-1.6.0.tgz", + "integrity": "sha512-Ir+AOibqzrIsL6ajt3Rz3LskB7OiMVHqltZmspbW/TJuTVuyOMirVqAkjfY6JISiLHgyNqicAC8AyHHGzNd/dA==", + "engines": { + "node": ">=0.1.90" + } + }, "node_modules/@dabh/diagnostics": { "version": "2.0.3", "resolved": "https://registry.npmjs.org/@dabh/diagnostics/-/diagnostics-2.0.3.tgz", @@ -1562,22 +1570,14 @@ } }, "node_modules/@mojaloop/central-services-logger": { - "version": "11.5.0", - "resolved": "https://registry.npmjs.org/@mojaloop/central-services-logger/-/central-services-logger-11.5.0.tgz", - "integrity": "sha512-pH73RiJ5fKTBTSdLocp1vPBad1D+Kh0HufdcfjLaBQj3dIBq72si0k+Z3L1MeOmMqMzpj+8M/he/izlgqJjVJA==", + "version": "11.5.1", + "resolved": "https://registry.npmjs.org/@mojaloop/central-services-logger/-/central-services-logger-11.5.1.tgz", + "integrity": "sha512-l+6+w35NqFJn1Xl82l55x71vCARWTkO6hYAgwbFuqVRqX0jqaRi4oiXG2WwPRVMLqVv8idAboCMX/I6vg/d4Kw==", "dependencies": { "parse-strings-in-object": "2.0.0", "rc": "1.2.8", "safe-stable-stringify": "^2.4.3", - "winston": "3.13.1" - } - }, - "node_modules/@mojaloop/central-services-logger/node_modules/@colors/colors": { - "version": "1.6.0", - "resolved": "https://registry.npmjs.org/@colors/colors/-/colors-1.6.0.tgz", - "integrity": "sha512-Ir+AOibqzrIsL6ajt3Rz3LskB7OiMVHqltZmspbW/TJuTVuyOMirVqAkjfY6JISiLHgyNqicAC8AyHHGzNd/dA==", - "engines": { - "node": ">=0.1.90" + "winston": "3.14.2" } }, "node_modules/@mojaloop/central-services-logger/node_modules/readable-stream": { @@ -1594,9 +1594,9 @@ } }, "node_modules/@mojaloop/central-services-logger/node_modules/winston": { - "version": "3.13.1", - "resolved": "https://registry.npmjs.org/winston/-/winston-3.13.1.tgz", - "integrity": "sha512-SvZit7VFNvXRzbqGHsv5KSmgbEYR5EiQfDAL9gxYkRqa934Hnk++zze0wANKtMHcy/gI4W/3xmSDwlhf865WGw==", + "version": "3.14.2", + "resolved": "https://registry.npmjs.org/winston/-/winston-3.14.2.tgz", + "integrity": "sha512-CO8cdpBB2yqzEf8v895L+GNKYJiEq8eKlHU38af3snQBQ+sdAIUepjMSguOIJC7ICbzm0ZI+Af2If4vIJrtmOg==", "dependencies": { "@colors/colors": "^1.6.0", "@dabh/diagnostics": "^2.0.2", @@ -1805,6 +1805,51 @@ "node": ">=18.x" } }, + "node_modules/@mojaloop/inter-scheme-proxy-cache-lib/node_modules/@mojaloop/central-services-logger": { + "version": "11.5.0", + "resolved": "https://registry.npmjs.org/@mojaloop/central-services-logger/-/central-services-logger-11.5.0.tgz", + "integrity": "sha512-pH73RiJ5fKTBTSdLocp1vPBad1D+Kh0HufdcfjLaBQj3dIBq72si0k+Z3L1MeOmMqMzpj+8M/he/izlgqJjVJA==", + "dependencies": { + "parse-strings-in-object": "2.0.0", + "rc": "1.2.8", + "safe-stable-stringify": "^2.4.3", + "winston": "3.13.1" + } + }, + "node_modules/@mojaloop/inter-scheme-proxy-cache-lib/node_modules/readable-stream": { + "version": "3.6.2", + "resolved": "https://registry.npmjs.org/readable-stream/-/readable-stream-3.6.2.tgz", + "integrity": "sha512-9u/sniCrY3D5WdsERHzHE4G2YCXqoG5FTHUiCC4SIbr6XcLZBY05ya9EKjYek9O5xOAwjGq+1JdGBAS7Q9ScoA==", + "dependencies": { + "inherits": "^2.0.3", + "string_decoder": "^1.1.1", + "util-deprecate": "^1.0.1" + }, + "engines": { + "node": ">= 6" + } + }, + "node_modules/@mojaloop/inter-scheme-proxy-cache-lib/node_modules/winston": { + "version": "3.13.1", + "resolved": "https://registry.npmjs.org/winston/-/winston-3.13.1.tgz", + "integrity": "sha512-SvZit7VFNvXRzbqGHsv5KSmgbEYR5EiQfDAL9gxYkRqa934Hnk++zze0wANKtMHcy/gI4W/3xmSDwlhf865WGw==", + "dependencies": { + "@colors/colors": "^1.6.0", + "@dabh/diagnostics": "^2.0.2", + "async": "^3.2.3", + "is-stream": "^2.0.0", + "logform": "^2.6.0", + "one-time": "^1.0.0", + "readable-stream": "^3.4.0", + "safe-stable-stringify": "^2.3.1", + "stack-trace": "0.0.x", + "triple-beam": "^1.3.0", + "winston-transport": "^4.7.0" + }, + "engines": { + "node": ">= 12.0.0" + } + }, "node_modules/@mojaloop/ml-number": { "version": "11.2.4", "resolved": "https://registry.npmjs.org/@mojaloop/ml-number/-/ml-number-11.2.4.tgz", @@ -8601,14 +8646,6 @@ "node": ">= 12.0.0" } }, - "node_modules/logform/node_modules/@colors/colors": { - "version": "1.6.0", - "resolved": "https://registry.npmjs.org/@colors/colors/-/colors-1.6.0.tgz", - "integrity": "sha512-Ir+AOibqzrIsL6ajt3Rz3LskB7OiMVHqltZmspbW/TJuTVuyOMirVqAkjfY6JISiLHgyNqicAC8AyHHGzNd/dA==", - "engines": { - "node": ">=0.1.90" - } - }, "node_modules/long": { "version": "5.2.3", "resolved": "https://registry.npmjs.org/long/-/long-5.2.3.tgz", @@ -9065,11 +9102,11 @@ } }, "node_modules/micromatch": { - "version": "4.0.5", - "resolved": "https://registry.npmjs.org/micromatch/-/micromatch-4.0.5.tgz", - "integrity": "sha512-DMy+ERcEW2q8Z2Po+WNXuw3c5YaUSFjAO5GsJqfEl7UjvtIuFKO6ZrKvcItdy98dwFI2N1tg3zNIdKaQT+aNdA==", + "version": "4.0.7", + "resolved": "https://registry.npmjs.org/micromatch/-/micromatch-4.0.7.tgz", + "integrity": "sha512-LPP/3KorzCwBxfeUuZmaR6bG2kdeHSbe0P2tY3FLRU4vYrjYz5hI4QZwV0njUx3jeuKe67YukQ1LSPZBKDqO/Q==", "dependencies": { - "braces": "^3.0.2", + "braces": "^3.0.3", "picomatch": "^2.3.1" }, "engines": { @@ -14642,14 +14679,6 @@ "node": ">= 6" } }, - "node_modules/winston/node_modules/@colors/colors": { - "version": "1.6.0", - "resolved": "https://registry.npmjs.org/@colors/colors/-/colors-1.6.0.tgz", - "integrity": "sha512-Ir+AOibqzrIsL6ajt3Rz3LskB7OiMVHqltZmspbW/TJuTVuyOMirVqAkjfY6JISiLHgyNqicAC8AyHHGzNd/dA==", - "engines": { - "node": ">=0.1.90" - } - }, "node_modules/winston/node_modules/readable-stream": { "version": "3.6.2", "resolved": "https://registry.npmjs.org/readable-stream/-/readable-stream-3.6.2.tgz", diff --git a/package.json b/package.json index c8e17f6e8..c99f1368f 100644 --- a/package.json +++ b/package.json @@ -90,7 +90,7 @@ "@hapi/vision": "7.0.3", "@mojaloop/central-services-error-handling": "13.0.1", "@mojaloop/central-services-health": "15.0.0", - "@mojaloop/central-services-logger": "11.5.0", + "@mojaloop/central-services-logger": "11.5.1", "@mojaloop/central-services-metrics": "12.0.8", "@mojaloop/central-services-shared": "18.6.3", "@mojaloop/central-services-stream": "11.3.1", diff --git a/src/domain/participant/index.js b/src/domain/participant/index.js index 394508c63..5cece7aeb 100644 --- a/src/domain/participant/index.js +++ b/src/domain/participant/index.js @@ -42,6 +42,7 @@ const KafkaProducer = require('@mojaloop/central-services-stream').Util.Producer const { randomUUID } = require('crypto') const Enum = require('@mojaloop/central-services-shared').Enum const Enums = require('../../lib/enumCached') +const { logger } = require('../../shared/logger') // Alphabetically ordered list of error texts used below const AccountInactiveErrorText = 'Account is currently set inactive' @@ -58,9 +59,12 @@ const ErrorHandler = require('@mojaloop/central-services-error-handling') const { destroyParticipantEndpointByParticipantId } = require('../../models/participant/participant') const create = async (payload) => { + const log = logger.child({ payload }) try { + log.info('creating participant with payload') return ParticipantModel.create({ name: payload.name, isProxy: !!payload.isProxy }) } catch (err) { + log.error('error creating participant', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -71,13 +75,16 @@ const getAll = async () => { await Promise.all(all.map(async (participant) => { participant.currencyList = await ParticipantCurrencyModel.getByParticipantId(participant.participantId) })) + logger.debug('getAll participants', { participants: all }) return all } catch (err) { + logger.error('error getting all participants', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } const getById = async (id) => { + logger.debug('getting participant by id', { id }) const participant = await ParticipantModel.getById(id) if (participant) { participant.currencyList = await ParticipantCurrencyModel.getByParticipantId(participant.participantId) @@ -86,6 +93,7 @@ const getById = async (id) => { } const getByName = async (name) => { + logger.debug('getting participant by name', { name }) const participant = await ParticipantModel.getByName(name) if (participant) { participant.currencyList = await ParticipantCurrencyModel.getByParticipantId(participant.participantId) @@ -94,17 +102,23 @@ const getByName = async (name) => { } const participantExists = (participant, checkIsActive = false) => { + const log = logger.child({ participant, checkIsActive }) + log.debug('checking if participant exists') if (participant) { if (!checkIsActive || participant.isActive) { return participant } + log.warn('participant is inactive') throw ErrorHandler.Factory.createInternalServerFSPIOPError(ParticipantInactiveText) } + log.warn('participant not found') throw ErrorHandler.Factory.createInternalServerFSPIOPError(ParticipantNotFoundText) } const update = async (name, payload) => { + const log = logger.child({ name, payload }) try { + log.info('updating participant') const participant = await ParticipantModel.getByName(name) participantExists(participant) await ParticipantModel.update(participant, payload.isActive) @@ -112,38 +126,50 @@ const update = async (name, payload) => { participant.currencyList = await ParticipantCurrencyModel.getByParticipantId(participant.participantId) return participant } catch (err) { + log.error('error updating participant', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } const createParticipantCurrency = async (participantId, currencyId, ledgerAccountTypeId, isActive = true) => { + const log = logger.child({ participantId, currencyId, ledgerAccountTypeId, isActive }) try { + log.info('creating participant currency') const participantCurrency = await ParticipantCurrencyModel.create(participantId, currencyId, ledgerAccountTypeId, isActive) return participantCurrency } catch (err) { + log.error('error creating participant currency', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } const createHubAccount = async (participantId, currencyId, ledgerAccountTypeId) => { + const log = logger.child({ participantId, currencyId, ledgerAccountTypeId }) try { + log.info('creating hub account') const participantCurrency = await ParticipantFacade.addHubAccountAndInitPosition(participantId, currencyId, ledgerAccountTypeId) return participantCurrency } catch (err) { + log.error('error creating hub account', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } const getParticipantCurrencyById = async (participantCurrencyId) => { + const log = logger.child({ participantCurrencyId }) try { + log.debug('getting participant currency by id') return await ParticipantCurrencyModel.getById(participantCurrencyId) } catch (err) { + log.error('error getting participant currency by id', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } const destroyByName = async (name) => { + const log = logger.child({ name }) try { + log.debug('destroying participant by name') const participant = await ParticipantModel.getByName(name) await ParticipantLimitModel.destroyByParticipantId(participant.participantId) await ParticipantPositionModel.destroyByParticipantId(participant.participantId) @@ -151,6 +177,7 @@ const destroyByName = async (name) => { await destroyParticipantEndpointByParticipantId(participant.participantId) return await ParticipantModel.destroyByName(name) } catch (err) { + log.error('error destroying participant by name', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -174,11 +201,15 @@ const destroyByName = async (name) => { */ const addEndpoint = async (name, payload) => { + const log = logger.child({ name, payload }) try { + log.info('adding endpoint') const participant = await ParticipantModel.getByName(name) participantExists(participant) + log.info('adding endpoint for participant', { participant }) return ParticipantFacade.addEndpoint(participant.participantId, payload) } catch (err) { + log.error('error adding endpoint', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -199,11 +230,15 @@ const addEndpoint = async (name, payload) => { */ const getEndpoint = async (name, type) => { + const log = logger.child({ name, type }) try { + log.debug('getting endpoint') const participant = await ParticipantModel.getByName(name) participantExists(participant) + log.debug('getting endpoint for participant', { participant }) return ParticipantFacade.getEndpoint(participant.participantId, type) } catch (err) { + log.error('error getting endpoint', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -223,11 +258,15 @@ const getEndpoint = async (name, type) => { */ const getAllEndpoints = async (name) => { + const log = logger.child({ name }) try { + log.debug('getting all endpoints for participant name') const participant = await ParticipantModel.getByName(name) participantExists(participant) + log.debug('getting all endpoints for participant', { participant }) return ParticipantFacade.getAllEndpoints(participant.participantId) } catch (err) { + log.error('error getting all endpoints', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -245,11 +284,15 @@ const getAllEndpoints = async (name) => { */ const destroyParticipantEndpointByName = async (name) => { + const log = logger.child({ name }) try { + log.debug('destroying participant endpoint by name') const participant = await ParticipantModel.getByName(name) participantExists(participant) + log.debug('destroying participant endpoint for participant', { participant }) return ParticipantModel.destroyParticipantEndpointByParticipantId(participant.participantId) } catch (err) { + log.error('error destroying participant endpoint by name', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -278,14 +321,18 @@ const destroyParticipantEndpointByName = async (name) => { */ const addLimitAndInitialPosition = async (participantName, limitAndInitialPositionObj) => { + const log = logger.child({ participantName, limitAndInitialPositionObj }) try { + log.debug('adding limit and initial position', { participantName, limitAndInitialPositionObj }) const participant = await ParticipantFacade.getByNameAndCurrency(participantName, limitAndInitialPositionObj.currency, Enum.Accounts.LedgerAccountType.POSITION) participantExists(participant) + log.debug('adding limit and initial position for participant', { participant }) const settlementAccount = await ParticipantFacade.getByNameAndCurrency(participantName, limitAndInitialPositionObj.currency, Enum.Accounts.LedgerAccountType.SETTLEMENT) const existingLimit = await ParticipantLimitModel.getByParticipantCurrencyId(participant.participantCurrencyId) const existingPosition = await ParticipantPositionModel.getByParticipantCurrencyId(participant.participantCurrencyId) const existingSettlementPosition = await ParticipantPositionModel.getByParticipantCurrencyId(settlementAccount.participantCurrencyId) if (existingLimit || existingPosition || existingSettlementPosition) { + log.warn('participant limit or initial position already set') throw ErrorHandler.Factory.createInternalServerFSPIOPError(ParticipantInitialPositionExistsText) } const limitAndInitialPosition = Object.assign({}, limitAndInitialPositionObj, { name: participantName }) @@ -296,6 +343,7 @@ const addLimitAndInitialPosition = async (participantName, limitAndInitialPositi await Kafka.produceGeneralMessage(Config.KAFKA_CONFIG, KafkaProducer, Enum.Events.Event.Type.NOTIFICATION, Enum.Transfers.AdminNotificationActions.LIMIT_ADJUSTMENT, createLimitAdjustmentMessageProtocol(payload), Enum.Events.EventStatus.SUCCESS) return ParticipantFacade.addLimitAndInitialPosition(participant.participantCurrencyId, settlementAccount.participantCurrencyId, limitAndInitialPosition, true) } catch (err) { + log.error('error adding limit and initial position', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -313,9 +361,12 @@ const addLimitAndInitialPosition = async (participantName, limitAndInitialPositi */ const getPositionByParticipantCurrencyId = async (participantCurrencyId) => { + const log = logger.child({ participantCurrencyId }) try { + log.debug('getting position by participant currency id') return ParticipantPositionModel.getByParticipantCurrencyId(participantCurrencyId) } catch (err) { + log.error('error getting position by participant currency id', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -333,9 +384,12 @@ const getPositionByParticipantCurrencyId = async (participantCurrencyId) => { */ const getPositionChangeByParticipantPositionId = async (participantPositionId) => { + const log = logger.child({ participantPositionId }) try { + log.debug('getting position change by participant position id') return ParticipantPositionChangeModel.getByParticipantPositionId(participantPositionId) } catch (err) { + log.error('error getting position change by participant position id', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -353,11 +407,15 @@ const getPositionChangeByParticipantPositionId = async (participantPositionId) = */ const destroyParticipantPositionByNameAndCurrency = async (name, currencyId) => { + const log = logger.child({ name, currencyId }) try { + log.debug('destroying participant position by participant name and currency') const participant = await ParticipantFacade.getByNameAndCurrency(name, currencyId, Enum.Accounts.LedgerAccountType.POSITION) + log.debug('destroying participant position for participant', { participant }) participantExists(participant) return ParticipantPositionModel.destroyByParticipantCurrencyId(participant.participantCurrencyId) } catch (err) { + log.error('error destroying participant position by name and currency', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -376,11 +434,15 @@ const destroyParticipantPositionByNameAndCurrency = async (name, currencyId) => */ const destroyParticipantLimitByNameAndCurrency = async (name, currencyId) => { + const log = logger.child({ name, currencyId }) try { + log.debug('destroying participant limit by participant name and currency') const participant = await ParticipantFacade.getByNameAndCurrency(name, currencyId, Enum.Accounts.LedgerAccountType.POSITION) + log.debug('destroying participant limit for participant', { participant }) participantExists(participant) return ParticipantLimitModel.destroyByParticipantCurrencyId(participant.participantCurrencyId) } catch (err) { + log.error('error destroying participant limit by name and currency', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -403,18 +465,24 @@ const destroyParticipantLimitByNameAndCurrency = async (name, currencyId) => { */ const getLimits = async (name, { currency = null, type = null }) => { + const log = logger.child({ name, currency, type }) try { let participant if (currency != null) { + log.debug('getting limits by name and currency') participant = await ParticipantFacade.getByNameAndCurrency(name, currency, Enum.Accounts.LedgerAccountType.POSITION) + log.debug('getting limits for participant', { participant }) participantExists(participant) return ParticipantFacade.getParticipantLimitsByCurrencyId(participant.participantCurrencyId, type) } else { + log.debug('getting limits by name') participant = await ParticipantModel.getByName(name) + log.debug('getting limits for participant', { participant }) participantExists(participant) return ParticipantFacade.getParticipantLimitsByParticipantId(participant.participantId, type, Enum.Accounts.LedgerAccountType.POSITION) } } catch (err) { + log.error('error getting limits', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -434,9 +502,12 @@ const getLimits = async (name, { currency = null, type = null }) => { */ const getLimitsForAllParticipants = async ({ currency = null, type = null }) => { + const log = logger.child({ currency, type }) try { + log.debug('getting limits for all participants', { currency, type }) return ParticipantFacade.getLimitsForAllParticipants(currency, type, Enum.Accounts.LedgerAccountType.POSITION) } catch (err) { + log.error('error getting limits for all participants', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -465,15 +536,19 @@ const getLimitsForAllParticipants = async ({ currency = null, type = null }) => */ const adjustLimits = async (name, payload) => { + const log = logger.child({ name, payload }) try { + log.debug('adjusting limits') const { limit, currency } = payload const participant = await ParticipantFacade.getByNameAndCurrency(name, currency, Enum.Accounts.LedgerAccountType.POSITION) + log.debug('adjusting limits for participant', { participant }) participantExists(participant) const result = await ParticipantFacade.adjustLimits(participant.participantCurrencyId, limit) payload.name = name await Kafka.produceGeneralMessage(Config.KAFKA_CONFIG, KafkaProducer, Enum.Events.Event.Type.NOTIFICATION, Enum.Transfers.AdminNotificationActions.LIMIT_ADJUSTMENT, createLimitAdjustmentMessageProtocol(payload), Enum.Events.EventStatus.SUCCESS) return result } catch (err) { + log.error('error adjusting limits', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -546,9 +621,12 @@ const createLimitAdjustmentMessageProtocol = (payload, action = Enum.Transfers.A */ const getPositions = async (name, query) => { + const log = logger.child({ name, query }) try { + log.debug('getting positions') if (query.currency) { const participant = await ParticipantFacade.getByNameAndCurrency(name, query.currency, Enum.Accounts.LedgerAccountType.POSITION) + log.debug('getting positions for participant', { participant }) participantExists(participant) const result = await PositionFacade.getByNameAndCurrency(name, Enum.Accounts.LedgerAccountType.POSITION, query.currency) // TODO this function only takes a max of 3 params, this has 4 let position = {} @@ -559,9 +637,11 @@ const getPositions = async (name, query) => { changedDate: result[0].changedDate } } + log.debug('found positions for participant', { participant, position }) return position } else { const participant = await ParticipantModel.getByName(name) + log.debug('getting positions for participant', { participant }) participantExists(participant) const result = await await PositionFacade.getByNameAndCurrency(name, Enum.Accounts.LedgerAccountType.POSITION) const positions = [] @@ -574,16 +654,21 @@ const getPositions = async (name, query) => { }) }) } + log.debug('found positions for participant', { participant, positions }) return positions } } catch (err) { + log.error('error getting positions', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } const getAccounts = async (name, query) => { + const log = logger.child({ name, query }) try { + log.debug('getting accounts') const participant = await ParticipantModel.getByName(name) + log.debug('getting accounts for participant', { participant }) participantExists(participant) const result = await PositionFacade.getAllByNameAndCurrency(name, query.currency) const positions = [] @@ -600,18 +685,24 @@ const getAccounts = async (name, query) => { }) }) } + log.debug('found accounts for participant', { participant, positions }) return positions } catch (err) { + log.error('error getting accounts', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } const updateAccount = async (payload, params, enums) => { + const log = logger.child({ payload, params, enums }) try { + log.debug('updating account') const { name, id } = params const participant = await ParticipantModel.getByName(name) + log.debug('updating account for participant', { participant }) participantExists(participant) const account = await ParticipantCurrencyModel.getById(id) + log.debug('updating account for participant', { participant, account }) if (!account) { throw ErrorHandler.Factory.createInternalServerFSPIOPError(AccountNotFoundErrorText) } else if (account.participantId !== participant.participantId) { @@ -621,22 +712,29 @@ const updateAccount = async (payload, params, enums) => { } return await ParticipantCurrencyModel.update(id, payload.isActive) } catch (err) { + log.error('error updating account', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } const getLedgerAccountTypeName = async (name) => { + const log = logger.child({ name }) try { + log.debug('getting ledger account type by name') return await LedgerAccountTypeModel.getLedgerAccountByName(name) } catch (err) { + log.error('error getting ledger account type by name', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } const getParticipantAccount = async (accountParams) => { + const log = logger.child({ accountParams }) try { + log.debug('getting participant account by params') return await ParticipantCurrencyModel.findOneByParams(accountParams) } catch (err) { + log.error('error getting participant account by params', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -690,7 +788,9 @@ const setPayerPayeeFundsInOut = (fspName, payload, enums) => { } const recordFundsInOut = async (payload, params, enums) => { + const log = logger.child({ payload, params, enums }) try { + log.debug('recording funds in/out') const { name, id, transferId } = params const participant = await ParticipantModel.getByName(name) const currency = (payload.amount && payload.amount.currency) || null @@ -699,6 +799,7 @@ const recordFundsInOut = async (payload, params, enums) => { participantExists(participant, checkIsActive) const accounts = await ParticipantFacade.getAllAccountsByNameAndCurrency(name, currency, isAccountActive) const accountMatched = accounts[accounts.map(account => account.participantCurrencyId).findIndex(i => i === id)] + log.debug('recording funds in/out for participant account', { participant, accountMatched }) if (!accountMatched) { throw ErrorHandler.Factory.createInternalServerFSPIOPError(ParticipantAccountCurrencyMismatchText) } else if (!accountMatched.accountIsActive) { @@ -714,6 +815,7 @@ const recordFundsInOut = async (payload, params, enums) => { } return await Kafka.produceGeneralMessage(Config.KAFKA_CONFIG, KafkaProducer, Enum.Events.Event.Type.ADMIN, Enum.Events.Event.Action.TRANSFER, messageProtocol, Enum.Events.EventStatus.SUCCESS) } catch (err) { + log.error('error recording funds in/out', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } @@ -722,17 +824,21 @@ const validateHubAccounts = async (currency) => { const ledgerAccountTypes = await Enums.getEnums('ledgerAccountType') const hubReconciliationAccountExists = await ParticipantCurrencyModel.hubAccountExists(currency, ledgerAccountTypes.HUB_RECONCILIATION) if (!hubReconciliationAccountExists) { + logger.error('Hub reconciliation account for the specified currency does not exist') throw ErrorHandler.Factory.createFSPIOPError(ErrorHandler.Enums.FSPIOPErrorCodes.ADD_PARTY_INFO_ERROR, 'Hub reconciliation account for the specified currency does not exist') } const hubMlnsAccountExists = await ParticipantCurrencyModel.hubAccountExists(currency, ledgerAccountTypes.HUB_MULTILATERAL_SETTLEMENT) if (!hubMlnsAccountExists) { + logger.error('Hub multilateral net settlement account for the specified currency does not exist') throw ErrorHandler.Factory.createFSPIOPError(ErrorHandler.Enums.FSPIOPErrorCodes.ADD_PARTY_INFO_ERROR, 'Hub multilateral net settlement account for the specified currency does not exist') } return true } const createAssociatedParticipantAccounts = async (currency, ledgerAccountTypeId, trx) => { + const log = logger.child({ currency, ledgerAccountTypeId }) try { + log.info('creating associated participant accounts') const nonHubParticipantWithCurrencies = await ParticipantFacade.getAllNonHubParticipantsWithCurrencies(trx) const participantCurrencies = nonHubParticipantWithCurrencies.map(item => ({ @@ -760,6 +866,7 @@ const createAssociatedParticipantAccounts = async (currency, ledgerAccountTypeId } await ParticipantPositionModel.createParticipantPositionRecords(participantPositionRecords, trx) } catch (err) { + log.error('error creating associated participant accounts', err) throw ErrorHandler.Factory.reformatFSPIOPError(err) } } diff --git a/src/handlers/transfers/prepare.js b/src/handlers/transfers/prepare.js index 6daf6c0f5..77a4c7852 100644 --- a/src/handlers/transfers/prepare.js +++ b/src/handlers/transfers/prepare.js @@ -365,6 +365,12 @@ const prepare = async (error, messages) => { ProxyCache.getFSPProxy(initiatingFsp), ProxyCache.getFSPProxy(counterPartyFsp) ]) + logger.debug('Prepare proxy cache lookup results', { + initiatingFsp, + counterPartyFsp, + initiatingFspProxyOrParticipantId: proxyObligation.initiatingFspProxyOrParticipantId, + counterPartyFspProxyOrParticipantId: proxyObligation.counterPartyFspProxyOrParticipantId + }) proxyObligation.isInitiatingFspProxy = !proxyObligation.initiatingFspProxyOrParticipantId.inScheme && proxyObligation.initiatingFspProxyOrParticipantId.proxyId !== null diff --git a/src/lib/proxyCache.js b/src/lib/proxyCache.js index 45e27ee62..21b4f6297 100644 --- a/src/lib/proxyCache.js +++ b/src/lib/proxyCache.js @@ -3,6 +3,7 @@ const { createProxyCache } = require('@mojaloop/inter-scheme-proxy-cache-lib') const { Enum } = require('@mojaloop/central-services-shared') const ParticipantService = require('../../src/domain/participant') const Config = require('./config.js') +const { logger } = require('../../src/shared/logger') let proxyCache @@ -33,6 +34,7 @@ const getCache = () => { } const getFSPProxy = async (dfspId) => { + logger.debug('Checking if dfspId is in scheme or proxy', { dfspId }) const participant = await ParticipantService.getByName(dfspId) return { inScheme: !!participant, @@ -41,6 +43,7 @@ const getFSPProxy = async (dfspId) => { } const checkSameCreditorDebtorProxy = async (debtorDfspId, creditorDfspId) => { + logger.debug('Checking if debtorDfspId and creditorDfspId are using the same proxy', { debtorDfspId, creditorDfspId }) const [debtorProxyId, creditorProxyId] = await Promise.all([ getCache().lookupProxyByDfspId(debtorDfspId), getCache().lookupProxyByDfspId(creditorDfspId) @@ -49,6 +52,7 @@ const checkSameCreditorDebtorProxy = async (debtorDfspId, creditorDfspId) => { } const getProxyParticipantAccountDetails = async (fspName, currency) => { + logger.debug('Getting account details for fspName and currency', { fspName, currency }) const proxyLookupResult = await getFSPProxy(fspName) if (proxyLookupResult.inScheme) { const participantCurrency = await ParticipantService.getAccountByNameAndCurrency( @@ -56,6 +60,7 @@ const getProxyParticipantAccountDetails = async (fspName, currency) => { currency, Enum.Accounts.LedgerAccountType.POSITION ) + logger.debug("Account details for fspName's currency", { fspName, currency, participantCurrency }) return { inScheme: true, participantCurrencyId: participantCurrency?.participantCurrencyId || null @@ -67,11 +72,13 @@ const getProxyParticipantAccountDetails = async (fspName, currency) => { currency, Enum.Accounts.LedgerAccountType.POSITION ) + logger.debug('Account details for proxy\'s currency', { proxyId: proxyLookupResult.proxyId, currency, participantCurrency }) return { inScheme: false, participantCurrencyId: participantCurrency?.participantCurrencyId || null } } + logger.debug('No proxy found for fspName', { fspName }) return { inScheme: false, participantCurrencyId: null diff --git a/src/shared/logger/Logger.js b/src/shared/logger/Logger.js deleted file mode 100644 index aaa9d5479..000000000 --- a/src/shared/logger/Logger.js +++ /dev/null @@ -1,101 +0,0 @@ -/***** - License - -------------- - Copyright © 2017 Bill & Melinda Gates Foundation - The Mojaloop files are made available by the Bill & Melinda Gates Foundation under the Apache License, Version 2.0 (the "License") and you may not use these files except in compliance with the License. You may obtain a copy of the License at - http://www.apache.org/licenses/LICENSE-2.0 - - Unless required by applicable law or agreed to in writing, the Mojaloop files are distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions and limitations under the License. - Contributors - -------------- - This is the official list of the Mojaloop project contributors for this file. - Names of the original copyright holders (individuals or organizations) - should be listed with a '*' in the first column. People who have - contributed from an organization can be listed under the organization - that actually holds the copyright for their contributions (see the - Gates Foundation organization for an example). Those individuals should have - their names indented and be marked with a '-'. Email address can be added - optionally within square brackets . - * Gates Foundation - - Name Surname - - * Eugen Klymniuk - -------------- - **********/ - -/* eslint-disable space-before-function-paren */ -const safeStringify = require('fast-safe-stringify') -const MlLogger = require('@mojaloop/central-services-logger') - -// update Logger impl. to avoid stringify string message: https://github.com/mojaloop/central-services-logger/blob/master/src/index.js#L49 -const makeLogString = (message, meta) => meta - ? `${message} - ${typeof meta === 'object' ? safeStringify(meta) : meta}` - : message - -// wrapper to avoid doing Logger.is{SomeLogLevel}Enabled checks everywhere -class Logger { - #log = MlLogger - - isErrorEnabled = this.#log.isErrorEnabled - // to be able to follow the same logic: log.isDebugEnabled && log.debug(`some log message: ${data}`) - isWarnEnabled = this.#log.isWarnEnabled - isAuditEnabled = this.#log.isAuditEnabled - isTraceEnabled = this.#log.isTraceEnabled - isInfoEnabled = this.#log.isInfoEnabled - isPerfEnabled = this.#log.isPerfEnabled - isVerboseEnabled = this.#log.isVerboseEnabled - isDebugEnabled = this.#log.isDebugEnabled - isSillyEnabled = this.#log.isSillyEnabled - - constructor (context = {}) { - this.context = context - } - - get log() { return this.#log } - - error(message, meta) { - this.isErrorEnabled && this.#log.error(this.#formatLog(message, meta)) - } - - warn(message, meta) { - this.isWarnEnabled && this.#log.warn(this.#formatLog(message, meta)) - } - - audit(message, meta) { - this.isAuditEnabled && this.#log.audit(this.#formatLog(message, meta)) - } - - trace(message, meta) { - this.isTraceEnabled && this.#log.trace(this.#formatLog(message, meta)) - } - - info(message, meta) { - this.isInfoEnabled && this.#log.info(this.#formatLog(message, meta)) - } - - perf(message, meta) { - this.isPerfEnabled && this.#log.perf(this.#formatLog(message, meta)) - } - - verbose(message, meta) { - this.isVerboseEnabled && this.#log.verbose(this.#formatLog(message, meta)) - } - - debug(message, meta) { - this.isDebugEnabled && this.#log.debug(this.#formatLog(message, meta)) - } - - silly(message, meta) { - this.isSillyEnabled && this.#log.silly(this.#formatLog(message, meta)) - } - - child(childContext = {}) { - return new Logger(Object.assign({}, this.context, childContext)) - } - - #formatLog(message, meta = {}) { - return makeLogString(message, Object.assign({}, meta, this.context)) - } -} - -module.exports = Logger diff --git a/src/shared/logger/index.js b/src/shared/logger/index.js index c1f42d932..96b77abeb 100644 --- a/src/shared/logger/index.js +++ b/src/shared/logger/index.js @@ -1,8 +1,8 @@ -const Logger = require('./Logger') +const { loggerFactory } = require('@mojaloop/central-services-logger/src/contextLogger') -const logger = new Logger() +const logger = loggerFactory('CL') // global logger module.exports = { logger, - Logger + loggerFactory } diff --git a/src/shared/loggingPlugin.js b/src/shared/loggingPlugin.js new file mode 100644 index 000000000..e0f01a991 --- /dev/null +++ b/src/shared/loggingPlugin.js @@ -0,0 +1,43 @@ +const { asyncStorage } = require('@mojaloop/central-services-logger/src/contextLogger') +const { logger } = require('./logger') // pass though options + +const loggingPlugin = { + name: 'loggingPlugin', + version: '1.0.0', + once: true, + register: async (server, options) => { + // const { logger } = options; + server.ext({ + type: 'onPreHandler', + method: (request, h) => { + const { path, method, headers, payload, query } = request + const { remoteAddress } = request.info + const requestId = request.info.id = `${request.info.id}__${headers.traceid}` + asyncStorage.enterWith({ requestId }) + + logger.isInfoEnabled && logger.info(`[==> req] ${method.toUpperCase()} ${path}`, { headers, payload, query, remoteAddress }) + return h.continue + } + }) + + server.ext({ + type: 'onPreResponse', + method: (request, h) => { + if (logger.isInfoEnabled) { + const { path, method, headers, payload, query, response } = request + const { received } = request.info + + const statusCode = response instanceof Error + ? response.output?.statusCode + : response.statusCode + const respTimeSec = ((Date.now() - received) / 1000).toFixed(3) + + logger.info(`[<== ${statusCode}][${respTimeSec} s] ${method.toUpperCase()} ${path}`, { headers, payload, query }) + } + return h.continue + } + }) + } +} + +module.exports = loggingPlugin diff --git a/src/shared/plugins.js b/src/shared/plugins.js index 9717dec5e..f1afa820a 100644 --- a/src/shared/plugins.js +++ b/src/shared/plugins.js @@ -7,6 +7,7 @@ const Blipp = require('blipp') const ErrorHandling = require('@mojaloop/central-services-error-handling') const APIDocumentation = require('@mojaloop/central-services-shared').Util.Hapi.APIDocumentation const Config = require('../lib/config') +const LoggingPlugin = require('./loggingPlugin') const registerPlugins = async (server) => { if (Config.API_DOC_ENDPOINTS_ENABLED) { @@ -39,6 +40,11 @@ const registerPlugins = async (server) => { plugin: require('hapi-auth-bearer-token') }) + await server.register({ + plugin: LoggingPlugin, + options: {} + }) + await server.register([Inert, Vision, Blipp, ErrorHandling]) } diff --git a/test/unit/handlers/transfers/FxFulfilService.test.js b/test/unit/handlers/transfers/FxFulfilService.test.js index e0a507d7f..72827f920 100644 --- a/test/unit/handlers/transfers/FxFulfilService.test.js +++ b/test/unit/handlers/transfers/FxFulfilService.test.js @@ -35,7 +35,7 @@ const Validator = require('../../../../src/handlers/transfers/validator') const FxTransferModel = require('../../../../src/models/fxTransfer') const Config = require('../../../../src/lib/config') const { ERROR_MESSAGES } = require('../../../../src/shared/constants') -const { Logger } = require('../../../../src/shared/logger') +const { logger } = require('../../../../src/shared/logger') const ProxyCache = require('#src/lib/proxyCache') const fixtures = require('../../../fixtures') @@ -46,7 +46,7 @@ const { Kafka, Comparators, Hash } = Util const { Action } = Enum.Events.Event const { TOPICS } = fixtures -const log = new Logger() +const log = logger // const functionality = Type.NOTIFICATION Test('FxFulfilService Tests -->', fxFulfilTest => {