diff --git a/docs/grafana-dashboard-billing-deduct.json b/docs/grafana-dashboard-billing-deduct.json new file mode 100644 index 00000000..0ba576c2 --- /dev/null +++ b/docs/grafana-dashboard-billing-deduct.json @@ -0,0 +1,253 @@ +{ + "__inputs": [], + "__elements": {}, + "__requires": [ + { + "type": "grafana", + "id": "grafana", + "name": "Grafana", + "version": "11.5.2" + }, + { + "type": "datasource", + "id": "prometheus", + "name": "Prometheus", + "version": "2.x" + } + ], + "annotations": { "list": [] }, + "editable": true, + "fiscalYearStartMonth": 0, + "graphTooltip": 0, + "id": null, + "links": [], + "panels": [ + { + "collapsed": false, + "gridPos": { "h": 1, "w": 24, "x": 0, "y": 0 }, + "id": 1, + "panels": [], + "title": "Billing Deduct Latency", + "type": "row" + }, + { + "datasource": { "type": "prometheus", "uid": "$datasource" }, + "description": "Histogram showing the distribution of POST /api/billing/deduct response times", + "fieldConfig": { + "defaults": { + "color": { "mode": "palette-classic" }, + "custom": { + "axisBorderShow": false, + "axisCenteredZero": false, + "axisLabel": "", + "axisPlacement": "auto", + "barAlignment": 0, + "drawStyle": "bars", + "fillOpacity": 80, + "gradientMode": "none", + "hideFrom": { + "graph": false, + "legend": false, + "tooltip": false + }, + "lineWidth": 1, + "scaleDistribution": { "type": "linear" }, + "thresholdsStyle": { "mode": "off" } + }, + "mappings": [], + "thresholds": { + "mode": "absolute", + "steps": [ + { "color": "green", "value": null }, + { "color": "red", "value": 80 } + ] + }, + "unit": "s" + }, + "overrides": [] + }, + "gridPos": { "h": 8, "w": 12, "x": 0, "y": 1 }, + "id": 2, + "options": { + "legend": { + "calcs": [], + "displayMode": "list", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "hideZeros": false, + "mode": "multi", + "sort": "none" + } + }, + "pluginVersion": "11.5.2", + "targets": [ + { + "datasource": { "type": "prometheus", "uid": "$datasource" }, + "disableTextWrap": false, + "editorMode": "code", + "expr": "rate(billing_deduct_duration_seconds_bucket{route=\"/api/billing/deduct\"}[$__rate_interval])", + "fullMetaSearch": false, + "includeNullMetadata": true, + "legendFormat": "le={{le}}", + "range": true, + "refId": "A", + "useBackend": false + } + ], + "title": "Billing Deduct Duration (Cumulative Distribution)", + "type": "timeseries" + }, + { + "datasource": { "type": "prometheus", "uid": "$datasource" }, + "description": "P50, P95, and P99 latency percentiles for billing deduct", + "fieldConfig": { + "defaults": { + "color": { "mode": "palette-classic" }, + "custom": { + "axisBorderShow": false, + "axisCenteredZero": false, + "axisLabel": "Latency (s)", + "axisPlacement": "auto", + "barAlignment": 0, + "drawStyle": "line", + "fillOpacity": 10, + "gradientMode": "none", + "hideFrom": { + "graph": false, + "legend": false, + "tooltip": false + }, + "lineInterpolation": "smooth", + "lineWidth": 2, + "pointSize": 3, + "scaleDistribution": { "type": "linear" }, + "showPoints": "never", + "spanNulls": true, + "stacking": { "group": "A", "mode": "none" }, + "thresholdsStyle": { "mode": "off" } + }, + "mappings": [], + "thresholds": { + "mode": "absolute", + "steps": [ + { "color": "green", "value": null }, + { "color": "red", "value": 80 } + ] + }, + "unit": "s" + }, + "overrides": [ + { + "matcher": { "id": "byName", "options": "P99" }, + "properties": [ + { "id": "color", "value": { "fixed": "red" } }, + { "id": "custom.lineWidth", "value": 2 } + ] + }, + { + "matcher": { "id": "byName", "options": "P95" }, + "properties": [ + { "id": "color", "value": { "fixed": "orange" } }, + { "id": "custom.lineWidth", "value": 2 } + ] + }, + { + "matcher": { "id": "byName", "options": "P50" }, + "properties": [ + { "id": "color", "value": { "fixed": "green" } } + ] + } + ] + }, + "gridPos": { "h": 8, "w": 12, "x": 12, "y": 1 }, + "id": 3, + "options": { + "legend": { + "calcs": [], + "displayMode": "table", + "placement": "bottom", + "showLegend": true + }, + "tooltip": { + "hideZeros": false, + "mode": "multi", + "sort": "none" + } + }, + "pluginVersion": "11.5.2", + "targets": [ + { + "datasource": { "type": "prometheus", "uid": "$datasource" }, + "disableTextWrap": false, + "editorMode": "code", + "expr": "histogram_quantile(0.50, rate(billing_deduct_duration_seconds_bucket{route=\"/api/billing/deduct\"}[$__rate_interval]))", + "fullMetaSearch": false, + "includeNullMetadata": true, + "legendFormat": "P50", + "range": true, + "refId": "A", + "useBackend": false + }, + { + "datasource": { "type": "prometheus", "uid": "$datasource" }, + "disableTextWrap": false, + "editorMode": "code", + "expr": "histogram_quantile(0.95, rate(billing_deduct_duration_seconds_bucket{route=\"/api/billing/deduct\"}[$__rate_interval]))", + "hide": false, + "legendFormat": "P95", + "range": true, + "refId": "B", + "useBackend": false + }, + { + "datasource": { "type": "prometheus", "uid": "$datasource" }, + "disableTextWrap": false, + "editorMode": "code", + "expr": "histogram_quantile(0.99, rate(billing_deduct_duration_seconds_bucket{route=\"/api/billing/deduct\"}[$__rate_interval]))", + "hide": false, + "legendFormat": "P99", + "range": true, + "refId": "C", + "useBackend": false + } + ], + "title": "Billing Deduct Latency Percentiles (P50 / P95 / P99)", + "type": "timeseries" + } + ], + "preload": false, + "refresh": "30s", + "schemaVersion": 41, + "tags": ["callora", "billing", "deduct", "latency"], + "templating": { + "list": [ + { + "current": { "selected": false, "text": "default", "value": "default" }, + "hide": 0, + "includeAll": false, + "label": "Datasource", + "multi": false, + "name": "datasource", + "options": [], + "query": "prometheus", + "queryValue": "", + "refresh": 1, + "regex": "", + "skipUrlSync": false, + "type": "datasource" + } + ] + }, + "time": { + "from": "now-6h", + "to": "now" + }, + "timepicker": {}, + "timezone": "browser", + "title": "Callora / Billing Deduct Latency", + "uid": "callora-billing-deduct-latency", + "version": 1, + "weekStart": "" +} diff --git a/src/__tests__/billingDeductMetrics.test.ts b/src/__tests__/billingDeductMetrics.test.ts new file mode 100644 index 00000000..e138dd03 --- /dev/null +++ b/src/__tests__/billingDeductMetrics.test.ts @@ -0,0 +1,259 @@ +import { EventEmitter } from 'node:events'; +import type { Request, Response } from 'express'; +import client from 'prom-client'; +import { + recordBillingDeductDuration, + resetBillingDeductMetrics, +} from '../metrics/registry.js'; +import { billingDeductHistogramMiddleware } from '../middleware/metricsHistogram.js'; + +interface MetricEntry { + value: number; + labels: Record; + metricName?: string; +} + +async function getMetricValues(name: string) { + const metrics = await client.register.getMetricsAsJSON(); + const found = metrics.find((m: any) => m.name === name); + if (!found) return undefined; + return { ...found, values: found.values as MetricEntry[] }; +} + +afterEach(() => { + resetBillingDeductMetrics(); +}); + +describe('billingDeductDuration histogram', () => { + it('is registered with correct name and type', async () => { + const metric = await getMetricValues('billing_deduct_duration_seconds'); + expect(metric).toBeDefined(); + expect(metric!.type).toBe('histogram'); + }); + + it('has expected buckets covering 1ms to 10s', async () => { + recordBillingDeductDuration(200, 50); + const metric = await getMetricValues('billing_deduct_duration_seconds'); + expect(metric).toBeDefined(); + const bucketValues = (metric!.values as MetricEntry[]).filter( + (v) => v.metricName === 'billing_deduct_duration_seconds_bucket', + ); + const les = bucketValues.map((v) => Number(v.labels.le)).filter(isFinite); + expect(les).toEqual( + expect.arrayContaining([0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10]), + ); + }); + + it('has route and status_code label names', async () => { + recordBillingDeductDuration(200, 50); + const metric = await getMetricValues('billing_deduct_duration_seconds'); + expect(metric).toBeDefined(); + const sampleLabels = (metric!.values as MetricEntry[])[0]?.labels; + expect(sampleLabels).toBeDefined(); + expect(sampleLabels).toHaveProperty('route'); + expect(sampleLabels).toHaveProperty('status_code'); + }); +}); + +describe('recordBillingDeductDuration', () => { + it('records an observation with the route label set to /api/billing/deduct', async () => { + recordBillingDeductDuration(200, 100); + const metric = await getMetricValues('billing_deduct_duration_seconds'); + expect(metric).toBeDefined(); + const countEntry = (metric!.values as MetricEntry[]).find( + (v) => + v.metricName === 'billing_deduct_duration_seconds_count' && + v.labels.route === '/api/billing/deduct' && + v.labels.status_code === '200', + ); + expect(countEntry).toBeDefined(); + expect(countEntry!.value).toBe(1); + }); + + it('records the status code label correctly for error responses', async () => { + recordBillingDeductDuration(402, 200); + const metric = await getMetricValues('billing_deduct_duration_seconds'); + const countEntry = (metric!.values as MetricEntry[]).find( + (v) => + v.metricName === 'billing_deduct_duration_seconds_count' && + v.labels.status_code === '402', + ); + expect(countEntry).toBeDefined(); + expect(countEntry!.value).toBe(1); + }); + + it('records a positive duration sum', async () => { + recordBillingDeductDuration(200, 500); + const metric = await getMetricValues('billing_deduct_duration_seconds'); + const sumEntry = (metric!.values as MetricEntry[]).find( + (v) => v.metricName === 'billing_deduct_duration_seconds_sum', + ); + expect(sumEntry).toBeDefined(); + expect(sumEntry!.value).toBeGreaterThan(0); + }); + + it('accumulates multiple observations for the same label set', async () => { + for (let i = 0; i < 5; i++) { + recordBillingDeductDuration(200, 100); + } + const metric = await getMetricValues('billing_deduct_duration_seconds'); + const countEntry = (metric!.values as MetricEntry[]).find( + (v) => + v.metricName === 'billing_deduct_duration_seconds_count' && + v.labels.route === '/api/billing/deduct' && + v.labels.status_code === '200', + ); + expect(countEntry).toBeDefined(); + expect(countEntry!.value).toBe(5); + }); + + it('records separate series for different status codes', async () => { + recordBillingDeductDuration(200, 50); + recordBillingDeductDuration(500, 100); + const metric = await getMetricValues('billing_deduct_duration_seconds'); + const count200 = (metric!.values as MetricEntry[]).find( + (v) => v.metricName === 'billing_deduct_duration_seconds_count' && v.labels.status_code === '200', + ); + const count500 = (metric!.values as MetricEntry[]).find( + (v) => v.metricName === 'billing_deduct_duration_seconds_count' && v.labels.status_code === '500', + ); + expect(count200).toBeDefined(); + expect(count200!.value).toBe(1); + expect(count500).toBeDefined(); + expect(count500!.value).toBe(1); + }); + + it('handles zero duration without error', () => { + expect(() => recordBillingDeductDuration(200, 0)).not.toThrow(); + }); + + it('handles very large duration values', () => { + expect(() => recordBillingDeductDuration(200, 30_000)).not.toThrow(); + }); +}); + +describe('billingDeductHistogramMiddleware', () => { + function buildReqRes(opts: { + method?: string; + statusCode?: number; + }) { + const { method = 'POST', statusCode = 200 } = opts; + const req = { method } as unknown as Request; + const res = Object.assign(new EventEmitter(), { statusCode }) as unknown as Response; + return { req, res }; + } + + it('records the histogram observation on response finish', async () => { + const { req, res } = buildReqRes({ statusCode: 200 }); + const next = jest.fn(); + billingDeductHistogramMiddleware(req, res, next); + expect(next).toHaveBeenCalledTimes(1); + res.emit('finish'); + const metric = await getMetricValues('billing_deduct_duration_seconds'); + const countEntry = (metric!.values as MetricEntry[]).find( + (v) => v.metricName === 'billing_deduct_duration_seconds_count', + ); + expect(countEntry).toBeDefined(); + expect(countEntry!.value).toBe(1); + }); + + it('records the correct status code label', async () => { + const { req, res } = buildReqRes({ statusCode: 402 }); + billingDeductHistogramMiddleware(req, res, jest.fn()); + res.emit('finish'); + const metric = await getMetricValues('billing_deduct_duration_seconds'); + const countEntry = (metric!.values as MetricEntry[]).find( + (v) => v.metricName === 'billing_deduct_duration_seconds_count' && v.labels.status_code === '402', + ); + expect(countEntry).toBeDefined(); + }); + + it('records the correct route label', async () => { + const { req, res } = buildReqRes({ statusCode: 200 }); + billingDeductHistogramMiddleware(req, res, jest.fn()); + res.emit('finish'); + const metric = await getMetricValues('billing_deduct_duration_seconds'); + const countEntry = (metric!.values as MetricEntry[]).find( + (v) => v.metricName === 'billing_deduct_duration_seconds_count', + ); + expect(countEntry).toBeDefined(); + expect(countEntry!.labels.route).toBe('/api/billing/deduct'); + }); + + it('calls next function exactly once', () => { + const { req, res } = buildReqRes({}); + const next = jest.fn(); + billingDeductHistogramMiddleware(req, res, next); + expect(next).toHaveBeenCalledTimes(1); + }); + + it('does not throw when finish is emitted before next', () => { + const { req, res } = buildReqRes({}); + billingDeductHistogramMiddleware(req, res, jest.fn()); + expect(() => res.emit('finish')).not.toThrow(); + }); + + it('handles multiple calls without error', () => { + for (let i = 0; i < 3; i++) { + const { req, res } = buildReqRes({ statusCode: 200 }); + billingDeductHistogramMiddleware(req, res, jest.fn()); + res.emit('finish'); + } + }); + + it('handles error status codes without throwing', () => { + const statusCodes = [400, 401, 402, 403, 500, 502, 503, 504]; + for (const code of statusCodes) { + const { req, res } = buildReqRes({ statusCode: code }); + expect(() => { + billingDeductHistogramMiddleware(req, res, jest.fn()); + res.emit('finish'); + }).not.toThrow(); + } + }); +}); + +describe('resetBillingDeductMetrics', () => { + it('clears all previously recorded observations', async () => { + recordBillingDeductDuration(200, 100); + resetBillingDeductMetrics(); + const metric = await getMetricValues('billing_deduct_duration_seconds'); + const countEntry = (metric!.values as MetricEntry[]).find( + (v) => v.metricName === 'billing_deduct_duration_seconds_count', + ); + expect(countEntry).toBeUndefined(); + }); + + it('allows new recordings after reset', async () => { + recordBillingDeductDuration(200, 100); + resetBillingDeductMetrics(); + recordBillingDeductDuration(200, 50); + const metric = await getMetricValues('billing_deduct_duration_seconds'); + const countEntry = (metric!.values as MetricEntry[]).find( + (v) => v.metricName === 'billing_deduct_duration_seconds_count', + ); + expect(countEntry).toBeDefined(); + expect(countEntry!.value).toBe(1); + }); +}); + +describe('metric registration and dashboard consistency', () => { + it('metric name appears in the exported metric registry', async () => { + const metrics = await client.register.getMetricsAsJSON(); + const metricNames = metrics.map((m: any) => m.name); + expect(metricNames).toContain('billing_deduct_duration_seconds'); + }); + + it('histogram bucket boundaries are consistent with the 1ms..10s requirement', async () => { + recordBillingDeductDuration(200, 50); + const metric = await getMetricValues('billing_deduct_duration_seconds'); + expect(metric).toBeDefined(); + const bucketValues = (metric!.values as MetricEntry[]).filter( + (v) => v.metricName === 'billing_deduct_duration_seconds_bucket', + ); + const les = bucketValues.map((v) => Number(v.labels.le)).filter(isFinite); + expect(les).toEqual( + expect.arrayContaining([0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10]), + ); + }); +}); diff --git a/src/metrics/registry.ts b/src/metrics/registry.ts new file mode 100644 index 00000000..42cdfba5 --- /dev/null +++ b/src/metrics/registry.ts @@ -0,0 +1,21 @@ +import client from 'prom-client'; + +const billingDeductDuration = new client.Histogram({ + name: 'billing_deduct_duration_seconds', + help: 'Latency of POST /api/billing/deduct in seconds', + labelNames: ['route', 'status_code'], + buckets: [0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10], +}); + +export function recordBillingDeductDuration(statusCode: number, durationMs: number): void { + billingDeductDuration.observe( + { route: '/api/billing/deduct', status_code: String(statusCode) }, + durationMs / 1000, + ); +} + +export function resetBillingDeductMetrics(): void { + billingDeductDuration.reset(); +} + +export { billingDeductDuration }; diff --git a/src/middleware/metricsHistogram.ts b/src/middleware/metricsHistogram.ts new file mode 100644 index 00000000..a017e7ed --- /dev/null +++ b/src/middleware/metricsHistogram.ts @@ -0,0 +1,18 @@ +import type { Request, Response, NextFunction } from 'express'; +import { performance } from 'node:perf_hooks'; +import { recordBillingDeductDuration } from '../metrics/registry.js'; + +export function billingDeductHistogramMiddleware( + req: Request, + res: Response, + next: NextFunction, +): void { + const start = performance.now(); + + res.on('finish', () => { + const durationMs = performance.now() - start; + recordBillingDeductDuration(res.statusCode, durationMs); + }); + + next(); +} diff --git a/src/routes/billing.ts b/src/routes/billing.ts index 0869b76f..402f275e 100644 --- a/src/routes/billing.ts +++ b/src/routes/billing.ts @@ -13,6 +13,7 @@ import { } from '../errors/index.js'; import { requireAuth, type AuthenticatedLocals } from '../middleware/requireAuth.js'; import { idempotencyMiddleware } from '../middleware/idempotency.js'; +import { billingDeductHistogramMiddleware } from '../middleware/metricsHistogram.js'; import { BillingService, type BillingDeductResult } from '../services/billing.js'; import { createSorobanRpcBillingClient, SorobanRpcError } from '../services/sorobanBilling.js'; import { redactSimulationDetails } from '../lib/simulationDiagnostics.js'; @@ -81,6 +82,7 @@ router.post( '/deduct', requireAuth, idempotencyMiddleware, + billingDeductHistogramMiddleware, async ( req: Request, res: Response,