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/middleware/account.ts

@@ -29,9 +29,11 @@ export function createAccountMiddleware(serverAddress: string): ILPMiddleware {
         )
       } 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
         }
       }
@@ -56,7 +58,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 disabled'
+            ctx.services.logger.error(
+              {
+                incomingPayment,
+                streamDestination: ctx.state.streamDestination
+              },
+              errorMessage
+            )
+            throw new Errors.UnreachableError(errorMessage)
           }
 
           // Create the tigerbeetle account if not exists.
@@ -67,6 +77,7 @@ export function createAccountMiddleware(serverAddress: string): ILPMiddleware {
               LiquidityAccountType.INCOMING
             )
           }
+          ctx.services.logger.trace('got account from incoming payment')
           return incomingPayment
         }
         // Open Payments SPSP fallback account
@@ -80,12 +91,14 @@ export function createAccountMiddleware(serverAddress: string): ILPMiddleware {
               LiquidityAccountType.WEB_MONETIZATION
             )
           }
+          ctx.services.logger.trace('got account from wallet address')
           return walletAddress
         }
       }
       const address = ctx.request.prepare.destination
       const peer = await peers.getByDestinationAddress(address)
       if (peer) {
+        ctx.services.logger.trace('got account from peer')
         return peer
       }
       if (
@@ -106,7 +119,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

@@ -1,5 +1,5 @@
 import { Errors } from 'ilp-packet'
-import { ILPContext, ILPMiddleware } from '../rafiki'
+import { ILPContext, ILPMiddleware, TransferOptions } from '../rafiki'
 import {
   isTransferError,
   TransferError
@@ -35,6 +35,15 @@ export function createBalanceMiddleware(): ILPMiddleware {
     })
     if (typeof destinationAmountOrError !== 'bigint') {
       // ConvertError
+      services.logger.error(
+        {
+          amount,
+          destinationAmountOrError,
+          sourceAsset: accounts.incoming.asset,
+          destinationAsset: accounts.outgoing.asset
+        },
+        'Could not get rates'
+      )
       throw new CannotReceiveError(
         `Exchange rate error: ${destinationAmountOrError}`
       )
@@ -51,20 +60,35 @@ 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)) {
+        const safeLogTransferError = (transferOptions: TransferOptions) => {
+          if (transferOptions.destinationAccount?.http?.outgoing.authToken) {
+            // @ts-expect-error - "The operand of a 'delete' operator must be optional"
+            delete transferOptions.destinationAccount.http.outgoing.authToken
+          }
+          services.logger.error(
+            { transferOptions },
+            'Could not create transfer'
+          )
+        }
+
         switch (trxOrError) {
           case TransferError.InsufficientBalance:
           case TransferError.InsufficientLiquidity:
+            safeLogTransferError(transferOptions)
             throw new InsufficientLiquidityError(trxOrError)
           default:
+            safeLogTransferError(transferOptions)
             // TODO: map transfer errors to ILP errors
             ctxThrow(500, destinationAmountOrError.toString())
         }

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

@@ -23,7 +23,7 @@ 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()
       }

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/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
       },