From 5292ad49d6c06e5efd563826c60df148a6b0185e Mon Sep 17 00:00:00 2001 From: Nathan Lie Date: Wed, 11 Jul 2018 17:34:32 -0500 Subject: [PATCH] feat: trace level logging (#437) --- package-lock.json | 33 ++++++++++++++----- src/backends/ecb-plus-xrp.ts | 2 +- src/backends/ecb.ts | 16 ++++----- src/backends/one-to-one.ts | 4 +-- src/backends/randomizer.ts | 4 +-- src/common/log.ts | 37 ++++++++++++++++++--- src/controllers/ccp.ts | 4 +-- src/controllers/echo.ts | 4 +-- src/controllers/ildcp-host.ts | 2 +- src/controllers/ilp-prepare.ts | 8 ++--- src/controllers/ilqp.ts | 2 +- src/index.ts | 3 +- src/middlewares/balance.ts | 14 ++++---- src/middlewares/max-packet-amount.ts | 2 +- src/middlewares/rate-limit.ts | 2 +- src/middlewares/throughput.ts | 4 +-- src/middlewares/validate-fulfillment.ts | 2 +- src/routing/ccp-receiver.ts | 14 ++++---- src/routing/ccp-sender.ts | 10 +++--- src/routing/dragon.ts | 2 +- src/services/accounts.ts | 10 +++--- src/services/config.ts | 2 +- src/services/core.ts | 4 +-- src/services/middleware-manager.ts | 2 +- src/services/quoter.ts | 8 ++--- src/services/route-broadcaster.ts | 14 ++++---- src/services/route-builder.ts | 44 ++++++++++++------------- 27 files changed, 150 insertions(+), 103 deletions(-) diff --git a/package-lock.json b/package-lock.json index 7c542447..e977425f 100644 --- a/package-lock.json +++ b/package-lock.json @@ -721,6 +721,11 @@ "resolved": "https://registry.npmjs.org/bindings/-/bindings-1.3.0.tgz", "integrity": "sha512-DpLh5EzMR2kzvX1KIlVC0VkC3iZtHKTgdtZ0a3pglBZdaQFjt5S9g9xd1lE+YvXyfd6mtCeRnrUfOLYiTMlNSw==" }, + "bintrees": { + "version": "1.0.1", + "resolved": "https://registry.npmjs.org/bintrees/-/bintrees-1.0.1.tgz", + "integrity": "sha1-DmVcm5wkNeqraL9AJyJtK1WjRSQ=" + }, "bl": { "version": "1.2.1", "resolved": "https://registry.npmjs.org/bl/-/bl-1.2.1.tgz", @@ -2455,14 +2460,12 @@ "balanced-match": { "version": "1.0.0", "bundled": true, - "dev": true, - "optional": true + "dev": true }, "brace-expansion": { "version": "1.1.11", "bundled": true, "dev": true, - "optional": true, "requires": { "balanced-match": "1.0.0", "concat-map": "0.0.1" @@ -2482,8 +2485,7 @@ "concat-map": { "version": "0.0.1", "bundled": true, - "dev": true, - "optional": true + "dev": true }, "console-control-strings": { "version": "1.1.0", @@ -2631,7 +2633,6 @@ "version": "3.0.4", "bundled": true, "dev": true, - "optional": true, "requires": { "brace-expansion": "1.1.11" } @@ -6829,6 +6830,14 @@ "integrity": "sha1-ihvjZr+Pwj2yvSPxDG/pILQ4nR8=", "dev": true }, + "prom-client": { + "version": "11.1.1", + "resolved": "https://registry.npmjs.org/prom-client/-/prom-client-11.1.1.tgz", + "integrity": "sha512-itUicyrq3Rko56v3ovQAMYwxEouK7lIylp26bjnlt1b/3fzn783riZnZn432I4udYmPsRgNx1F/u9RFvLyH7zA==", + "requires": { + "tdigest": "0.1.1" + } + }, "promise-polyfill": { "version": "6.1.0", "resolved": "https://registry.npmjs.org/promise-polyfill/-/promise-polyfill-6.1.0.tgz", @@ -7218,8 +7227,8 @@ "resolved": "https://registry.npmjs.org/riverpig/-/riverpig-1.1.4.tgz", "integrity": "sha512-V2hBp+E8a6MpV7hXGlX0gelkC1gTHTa6a+JQ8t2+IjnhTesDYIpBwI7IG+qtb7aTj4A2R0SnOcUDLjLSBc3A6A==", "requires": { - "chalk": "^2.3.0", - "debug": "^3.1.0" + "chalk": "2.3.0", + "debug": "3.1.0" } }, "run-async": { @@ -7869,6 +7878,14 @@ "xtend": "4.0.1" } }, + "tdigest": { + "version": "0.1.1", + "resolved": "https://registry.npmjs.org/tdigest/-/tdigest-0.1.1.tgz", + "integrity": "sha1-Ljyyw56kSeVdHmzZEReszKRYgCE=", + "requires": { + "bintrees": "1.0.1" + } + }, "term-size": { "version": "1.2.0", "resolved": "https://registry.npmjs.org/term-size/-/term-size-1.2.0.tgz", diff --git a/src/backends/ecb-plus-xrp.ts b/src/backends/ecb-plus-xrp.ts index 17d8622b..ac146334 100644 --- a/src/backends/ecb-plus-xrp.ts +++ b/src/backends/ecb-plus-xrp.ts @@ -24,7 +24,7 @@ export default class ECBAndXRPBackend extends ECBBackend { } const body = await rateRes.json() const rate = Number(body.rate).toFixed(5) - log.debug('loaded EUR/XRP rate. rate=%s', rate) + log.trace('loaded EUR/XRP rate. rate=%s', rate) return Number(rate) } } diff --git a/src/backends/ecb.ts b/src/backends/ecb.ts index ae1e3d23..4febcb2c 100644 --- a/src/backends/ecb.ts +++ b/src/backends/ecb.ts @@ -56,10 +56,10 @@ export default class ECBBackend implements BackendInstance { async connect () { let apiData if (this.mockData) { - log.debug('connect using mock data.') + log.info('connect using mock data.') apiData = this.mockData } else { - log.debug('connect. uri=' + this.ratesApiUrl) + log.info('connect. uri=' + this.ratesApiUrl) let result = await fetchUri(this.ratesApiUrl) apiData = await parseXMLResponse(await result.text()) } @@ -67,7 +67,7 @@ export default class ECBBackend implements BackendInstance { this.rates[apiData.base] = 1 this.currencies = Object.keys(this.rates) this.currencies.sort() - log.debug('data loaded. noCurrencies=' + this.currencies.length) + log.info('data loaded. numCurrencies=' + this.currencies.length) } _formatAmount (amount: string) { @@ -90,11 +90,11 @@ export default class ECBBackend implements BackendInstance { const destinationInfo = this.getInfo(destinationAccount) if (!sourceInfo) { - log.warn('unable to fetch account info for source account. accountId=%s', sourceAccount) + log.error('unable to fetch account info for source account. accountId=%s', sourceAccount) throw new Error('unable to fetch account info for source account. accountId=' + sourceAccount) } if (!destinationInfo) { - log.warn('unable to fetch account info for destination account. accountId=%s', destinationAccount) + log.error('unable to fetch account info for destination account. accountId=%s', destinationAccount) throw new Error('unable to fetch account info for destination account. accountId=' + destinationAccount) } @@ -106,12 +106,12 @@ export default class ECBBackend implements BackendInstance { const destinationRate = this.rates[destinationCurrency] if (!sourceRate) { - log.warn('no rate available for source currency. currency=%s', sourceCurrency) + log.error('no rate available for source currency. currency=%s', sourceCurrency) throw new Error('no rate available. currency=' + sourceCurrency) } if (!destinationRate) { - log.warn('no rate available for destination currency. currency=%s', destinationCurrency) + log.error('no rate available for destination currency. currency=%s', destinationCurrency) throw new Error('no rate available. currency=' + destinationCurrency) } @@ -126,7 +126,7 @@ export default class ECBBackend implements BackendInstance { .times(new BigNumber(1).minus(this.spread)) .toPrecision(15) - log.debug('quoted rate. from=%s to=%s fromCur=%s toCur=%s rate=%s spread=%s', sourceAccount, destinationAccount, sourceCurrency, destinationCurrency, rate, this.spread) + log.trace('quoted rate. from=%s to=%s fromCur=%s toCur=%s rate=%s spread=%s', sourceAccount, destinationAccount, sourceCurrency, destinationCurrency, rate, this.spread) return Number(rate) } diff --git a/src/backends/one-to-one.ts b/src/backends/one-to-one.ts index 02069fd4..8be96c34 100644 --- a/src/backends/one-to-one.ts +++ b/src/backends/one-to-one.ts @@ -50,11 +50,11 @@ export default class OneToOneBackend implements BackendInstance { const destinationInfo = this.getInfo(destinationAccount) if (!sourceInfo) { - log.warn('unable to fetch account info for source account. accountId=%s', sourceAccount) + log.error('unable to fetch account info for source account. accountId=%s', sourceAccount) throw new Error('unable to fetch account info for source account. accountId=' + sourceAccount) } if (!destinationInfo) { - log.warn('unable to fetch account info for destination account. accountId=%s', destinationAccount) + log.error('unable to fetch account info for destination account. accountId=%s', destinationAccount) throw new Error('unable to fetch account info for destination account. accountId=' + destinationAccount) } diff --git a/src/backends/randomizer.ts b/src/backends/randomizer.ts index c978dc1d..8d235ce7 100644 --- a/src/backends/randomizer.ts +++ b/src/backends/randomizer.ts @@ -55,11 +55,11 @@ export default class RandomizerBackend implements BackendInstance { const destinationInfo = this.getInfo(destinationAccount) if (!sourceInfo) { - log.warn('unable to fetch account info for source account. accountId=%s', sourceAccount) + log.error('unable to fetch account info for source account. accountId=%s', sourceAccount) throw new Error('unable to fetch account info for source account. accountId=' + sourceAccount) } if (!destinationInfo) { - log.warn('unable to fetch account info for destination account. accountId=%s', destinationAccount) + log.error('unable to fetch account info for destination account. accountId=%s', destinationAccount) throw new Error('unable to fetch account info for destination account. accountId=' + destinationAccount) } diff --git a/src/common/log.ts b/src/common/log.ts index cc42d10f..fa958ba7 100644 --- a/src/common/log.ts +++ b/src/common/log.ts @@ -1,15 +1,44 @@ import * as riverpig from 'riverpig' +import { LoggerConfig } from 'riverpig' +import { Logger } from 'riverpig' +import * as debug from 'debug' import through2 = require('through2') const logStream = through2() logStream.pipe(process.stdout) -// TODO: Not clear why I needed this, but got a -// TypeScript error without it. -export interface ConnectorLogger extends riverpig.Logger { } +export class ConnectorLogger { + river: any + tracer: any + + constructor (namespace: string, config0?: LoggerConfig) { + this.river = riverpig(namespace, config0) + this.tracer = this.river.trace || debug(namespace + ':trace') + } + + info (msg: any, ...elements: any[]): void { + this.river.info(msg, ...elements) + } + + warn (msg: any, ...elements: any[]): void { + this.river.warn(msg, ...elements) + } + + error (msg: any, ...elements: any[]): void { + this.river.error(msg, ...elements) + } + + debug (msg: any, ...elements: any[]): void { + this.river.debug(msg, ...elements) + } + + trace (msg: any, ...elements: any[]): void { + this.tracer(msg, ...elements) + } +} export const createRaw = (namespace: string): ConnectorLogger => { - return riverpig(namespace, { + return new ConnectorLogger(namespace, { stream: logStream }) } diff --git a/src/controllers/ccp.ts b/src/controllers/ccp.ts index 285165f1..1c2f409d 100644 --- a/src/controllers/ccp.ts +++ b/src/controllers/ccp.ts @@ -35,7 +35,7 @@ export default class CcpController { async handleRouteControl (data: Buffer, sourceAccount: string) { const routeControl = deserializeCcpRouteControlRequest(data) - log.debug('received route control message. sender=%s, tableId=%s epoch=%s features=%s', sourceAccount, routeControl.lastKnownRoutingTableId, routeControl.lastKnownEpoch, routeControl.features.join(',')) + log.trace('received route control message. sender=%s, tableId=%s epoch=%s features=%s', sourceAccount, routeControl.lastKnownRoutingTableId, routeControl.lastKnownEpoch, routeControl.features.join(',')) this.routeBroadcaster.handleRouteControl(sourceAccount, routeControl) @@ -44,7 +44,7 @@ export default class CcpController { async handleRouteUpdate (data: Buffer, sourceAccount: string) { const routeUpdate = deserializeCcpRouteUpdateRequest(data) - log.debug('received routes. sender=%s speaker=%s currentEpoch=%s fromEpoch=%s toEpoch=%s newRoutes=%s withdrawnRoutes=%s', sourceAccount, routeUpdate.speaker, routeUpdate.currentEpochIndex, routeUpdate.fromEpochIndex, routeUpdate.toEpochIndex, routeUpdate.newRoutes.length, routeUpdate.withdrawnRoutes.length) + log.trace('received routes. sender=%s speaker=%s currentEpoch=%s fromEpoch=%s toEpoch=%s newRoutes=%s withdrawnRoutes=%s', sourceAccount, routeUpdate.speaker, routeUpdate.currentEpochIndex, routeUpdate.fromEpochIndex, routeUpdate.toEpochIndex, routeUpdate.newRoutes.length, routeUpdate.withdrawnRoutes.length) this.routeBroadcaster.handleRouteUpdate(sourceAccount, routeUpdate) diff --git a/src/controllers/echo.ts b/src/controllers/echo.ts index dd25a408..5f540d14 100644 --- a/src/controllers/echo.ts +++ b/src/controllers/echo.ts @@ -44,7 +44,7 @@ export default class EchoController { if (type === 0) { const sourceAddress = reader.readVarOctetString().toString('ascii') - log.debug('responding to ping. sourceAccount=%s sourceAddress=%s cond=%s', sourceAccount, sourceAddress, parsedPacket.executionCondition.slice(0, 9).toString('base64')) + log.trace('responding to ping. sourceAccount=%s sourceAddress=%s cond=%s', sourceAccount, sourceAddress, parsedPacket.executionCondition.slice(0, 9).toString('base64')) const nextHop = this.routeBuilder.getNextHop(sourceAccount, sourceAddress) @@ -62,7 +62,7 @@ export default class EchoController { data: writer.getBuffer() }), nextHop) } else { - log.debug('received unexpected ping response. sourceAccount=%s', sourceAccount) + log.error('received unexpected ping response. sourceAccount=%s', sourceAccount) throw new InvalidPacketError('unexpected ping response.') } } diff --git a/src/controllers/ildcp-host.ts b/src/controllers/ildcp-host.ts index ac55817e..16120c60 100644 --- a/src/controllers/ildcp-host.ts +++ b/src/controllers/ildcp-host.ts @@ -14,7 +14,7 @@ export default class IldcpHostController { async handle (data: Buffer, sourceAccount: string) { const clientAddress = this.accounts.getChildAddress(sourceAccount) const info = this.accounts.getInfo(sourceAccount) - log.debug('responding to ILDCP config request. clientAddress=%s', clientAddress) + log.trace('responding to ILDCP config request. clientAddress=%s', clientAddress) return ILDCP.serve({ requestPacket: data, diff --git a/src/controllers/ilp-prepare.ts b/src/controllers/ilp-prepare.ts index c35e2db4..ef5e1921 100644 --- a/src/controllers/ilp-prepare.ts +++ b/src/controllers/ilp-prepare.ts @@ -34,7 +34,7 @@ export default class IlpPrepareController { const parsedPacket = IlpPacket.deserializeIlpPrepare(packet) const { amount, executionCondition, destination, expiresAt } = parsedPacket - log.debug('handling ilp prepare. sourceAccount=%s destination=%s amount=%s condition=%s expiry=%s packet=%s', sourceAccount, destination, amount, executionCondition.toString('base64'), expiresAt.toISOString(), packet.toString('base64')) + log.trace('handling ilp prepare. sourceAccount=%s destination=%s amount=%s condition=%s expiry=%s packet=%s', sourceAccount, destination, amount, executionCondition.toString('base64'), expiresAt.toISOString(), packet.toString('base64')) if (destination.startsWith(PEER_PROTOCOL_PREFIX)) { return this.peerProtocolController.handle(packet, sourceAccount, { parsedPacket }) @@ -44,11 +44,11 @@ export default class IlpPrepareController { const { nextHop, nextHopPacket } = await this.routeBuilder.getNextHopPacket(sourceAccount, parsedPacket) - log.debug('sending outbound ilp prepare. destination=%s amount=%s', destination, nextHopPacket.amount) + log.trace('sending outbound ilp prepare. destination=%s amount=%s', destination, nextHopPacket.amount) const result = await outbound(IlpPacket.serializeIlpPrepare(nextHopPacket), nextHop) if (result[0] === IlpPacket.Type.TYPE_ILP_FULFILL) { - log.debug('got fulfillment. cond=%s nextHop=%s amount=%s', executionCondition.slice(0, 6).toString('base64'), nextHop, nextHopPacket.amount) + log.trace('got fulfillment. cond=%s nextHop=%s amount=%s', executionCondition.slice(0, 6).toString('base64'), nextHop, nextHopPacket.amount) this.backend.submitPayment({ sourceAccount: sourceAccount, @@ -58,7 +58,7 @@ export default class IlpPrepareController { }) .catch(err => { const errInfo = (err && typeof err === 'object' && err.stack) ? err.stack : String(err) - log.warn('error while submitting payment to backend. error=%s', errInfo) + log.error('error while submitting payment to backend. error=%s', errInfo) }) } diff --git a/src/controllers/ilqp.ts b/src/controllers/ilqp.ts index 9e98f72b..b05c9bd0 100644 --- a/src/controllers/ilqp.ts +++ b/src/controllers/ilqp.ts @@ -13,7 +13,7 @@ export default class IlqpController { } async sendData (packet: Buffer, sourceAccount: string) { - log.debug('responding to ILQP quote request. clientName=' + sourceAccount) + log.trace('responding to ILQP quote request. clientName=' + sourceAccount) switch (packet[0]) { case IlpPacket.Type.TYPE_ILQP_LIQUIDITY_REQUEST: diff --git a/src/index.ts b/src/index.ts index b3b52917..53987726 100644 --- a/src/index.ts +++ b/src/index.ts @@ -4,6 +4,7 @@ require('source-map-support').install() import createApp from './app' import { create as createLogger } from './common/log' + const log = createLogger('app') module.exports = { @@ -36,7 +37,7 @@ if (!module.parent) { process.exit(0) } catch (err) { const errInfo = (err && typeof err === 'object' && err.stack) ? err.stack : err - console.error('error while shutting down. error=%s', errInfo) + log.error('error while shutting down. error=%s', errInfo) process.exit(1) } }) diff --git a/src/middlewares/balance.ts b/src/middlewares/balance.ts index 5717abe6..f5516df1 100644 --- a/src/middlewares/balance.ts +++ b/src/middlewares/balance.ts @@ -32,7 +32,7 @@ class Balance { const newBalance = this.balance.plus(amount) if (newBalance.gt(this.maximum)) { - log.info('rejected balance update. oldBalance=%s newBalance=%s amount=%s', this.balance, newBalance, amount) + log.error('rejected balance update. oldBalance=%s newBalance=%s amount=%s', this.balance, newBalance, amount) throw new InsufficientLiquidityError('exceeded maximum balance.') } @@ -43,7 +43,7 @@ class Balance { const newBalance = this.balance.minus(amount) if (newBalance.lt(this.minimum)) { - log.info('rejected balance update. oldBalance=%s newBalance=%s amount=%s', this.balance, newBalance, amount) + log.error('rejected balance update. oldBalance=%s newBalance=%s amount=%s', this.balance, newBalance, amount) throw new Error(`insufficient funds. oldBalance=${this.balance} proposedBalance=${newBalance}`) } @@ -93,7 +93,7 @@ export default class BalanceMiddleware implements Middleware { }) this.balances.set(accountId, balance) - log.debug('initializing balance for account. accountId=%s minimumBalance=%s maximumBalance=%s', accountId, minimum, maximum) + log.info('initializing balance for account. accountId=%s minimumBalance=%s maximumBalance=%s', accountId, minimum, maximum) pipelines.startup.insertLast({ name: 'balance', @@ -120,7 +120,7 @@ export default class BalanceMiddleware implements Middleware { // Increase balance on prepare balance.add(parsedPacket.amount) - log.debug('balance increased due to incoming ilp prepare. accountId=%s amount=%s newBalance=%s', accountId, parsedPacket.amount, balance.getValue()) + log.trace('balance increased due to incoming ilp prepare. accountId=%s amount=%s newBalance=%s', accountId, parsedPacket.amount, balance.getValue()) this.stats.balance.setValue(account, {}, balance.getValue().toNumber()) let result @@ -157,7 +157,7 @@ export default class BalanceMiddleware implements Middleware { name: 'balance', method: async (amount: string, next: MiddlewareCallback) => { balance.subtract(amount) - log.debug('balance reduced due to incoming settlement. accountId=%s amount=%s newBalance=%s', accountId, amount, balance.getValue()) + log.trace('balance reduced due to incoming settlement. accountId=%s amount=%s newBalance=%s', accountId, amount, balance.getValue()) this.stats.balance.setValue(account, {}, balance.getValue().toNumber()) return next(amount) } @@ -192,7 +192,7 @@ export default class BalanceMiddleware implements Middleware { // Decrease balance on prepare balance.subtract(parsedPacket.amount) this.maybeSettle(accountId).catch(log.error) - log.debug('balance decreased due to outgoing ilp fulfill. accountId=%s amount=%s newBalance=%s', accountId, parsedPacket.amount, balance.getValue()) + log.trace('balance decreased due to outgoing ilp fulfill. accountId=%s amount=%s newBalance=%s', accountId, parsedPacket.amount, balance.getValue()) this.stats.balance.setValue(account, {}, balance.getValue().toNumber()) this.stats.outgoingDataPacketValue.increment(account, { result : 'fulfilled' }, +parsedPacket.amount) } @@ -208,7 +208,7 @@ export default class BalanceMiddleware implements Middleware { name: 'balance', method: async (amount: string, next: MiddlewareCallback) => { balance.add(amount) - log.debug('balance increased due to outgoing settlement. accountId=%s amount=%s newBalance=%s', accountId, amount, balance.getValue()) + log.trace('balance increased due to outgoing settlement. accountId=%s amount=%s newBalance=%s', accountId, amount, balance.getValue()) this.stats.balance.setValue(account, {}, balance.getValue().toNumber()) return next(amount) diff --git a/src/middlewares/max-packet-amount.ts b/src/middlewares/max-packet-amount.ts index 7b85d333..c0f52e2a 100644 --- a/src/middlewares/max-packet-amount.ts +++ b/src/middlewares/max-packet-amount.ts @@ -30,7 +30,7 @@ export default class MaxPacketAmountMiddleware implements Middleware { const amount = new BigNumber(parsedPacket.amount) if (amount.gt(maxPacketAmount)) { - log.info('rejecting packet for exceeding max amount. accountId=%s maxAmount=%s actualAmount=%s', accountId, maxPacketAmount, parsedPacket.amount) + log.debug('rejecting packet for exceeding max amount. accountId=%s maxAmount=%s actualAmount=%s', accountId, maxPacketAmount, parsedPacket.amount) throw new AmountTooLargeError(`packet size too large. maxAmount=${maxPacketAmount} actualAmount=${parsedPacket.amount}`, { receivedAmount: parsedPacket.amount, maximumAmount: maxPacketAmount diff --git a/src/middlewares/rate-limit.ts b/src/middlewares/rate-limit.ts index 6b80b5c4..a1bfa2bc 100644 --- a/src/middlewares/rate-limit.ts +++ b/src/middlewares/rate-limit.ts @@ -35,7 +35,7 @@ export default class RateLimitMiddleware implements Middleware { capacity = refillCount } = accountInfo.rateLimit || {} - log.debug('created token bucket for account. accountId=%s refillPeriod=%s refillCount=%s capacity=%s', accountId, refillPeriod, refillCount, capacity) + log.trace('created token bucket for account. accountId=%s refillPeriod=%s refillCount=%s capacity=%s', accountId, refillPeriod, refillCount, capacity) // TODO: When we add the ability to update middleware, our state will get // reset every update, which may not be desired. diff --git a/src/middlewares/throughput.ts b/src/middlewares/throughput.ts index 5afed1f9..8c63be2c 100644 --- a/src/middlewares/throughput.ts +++ b/src/middlewares/throughput.ts @@ -32,7 +32,7 @@ export default class ThroughputMiddleware implements Middleware { // TODO: When we add the ability to update middleware, our state will get // reset every update, which may not be desired. const incomingBucket = new TokenBucket({ refillPeriod, refillCount: Number(incomingAmount) }) - log.debug('created incoming amount limit token bucket for account. accountId=%s refillPeriod=%s incomingAmount=%s', accountId, refillPeriod, incomingAmount) + log.trace('created incoming amount limit token bucket for account. accountId=%s refillPeriod=%s incomingAmount=%s', accountId, refillPeriod, incomingAmount) pipelines.incomingData.insertLast({ name: 'throughput', @@ -57,7 +57,7 @@ export default class ThroughputMiddleware implements Middleware { // TODO: When we add the ability to update middleware, our state will get // reset every update, which may not be desired. const incomingBucket = new TokenBucket({ refillPeriod, refillCount: Number(outgoingAmount) }) - log.debug('created outgoing amount limit token bucket for account. accountId=%s refillPeriod=%s outgoingAmount=%s', accountId, refillPeriod, outgoingAmount) + log.trace('created outgoing amount limit token bucket for account. accountId=%s refillPeriod=%s outgoingAmount=%s', accountId, refillPeriod, outgoingAmount) pipelines.outgoingData.insertLast({ name: 'throughput', diff --git a/src/middlewares/validate-fulfillment.ts b/src/middlewares/validate-fulfillment.ts index 0dea71ba..3d0f1259 100644 --- a/src/middlewares/validate-fulfillment.ts +++ b/src/middlewares/validate-fulfillment.ts @@ -20,7 +20,7 @@ export default class ValidateFulfillmentMiddleware implements Middleware { const calculatedCondition = createHash('sha256').update(fulfillment).digest() if (!calculatedCondition.equals(executionCondition)) { - log.warn('received incorrect fulfillment from account. accountId=%s fulfillment=%s calculatedCondition=%s executionCondition=%s', accountId, fulfillment.toString('base64'), calculatedCondition.toString('base64'), executionCondition.toString('base64')) + log.error('received incorrect fulfillment from account. accountId=%s fulfillment=%s calculatedCondition=%s executionCondition=%s', accountId, fulfillment.toString('base64'), calculatedCondition.toString('base64'), executionCondition.toString('base64')) throw new UnreachableError('fulfillment did not match expected value.') } } diff --git a/src/routing/ccp-receiver.ts b/src/routing/ccp-receiver.ts index 5d6dd2a3..ff6bbcf8 100644 --- a/src/routing/ccp-receiver.ts +++ b/src/routing/ccp-receiver.ts @@ -97,32 +97,32 @@ export default class CcpReceiver { this.bump(holdDownTime) if (this.routingTableId !== routingTableId) { - this.log.info('saw new routing table. oldId=%s newId=%s', this.routingTableId, routingTableId) + this.log.trace('saw new routing table. oldId=%s newId=%s', this.routingTableId, routingTableId) this.routingTableId = routingTableId this.epoch = 0 } if (fromEpochIndex > this.epoch) { // There is a gap, we need to go back to the last epoch we have - this.log.debug('gap in routing updates. expectedEpoch=%s actualFromEpoch=%s', this.epoch, fromEpochIndex) + this.log.trace('gap in routing updates. expectedEpoch=%s actualFromEpoch=%s', this.epoch, fromEpochIndex) return [] } if (this.epoch > toEpochIndex) { // This routing update is older than what we already have - this.log.debug('old routing update, ignoring. expectedEpoch=%s actualToEpoch=%s', this.epoch, toEpochIndex) + this.log.trace('old routing update, ignoring. expectedEpoch=%s actualToEpoch=%s', this.epoch, toEpochIndex) return [] } // just a heartbeat if (newRoutes.length === 0 && withdrawnRoutes.length === 0) { - this.log.debug('pure heartbeat. fromEpoch=%s toEpoch=%s', fromEpochIndex, toEpochIndex) + this.log.trace('pure heartbeat. fromEpoch=%s toEpoch=%s', fromEpochIndex, toEpochIndex) this.epoch = toEpochIndex return [] } const changedPrefixes: string[] = [] if (withdrawnRoutes.length > 0) { - this.log.debug('informed of no longer reachable routes. count=%s routes=%s', withdrawnRoutes.length, withdrawnRoutes) + this.log.trace('informed of no longer reachable routes. count=%s routes=%s', withdrawnRoutes.length, withdrawnRoutes) for (const prefix of withdrawnRoutes) { if (this.deleteRoute(prefix)) { changedPrefixes.push(prefix) @@ -143,7 +143,7 @@ export default class CcpReceiver { this.epoch = toEpochIndex - this.log.info('applied route update. changedPrefixesCount=%s fromEpoch=%s toEpoch=%s', changedPrefixes.length, fromEpochIndex, toEpochIndex) + this.log.trace('applied route update. changedPrefixesCount=%s fromEpoch=%s toEpoch=%s', changedPrefixes.length, fromEpochIndex, toEpochIndex) return changedPrefixes } @@ -168,7 +168,7 @@ export default class CcpReceiver { this.plugin.sendData(serializeCcpRouteControlRequest(routeControl)) .then(data => { if (data[0] === Type.TYPE_ILP_FULFILL) { - this.log.debug('successfully sent route control message.') + this.log.trace('successfully sent route control message.') } else if (data[0] === Type.TYPE_ILP_REJECT) { this.log.debug('route control message was rejected. rejection=%j', deserializeIlpReject(data)) throw new Error('route control message rejected.') diff --git a/src/routing/ccp-sender.ts b/src/routing/ccp-sender.ts index 3c6de587..ebddc5d9 100644 --- a/src/routing/ccp-sender.ts +++ b/src/routing/ccp-sender.ts @@ -111,15 +111,15 @@ export default class CcpSender { features }: CcpRouteControlRequest) { if (this.mode !== mode) { - this.log.debug('peer requested changing routing mode. oldMode=%s newMode=%s', ModeReverseMap[this.mode], ModeReverseMap[mode]) + this.log.trace('peer requested changing routing mode. oldMode=%s newMode=%s', ModeReverseMap[this.mode], ModeReverseMap[mode]) } this.mode = mode if (lastKnownRoutingTableId !== this.forwardingRoutingTable.routingTableId) { - this.log.debug('peer has old routing table id, resetting lastKnownEpoch to zero. theirTableId=%s correctTableId=%s', lastKnownRoutingTableId, this.forwardingRoutingTable.routingTableId) + this.log.trace('peer has old routing table id, resetting lastKnownEpoch to zero. theirTableId=%s correctTableId=%s', lastKnownRoutingTableId, this.forwardingRoutingTable.routingTableId) this.lastKnownEpoch = 0 } else { - this.log.debug('peer epoch set. epoch=%s currentEpoch=%s', this.accountId, lastKnownEpoch, this.forwardingRoutingTable.currentEpoch) + this.log.trace('peer epoch set. epoch=%s currentEpoch=%s', this.accountId, lastKnownEpoch, this.forwardingRoutingTable.currentEpoch) this.lastKnownEpoch = lastKnownEpoch } @@ -159,7 +159,7 @@ export default class CcpSender { delay = Math.max(MINIMUM_UPDATE_INTERVAL, delay) - this.log.debug('scheduling next route update. accountId=%s delay=%s currentEpoch=%s peerHasEpoch=%s', this.accountId, delay, this.forwardingRoutingTable.currentEpoch, this.lastKnownEpoch) + this.log.trace('scheduling next route update. accountId=%s delay=%s currentEpoch=%s peerHasEpoch=%s', this.accountId, delay, this.forwardingRoutingTable.currentEpoch, this.lastKnownEpoch) this.sendRouteUpdateTimer = setTimeout(() => { this.sendSingleRouteUpdate() .then(() => this.scheduleRouteUpdate()) @@ -233,7 +233,7 @@ export default class CcpSender { } } - this.log.debug('broadcasting routes to peer. speaker=%s peer=%s fromEpoch=%s toEpoch=%s routeCount=%s unreachableCount=%s', this.getOwnAddress(), this.accountId, this.lastKnownEpoch, toEpoch, newRoutes.length, withdrawnRoutes.length) + this.log.trace('broadcasting routes to peer. speaker=%s peer=%s fromEpoch=%s toEpoch=%s routeCount=%s unreachableCount=%s', this.getOwnAddress(), this.accountId, this.lastKnownEpoch, toEpoch, newRoutes.length, withdrawnRoutes.length) const routeUpdate: CcpRouteUpdateRequest = { speaker: this.getOwnAddress(), diff --git a/src/routing/dragon.ts b/src/routing/dragon.ts index 0b7908ae..a80ff0ff 100644 --- a/src/routing/dragon.ts +++ b/src/routing/dragon.ts @@ -59,7 +59,7 @@ export function canDragonFilter ( continue } - log.debug('applied DRAGON route filter. prefix=%s parentPrefix=%s', prefix, parentPrefix) + log.trace('applied DRAGON route filter. prefix=%s parentPrefix=%s', prefix, parentPrefix) return true } diff --git a/src/services/accounts.ts b/src/services/accounts.ts index 6f595102..8644bd57 100644 --- a/src/services/accounts.ts +++ b/src/services/accounts.ts @@ -47,7 +47,7 @@ export default class Accounts extends EventEmitter { } else if (this.config.ilpAddress === 'unknown' && inheritFrom) { const parent = this.getPlugin(inheritFrom) - log.debug('connecting to parent. accountId=%s', inheritFrom) + log.trace('connecting to parent. accountId=%s', inheritFrom) await parent.connect({}) const ildcpInfo = await ILDCP.fetch(parent.sendData.bind(parent)) @@ -78,7 +78,7 @@ export default class Accounts extends EventEmitter { } setOwnAddress (newAddress) { - log.info('setting ilp address. oldAddress=%s newAddress=%s', this.address, newAddress) + log.trace('setting ilp address. oldAddress=%s newAddress=%s', this.address, newAddress) this.address = newAddress } @@ -86,7 +86,7 @@ export default class Accounts extends EventEmitter { const account = this.accounts.get(accountId) if (!account) { - log.warn('could not find plugin for account id. accountId=%s', accountId) + log.error('could not find plugin for account id. accountId=%s', accountId) throw new Error('unknown account id. accountId=' + accountId) } @@ -105,7 +105,7 @@ export default class Accounts extends EventEmitter { const account = this.accounts.get(accountId) if (!account) { - log.debug('no currency found. account=%s', accountId) + log.error('no currency found. account=%s', accountId) return undefined } @@ -127,7 +127,7 @@ export default class Accounts extends EventEmitter { this.config.validateAccount(accountId, creds) } catch (err) { if (err.name === 'InvalidJsonBodyError') { - log.warn('validation error in account config. id=%s', accountId) + log.error('validation error in account config. id=%s', accountId) err.debugPrint(log.warn) throw new Error('error while adding account, see error log for details.') } diff --git a/src/services/config.ts b/src/services/config.ts index 32072ed1..b54cb783 100644 --- a/src/services/config.ts +++ b/src/services/config.ts @@ -79,7 +79,7 @@ export default class Config extends ConfigSchemaTyping { try { config[key] = JSON.parse(envValue) } catch (err) { - log.warn('unable to parse config. key=%s', envKey) + log.error('unable to parse config. key=%s', envKey) } break case 'boolean': diff --git a/src/services/core.ts b/src/services/core.ts index 9a700cd6..e6e96bbd 100644 --- a/src/services/core.ts +++ b/src/services/core.ts @@ -35,7 +35,7 @@ export default class Core { } if (!Buffer.isBuffer(data)) { - log.warn('data handler was passed a non-buffer. typeof=%s data=%s', typeof data, data) + log.error('data handler was passed a non-buffer. typeof=%s data=%s', typeof data, data) throw new Error('data handler was passed a non-buffer. typeof=' + typeof data) } @@ -47,7 +47,7 @@ export default class Core { case IlpPacket.Type.TYPE_ILQP_BY_DESTINATION_REQUEST: return this.ilqpController.sendData(data, accountId) default: - log.warn('received invalid packet type. source=%s type=%s', accountId, data[0]) + log.error('received invalid packet type. source=%s type=%s', accountId, data[0]) throw new InvalidPacketError('invalid packet type received. type=' + data[0]) } } diff --git a/src/services/middleware-manager.ts b/src/services/middleware-manager.ts index cb25501d..9dcb0c6b 100644 --- a/src/services/middleware-manager.ts +++ b/src/services/middleware-manager.ts @@ -144,7 +144,7 @@ export default class MiddlewareManager { } catch (err) { const errInfo = (err && typeof err === 'object' && err.stack) ? err.stack : String(err) - log.warn('failed to apply middleware to account. middlewareName=%s accountId=%s error=%s', middlewareName, accountId, errInfo) + log.error('failed to apply middleware to account. middlewareName=%s accountId=%s error=%s', middlewareName, accountId, errInfo) throw new Error('failed to apply middleware. middlewareName=' + middlewareName) } } diff --git a/src/services/quoter.ts b/src/services/quoter.ts index ea7059e9..f27ddfcb 100644 --- a/src/services/quoter.ts +++ b/src/services/quoter.ts @@ -46,10 +46,10 @@ export default class Quoter { if (cachedCurve) { if (cachedCurve.expiry < Date.now()) { - log.debug('cleaning up expired cached curve. prefix=%s expiry=%s', cachedCurve.prefix, new Date(cachedCurve.expiry).toISOString()) + log.trace('cleaning up expired cached curve. prefix=%s expiry=%s', cachedCurve.prefix, new Date(cachedCurve.expiry).toISOString()) this.cache.delete(cachedCurve.prefix) } else { - log.debug('returning cached curve. prefix=%s', cachedCurve.prefix) + log.trace('returning cached curve. prefix=%s', cachedCurve.prefix) return cachedCurve } } @@ -59,7 +59,7 @@ export default class Quoter { destinationHoldDuration: DESTINATION_HOLD_DURATION }) const plugin = this.accounts.getPlugin(nextHop) - log.debug('sending quote request packet. connector=%s', nextHop) + log.trace('sending quote request packet. connector=%s', nextHop) const quoteResponsePacket = await plugin.sendData(quoteRequestPacket) if (quoteResponsePacket[0] === IlpPacket.Type.TYPE_ILQP_LIQUIDITY_RESPONSE) { @@ -76,7 +76,7 @@ export default class Quoter { } cacheCurve ({ prefix, curve, expiry, minMessageWindow }: CachedCurve) { - log.debug('caching curve. prefix=%s expiry=%s minMessageWindow=%s', prefix, expiry, minMessageWindow) + log.trace('caching curve. prefix=%s expiry=%s minMessageWindow=%s', prefix, expiry, minMessageWindow) this.cache.insert(prefix, { prefix, curve, diff --git a/src/services/route-broadcaster.ts b/src/services/route-broadcaster.ts index 78e29b4c..6eb8ef35 100644 --- a/src/services/route-broadcaster.ts +++ b/src/services/route-broadcaster.ts @@ -140,7 +140,7 @@ export default class RouteBroadcaster { } if (!sendRoutes && !receiveRoutes) { - log.debug('not sending/receiving routes for peer, set sendRoutes/receiveRoutes to override. accountId=%s', accountId) + log.warn('not sending/receiving routes for peer, set sendRoutes/receiveRoutes to override. accountId=%s', accountId) return } @@ -162,7 +162,7 @@ export default class RouteBroadcaster { const plugin = this.accounts.getPlugin(accountId) if (plugin.isConnected()) { - log.debug('add peer. accountId=%s sendRoutes=%s receiveRoutes=%s', accountId, sendRoutes, receiveRoutes) + log.trace('add peer. accountId=%s sendRoutes=%s receiveRoutes=%s', accountId, sendRoutes, receiveRoutes) const peer = new Peer({ deps: this.deps, accountId, sendRoutes, receiveRoutes }) this.peers.set(accountId, peer) const receiver = peer.getReceiver() @@ -183,7 +183,7 @@ export default class RouteBroadcaster { const sender = peer.getSender() const receiver = peer.getReceiver() - log.info('remove peer. peerId=' + accountId) + log.trace('remove peer. peerId=' + accountId) if (sender) { sender.stop() } @@ -268,7 +268,7 @@ export default class RouteBroadcaster { } reloadLocalRoutes () { - log.debug('reload local and configured routes.') + log.trace('reload local and configured routes.') this.localRoutes = new Map() const localAccounts = this.accounts.getAccountIds() @@ -434,10 +434,10 @@ export default class RouteBroadcaster { if (newNextHop !== currentNextHop) { if (route) { - log.debug('new best route for prefix. prefix=%s oldBest=%s newBest=%s', prefix, currentNextHop, newNextHop) + log.trace('new best route for prefix. prefix=%s oldBest=%s newBest=%s', prefix, currentNextHop, newNextHop) this.localRoutingTable.insert(prefix, route) } else { - log.debug('no more route available for prefix. prefix=%s', prefix) + log.trace('no more route available for prefix. prefix=%s', prefix) this.localRoutingTable.delete(prefix) } @@ -498,7 +498,7 @@ export default class RouteBroadcaster { this.forwardingRoutingTable.insert(prefix, routeUpdate) - log.debug('logging route update. update=%j', routeUpdate) + log.trace('logging route update. update=%j', routeUpdate) if (currentBest) { this.forwardingRoutingTable.log[currentBest.epoch] = null diff --git a/src/services/route-builder.ts b/src/services/route-builder.ts index 97db68aa..fa696599 100644 --- a/src/services/route-builder.ts +++ b/src/services/route-builder.ts @@ -66,12 +66,12 @@ export default class RouteBuilder { const route = this.routingTable.resolve(destinationAccount) if (!route) { - log.info('no route found for quote. destinationAccount=' + destinationAccount) + log.debug('no route found for quote. destinationAccount=' + destinationAccount) throw new UnreachableError('no route found. to=' + destinationAccount) } if (!this.config.reflectPayments && sourceAccount === route.nextHop) { - log.info('refusing to route payments back to sender. sourceAccount=%s destinationAccount=%s', sourceAccount, destinationAccount) + log.debug('refusing to route payments back to sender. sourceAccount=%s destinationAccount=%s', sourceAccount, destinationAccount) throw new UnreachableError('refusing to route payments back to sender. sourceAccount=' + sourceAccount + ' destinationAccount=' + destinationAccount) } @@ -80,22 +80,22 @@ export default class RouteBuilder { async quoteLocal (sourceAccount: string, destinationAccount: string) { if (!this.accounts.getAssetCode(sourceAccount)) { - log.info('source account is unavailable. sourceAccount=' + sourceAccount) + log.debug('source account is unavailable. sourceAccount=' + sourceAccount) throw new UnreachableError('no route from source. sourceAccount=' + sourceAccount) } const nextHop = this.getNextHop(sourceAccount, destinationAccount) if (!this.accounts.getAssetCode(nextHop)) { - log.info('next hop is unavailable. nextHop=' + nextHop) + log.debug('next hop is unavailable. nextHop=' + nextHop) throw new UnreachableError('no route to next hop. nextHop=' + nextHop) } - log.debug('determined next hop. nextHop=' + nextHop) + log.trace('determined next hop. nextHop=' + nextHop) const rate = await this.backend.getRate(sourceAccount, nextHop) - log.debug('determined local rate. rate=' + rate) + log.trace('determined local rate. rate=' + rate) return { nextHop, rate } } @@ -108,7 +108,7 @@ export default class RouteBuilder { * @returns {QuoteLiquidityResponse} */ async quoteLiquidity (sourceAccount: string, packet: IlpPacket.IlqpLiquidityRequest) { - log.info('creating liquidity quote. sourceAccount=%s destinationAccount=%s', + log.trace('creating liquidity quote. sourceAccount=%s destinationAccount=%s', sourceAccount, packet.destinationAccount) const { nextHop, rate } = await this.quoteLocal(sourceAccount, packet.destinationAccount) @@ -121,7 +121,7 @@ export default class RouteBuilder { let sourceHoldDuration let expiresAt if (packet.destinationAccount.startsWith(nextHop)) { - log.debug('local destination.') + log.trace('local destination.') liquidityCurve = localCurve appliesToPrefix = nextHop sourceHoldDuration = packet.destinationHoldDuration + this.config.minMessageWindow @@ -129,10 +129,10 @@ export default class RouteBuilder { } else { const quote = await this.quoter.quoteLiquidity(nextHop, packet.destinationAccount) if (!quote) { - log.info('no quote found. sourceAccount=%s params=%j', sourceAccount, packet) + log.debug('no quote found. sourceAccount=%s params=%j', sourceAccount, packet) throw new UnreachableError('no quote found. to=' + packet.destinationAccount) } - log.debug('remote destination. quote=%j', quote) + log.trace('remote destination. quote=%j', quote) liquidityCurve = localCurve.join(quote.curve) appliesToPrefix = quote.prefix @@ -175,7 +175,7 @@ export default class RouteBuilder { * @returns {QuoteBySourceResponse} */ async quoteBySource (sourceAccount: string, packet: IlpPacket.IlqpBySourceRequest) { - log.info('creating quote by source amount. sourceAccount=%s destinationAccount=%s sourceAmount=%s', + log.trace('creating quote by source amount. sourceAccount=%s destinationAccount=%s sourceAmount=%s', sourceAccount, packet.destinationAccount, packet.sourceAmount) if (packet.sourceAmount === '0') { @@ -188,16 +188,16 @@ export default class RouteBuilder { let destinationAmount let sourceHoldDuration if (packet.destinationAccount.startsWith(nextHop)) { - log.debug('local destination. destinationAmount=' + nextAmount) + log.trace('local destination. destinationAmount=' + nextAmount) destinationAmount = nextAmount sourceHoldDuration = packet.destinationHoldDuration + this.config.minMessageWindow } else { const quote = await this.quoter.quoteLiquidity(nextHop, packet.destinationAccount) if (!quote) { - log.info('no quote found. sourceAccount=%s params=%j', sourceAccount, packet) + log.debug('no quote found. sourceAccount=%s params=%j', sourceAccount, packet) throw new UnreachableError('no quote found. to=' + packet.destinationAccount) } - log.debug('remote destination. quote=%j', quote) + log.trace('remote destination. quote=%j', quote) destinationAmount = quote.curve.amountAt(packet.sourceAmount).times(rate).integerValue(BigNumber.ROUND_FLOOR).toString() sourceHoldDuration = packet.destinationHoldDuration + quote.minMessageWindow + this.config.minMessageWindow @@ -226,7 +226,7 @@ export default class RouteBuilder { * @returns {QuoteByDestinationResponse} */ async quoteByDestination (sourceAccount: string, packet: IlpPacket.IlqpByDestinationRequest) { - log.info('creating quote by destination amount. sourceAccount=%s destinationAccount=%s destinationAmount=%s', + log.trace('creating quote by destination amount. sourceAccount=%s destinationAccount=%s destinationAmount=%s', sourceAccount, packet.destinationAccount, packet.destinationAmount) if (packet.destinationAmount === '0') { @@ -238,16 +238,16 @@ export default class RouteBuilder { let nextHopAmount let nextHopHoldDuration if (packet.destinationAccount.startsWith(nextHop)) { - log.debug('local destination.') + log.trace('local destination.') nextHopAmount = packet.destinationAmount nextHopHoldDuration = packet.destinationHoldDuration } else { const quote = await this.quoter.quoteLiquidity(nextHop, packet.destinationAccount) if (!quote) { - log.info('no quote found. sourceAccount=%s params=%j', sourceAccount, packet) + log.debug('no quote found. sourceAccount=%s params=%j', sourceAccount, packet) throw new UnreachableError('no quote found. to=' + packet.destinationAccount) } - log.debug('remote destination. quote=%j', quote) + log.trace('remote destination. quote=%j', quote) nextHopAmount = quote.curve.amountReverse(packet.destinationAmount).toString() nextHopHoldDuration = packet.destinationHoldDuration + quote.minMessageWindow @@ -292,7 +292,7 @@ export default class RouteBuilder { data } = sourcePacket - log.info( + log.trace( 'constructing next hop packet. sourceAccount=%s sourceAmount=%s destination=%s', sourceAccount, amount, destination ) @@ -304,17 +304,17 @@ export default class RouteBuilder { const route = this.routingTable.resolve(destination) if (!route) { - log.info('could not find route for transfer. sourceAccount=%s sourceAmount=%s destinationAccount=%s', sourceAccount, amount, destination) + log.debug('could not find route for transfer. sourceAccount=%s sourceAmount=%s destinationAccount=%s', sourceAccount, amount, destination) throw new UnreachableError('no route found. source=' + sourceAccount + ' destination=' + destination) } const nextHop = route.nextHop - log.debug('determined next hop. nextHop=%s', nextHop) + log.trace('determined next hop. nextHop=%s', nextHop) const rate = await this.backend.getRate(sourceAccount, nextHop) - log.debug('determined local rate. rate=%s', rate) + log.trace('determined local rate. rate=%s', rate) this._verifyPluginIsConnected(nextHop)