feat(backend): improve ilp connector logs

packages/backend/src/payment-method/ilp/connector/core/controllers/stream.ts

@@ -53,11 +53,12 @@ export function createStreamController(): ILPMiddleware {
       } else {
         logger.warn(
           {
+            connectionKey,
             totalReceived,
             err,
             err2
           },
-          'error incrementing stream totalReceived'
+          'failed to increment stream totalReceived'
         )
       }
       response.reply = moneyOrReply.accept()

packages/backend/src/payment-method/ilp/connector/core/factories/test-logger.ts

@@ -1,11 +1,14 @@
-import { Factory } from 'rosie'
+import { Factory, IFactory } from 'rosie'
 import { Logger } from 'pino'
 
-export const TestLoggerFactory = Factory.define<Logger>('TestLogger').attrs({
+export const TestLoggerFactory: IFactory<Logger> = Factory.define<Logger>(
+  'TestLogger'
+).attrs({
   debug: () => jest.fn(),
   fatal: () => jest.fn(),
   error: () => jest.fn(),
   warn: () => jest.fn(),
   info: () => jest.fn(),
-  trace: () => jest.fn()
+  trace: () => jest.fn(),
+  child: () => jest.fn().mockImplementation(() => TestLoggerFactory.build())
 })

packages/backend/src/payment-method/ilp/connector/core/middleware/account.ts

@@ -27,19 +27,31 @@ export function createAccountMiddleware(serverAddress: string): ILPMiddleware {
           account,
           accountType
         )
+        ctx.services.logger.debug(
+          { account, accountType },
+          'Created liquidity account'
+        )
       } catch (err) {
         // Don't complain if liquidity account already exists.
-        if (err instanceof AccountAlreadyExistsError) {
-          // Do nothing.
-        } else {
+        if (!(err instanceof AccountAlreadyExistsError)) {
+          ctx.services.logger.error(
+            { account, accountType, err },
+            'Failed to create liquidity account'
+          )
           throw err
         }
       }
     }
 
     const { walletAddresses, incomingPayments, peers } = ctx.services
     const incomingAccount = ctx.state.incomingAccount
-    if (!incomingAccount) ctx.throw(401, 'unauthorized')
+    if (!incomingAccount) {
+      ctx.services.logger.error(
+        { state: ctx.state },
+        'Unauthorized: No incoming account'
+      )
+      ctx.throw(401, 'unauthorized')
+    }
 
     const getAccountByDestinationAddress = async (): Promise<
       OutgoingAccount | undefined
@@ -56,7 +68,15 @@ export function createAccountMiddleware(serverAddress: string): ILPMiddleware {
               IncomingPaymentState.Expired
             ].includes(incomingPayment.state)
           ) {
-            throw new Errors.UnreachableError('destination account is disabled')
+            const errorMessage = 'destination account is in an incorrect state'
+            ctx.services.logger.error(
+              {
+                incomingPayment,
+                streamDestination: ctx.state.streamDestination
+              },
+              errorMessage
+            )
+            throw new Errors.UnreachableError(errorMessage)
           }
 
           // Create the tigerbeetle account if not exists.
@@ -67,6 +87,10 @@ export function createAccountMiddleware(serverAddress: string): ILPMiddleware {
               LiquidityAccountType.INCOMING
             )
           }
+          ctx.services.logger.debug(
+            { incomingPaymentId: incomingPayment.id },
+            'destination account is incoming payment'
+          )
           return incomingPayment
         }
         // Open Payments SPSP fallback account
@@ -80,12 +104,20 @@ export function createAccountMiddleware(serverAddress: string): ILPMiddleware {
               LiquidityAccountType.WEB_MONETIZATION
             )
           }
