feat: trace level logging (#437)

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)
   }
 }

src/backends/ecb.ts

@@ -56,18 +56,18 @@ 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())
     }
     this.rates = apiData.rates
     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)
   }

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)
     }
 

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)
     }
 

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
   })
 }

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)
 

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.')
     }
   }

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,

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)
         })
     }
 

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:

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)
     }
   })

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<string, void>) => {
           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<string, void>) => {
           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)