From af91a0dbf309a4a38820afc243e81dd8fb25cb08 Mon Sep 17 00:00:00 2001 From: Jason Bruwer Date: Wed, 14 Aug 2024 23:58:30 +0100 Subject: [PATCH] feat(2737): add fees as metric for outgoing payment. (#2831) * feat(2737): add fees as metric for outgoing payment. * feat(2737): rename to payment_fees. * feat(2737): test case updates. * feat(2737): formatting. * feat(2737): re-order test cases. Move fee collector. * feat(2737): dashboard and doc updates. * feat(2737): merged with main. * feat(2737): review feedback applied from @JoblersTune. * feat(2737): review feedback applied from @mkurapov. * feat(2737): additional tests for covert of assets and rates. * feat(2737): additional tests ensuring the increment counter was called. * feat(2737): additional tests ensuring the increment counter was called. * feat(2737): readme. --- .../payment/outgoing/lifecycle.ts | 26 ++- .../payment/outgoing/service.test.ts | 58 +++++- .../open_payments/payment/outgoing/service.ts | 4 +- .../backend/src/telemetry/service.test.ts | 174 ++++++++++++++++++ packages/backend/src/telemetry/service.ts | 62 ++++++- packages/backend/src/tests/telemetry.ts | 3 +- .../src/content/docs/telemetry/overview.md | 3 + 7 files changed, 316 insertions(+), 14 deletions(-) diff --git a/packages/backend/src/open_payments/payment/outgoing/lifecycle.ts b/packages/backend/src/open_payments/payment/outgoing/lifecycle.ts index a825bd6515..f273e008a1 100644 --- a/packages/backend/src/open_payments/payment/outgoing/lifecycle.ts +++ b/packages/backend/src/open_payments/payment/outgoing/lifecycle.ts @@ -8,6 +8,7 @@ import { import { ServiceDependencies } from './service' import { Receiver } from '../../receiver/model' import { TransactionOrKnex } from 'objection' +import { ValueType } from '@opentelemetry/api' // "payment" is locked by the "deps.knex" transaction. export async function handleSending( @@ -85,14 +86,24 @@ export async function handleSending( const payEndTime = Date.now() if (deps.telemetry) { - deps.telemetry.incrementCounter('transactions_total', 1, { - description: 'Count of funded transactions' - }) - const payDuration = payEndTime - payStartTime - deps.telemetry.recordHistogram('ilp_pay_time_ms', payDuration, { - description: 'Time to complete an ILP payment' - }) + await Promise.all([ + deps.telemetry.incrementCounter('transactions_total', 1, { + description: 'Count of funded transactions' + }), + deps.telemetry.recordHistogram('ilp_pay_time_ms', payDuration, { + description: 'Time to complete an ILP payment' + }), + deps.telemetry.incrementCounterWithTransactionAmountDifference( + 'transaction_fee_amounts', + payment.sentAmount, + payment.receiveAmount, + { + description: 'Amount sent through the network as fees', + valueType: ValueType.DOUBLE + } + ) + ]) } await handleCompleted(deps, payment) @@ -147,6 +158,7 @@ async function handleCompleted( await payment.$query(deps.knex).patch({ state: OutgoingPaymentState.Completed }) + await sendWebhookEvent( deps, payment, diff --git a/packages/backend/src/open_payments/payment/outgoing/service.test.ts b/packages/backend/src/open_payments/payment/outgoing/service.test.ts index 41085233d4..d2b09e516d 100644 --- a/packages/backend/src/open_payments/payment/outgoing/service.test.ts +++ b/packages/backend/src/open_payments/payment/outgoing/service.test.ts @@ -50,6 +50,7 @@ import { mockRatesApi } from '../../../tests/rates' import { UnionOmit } from '../../../shared/utils' import { QuoteError } from '../../quote/errors' import { withConfigOverride } from '../../../tests/helpers' +import { TelemetryService } from '../../../telemetry/service' describe('OutgoingPaymentService', (): void => { let deps: IocContract @@ -58,6 +59,7 @@ describe('OutgoingPaymentService', (): void => { let accountingService: AccountingService let paymentMethodHandlerService: PaymentMethodHandlerService let quoteService: QuoteService + let telemetryService: TelemetryService let knex: Knex let walletAddressId: string let incomingPayment: IncomingPayment @@ -243,12 +245,17 @@ describe('OutgoingPaymentService', (): void => { XRP: exchangeRate })) - deps = await initIocContainer({ ...Config, exchangeRatesUrl }) + deps = await initIocContainer({ + ...Config, + exchangeRatesUrl, + enableTelemetry: true + }) appContainer = await createTestApp(deps) outgoingPaymentService = await deps.use('outgoingPaymentService') accountingService = await deps.use('accountingService') paymentMethodHandlerService = await deps.use('paymentMethodHandlerService') quoteService = await deps.use('quoteService') + telemetryService = (await deps.use('telemetry'))! config = await deps.use('config') knex = appContainer.knex }) @@ -1154,11 +1161,58 @@ describe('OutgoingPaymentService', (): void => { return payment } + test('COMPLETED with Telemetry Fee Counter (receiveAmount < incomingPayment.incomingAmount)', async (): Promise => { + const spyTelFeeAmount = jest.spyOn( + telemetryService, + 'incrementCounterWithTransactionAmountDifference' + ) + const spyCounter = jest.spyOn(telemetryService, 'incrementCounter') + + incomingPayment = await createIncomingPayment(deps, { + walletAddressId: receiverWalletAddress.id, + incomingAmount: { + value: receiveAmount.value * 2n, + assetCode: receiverWalletAddress.asset.code, + assetScale: receiverWalletAddress.asset.scale + } + }) + assert.ok(incomingPayment.walletAddress) + + const createdPayment = await setup({ + receiver: incomingPayment.getUrl(incomingPayment.walletAddress), + receiveAmount, + method: 'ilp' + }) + + mockPaymentHandlerPay(createdPayment, incomingPayment) + const payment = await processNext( + createdPayment.id, + OutgoingPaymentState.Completed + ) + await expectOutcome(payment, { + accountBalance: 0n, + amountSent: payment.debitAmount.value, + amountDelivered: payment.receiveAmount.value, + incomingPaymentReceived: payment.receiveAmount.value, + withdrawAmount: 0n + }) + // [incrementCounterWithTransactionAmountDifference] called and [incrementCounter] only once due to [Count of funded transactions] + expect(spyTelFeeAmount).toHaveBeenCalledTimes(1) + expect(spyCounter).toHaveBeenCalledTimes(1) + expect(spyCounter).toHaveBeenCalledTimes(1) + }) + test.each` debitAmount | receiveAmount ${debitAmount} | ${undefined} ${undefined} | ${receiveAmount} `('COMPLETED', async ({ debitAmount, receiveAmount }): Promise => { + const spyTelFeeAmount = jest.spyOn( + telemetryService, + 'incrementCounterWithTransactionAmountDifference' + ) + const spyCounter = jest.spyOn(telemetryService, 'incrementCounter') + const createdPayment = await setup({ receiver, debitAmount, @@ -1179,6 +1233,8 @@ describe('OutgoingPaymentService', (): void => { incomingPaymentReceived: payment.receiveAmount.value, withdrawAmount: 0n }) + expect(spyTelFeeAmount).toHaveBeenCalledTimes(1) + expect(spyCounter).toHaveBeenCalledTimes(1) }) test('COMPLETED (receiveAmount < incomingPayment.incomingAmount)', async (): Promise => { diff --git a/packages/backend/src/open_payments/payment/outgoing/service.ts b/packages/backend/src/open_payments/payment/outgoing/service.ts index bb44909ae6..b47a4ed3e9 100644 --- a/packages/backend/src/open_payments/payment/outgoing/service.ts +++ b/packages/backend/src/open_payments/payment/outgoing/service.ts @@ -237,9 +237,7 @@ async function createOutgoingPayment( const peer = await deps.peerService.getByDestinationAddress( receiver.ilpAddress ) - if (peer) { - await payment.$query(trx).patch({ peerId: peer.id }) - } + if (peer) await payment.$query(trx).patch({ peerId: peer.id }) await sendWebhookEvent( deps, diff --git a/packages/backend/src/telemetry/service.test.ts b/packages/backend/src/telemetry/service.test.ts index b741a17c9e..3834212f01 100644 --- a/packages/backend/src/telemetry/service.test.ts +++ b/packages/backend/src/telemetry/service.test.ts @@ -8,6 +8,7 @@ import { mockCounter, mockHistogram } from '../tests/telemetry' import { TelemetryService } from './service' import { Counter, Histogram } from '@opentelemetry/api' import { privacy } from './privacy' +import { mockRatesApi } from '../tests/rates' jest.mock('@opentelemetry/api', () => ({ ...jest.requireActual('@opentelemetry/api'), @@ -36,6 +37,18 @@ describe('TelemetryServiceImpl', () => { let aseRatesService: RatesService let internalRatesService: RatesService + let apiRequestCount = 0 + const exchangeRatesUrl = 'http://example-rates.com' + + const exampleRates = { + USD: { + EUR: 2 + }, + EUR: { + USD: 1.12 + } + } + beforeAll(async (): Promise => { deps = initIocContainer({ ...Config, @@ -49,6 +62,11 @@ describe('TelemetryServiceImpl', () => { telemetryService = await deps.use('telemetry')! aseRatesService = await deps.use('ratesService')! internalRatesService = await deps.use('internalRatesService')! + + mockRatesApi(exchangeRatesUrl, (base) => { + apiRequestCount++ + return exampleRates[base as keyof typeof exampleRates] + }) }) afterAll(async (): Promise => { @@ -122,6 +140,162 @@ describe('TelemetryServiceImpl', () => { expect(histogram?.record).toHaveBeenCalledTimes(2) }) + describe('incrementCounterWithTransactionAmountDifference', () => { + it('should not record fee when there is no fee value', async () => { + const spyAseConvert = jest.spyOn(aseRatesService, 'convert') + const spyIncCounter = jest.spyOn(telemetryService, 'incrementCounter') + + await telemetryService.incrementCounterWithTransactionAmountDifference( + 'test_amount_diff_counter', + { + value: 100n, + assetCode: 'USD', + assetScale: 2 + }, + { + value: 100n, + assetCode: 'USD', + assetScale: 2 + } + ) + + expect(spyAseConvert).toHaveBeenCalled() + expect(spyIncCounter).not.toHaveBeenCalled() + }) + + it('should not record fee negative fee value', async () => { + const spyConvert = jest.spyOn(aseRatesService, 'convert') + const spyIncCounter = jest.spyOn(telemetryService, 'incrementCounter') + + await telemetryService.incrementCounterWithTransactionAmountDifference( + 'test_amount_diff_counter', + { + value: 100n, + assetCode: 'USD', + assetScale: 2 + }, + { + value: 101n, + assetCode: 'USD', + assetScale: 2 + } + ) + + expect(spyConvert).toHaveBeenCalled() + expect(spyIncCounter).not.toHaveBeenCalled() + }) + + it('should not record zero amounts', async () => { + const spyConvert = jest.spyOn(aseRatesService, 'convert') + const spyIncCounter = jest.spyOn(telemetryService, 'incrementCounter') + + await telemetryService.incrementCounterWithTransactionAmountDifference( + 'test_amount_diff_counter', + { + value: 0n, + assetCode: 'USD', + assetScale: 2 + }, + { + value: 0n, + assetCode: 'USD', + assetScale: 2 + } + ) + + expect(spyConvert).not.toHaveBeenCalled() + expect(spyIncCounter).not.toHaveBeenCalled() + }) + + it('should record since it is a valid fee', async () => { + const spyConvert = jest.spyOn(aseRatesService, 'convert') + const spyIncCounter = jest.spyOn(telemetryService, 'incrementCounter') + + const source = { + value: 100n, + assetCode: 'USD', + assetScale: 2 + } + const destination = { + value: 50n, + assetCode: 'USD', + assetScale: 2 + } + + const name = 'test_amount_diff_counter' + await telemetryService.incrementCounterWithTransactionAmountDifference( + name, + source, + destination + ) + + expect(spyConvert).toHaveBeenCalledTimes(2) + expect(spyConvert).toHaveBeenNthCalledWith( + 1, + expect.objectContaining({ + sourceAmount: source.value, + sourceAsset: { code: source.assetCode, scale: source.assetScale } + }) + ) + expect(spyConvert).toHaveBeenNthCalledWith( + 2, + expect.objectContaining({ + sourceAmount: destination.value, + sourceAsset: { + code: destination.assetCode, + scale: destination.assetScale + } + }) + ) + // Ensure the [incrementCounter] was called with the correct calculated value. Expected 5000 due to scale = 4. + expect(spyIncCounter).toHaveBeenCalledWith(name, 5000, {}) + }) + + it('should record since it is a valid fee for different assets', async () => { + const spyConvert = jest.spyOn(aseRatesService, 'convert') + const spyIncCounter = jest.spyOn(telemetryService, 'incrementCounter') + + const source = { + value: 100n, + assetCode: 'USD', + assetScale: 2 + } + const destination = { + value: 50n, + assetCode: 'EUR', + assetScale: 2 + } + + const name = 'test_amount_diff_counter' + await telemetryService.incrementCounterWithTransactionAmountDifference( + name, + source, + destination + ) + + expect(spyConvert).toHaveBeenCalledTimes(2) + expect(spyConvert).toHaveBeenNthCalledWith( + 1, + expect.objectContaining({ + sourceAmount: source.value, + sourceAsset: { code: source.assetCode, scale: source.assetScale } + }) + ) + expect(spyConvert).toHaveBeenNthCalledWith( + 2, + expect.objectContaining({ + sourceAmount: destination.value, + sourceAsset: { + code: destination.assetCode, + scale: destination.assetScale + } + }) + ) + expect(spyIncCounter).toHaveBeenCalledWith(name, 4400, {}) + expect(apiRequestCount).toBe(1) + }) + }) + describe('incrementCounterWithTransactionAmount', () => { it('should try to convert using aseRatesService and fallback to internalRatesService', async () => { const aseConvertSpy = jest diff --git a/packages/backend/src/telemetry/service.ts b/packages/backend/src/telemetry/service.ts index f7f18cf0ec..d0c03435a9 100644 --- a/packages/backend/src/telemetry/service.ts +++ b/packages/backend/src/telemetry/service.ts @@ -16,6 +16,13 @@ export interface TelemetryService { incrementCounterWithTransactionAmount( name: string, amount: { value: bigint; assetCode: string; assetScale: number }, + attributes?: Record, + preservePrivacy?: boolean + ): Promise + incrementCounterWithTransactionAmountDifference( + name: string, + amountSource: { value: bigint; assetCode: string; assetScale: number }, + amountDestination: { value: bigint; assetCode: string; assetScale: number }, attributes?: Record ): Promise recordHistogram( @@ -94,10 +101,58 @@ class TelemetryServiceImpl implements TelemetryService { }) } + public async incrementCounterWithTransactionAmountDifference( + name: string, + amountSource: { value: bigint; assetCode: string; assetScale: number }, + amountDestination: { value: bigint; assetCode: string; assetScale: number }, + attributes: Record = {} + ): Promise { + if (!amountSource.value || !amountDestination.value) return + + const convertedSource = await this.convertAmount({ + sourceAmount: amountSource.value, + sourceAsset: { + code: amountSource.assetCode, + scale: amountSource.assetScale + } + }) + if (isConvertError(convertedSource)) { + this.deps.logger.error( + `Unable to convert source amount: ${convertedSource}` + ) + return + } + const convertedDestination = await this.convertAmount({ + sourceAmount: amountDestination.value, + sourceAsset: { + code: amountDestination.assetCode, + scale: amountDestination.assetScale + } + }) + if (isConvertError(convertedDestination)) { + this.deps.logger.error( + `Unable to convert destination amount: ${convertedSource}` + ) + return + } + + const diff = BigInt(convertedSource - convertedDestination) + if (diff === 0n) return + + if (diff < 0n) { + this.deps.logger.error( + `Difference should not be negative!: ${diff}, source asset ${amountSource.assetCode} vs destination asset ${amountDestination.assetCode}.` + ) + return + } + this.incrementCounter(name, Number(diff), attributes) + } + public async incrementCounterWithTransactionAmount( name: string, amount: { value: bigint; assetCode: string; assetScale: number }, - attributes: Record = {} + attributes: Record = {}, + preservePrivacy = true ): Promise { const { value, assetCode, assetScale } = amount try { @@ -110,11 +165,14 @@ class TelemetryServiceImpl implements TelemetryService { return } - const obfuscatedAmount = privacy.applyPrivacy(Number(converted)) + const obfuscatedAmount = preservePrivacy + ? privacy.applyPrivacy(Number(converted)) + : Number(converted) this.incrementCounter(name, obfuscatedAmount, attributes) } catch (e) { this.deps.logger.error(e, `Unable to collect telemetry`) } + return Promise.resolve() } public recordHistogram( diff --git a/packages/backend/src/tests/telemetry.ts b/packages/backend/src/tests/telemetry.ts index ec5d5650fe..22b375d68e 100644 --- a/packages/backend/src/tests/telemetry.ts +++ b/packages/backend/src/tests/telemetry.ts @@ -34,7 +34,8 @@ export class MockTelemetryService implements TelemetryService { incrementCounter(): void {} async incrementCounterWithTransactionAmount(): Promise {} - recordHistogram(): void {} + async incrementCounterWithTransactionAmountDifference(): Promise {} + async recordHistogram(): Promise {} public getInstanceName(): string | undefined { return 'serviceName' } diff --git a/packages/documentation/src/content/docs/telemetry/overview.md b/packages/documentation/src/content/docs/telemetry/overview.md index 8527f9c499..71590422ae 100644 --- a/packages/documentation/src/content/docs/telemetry/overview.md +++ b/packages/documentation/src/content/docs/telemetry/overview.md @@ -70,6 +70,9 @@ Currently collected metrics: - `transactions_amount` - Counter metric - Description: “Amount sent through the network”. - This amount metric increases by the amount sent in each ILP packet. +- `transaction_fee_amounts` - Counter metric + - Description: “Fee amount sent through the network”. + - This fee amount metric increases by the (amount sent minus amount received) for an outgoing payment. - `ilp_pay_time_ms` - Histogram metric - Description: “Time to complete an ILP payment” - This histogram metric records the time taken to make an ILP payment.