+          ctx.services.logger.debug(
+            { walletAddressId: walletAddress.id },
+            'destination account is wallet address'
+          )
           return walletAddress
         }
       }
       const address = ctx.request.prepare.destination
       const peer = await peers.getByDestinationAddress(address)
       if (peer) {
+        ctx.services.logger.debug(
+          { peerId: peer.id },
+          'destination account is peer'
+        )
         return peer
       }
       if (
@@ -106,7 +138,15 @@ export function createAccountMiddleware(serverAddress: string): ILPMiddleware {
 
     const outgoingAccount = await getAccountByDestinationAddress()
     if (!outgoingAccount) {
-      throw new Errors.UnreachableError('unknown destination account')
+      const errorMessage = 'unknown destination account'
+      ctx.services.logger.error(
+        {
+          streamDestination: ctx.state.streamDestination,
+          destinationAddress: ctx.request.prepare.destination
+        },
+        errorMessage
+      )
+      throw new Errors.UnreachableError(errorMessage)
     }
     ctx.accounts = {
       get incoming(): IncomingAccount {

packages/backend/src/payment-method/ilp/connector/core/middleware/balance.ts

@@ -20,6 +20,12 @@ export function createBalanceMiddleware(): ILPMiddleware {
     next: () => Promise<void>
   ): Promise<void> => {
     const { amount } = request.prepare
+    const logger = services.logger.child(
+      { module: 'balance-middleware' },
+      {
+        redact: ['transferOptions.destinationAccount.http.outgoing.authToken']
+      }
+    )
 
     // Ignore zero amount packets
     if (amount === '0') {
@@ -35,6 +41,15 @@ export function createBalanceMiddleware(): ILPMiddleware {
     })
     if (typeof destinationAmountOrError !== 'bigint') {
       // ConvertError
+      logger.error(
+        {
+          amount,
+          destinationAmountOrError,
+          sourceAsset: accounts.incoming.asset,
+          destinationAsset: accounts.outgoing.asset
+        },
+        'Could not get rates'
+      )
       throw new CannotReceiveError(
         `Exchange rate error: ${destinationAmountOrError}`
       )
@@ -51,15 +66,20 @@ export function createBalanceMiddleware(): ILPMiddleware {
     const createPendingTransfer = async (): Promise<
       Transaction | undefined
     > => {
-      const trxOrError = await services.accounting.createTransfer({
+      const transferOptions = {
         sourceAccount: accounts.incoming,
         destinationAccount: accounts.outgoing,
         sourceAmount,
         destinationAmount: destinationAmountOrError,
         timeout: 5
-      })
-
+      }
+      const trxOrError =
+        await services.accounting.createTransfer(transferOptions)
       if (isTransferError(trxOrError)) {
+        logger.error(
+          { transferOptions, transferError: trxOrError },
+          'Could not create transfer'
+        )
         switch (trxOrError) {
           case TransferError.InsufficientBalance:
           case TransferError.InsufficientLiquidity:

packages/backend/src/payment-method/ilp/connector/core/middleware/error-handler.ts

@@ -1,5 +1,4 @@
 import { errorToIlpReject, isIlpError, IlpErrorCode } from 'ilp-packet'
-import { HttpError } from 'koa'
 import { ILPContext, ILPMiddleware } from '../rafiki'
 
 /**
@@ -23,16 +22,17 @@ export function createIncomingErrorHandlerMiddleware(
       if (!err || typeof err !== 'object') {
         err = new Error('Non-object thrown: ' + e)
       }
-      ctx.services.logger.debug({ err }, 'Error thrown in incoming pipeline')
+      ctx.services.logger.info({ err }, 'Error thrown in incoming pipeline')
       if (ctx.revertTotalReceived) {
         await ctx.revertTotalReceived()
       }
       if (isIlpError(err)) {
         ctx.response.reject = errorToIlpReject(serverAddress, err)
       } else {
-        ctx.services.logger.error(err instanceof HttpError && err.message)
+        const message = 'unexpected internal error'
+        ctx.services.logger.error({ err }, message)
         ctx.response.reject = errorToIlpReject(serverAddress, {
-          message: 'unexpected internal error',
+          message,
           ilpErrorCode: IlpErrorCode.T00_INTERNAL_ERROR,
           name: ''
         })

packages/backend/src/payment-method/ilp/connector/core/middleware/ildcp.ts

@@ -22,7 +22,7 @@ export function createIldcpMiddleware(serverAddress: string): ILPMiddleware {
 
     const clientAddress = incoming.staticIlpAddress
     if (!clientAddress) {
-      logger.warn(
+      logger.error(
         {
           peerId: incoming.id
         },

packages/backend/src/payment-method/ilp/connector/core/middleware/max-packet-amount.ts

@@ -14,7 +14,7 @@ export function createIncomingMaxPacketAmountMiddleware(): ILPMiddleware {
     if (maxPacketAmount) {
       const amount = request.prepare.intAmount
       if (amount > maxPacketAmount) {
-        logger.warn(
+        logger.error(
           { maxPacketAmount: maxPacketAmount.toString(), request },
           'rejected a packet due to amount exceeding maxPacketAmount'
         )

packages/backend/src/payment-method/ilp/connector/core/middleware/reduce-expiry.ts

@@ -24,7 +24,7 @@ function getDestinationExpiry(
   const sourceExpiryTime = request.expiresAt.getTime()
 
   if (sourceExpiryTime < Date.now()) {
-    log.trace('incoming packet has already expired', { request })
+    log.debug({ request }, 'incoming packet has already expired')
     throw new InsufficientTimeoutError(
       'source transfer has already expired.' +
         ' sourceExpiry=' +
@@ -42,9 +42,15 @@ function getDestinationExpiry(
   )
 
   if (destinationExpiryTime < Date.now() + minExpirationWindow) {
-    log.trace('incoming packet expires too soon to complete payment', {
-      request
-    })
+    log.debug(
+      {
+        expectedDestinationExpiryTime,
+        maxHoldTime,
+        request,
+        minExpirationWindow
+      },
+      'incoming packet expires too soon to complete payment'
+    )
     throw new InsufficientTimeoutError(
       'source transfer expires too soon to complete payment.' +
         ' actualSourceExpiry=' +

packages/backend/src/payment-method/ilp/connector/core/middleware/validate-fulfillment.ts

@@ -17,7 +17,10 @@ export function createOutgoingValidateFulfillmentMiddleware(): ILPMiddleware {
         .update(fulfillment)
         .digest()
       if (!calculatedCondition.equals(executionCondition)) {
-        logger.warn({ response }, 'invalid fulfillment')
+        logger.error(
+          { response, calculatedCondition, executionCondition },
+          'invalid fulfillment'
+        )
         throw new WrongConditionError(
           'fulfillment did not match expected value.'
         )

packages/backend/src/payment-method/ilp/connector/core/test/middleware/account-middleware.test.ts

@@ -100,7 +100,7 @@ describe('Account Middleware', () => {
     expect(ctx.accounts.outgoing).toEqual(outgoingAccount)
   })
 
-  test('return an error when the destination account is disabled', async () => {
+  test('return an error when the destination account is in an incorrect state', async () => {
     const outgoingAccount = IncomingPaymentAccountFactory.build({
       id: 'deactivatedIncomingPayment',
       state: 'COMPLETED'
@@ -122,7 +122,7 @@ describe('Account Middleware', () => {
       }
     })
     await expect(middleware(ctx, next)).rejects.toThrow(
-      'destination account is disabled'
+      'destination account is in an incorrect state'
     )
   })
 

packages/backend/src/payment-method/ilp/connector/core/test/middleware/error-handler-middleware.test.ts

@@ -19,7 +19,7 @@ describe('Error Handler Middleware', () => {
     await expect(middleware(ctx, next)).resolves.toBeUndefined()
 
     expect(ctx.response.reject).toBeDefined()
-    expect(ctx.services.logger.debug).toHaveBeenCalledWith(
+    expect(ctx.services.logger.info).toHaveBeenCalledWith(
       {
         err: errorToBeThrown
       },
@@ -50,7 +50,7 @@ describe('Error Handler Middleware', () => {
     expect(ctx.response.reject).toEqual(
       errorToIlpReject(ADDRESS, errorToBeThrown)
     )
-    expect(ctx.services.logger.debug).toHaveBeenCalledWith(
+    expect(ctx.services.logger.info).toHaveBeenCalledWith(
       {
         err: errorToBeThrown
       },

packages/backend/src/payment-method/ilp/connector/core/test/middleware/max-packet-amount.test.ts

@@ -51,7 +51,7 @@ describe('Max Packet Amount Middleware', function () {
     expect(next).toHaveBeenCalled()
   })
 
-  test('throws AmounTooLargeError and logs warning if prepare amount exceeds maximum balance for the peer', async () => {
+  test('throws AmounTooLargeError and logs error if prepare amount exceeds maximum balance for the peer', async () => {
     const prepareOverMaxAmount = IlpPrepareFactory.build({ amount: '51' })
     ctx.request.prepare = new ZeroCopyIlpPrepare(prepareOverMaxAmount)
     const next = jest.fn()
@@ -61,7 +61,7 @@ describe('Max Packet Amount Middleware', function () {
     )
 
     expect(next).toHaveBeenCalledTimes(0)
-    expect(ctx.services.logger.warn).toHaveBeenCalledWith(
+    expect(ctx.services.logger.error).toHaveBeenCalledWith(
       {
         // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
         maxPacketAmount: alice.maxPacketAmount!.toString(),

packages/backend/src/payment-method/ilp/connector/core/test/middleware/validate-fulfillment.test.ts

@@ -39,7 +39,7 @@ describe('Validate Fulfillment Middleware', function () {
     await expect(middleware(ctx, next)).rejects.toBeInstanceOf(
       WrongConditionError
     )
-    expect(ctx.services.logger.warn).toHaveBeenCalled()
+    expect(ctx.services.logger.error).toHaveBeenCalled()
   })
 
   test('forwards fulfills with correct fullfillment', async () => {