From 771b2fd59ef919b9967b04cb3754ff65c1f4579c Mon Sep 17 00:00:00 2001 From: Kaylahray Date: Sun, 28 Jun 2026 18:52:07 +0100 Subject: [PATCH] backend observability --- backend/package-lock.json | 134 ++-------- backend/src/app.module.ts | 7 +- backend/src/auth/auth.service.spec.ts | 6 + backend/src/auth/auth.service.ts | 55 ++++ backend/src/config/observability.config.ts | 12 + backend/src/invoices/invoices.cron.spec.ts | 6 + backend/src/invoices/invoices.import.spec.ts | 6 + .../invoices/invoices.service.soroban.spec.ts | 6 + backend/src/invoices/invoices.service.spec.ts | 6 + backend/src/invoices/invoices.service.ts | 16 ++ backend/src/main.ts | 8 +- .../correlation-id.middleware.ts | 41 +++ .../observability/http-exception.filter.ts | 49 ++++ .../src/observability/logging.interceptor.ts | 61 +++++ .../src/observability/observability.module.ts | 30 +++ .../request-context.service.spec.ts | 48 ++++ .../observability/request-context.service.ts | 85 ++++++ .../structured-logger.service.ts | 60 +++++ .../testing/observability.mock.ts | 22 ++ .../src/observability/tracing.util.spec.ts | 75 ++++++ backend/src/observability/tracing.util.ts | 61 +++++ backend/src/prisma/prisma.service.ts | 34 ++- .../src/stellar/horizon-watcher.service.ts | 250 ++++++++++++------ .../stellar/soroban-events.service.spec.ts | 14 + backend/src/stellar/soroban-events.service.ts | 183 ++++++++----- .../src/stellar/soroban.integration.spec.ts | 17 +- web/lib/api-client.ts | 12 +- 27 files changed, 1037 insertions(+), 267 deletions(-) create mode 100644 backend/src/config/observability.config.ts create mode 100644 backend/src/observability/correlation-id.middleware.ts create mode 100644 backend/src/observability/http-exception.filter.ts create mode 100644 backend/src/observability/logging.interceptor.ts create mode 100644 backend/src/observability/observability.module.ts create mode 100644 backend/src/observability/request-context.service.spec.ts create mode 100644 backend/src/observability/request-context.service.ts create mode 100644 backend/src/observability/structured-logger.service.ts create mode 100644 backend/src/observability/testing/observability.mock.ts create mode 100644 backend/src/observability/tracing.util.spec.ts create mode 100644 backend/src/observability/tracing.util.ts diff --git a/backend/package-lock.json b/backend/package-lock.json index d26993e..e2f652e 100644 --- a/backend/package-lock.json +++ b/backend/package-lock.json @@ -1533,6 +1533,7 @@ "resolved": "https://registry.npmjs.org/@isaacs/cliui/-/cliui-8.0.2.tgz", "integrity": "sha512-O8jcjabXaleOG9DQ0+ARXWZBTfnP4WNAqzuiJK7ll44AmxGKv/J2M4TPjxjY3znBCfvBXFzucm1twdyFybFqEA==", "license": "ISC", + "peer": true, "dependencies": { "string-width": "^5.1.2", "string-width-cjs": "npm:string-width@^4.2.0", @@ -1550,6 +1551,7 @@ "resolved": "https://registry.npmjs.org/ansi-regex/-/ansi-regex-6.2.2.tgz", "integrity": "sha512-Bq3SmSpyFHaWjPk8If9yc6svM8c56dB5BAtW4Qbw5jHTwwXXcTLoRMkpDJp6VL0XzlWaCHTXrkFURMYmD0sLqg==", "license": "MIT", + "peer": true, "engines": { "node": ">=12" }, @@ -1562,6 +1564,7 @@ "resolved": "https://registry.npmjs.org/ansi-styles/-/ansi-styles-6.2.3.tgz", "integrity": "sha512-4Dj6M28JB+oAH8kFkTLUo+a2jwOFkuqb3yucU0CANcRRUbxS0cP0nZYCGjcc3BNXwRIsUVmDGgzawme7zvJHvg==", "license": "MIT", + "peer": true, "engines": { "node": ">=12" }, @@ -1573,13 +1576,15 @@ "version": "9.2.2", "resolved": "https://registry.npmjs.org/emoji-regex/-/emoji-regex-9.2.2.tgz", "integrity": "sha512-L18DaJsXSUk2+42pv8mLs5jJT2hqFkFE4j21wOmgbUqsZ2hL72NsUU785g9RXgo3s0ZNgVl42TiHp3ZtOv/Vyg==", - "license": "MIT" + "license": "MIT", + "peer": true }, "node_modules/@isaacs/cliui/node_modules/string-width": { "version": "5.1.2", "resolved": "https://registry.npmjs.org/string-width/-/string-width-5.1.2.tgz", "integrity": "sha512-HnLOCR3vjcY8beoNLtcjZ5/nxn2afmME6lhrDrebokqMap+XbeW8n9TXpPDOqdGK5qcI3oT0GKTW6wC7EMiVqA==", "license": "MIT", + "peer": true, "dependencies": { "eastasianwidth": "^0.2.0", "emoji-regex": "^9.2.2", @@ -1597,6 +1602,7 @@ "resolved": "https://registry.npmjs.org/strip-ansi/-/strip-ansi-7.2.0.tgz", "integrity": "sha512-yDPMNjp4WyfYBkHnjIRLfca1i6KMyGCtsVgoKe/z1+6vukgaENdgGBZt+ZmKPc4gavvEZ5OgHfHdrazhgNyG7w==", "license": "MIT", + "peer": true, "dependencies": { "ansi-regex": "^6.2.2" }, @@ -1612,6 +1618,7 @@ "resolved": "https://registry.npmjs.org/wrap-ansi/-/wrap-ansi-8.1.0.tgz", "integrity": "sha512-si7QWI6zUMq56bESFvagtmzMdGOtoxfR+Sez11Mobfc7tm+VkUckk9bW2UeffTGVUbOksxmSw0AA2gs8g71NCQ==", "license": "MIT", + "peer": true, "dependencies": { "ansi-styles": "^6.1.0", "string-width": "^5.0.1", @@ -2382,6 +2389,7 @@ "dev": true, "license": "MIT", "optional": true, + "peer": true, "dependencies": { "@types/node": "*", "jest-regex-util": "30.0.1" @@ -2708,6 +2716,7 @@ "dev": true, "license": "MIT", "optional": true, + "peer": true, "dependencies": { "@sinclair/typebox": "^0.34.0" }, @@ -2960,6 +2969,7 @@ "dev": true, "license": "MIT", "optional": true, + "peer": true, "dependencies": { "@jest/pattern": "30.0.1", "@jest/schemas": "30.0.5", @@ -3689,6 +3699,7 @@ "integrity": "sha512-+1VkjdD0QBLPodGrJUeqarH8VAIvQODIbwh9XpP5Syisf7YoQgsJKPNFoqqLQlu+VQ/tVSshMR6loPMn8U+dPg==", "license": "MIT", "optional": true, + "peer": true, "engines": { "node": ">=14" } @@ -4001,7 +4012,8 @@ "integrity": "sha512-kKJTNuK3AQOrgjjotVxMrCn1sUJwM76wMszfq1kdU4uYVJjvEWuFQ6HgvLt4Xz3fSmZlTOxJ/Ie13KnIcWQXFA==", "dev": true, "license": "MIT", - "optional": true + "optional": true, + "peer": true }, "node_modules/@sinonjs/commons": { "version": "3.0.1", @@ -4832,14 +4844,6 @@ "url": "https://opencollective.com/eslint" } }, - "node_modules/@ungap/structured-clone": { - "version": "1.3.0", - "resolved": "https://registry.npmjs.org/@ungap/structured-clone/-/structured-clone-1.3.0.tgz", - "integrity": "sha512-WmoN8qaIAo7WTYWbAZuG8PYEhn5fkz7dZrqTBZ7dtt//lL2Gwms1IcnQ5yHqjDfX8Ft5j4YzDM23f87zBfDe9g==", - "dev": true, - "license": "ISC", - "optional": true - }, "node_modules/@webassemblyjs/ast": { "version": "1.14.1", "resolved": "https://registry.npmjs.org/@webassemblyjs/ast/-/ast-1.14.1.tgz", @@ -5321,27 +5325,6 @@ "proxy-from-env": "^1.1.0" } }, - "node_modules/babel-plugin-istanbul": { - "version": "7.0.1", - "resolved": "https://registry.npmjs.org/babel-plugin-istanbul/-/babel-plugin-istanbul-7.0.1.tgz", - "integrity": "sha512-D8Z6Qm8jCvVXtIRkBnqNHX0zJ37rQcFJ9u8WOS6tkYOsRdHBzypCstaxWiu5ZIlqQtviRYbgnRLSoCEvjqcqbA==", - "dev": true, - "license": "BSD-3-Clause", - "optional": true, - "workspaces": [ - "test/babel-8" - ], - "dependencies": { - "@babel/helper-plugin-utils": "^7.0.0", - "@istanbuljs/load-nyc-config": "^1.0.0", - "@istanbuljs/schema": "^0.1.3", - "istanbul-lib-instrument": "^6.0.2", - "test-exclude": "^6.0.0" - }, - "engines": { - "node": ">=12" - } - }, "node_modules/babel-preset-current-node-syntax": { "version": "1.2.0", "resolved": "https://registry.npmjs.org/babel-preset-current-node-syntax/-/babel-preset-current-node-syntax-1.2.0.tgz", @@ -5849,6 +5832,7 @@ ], "license": "MIT", "optional": true, + "peer": true, "engines": { "node": ">=8" } @@ -6661,7 +6645,8 @@ "version": "0.2.0", "resolved": "https://registry.npmjs.org/eastasianwidth/-/eastasianwidth-0.2.0.tgz", "integrity": "sha512-I88TYZWc9XiYHRQ4/3c5rjjfgkjhLyW2luGIheGERbNQ6OY7yTybanSpDXZa8y7VUP9YmDcYa+eyq4ca7iLqWA==", - "license": "MIT" + "license": "MIT", + "peer": true }, "node_modules/ecdsa-sig-formatter": { "version": "1.0.11", @@ -8635,6 +8620,7 @@ "resolved": "https://registry.npmjs.org/jackspeak/-/jackspeak-3.4.3.tgz", "integrity": "sha512-OGlZQpz2yfahA/Rd1Y8Cd9SIEsqvXkLVoSw/cgwhnhFMDbsQFeZYoJJ7bIZBS9BcamUW96asq/npPWugM+RQBw==", "license": "BlueOak-1.0.0", + "peer": true, "dependencies": { "@isaacs/cliui": "^8.0.2" }, @@ -9620,32 +9606,6 @@ "node": "^14.15.0 || ^16.10.0 || >=18.0.0" } }, - "node_modules/jest-haste-map": { - "version": "30.2.0", - "resolved": "https://registry.npmjs.org/jest-haste-map/-/jest-haste-map-30.2.0.tgz", - "integrity": "sha512-sQA/jCb9kNt+neM0anSj6eZhLZUIhQgwDt7cPGjumgLM4rXsfb9kpnlacmvZz3Q5tb80nS+oG/if+NBKrHC+Xw==", - "dev": true, - "license": "MIT", - "optional": true, - "dependencies": { - "@jest/types": "30.2.0", - "@types/node": "*", - "anymatch": "^3.1.3", - "fb-watchman": "^2.0.2", - "graceful-fs": "^4.2.11", - "jest-regex-util": "30.0.1", - "jest-util": "30.2.0", - "jest-worker": "30.2.0", - "micromatch": "^4.0.8", - "walker": "^1.0.8" - }, - "engines": { - "node": "^18.14.0 || ^20.0.0 || ^22.0.0 || >=24.0.0" - }, - "optionalDependencies": { - "fsevents": "^2.3.3" - } - }, "node_modules/jest-leak-detector": { "version": "29.7.0", "resolved": "https://registry.npmjs.org/jest-leak-detector/-/jest-leak-detector-29.7.0.tgz", @@ -9860,6 +9820,7 @@ "dev": true, "license": "MIT", "optional": true, + "peer": true, "engines": { "node": "^18.14.0 || ^20.0.0 || ^22.0.0 || >=24.0.0" } @@ -10946,6 +10907,7 @@ "dev": true, "license": "MIT", "optional": true, + "peer": true, "dependencies": { "@jest/types": "30.2.0", "@types/node": "*", @@ -11132,41 +11094,6 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, - "node_modules/jest-worker": { - "version": "30.2.0", - "resolved": "https://registry.npmjs.org/jest-worker/-/jest-worker-30.2.0.tgz", - "integrity": "sha512-0Q4Uk8WF7BUwqXHuAjc23vmopWJw5WH7w2tqBoUOZpOjW/ZnR44GXXd1r82RvnmI2GZge3ivrYXk/BE2+VtW2g==", - "dev": true, - "license": "MIT", - "optional": true, - "dependencies": { - "@types/node": "*", - "@ungap/structured-clone": "^1.3.0", - "jest-util": "30.2.0", - "merge-stream": "^2.0.0", - "supports-color": "^8.1.1" - }, - "engines": { - "node": "^18.14.0 || ^20.0.0 || ^22.0.0 || >=24.0.0" - } - }, - "node_modules/jest-worker/node_modules/supports-color": { - "version": "8.1.1", - "resolved": "https://registry.npmjs.org/supports-color/-/supports-color-8.1.1.tgz", - "integrity": "sha512-MpUEN2OodtUzxvKQl72cUF7RQ5EiHsGvSsVG0ia9c5RbWGL2CI4C7EpPS8UTBIplnlzZiNuV56w+FuNxy3ty2Q==", - "dev": true, - "license": "MIT", - "optional": true, - "dependencies": { - "has-flag": "^4.0.0" - }, - "engines": { - "node": ">=10" - }, - "funding": { - "url": "https://github.com/chalk/supports-color?sponsor=1" - } - }, "node_modules/jest/node_modules/@jest/schemas": { "version": "29.6.3", "resolved": "https://registry.npmjs.org/@jest/schemas/-/schemas-29.6.3.tgz", @@ -12203,7 +12130,8 @@ "version": "1.0.1", "resolved": "https://registry.npmjs.org/package-json-from-dist/-/package-json-from-dist-1.0.1.tgz", "integrity": "sha512-UEZIS3/by4OC8vL3P2dTXRETpebLI2NiI5vIrjaD/5UtrkFX/tNbwjTSRAGC/+7CAo2pIcBaRgWmcBBHcsaCIw==", - "license": "BlueOak-1.0.0" + "license": "BlueOak-1.0.0", + "peer": true }, "node_modules/parent-module": { "version": "1.0.1", @@ -13710,6 +13638,7 @@ "resolved": "https://registry.npmjs.org/string-width/-/string-width-4.2.3.tgz", "integrity": "sha512-wKyQRQpjJ0sIp62ErSZdGsjMJWsap5oRNihHhu6G7JVO/9jIB6UyevL+tXuOqrng8j/cxKTWyWUwvSTriiZz/g==", "license": "MIT", + "peer": true, "dependencies": { "emoji-regex": "^8.0.0", "is-fullwidth-code-point": "^3.0.0", @@ -13737,6 +13666,7 @@ "resolved": "https://registry.npmjs.org/strip-ansi/-/strip-ansi-6.0.1.tgz", "integrity": "sha512-Y38VPSHcqkFrCpFnQ9vuSXmquuv5oXOKpGeT6aGrr3o3Gc9AlVa6JBfUSOCnbxGGZF+/0ooI7KrPuUSztUdU5A==", "license": "MIT", + "peer": true, "dependencies": { "ansi-regex": "^5.0.1" }, @@ -15065,6 +14995,7 @@ "resolved": "https://registry.npmjs.org/wrap-ansi/-/wrap-ansi-7.0.0.tgz", "integrity": "sha512-YVGIj2kamLSTxw6NsZjoBxfSwsn0ycdesmc4p+Q21c5zPuZ1pl+NfxVdxPtdHvmNVOQ6XSYG4AUtyt/Fi7D16Q==", "license": "MIT", + "peer": true, "dependencies": { "ansi-styles": "^4.0.0", "string-width": "^4.1.0", @@ -15083,21 +15014,6 @@ "integrity": "sha512-l4Sp/DRseor9wL6EvV2+TuQn63dMkPjZ/sp9XkghTEbV9KlPS1xUsZ3u7/IQO4wxtcFB4bgpQPRcR3QCvezPcQ==", "license": "ISC" }, - "node_modules/write-file-atomic": { - "version": "5.0.1", - "resolved": "https://registry.npmjs.org/write-file-atomic/-/write-file-atomic-5.0.1.tgz", - "integrity": "sha512-+QU2zd6OTD8XWIJCbffaiQeH9U73qIqafo1x6V1snCWYGJf6cVE0cDR4D8xRzcEnfI21IFrUPzPGtcPf8AC+Rw==", - "dev": true, - "license": "ISC", - "optional": true, - "dependencies": { - "imurmurhash": "^0.1.4", - "signal-exit": "^4.0.1" - }, - "engines": { - "node": "^14.17.0 || ^16.13.0 || >=18.0.0" - } - }, "node_modules/xtend": { "version": "4.0.2", "resolved": "https://registry.npmjs.org/xtend/-/xtend-4.0.2.tgz", diff --git a/backend/src/app.module.ts b/backend/src/app.module.ts index bc688bf..ffb208d 100644 --- a/backend/src/app.module.ts +++ b/backend/src/app.module.ts @@ -6,6 +6,8 @@ import { ConfigModule, ConfigService } from "@nestjs/config"; import appConfig from "./config/app.config"; import stellarConfig from "./config/stellar.config"; import throttlerConfig from "./config/throttler.config"; +import observabilityConfig from "./config/observability.config"; +import { ObservabilityModule } from "./observability/observability.module"; // Modules import { HealthModule } from "./health/health.module"; @@ -38,7 +40,7 @@ import { MerchantModule } from "./merchant/merchant.module"; ConfigModule.forRoot({ isGlobal: true, envFilePath: [".env", ".env.example"], - load: [appConfig, stellarConfig, throttlerConfig], + load: [appConfig, stellarConfig, throttlerConfig, observabilityConfig], validationSchema: Joi.object({ PORT: Joi.number().default(3001), CORS_ORIGIN: Joi.string().default("http://localhost:3000"), @@ -86,12 +88,15 @@ import { MerchantModule } from "./merchant/merchant.module"; REDIS_PASSWORD: Joi.string().optional().allow(""), REDIS_DB: Joi.number().integer().min(0).default(0), REDIS_KEY_PREFIX: Joi.string().default("invoisio:throttle:"), + SLOW_DB_THRESHOLD_MS: Joi.number().integer().min(1).default(200), + SLOW_NETWORK_THRESHOLD_MS: Joi.number().integer().min(1).default(500), }), validationOptions: { abortEarly: false, allowUnknown: true, }, }), + ObservabilityModule, CustomThrottlerModule, PrismaModule, ScheduleModule.forRoot(), diff --git a/backend/src/auth/auth.service.spec.ts b/backend/src/auth/auth.service.spec.ts index 178d96b..4caea97 100644 --- a/backend/src/auth/auth.service.spec.ts +++ b/backend/src/auth/auth.service.spec.ts @@ -4,6 +4,8 @@ import { BadRequestException, UnauthorizedException } from "@nestjs/common"; import * as StellarSdk from "@stellar/stellar-sdk"; import { AuthService } from "./auth.service"; import { PrismaService } from "../prisma/prisma.service"; +import { StructuredLogger } from "../observability/structured-logger.service"; +import { mockStructuredLogger } from "../observability/testing/observability.mock"; const mockPrisma = () => ({ merchant: { @@ -30,6 +32,10 @@ describe("AuthService", () => { AuthService, { provide: PrismaService, useFactory: mockPrisma }, { provide: JwtService, useValue: { sign: jest.fn(() => "jwt-token") } }, + { + provide: StructuredLogger, + useValue: mockStructuredLogger, + }, ], }).compile(); diff --git a/backend/src/auth/auth.service.ts b/backend/src/auth/auth.service.ts index 0e89efc..449c63c 100644 --- a/backend/src/auth/auth.service.ts +++ b/backend/src/auth/auth.service.ts @@ -5,6 +5,7 @@ import { } from "@nestjs/common"; import { JwtService } from "@nestjs/jwt"; import { PrismaService } from "../prisma/prisma.service"; +import { StructuredLogger } from "../observability/structured-logger.service"; import * as crypto from "crypto"; import * as StellarSdk from "@stellar/stellar-sdk"; import { NonceRequestDto, VerifyRequestDto } from "./dtos/auth.dto"; @@ -17,6 +18,7 @@ export class AuthService { constructor( private readonly prisma: PrismaService, private readonly jwtService: JwtService, + private readonly logger: StructuredLogger, ) {} /** @@ -29,6 +31,12 @@ export class AuthService { ): Promise<{ nonce: string; expiresAt: number }> { this.assertValidPublicKey(dto.publicKey); + this.logger.info("auth.nonce.start", { + domain: "auth", + event: "nonce_requested", + publicKey: dto.publicKey, + }); + const existing = await this.prisma.user.findUnique({ where: { publicKey: dto.publicKey }, }); @@ -74,6 +82,13 @@ export class AuthService { merchantId, }, }); + this.logger.info("auth.nonce.issued", { + domain: "auth", + event: "nonce_issued", + publicKey: dto.publicKey, + isNewUser: true, + expiresAt: Number(expiresAt), + }); return { nonce, expiresAt: Number(expiresAt) }; } @@ -86,6 +101,14 @@ export class AuthService { }, }); + this.logger.info("auth.nonce.issued", { + domain: "auth", + event: "nonce_issued", + publicKey: dto.publicKey, + isNewUser: false, + expiresAt: Number(expiresAt), + }); + return { nonce, expiresAt: Number(expiresAt) }; } @@ -101,12 +124,24 @@ export class AuthService { async verify(dto: VerifyRequestDto): Promise<{ accessToken: string }> { this.assertValidPublicKey(dto.publicKey); + this.logger.info("auth.verify.start", { + domain: "auth", + event: "verify_started", + publicKey: dto.publicKey, + }); + // 1. Find user — unauthorized if no record or no active nonce const user = await this.prisma.user.findUnique({ where: { publicKey: dto.publicKey }, }); if (!user || !user.nonce) { + this.logger.warn("auth.verify.failed", { + domain: "auth", + event: "verify_failed", + reason: "no_active_nonce", + publicKey: dto.publicKey, + }); throw new UnauthorizedException( "No active nonce found. Request a new nonce first.", ); @@ -114,6 +149,12 @@ export class AuthService { // 2. Replay guard — unauthorized if nonce already consumed if (user.nonceUsedAt != null) { + this.logger.warn("auth.verify.failed", { + domain: "auth", + event: "verify_failed", + reason: "nonce_replay", + publicKey: dto.publicKey, + }); throw new UnauthorizedException( "Nonce has already been used. Request a new nonce.", ); @@ -121,6 +162,12 @@ export class AuthService { // 3. Expiry — unauthorized if nonce has expired if (Date.now() > Number(user.nonceExpiresAt ?? 0n)) { + this.logger.warn("auth.verify.failed", { + domain: "auth", + event: "verify_failed", + reason: "nonce_expired", + publicKey: dto.publicKey, + }); throw new UnauthorizedException( "Nonce has expired. Request a new nonce.", ); @@ -148,6 +195,14 @@ export class AuthService { }; const accessToken = this.jwtService.sign(payload); + this.logger.info("auth.verify.success", { + domain: "auth", + event: "verify_succeeded", + userId: user.id, + merchantId: user.merchantId ?? undefined, + publicKey: dto.publicKey, + }); + return { accessToken }; } diff --git a/backend/src/config/observability.config.ts b/backend/src/config/observability.config.ts new file mode 100644 index 0000000..0fb69d6 --- /dev/null +++ b/backend/src/config/observability.config.ts @@ -0,0 +1,12 @@ +import { registerAs } from "@nestjs/config"; + +export default registerAs("observability", () => ({ + slowDbThresholdMs: parseInt( + process.env.SLOW_DB_THRESHOLD_MS || "200", + 10, + ), + slowNetworkThresholdMs: parseInt( + process.env.SLOW_NETWORK_THRESHOLD_MS || "500", + 10, + ), +})); diff --git a/backend/src/invoices/invoices.cron.spec.ts b/backend/src/invoices/invoices.cron.spec.ts index d86721f..63db18c 100644 --- a/backend/src/invoices/invoices.cron.spec.ts +++ b/backend/src/invoices/invoices.cron.spec.ts @@ -5,6 +5,8 @@ import { SorobanService } from "../soroban/soroban.service"; import { PrismaService } from "../prisma/prisma.service"; import { WebhooksService } from "../webhooks/webhooks.service"; import { NotificationsService } from "../notifications/notifications.service"; +import { StructuredLogger } from "../observability/structured-logger.service"; +import { mockStructuredLogger } from "../observability/testing/observability.mock"; describe("InvoicesService Cron", () => { let service: InvoicesService; @@ -44,6 +46,10 @@ describe("InvoicesService Cron", () => { notifyInvoiceOverdue: jest.fn(), }, }, + { + provide: StructuredLogger, + useValue: mockStructuredLogger, + }, ], }).compile(); diff --git a/backend/src/invoices/invoices.import.spec.ts b/backend/src/invoices/invoices.import.spec.ts index 8adce88..bf77351 100644 --- a/backend/src/invoices/invoices.import.spec.ts +++ b/backend/src/invoices/invoices.import.spec.ts @@ -6,6 +6,8 @@ import { SorobanService } from "../soroban/soroban.service"; import { PrismaService } from "../prisma/prisma.service"; import { WebhooksService } from "../webhooks/webhooks.service"; import { NotificationsService } from "../notifications/notifications.service"; +import { StructuredLogger } from "../observability/structured-logger.service"; +import { mockStructuredLogger } from "../observability/testing/observability.mock"; const MERCHANT_A = "merchant-a"; const USER_A = "user-a"; @@ -65,6 +67,10 @@ describe("InvoicesService - importFromCsv", () => { notifyInvoiceOverdue: jest.fn(), }, }, + { + provide: StructuredLogger, + useValue: mockStructuredLogger, + }, ], }).compile(); diff --git a/backend/src/invoices/invoices.service.soroban.spec.ts b/backend/src/invoices/invoices.service.soroban.spec.ts index bd39b99..53722c1 100644 --- a/backend/src/invoices/invoices.service.soroban.spec.ts +++ b/backend/src/invoices/invoices.service.soroban.spec.ts @@ -3,6 +3,8 @@ import { StellarService } from "../stellar/stellar.service"; import { SorobanService } from "../soroban/soroban.service"; import { WebhooksService } from "../webhooks/webhooks.service"; import { NotificationsService } from "../notifications/notifications.service"; +import { StructuredLogger } from "../observability/structured-logger.service"; +import { mockStructuredLogger } from "../observability/testing/observability.mock"; class FakePrisma { invoice = { @@ -116,6 +118,9 @@ describe("InvoicesService.applySorobanPaymentEvent", () => { notifyInvoiceOverdue: async () => {}, } as unknown as NotificationsService; + const structuredLoggerStub = + mockStructuredLogger as unknown as StructuredLogger; + beforeEach(async () => { prisma = new FakePrisma(); service = new InvoicesService( @@ -124,6 +129,7 @@ describe("InvoicesService.applySorobanPaymentEvent", () => { prisma, webhooksStub, notificationsStub, + structuredLoggerStub, ); }); diff --git a/backend/src/invoices/invoices.service.spec.ts b/backend/src/invoices/invoices.service.spec.ts index 9fe29c8..bbca027 100644 --- a/backend/src/invoices/invoices.service.spec.ts +++ b/backend/src/invoices/invoices.service.spec.ts @@ -10,6 +10,8 @@ import { SorobanService } from "../soroban/soroban.service"; import { PrismaService } from "../prisma/prisma.service"; import { WebhooksService } from "../webhooks/webhooks.service"; import { NotificationsService } from "../notifications/notifications.service"; +import { StructuredLogger } from "../observability/structured-logger.service"; +import { mockStructuredLogger } from "../observability/testing/observability.mock"; const MERCHANT_A = "merchant-a"; const MERCHANT_B = "merchant-b"; @@ -223,6 +225,10 @@ describe("InvoicesService", () => { notifyInvoiceOverdue: jest.fn(), }, }, + { + provide: StructuredLogger, + useValue: mockStructuredLogger, + }, ], }).compile(); diff --git a/backend/src/invoices/invoices.service.ts b/backend/src/invoices/invoices.service.ts index 8d6253f..14fa366 100644 --- a/backend/src/invoices/invoices.service.ts +++ b/backend/src/invoices/invoices.service.ts @@ -21,6 +21,7 @@ import { Prisma, InvoiceStatus } from "@prisma/client"; import { WebhooksService } from "../webhooks/webhooks.service"; import { NotificationsService } from "../notifications/notifications.service"; import { InvoiceEventsService } from "../realtime/invoice-events.service"; +import { StructuredLogger } from "../observability/structured-logger.service"; const REQUIRED_CSV_HEADERS = [ "invoiceNumber", @@ -44,6 +45,7 @@ export class InvoicesService implements OnModuleInit { private readonly prisma: PrismaService, private readonly webhooksService: WebhooksService, private readonly notificationsService: NotificationsService, + private readonly structuredLogger: StructuredLogger, @Optional() private readonly invoiceEvents?: InvoiceEventsService, ) {} @@ -323,6 +325,20 @@ export class InvoicesService implements OnModuleInit { }, }, }); + + this.structuredLogger.info("invoice.created", { + domain: "invoices", + event: "invoice_created", + invoiceId: created.id, + invoiceNumber: created.invoiceNumber, + memo: created.memo, + merchantId, + userId, + amount: created.amount, + assetCode: created.assetCode, + status: created.status, + }); + return this.normalizeInvoice(created); } diff --git a/backend/src/main.ts b/backend/src/main.ts index 88dc586..a733173 100644 --- a/backend/src/main.ts +++ b/backend/src/main.ts @@ -23,7 +23,13 @@ async function bootstrap() { origin: corsOrigin, credentials: true, methods: ["GET", "POST", "PUT", "DELETE", "OPTIONS", "PATCH"], - allowedHeaders: ["Content-Type", "Authorization"], + allowedHeaders: [ + "Content-Type", + "Authorization", + "X-Correlation-ID", + "X-Request-ID", + ], + exposedHeaders: ["X-Correlation-ID"], }); // Global validation pipe diff --git a/backend/src/observability/correlation-id.middleware.ts b/backend/src/observability/correlation-id.middleware.ts new file mode 100644 index 0000000..f35c4a3 --- /dev/null +++ b/backend/src/observability/correlation-id.middleware.ts @@ -0,0 +1,41 @@ +import { Injectable, NestMiddleware } from "@nestjs/common"; +import { randomUUID } from "node:crypto"; +import { NextFunction, Request, Response } from "express"; +import { RequestContextService } from "./request-context.service"; + +const CORRELATION_HEADER = "x-correlation-id"; +const REQUEST_ID_HEADER = "x-request-id"; + +@Injectable() +export class CorrelationIdMiddleware implements NestMiddleware { + constructor(private readonly requestContext: RequestContextService) {} + + use(req: Request, res: Response, next: NextFunction): void { + const incoming = + this.readHeader(req, CORRELATION_HEADER) ?? + this.readHeader(req, REQUEST_ID_HEADER); + const correlationId = incoming ?? randomUUID(); + + res.setHeader(CORRELATION_HEADER, correlationId); + + void this.requestContext.runWithContext( + { + correlationId, + traceId: correlationId, + httpMethod: req.method, + httpPath: req.originalUrl ?? req.url, + }, + () => { + next(); + }, + ); + } + + private readHeader(req: Request, name: string): string | undefined { + const value = req.headers[name]; + if (typeof value === "string" && value.trim().length > 0) { + return value.trim(); + } + return undefined; + } +} diff --git a/backend/src/observability/http-exception.filter.ts b/backend/src/observability/http-exception.filter.ts new file mode 100644 index 0000000..63a5b53 --- /dev/null +++ b/backend/src/observability/http-exception.filter.ts @@ -0,0 +1,49 @@ +import { + ArgumentsHost, + Catch, + ExceptionFilter, + HttpException, + HttpStatus, +} from "@nestjs/common"; +import { Response } from "express"; +import { RequestContextService } from "./request-context.service"; +import { StructuredLogger } from "./structured-logger.service"; + +@Catch() +export class HttpExceptionFilter implements ExceptionFilter { + constructor( + private readonly requestContext: RequestContextService, + private readonly logger: StructuredLogger, + ) {} + + catch(exception: unknown, host: ArgumentsHost): void { + const ctx = host.switchToHttp(); + const response = ctx.getResponse(); + + const status = + exception instanceof HttpException + ? exception.getStatus() + : HttpStatus.INTERNAL_SERVER_ERROR; + + const message = + exception instanceof HttpException + ? exception.getResponse() + : "Internal server error"; + + const correlationId = this.requestContext.getCorrelationId(); + + this.logger.error("http.exception", { + statusCode: status, + error: typeof message === "string" ? message : JSON.stringify(message), + }); + + response.status(status).json({ + error: + typeof message === "string" + ? message + : (message as { message?: string }).message || "Internal server error", + correlationId, + traceId: this.requestContext.getTraceId(), + }); + } +} diff --git a/backend/src/observability/logging.interceptor.ts b/backend/src/observability/logging.interceptor.ts new file mode 100644 index 0000000..de604ac --- /dev/null +++ b/backend/src/observability/logging.interceptor.ts @@ -0,0 +1,61 @@ +import { + CallHandler, + ExecutionContext, + Injectable, + NestInterceptor, +} from "@nestjs/common"; +import { Observable, tap } from "rxjs"; +import { Request, Response } from "express"; +import { StructuredLogger } from "./structured-logger.service"; +import { RequestContextService } from "./request-context.service"; + +@Injectable() +export class LoggingInterceptor implements NestInterceptor { + constructor( + private readonly logger: StructuredLogger, + private readonly requestContext: RequestContextService, + ) {} + + intercept(context: ExecutionContext, next: CallHandler): Observable { + if (context.getType() !== "http") { + return next.handle(); + } + + const req = context.switchToHttp().getRequest(); + const res = context.switchToHttp().getResponse(); + const startedAt = Date.now(); + + const user = (req as Request & { user?: { id?: string; merchantId?: string } }) + .user; + if (user?.id || user?.merchantId) { + this.requestContext.setUserContext(user.id, user.merchantId ?? undefined); + } + + this.logger.info("http.request.start", { + method: req.method, + path: req.originalUrl ?? req.url, + }); + + return next.handle().pipe( + tap({ + next: () => { + this.logger.info("http.request.complete", { + method: req.method, + path: req.originalUrl ?? req.url, + statusCode: res.statusCode, + durationMs: Date.now() - startedAt, + }); + }, + error: (error: unknown) => { + this.logger.error("http.request.error", { + method: req.method, + path: req.originalUrl ?? req.url, + statusCode: res.statusCode, + durationMs: Date.now() - startedAt, + error: error instanceof Error ? error.message : String(error), + }); + }, + }), + ); + } +} diff --git a/backend/src/observability/observability.module.ts b/backend/src/observability/observability.module.ts new file mode 100644 index 0000000..6a42a0a --- /dev/null +++ b/backend/src/observability/observability.module.ts @@ -0,0 +1,30 @@ +import { Global, MiddlewareConsumer, Module, NestModule } from "@nestjs/common"; +import { APP_FILTER, APP_INTERCEPTOR } from "@nestjs/core"; +import { CorrelationIdMiddleware } from "./correlation-id.middleware"; +import { HttpExceptionFilter } from "./http-exception.filter"; +import { LoggingInterceptor } from "./logging.interceptor"; +import { RequestContextService } from "./request-context.service"; +import { StructuredLogger } from "./structured-logger.service"; + +@Global() +@Module({ + providers: [ + RequestContextService, + StructuredLogger, + CorrelationIdMiddleware, + { + provide: APP_INTERCEPTOR, + useClass: LoggingInterceptor, + }, + { + provide: APP_FILTER, + useClass: HttpExceptionFilter, + }, + ], + exports: [RequestContextService, StructuredLogger], +}) +export class ObservabilityModule implements NestModule { + configure(consumer: MiddlewareConsumer): void { + consumer.apply(CorrelationIdMiddleware).forRoutes("*"); + } +} diff --git a/backend/src/observability/request-context.service.spec.ts b/backend/src/observability/request-context.service.spec.ts new file mode 100644 index 0000000..0ddea9b --- /dev/null +++ b/backend/src/observability/request-context.service.spec.ts @@ -0,0 +1,48 @@ +import { Test, TestingModule } from "@nestjs/testing"; +import { RequestContextService } from "./request-context.service"; +import { StructuredLogger } from "./structured-logger.service"; + +describe("RequestContextService", () => { + let service: RequestContextService; + + beforeEach(async () => { + const module: TestingModule = await Test.createTestingModule({ + providers: [RequestContextService, StructuredLogger], + }).compile(); + + service = module.get(RequestContextService); + }); + + it("propagates correlationId across async boundaries", async () => { + const seen: string[] = []; + + await service.runWithContext( + { correlationId: "corr-1", traceId: "corr-1" }, + async () => { + seen.push(service.getCorrelationId() ?? ""); + await Promise.resolve(); + seen.push(service.getCorrelationId() ?? ""); + }, + ); + + expect(seen).toEqual(["corr-1", "corr-1"]); + }); + + it("inherits traceId in child worker context", async () => { + let childTraceId: string | undefined; + + await service.runWithWorkerContext( + { workerName: "horizon-watcher", correlationId: "worker-corr" }, + async () => { + await service.runWithChildContext( + { correlationId: "horizon:tx-123" }, + async () => { + childTraceId = service.getTraceId(); + }, + ); + }, + ); + + expect(childTraceId).toBe("worker-corr"); + }); +}); diff --git a/backend/src/observability/request-context.service.ts b/backend/src/observability/request-context.service.ts new file mode 100644 index 0000000..02f5100 --- /dev/null +++ b/backend/src/observability/request-context.service.ts @@ -0,0 +1,85 @@ +import { Injectable } from "@nestjs/common"; +import { AsyncLocalStorage } from "node:async_hooks"; +import { randomUUID } from "node:crypto"; + +export type RequestContextStore = { + correlationId: string; + traceId: string; + workerRunId?: string; + workerName?: string; + httpMethod?: string; + httpPath?: string; + merchantId?: string; + userId?: string; +}; + +export type WorkerContextOptions = { + workerName: string; + correlationId?: string; + attributes?: Record; +}; + +@Injectable() +export class RequestContextService { + private readonly storage = new AsyncLocalStorage(); + + runWithContext( + store: RequestContextStore, + callback: () => Promise | T, + ): Promise { + return Promise.resolve(this.storage.run(store, callback)); + } + + runWithWorkerContext( + options: WorkerContextOptions, + callback: () => Promise | T, + ): Promise { + const correlationId = options.correlationId ?? randomUUID(); + const store: RequestContextStore = { + correlationId, + traceId: correlationId, + workerRunId: randomUUID(), + workerName: options.workerName, + }; + return this.runWithContext(store, callback); + } + + runWithChildContext( + partial: Partial, + callback: () => Promise | T, + ): Promise { + const parent = this.storage.getStore(); + const correlationId = + partial.correlationId ?? parent?.correlationId ?? randomUUID(); + const store: RequestContextStore = { + correlationId, + traceId: parent?.traceId ?? correlationId, + workerRunId: partial.workerRunId ?? parent?.workerRunId, + workerName: partial.workerName ?? parent?.workerName, + httpMethod: partial.httpMethod ?? parent?.httpMethod, + httpPath: partial.httpPath ?? parent?.httpPath, + merchantId: partial.merchantId ?? parent?.merchantId, + userId: partial.userId ?? parent?.userId, + }; + return this.runWithContext(store, callback); + } + + getStore(): RequestContextStore | undefined { + return this.storage.getStore(); + } + + getCorrelationId(): string | undefined { + return this.storage.getStore()?.correlationId; + } + + getTraceId(): string | undefined { + return this.storage.getStore()?.traceId; + } + + setUserContext(userId?: string, merchantId?: string): void { + const store = this.storage.getStore(); + if (!store) return; + if (userId !== undefined) store.userId = userId; + if (merchantId !== undefined) store.merchantId = merchantId; + } +} diff --git a/backend/src/observability/structured-logger.service.ts b/backend/src/observability/structured-logger.service.ts new file mode 100644 index 0000000..8e2fbfe --- /dev/null +++ b/backend/src/observability/structured-logger.service.ts @@ -0,0 +1,60 @@ +import { Injectable } from "@nestjs/common"; +import { RequestContextService } from "./request-context.service"; + +export type LogLevel = "debug" | "info" | "warn" | "error"; + +export type StructuredLogFields = Record; + +@Injectable() +export class StructuredLogger { + constructor(private readonly requestContext: RequestContextService) {} + + debug(message: string, fields?: StructuredLogFields): void { + this.write("debug", message, fields); + } + + info(message: string, fields?: StructuredLogFields): void { + this.write("info", message, fields); + } + + warn(message: string, fields?: StructuredLogFields): void { + this.write("warn", message, fields); + } + + error(message: string, fields?: StructuredLogFields): void { + this.write("error", message, fields); + } + + private write( + level: LogLevel, + message: string, + fields?: StructuredLogFields, + ): void { + const ctx = this.requestContext.getStore(); + const entry = { + timestamp: new Date().toISOString(), + level, + message, + ...(ctx?.correlationId ? { correlationId: ctx.correlationId } : {}), + ...(ctx?.traceId ? { traceId: ctx.traceId } : {}), + ...(ctx?.workerRunId ? { workerRunId: ctx.workerRunId } : {}), + ...(ctx?.workerName ? { workerName: ctx.workerName } : {}), + ...(ctx?.httpMethod ? { httpMethod: ctx.httpMethod } : {}), + ...(ctx?.httpPath ? { httpPath: ctx.httpPath } : {}), + ...(ctx?.merchantId ? { merchantId: ctx.merchantId } : {}), + ...(ctx?.userId ? { userId: ctx.userId } : {}), + ...fields, + }; + + const line = JSON.stringify(entry); + if (level === "error") { + console.error(line); + return; + } + if (level === "warn") { + console.warn(line); + return; + } + console.log(line); + } +} diff --git a/backend/src/observability/testing/observability.mock.ts b/backend/src/observability/testing/observability.mock.ts new file mode 100644 index 0000000..4b12e93 --- /dev/null +++ b/backend/src/observability/testing/observability.mock.ts @@ -0,0 +1,22 @@ +export const mockStructuredLogger = { + debug: jest.fn(), + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), +}; + +export const mockRequestContextService = { + runWithContext: jest.fn( + (_store: unknown, callback: () => unknown) => callback(), + ), + runWithWorkerContext: jest.fn( + (_options: unknown, callback: () => unknown) => callback(), + ), + runWithChildContext: jest.fn( + (_partial: unknown, callback: () => unknown) => callback(), + ), + getStore: jest.fn(), + getCorrelationId: jest.fn(), + getTraceId: jest.fn(), + setUserContext: jest.fn(), +}; diff --git a/backend/src/observability/tracing.util.spec.ts b/backend/src/observability/tracing.util.spec.ts new file mode 100644 index 0000000..e4d4cb7 --- /dev/null +++ b/backend/src/observability/tracing.util.spec.ts @@ -0,0 +1,75 @@ +import { StructuredLogger } from "./structured-logger.service"; +import { RequestContextService } from "./request-context.service"; +import { traceAsync } from "./tracing.util"; + +describe("traceAsync", () => { + const requestContext = new RequestContextService(); + const logger = new StructuredLogger(requestContext); + const infoSpy = jest.spyOn(logger, "info").mockImplementation(() => undefined); + const warnSpy = jest.spyOn(logger, "warn").mockImplementation(() => undefined); + const debugSpy = jest.spyOn(logger, "debug").mockImplementation(() => undefined); + const errorSpy = jest.spyOn(logger, "error").mockImplementation(() => undefined); + + beforeEach(() => { + jest.clearAllMocks(); + }); + + it("flags slow network spans", async () => { + await requestContext.runWithContext( + { correlationId: "trace-1", traceId: "trace-1" }, + async () => { + await traceAsync( + logger, + { + operation: "test.slow", + category: "network", + slowThresholdMs: 0, + }, + async () => { + await new Promise((resolve) => setTimeout(resolve, 5)); + return "ok"; + }, + ); + }, + ); + + expect(warnSpy).toHaveBeenCalledWith( + "span.slow", + expect.objectContaining({ + operation: "test.slow", + category: "network", + slow: true, + }), + ); + expect(debugSpy).not.toHaveBeenCalledWith( + "span.complete", + expect.anything(), + ); + }); + + it("logs span errors", async () => { + await expect( + traceAsync( + logger, + { + operation: "test.error", + category: "database", + slowThresholdMs: 200, + }, + async () => { + throw new Error("db failed"); + }, + ), + ).rejects.toThrow("db failed"); + + expect(errorSpy).toHaveBeenCalledWith( + "span.error", + expect.objectContaining({ + operation: "test.error", + category: "database", + error: "db failed", + }), + ); + expect(infoSpy).not.toHaveBeenCalled(); + }); +}); diff --git a/backend/src/observability/tracing.util.ts b/backend/src/observability/tracing.util.ts new file mode 100644 index 0000000..4e44265 --- /dev/null +++ b/backend/src/observability/tracing.util.ts @@ -0,0 +1,61 @@ +import { randomUUID } from "node:crypto"; +import { StructuredLogger } from "./structured-logger.service"; + +export type TraceCategory = "database" | "network"; + +export type TraceOptions = { + operation: string; + category: TraceCategory; + slowThresholdMs: number; + attributes?: Record; +}; + +export async function traceAsync( + logger: StructuredLogger, + options: TraceOptions, + fn: () => Promise, +): Promise { + const startedAt = Date.now(); + const spanId = randomUUID(); + + logger.debug("span.start", { + spanId, + operation: options.operation, + category: options.category, + ...options.attributes, + }); + + try { + const result = await fn(); + const durationMs = Date.now() - startedAt; + const slow = durationMs >= options.slowThresholdMs; + + const payload = { + spanId, + operation: options.operation, + category: options.category, + durationMs, + slow, + ...options.attributes, + }; + + if (slow) { + logger.warn("span.slow", payload); + } else { + logger.debug("span.complete", payload); + } + + return result; + } catch (error) { + const durationMs = Date.now() - startedAt; + logger.error("span.error", { + spanId, + operation: options.operation, + category: options.category, + durationMs, + error: error instanceof Error ? error.message : String(error), + ...options.attributes, + }); + throw error; + } +} diff --git a/backend/src/prisma/prisma.service.ts b/backend/src/prisma/prisma.service.ts index 1c0bb0c..6a0a5a6 100644 --- a/backend/src/prisma/prisma.service.ts +++ b/backend/src/prisma/prisma.service.ts @@ -4,10 +4,12 @@ import { OnModuleDestroy, Logger, } from "@nestjs/common"; +import { ConfigService } from "@nestjs/config"; import { PrismaClient } from "@prisma/client"; import { PrismaPg } from "@prisma/adapter-pg"; import { MerchantContextService } from "./merchant-context.service"; import { applyMerchantScope } from "./merchant-scope.util"; +import { StructuredLogger } from "../observability/structured-logger.service"; @Injectable() export class PrismaService @@ -16,7 +18,11 @@ export class PrismaService { private readonly logger = new Logger(PrismaService.name); - constructor(private readonly merchantContext: MerchantContextService) { + constructor( + private readonly merchantContext: MerchantContextService, + private readonly structuredLogger: StructuredLogger, + private readonly configService: ConfigService, + ) { const adapter = new PrismaPg({ connectionString: process.env.DATABASE_URL, }); @@ -35,7 +41,25 @@ export class PrismaService this.merchantContext.getMerchantId(), this.logger, ); - return next(params); + + const startedAt = Date.now(); + const result = await next(params); + const durationMs = Date.now() - startedAt; + const slowThresholdMs = this.getSlowDbThresholdMs(); + const operation = params.model + ? `${params.model}.${params.action}` + : params.action; + + if (durationMs >= slowThresholdMs) { + this.structuredLogger.warn("db.query.slow", { + category: "database", + operation, + durationMs, + slow: true, + }); + } + + return result; }); } @@ -54,4 +78,10 @@ export class PrismaService ): Promise { return this.merchantContext.runWithMerchantScope(merchantId, callback); } + + private getSlowDbThresholdMs(): number { + return ( + this.configService.get("observability.slowDbThresholdMs") ?? 200 + ); + } } diff --git a/backend/src/stellar/horizon-watcher.service.ts b/backend/src/stellar/horizon-watcher.service.ts index 164e0db..3d5327d 100644 --- a/backend/src/stellar/horizon-watcher.service.ts +++ b/backend/src/stellar/horizon-watcher.service.ts @@ -1,6 +1,5 @@ import { Injectable, - Logger, OnModuleDestroy, OnModuleInit, } from "@nestjs/common"; @@ -10,10 +9,12 @@ import { StellarService } from "./stellar.service"; import { InvoicesService } from "../invoices/invoices.service"; import { InvoicePaidEvent } from "./events/invoice-paid.event"; import { SorobanService } from "./soroban.service"; +import { RequestContextService } from "../observability/request-context.service"; +import { StructuredLogger } from "../observability/structured-logger.service"; +import { traceAsync } from "../observability/tracing.util"; @Injectable() export class HorizonWatcherService implements OnModuleInit, OnModuleDestroy { - private readonly logger = new Logger(HorizonWatcherService.name); private pollTimer: ReturnType | null = null; private cursor = "now"; private polling = false; @@ -25,21 +26,26 @@ export class HorizonWatcherService implements OnModuleInit, OnModuleDestroy { private readonly stellarService: StellarService, private readonly invoicesService: InvoicesService, private readonly sorobanService: SorobanService, + private readonly requestContext: RequestContextService, + private readonly logger: StructuredLogger, ) {} onModuleInit(): void { const merchantKey = this.stellarService.getMerchantPublicKey(); if (!merchantKey) { - this.logger.warn( - "MERCHANT_PUBLIC_KEY not configured; Horizon watcher disabled", - ); + this.logger.warn("horizon.watcher.disabled", { + domain: "horizon", + reason: "missing_merchant_public_key", + }); return; } const intervalMs = this.getPollIntervalMs(); - this.logger.log( - `Horizon payment watcher started (interval: ${intervalMs}ms, account: ${merchantKey})`, - ); + this.logger.info("horizon.watcher.started", { + domain: "horizon", + intervalMs, + account: merchantKey, + }); void this.pollPayments(); this.pollTimer = setInterval(() => void this.pollPayments(), intervalMs); @@ -59,86 +65,136 @@ export class HorizonWatcherService implements OnModuleInit, OnModuleDestroy { const merchantKey = this.stellarService.getMerchantPublicKey(); if (!merchantKey) return; - this.polling = true; - try { - const server = this.stellarService.getServer(); - const config = this.stellarService.getConfig(); - const memoPrefix: string = config?.memoPrefix ?? "invoisio-"; - - const response = await server - .payments() - .forAccount(merchantKey) - .cursor(this.cursor) - .order("asc") - .limit(200) - .call(); - - for (const record of response.records) { - const type: string = (record as any).type; - if ( - type !== "payment" && - type !== "path_payment_strict_receive" && - type !== "path_payment_strict_send" - ) { - continue; - } + await this.requestContext.runWithWorkerContext( + { workerName: "horizon-watcher" }, + async () => { + this.polling = true; + try { + const server = this.stellarService.getServer(); + const config = this.stellarService.getConfig(); + const memoPrefix: string = config?.memoPrefix ?? "invoisio-"; - if ((record as any).to !== merchantKey) { - this.cursor = (record as any).paging_token; - continue; - } + const response = await traceAsync( + this.logger, + { + operation: "horizon.payments.list", + category: "network", + slowThresholdMs: this.getSlowNetworkThresholdMs(), + attributes: { account: merchantKey, cursor: this.cursor }, + }, + () => + server + .payments() + .forAccount(merchantKey) + .cursor(this.cursor) + .order("asc") + .limit(200) + .call(), + ); - await this.processPayment(record, memoPrefix); - this.cursor = (record as any).paging_token; - } - } catch (error) { - this.logger.warn( - `Horizon poll error (transient, will retry): ${(error as Error).message}`, - ); - } finally { - this.polling = false; - } + this.logger.debug("horizon.poll.complete", { + domain: "horizon", + recordCount: response.records.length, + cursor: this.cursor, + }); + + for (const record of response.records) { + const type: string = (record as any).type; + if ( + type !== "payment" && + type !== "path_payment_strict_receive" && + type !== "path_payment_strict_send" + ) { + continue; + } + + if ((record as any).to !== merchantKey) { + this.cursor = (record as any).paging_token; + continue; + } + + await this.processPayment(record, memoPrefix); + this.cursor = (record as any).paging_token; + } + } catch (error) { + this.logger.warn("horizon.poll.error", { + domain: "horizon", + error: (error as Error).message, + }); + } finally { + this.polling = false; + } + }, + ); } private async processPayment(record: any, memoPrefix: string): Promise { - try { - const tx = await record.transaction(); - const rawMemo: string | undefined = tx?.memo; - if (!rawMemo) return; + const txHash: string = record.transaction_hash; - const memoId = this.resolveMemoId(rawMemo, memoPrefix); - if (!memoId) return; + await this.requestContext.runWithChildContext( + { correlationId: `horizon:${txHash}` }, + async () => { + try { + const tx = await traceAsync( + this.logger, + { + operation: "horizon.transaction.get", + category: "network", + slowThresholdMs: this.getSlowNetworkThresholdMs(), + attributes: { txHash }, + }, + () => record.transaction(), + ); - const invoice = await this.invoicesService.findByMemo(memoId); - if (!invoice || invoice.status === "paid") return; + const rawMemo: string | undefined = (tx as { memo?: string } | null) + ?.memo; + if (!rawMemo) return; - const txHash: string = record.transaction_hash; - await this.invoicesService.markAsPaid(invoice.id, txHash); + const memoId = this.resolveMemoId(rawMemo, memoPrefix); + if (!memoId) return; - const event = new InvoicePaidEvent( - invoice.id, - txHash, - memoId, - record.amount ?? "0", - record.asset_code ?? "XLM", - ); - this.invoicePaid$.next(event); + const invoice = await this.invoicesService.findByMemo(memoId); + if (!invoice || invoice.status === "paid") return; - this.logger.log( - `Invoice ${invoice.id} marked paid | tx: ${txHash} | memo: ${memoId}`, - ); + await this.invoicesService.markAsPaid(invoice.id, txHash); - // Anchor to Soroban (non-blocking) - this.anchorToSoroban(invoice, record, txHash).catch((err) => - this.logger.error( - `Soroban anchor failed for invoice ${invoice.id}: ${err.message}`, - ), - ); - } catch (err) { - this.logger.warn( - `Failed to process payment ${record.id}: ${(err as Error).message}`, - ); - } + const event = new InvoicePaidEvent( + invoice.id, + txHash, + memoId, + record.amount ?? "0", + record.asset_code ?? "XLM", + ); + this.invoicePaid$.next(event); + + this.logger.info("horizon.payment.matched", { + domain: "horizon", + event: "invoice_marked_paid", + invoiceId: invoice.id, + txHash, + memo: memoId, + amount: record.amount ?? "0", + assetCode: record.asset_code ?? "XLM", + }); + + this.anchorToSoroban(invoice, record, txHash).catch((err) => + this.logger.error("horizon.soroban_anchor.failed", { + domain: "horizon", + invoiceId: invoice.id, + txHash, + error: err.message, + }), + ); + } catch (err) { + this.logger.warn("horizon.payment.process_failed", { + domain: "horizon", + paymentId: record.id, + txHash, + error: (err as Error).message, + }); + } + }, + ); } private async anchorToSoroban( @@ -148,13 +204,23 @@ export class HorizonWatcherService implements OnModuleInit, OnModuleDestroy { ): Promise { const amount = this.convertToStroops(record.amount, record.asset_code); - const metadata = await this.sorobanService.recordPayment({ - invoiceId: invoice.memo, - payer: record.from, - assetCode: record.asset_code ?? "XLM", - assetIssuer: record.asset_issuer ?? "", - amount, - }); + const metadata = await traceAsync( + this.logger, + { + operation: "soroban.record_payment", + category: "network", + slowThresholdMs: this.getSlowNetworkThresholdMs(), + attributes: { invoiceId: invoice.id, txHash }, + }, + () => + this.sorobanService.recordPayment({ + invoiceId: invoice.memo, + payer: record.from, + assetCode: record.asset_code ?? "XLM", + assetIssuer: record.asset_issuer ?? "", + amount, + }), + ); if (metadata) { await this.invoicesService.updateSorobanMetadata( @@ -162,9 +228,12 @@ export class HorizonWatcherService implements OnModuleInit, OnModuleDestroy { metadata.txHash, metadata.contractId, ); - this.logger.log( - `Soroban anchor complete for invoice ${invoice.id} | tx: ${metadata.txHash}`, - ); + this.logger.info("horizon.soroban_anchor.complete", { + domain: "horizon", + invoiceId: invoice.id, + sorobanTxHash: metadata.txHash, + contractId: metadata.contractId, + }); } } @@ -191,4 +260,11 @@ export class HorizonWatcherService implements OnModuleInit, OnModuleDestroy { const parsed = parseInt(raw ?? "", 10); return Number.isFinite(parsed) && parsed > 0 ? parsed : 15_000; } + + private getSlowNetworkThresholdMs(): number { + return ( + this.configService.get("observability.slowNetworkThresholdMs") ?? + 500 + ); + } } diff --git a/backend/src/stellar/soroban-events.service.spec.ts b/backend/src/stellar/soroban-events.service.spec.ts index 920b699..358bd7d 100644 --- a/backend/src/stellar/soroban-events.service.spec.ts +++ b/backend/src/stellar/soroban-events.service.spec.ts @@ -2,6 +2,12 @@ import { Test, TestingModule } from "@nestjs/testing"; import { SorobanEventsService } from "./soroban-events.service"; import { ConfigService } from "@nestjs/config"; import { InvoicesService } from "../invoices/invoices.service"; +import { RequestContextService } from "../observability/request-context.service"; +import { StructuredLogger } from "../observability/structured-logger.service"; +import { + mockRequestContextService, + mockStructuredLogger, +} from "../observability/testing/observability.mock"; describe("SorobanEventsService", () => { let service: SorobanEventsService; @@ -32,6 +38,14 @@ describe("SorobanEventsService", () => { SorobanEventsService, { provide: ConfigService, useValue: mockConfigService }, { provide: InvoicesService, useValue: mockInvoicesService }, + { + provide: RequestContextService, + useValue: mockRequestContextService, + }, + { + provide: StructuredLogger, + useValue: mockStructuredLogger, + }, ], }).compile(); diff --git a/backend/src/stellar/soroban-events.service.ts b/backend/src/stellar/soroban-events.service.ts index caf2071..6a25b3b 100644 --- a/backend/src/stellar/soroban-events.service.ts +++ b/backend/src/stellar/soroban-events.service.ts @@ -1,6 +1,5 @@ import { Injectable, - Logger, OnModuleDestroy, OnModuleInit, } from "@nestjs/common"; @@ -8,12 +7,14 @@ import { ConfigService } from "@nestjs/config"; import { InvoicesService } from "../invoices/invoices.service"; import https from "node:https"; import { URL } from "node:url"; +import { RequestContextService } from "../observability/request-context.service"; +import { StructuredLogger } from "../observability/structured-logger.service"; +import { traceAsync } from "../observability/tracing.util"; type Json = Record; @Injectable() export class SorobanEventsService implements OnModuleInit, OnModuleDestroy { - private readonly logger = new Logger(SorobanEventsService.name); private running = false; private timer: ReturnType | null = null; private cursor: string | undefined = undefined; @@ -22,21 +23,26 @@ export class SorobanEventsService implements OnModuleInit, OnModuleDestroy { constructor( private readonly config: ConfigService, private readonly invoices: InvoicesService, + private readonly requestContext: RequestContextService, + private readonly logger: StructuredLogger, ) {} onModuleInit(): void { const rpcUrl = this.getRpcUrl(); const contractId = this.getContractId(); if (!rpcUrl || !contractId) { - this.logger.warn( - "Soroban events disabled (missing SOROBAN_RPC_URL or SOROBAN_CONTRACT_ID)", - ); + this.logger.warn("soroban.events.disabled", { + domain: "soroban", + reason: "missing_rpc_or_contract", + }); return; } this.running = true; - this.logger.log( - `Soroban event subscriber started (rpc: ${rpcUrl}, contract: ${contractId})`, - ); + this.logger.info("soroban.events.started", { + domain: "soroban", + rpcUrl, + contractId, + }); this.scheduleNext(0); } @@ -56,68 +62,100 @@ export class SorobanEventsService implements OnModuleInit, OnModuleDestroy { private async tick(): Promise { if (!this.running) return; - try { - const resp = await this.fetchEvents(); - const events: any[] = resp?.result?.events ?? []; - for (const ev of events) { - await this.handleEvent(ev); - this.cursor = ev?.pagingToken ?? ev?.paging_token ?? this.cursor; - } - this.backoffMs = 1000; - this.scheduleNext(events.length > 0 ? 50 : 500); - } catch (err) { - const msg = (err as Error).message; - this.logger.warn(`Soroban getEvents error: ${msg}`); - this.backoffMs = Math.min(this.backoffMs * 2, 30000); - this.scheduleNext(this.backoffMs); - } + + await this.requestContext.runWithWorkerContext( + { workerName: "soroban-events" }, + async () => { + try { + const resp = await this.fetchEvents(); + const events: any[] = resp?.result?.events ?? []; + + this.logger.debug("soroban.events.poll.complete", { + domain: "soroban", + eventCount: events.length, + cursor: this.cursor, + }); + + for (const ev of events) { + await this.handleEvent(ev); + this.cursor = ev?.pagingToken ?? ev?.paging_token ?? this.cursor; + } + this.backoffMs = 1000; + this.scheduleNext(events.length > 0 ? 50 : 500); + } catch (err) { + const msg = (err as Error).message; + this.logger.warn("soroban.events.poll.error", { + domain: "soroban", + error: msg, + backoffMs: this.backoffMs, + }); + this.backoffMs = Math.min(this.backoffMs * 2, 30000); + this.scheduleNext(this.backoffMs); + } + }, + ); } async handleEvent(ev: any): Promise { - const topic = ev?.topic ?? ev?.topics ?? ev?.event?.topics ?? null; - const expect = this.getTopic(); - if (Array.isArray(topic) && expect && topic.length > 0) { - const flat = topic.map((t: any) => - typeof t === "string" ? t : String(t?.symbol ?? t), - ); - const hasTopic = - flat.includes(expect) || - flat.includes(expect.toLowerCase()) || - flat.includes(expect.toUpperCase()); - if (!hasTopic) { - return; - } - } + const eventId = String(ev?.id ?? ev?.eventId ?? ev?.pagingToken ?? Date.now()); + + await this.requestContext.runWithChildContext( + { correlationId: `soroban:${eventId}` }, + async () => { + const topic = ev?.topic ?? ev?.topics ?? ev?.event?.topics ?? null; + const expect = this.getTopic(); + if (Array.isArray(topic) && expect && topic.length > 0) { + const flat = topic.map((t: any) => + typeof t === "string" ? t : String(t?.symbol ?? t), + ); + const hasTopic = + flat.includes(expect) || + flat.includes(expect.toLowerCase()) || + flat.includes(expect.toUpperCase()); + if (!hasTopic) { + return; + } + } - const val = - ev?.value ?? - ev?.event?.value ?? - ev?.data ?? - ev?.event?.data ?? - ev?.body ?? - {}; + const val = + ev?.value ?? + ev?.event?.value ?? + ev?.data ?? + ev?.event?.data ?? + ev?.body ?? + {}; - const payload = this.coercePaymentRecorded(val); - if (!payload || !payload.invoice_id) { - return; - } + const payload = this.coercePaymentRecorded(val); + if (!payload || !payload.invoice_id) { + return; + } - await this.invoices.applySorobanPaymentEvent({ - eventId: String(ev?.id ?? ev?.eventId ?? ev?.pagingToken ?? Date.now()), - contractId: this.getContractId(), - ledger: - Number(ev?.ledger ?? ev?.inLedger ?? ev?.ledgers ?? 0) || undefined, - invoice_id: String(payload.invoice_id), - payer: payload.payer ? String(payload.payer) : undefined, - asset_code: payload.asset_code ? String(payload.asset_code) : undefined, - asset_issuer: payload.asset_issuer - ? String(payload.asset_issuer) - : undefined, - amount: - payload.amount !== undefined - ? (payload.amount as any).toString() - : undefined, - }); + this.logger.info("soroban.event.received", { + domain: "soroban", + event: "payment_recorded", + eventId, + invoiceId: String(payload.invoice_id), + ledger: Number(ev?.ledger ?? ev?.inLedger ?? ev?.ledgers ?? 0) || undefined, + }); + + await this.invoices.applySorobanPaymentEvent({ + eventId, + contractId: this.getContractId(), + ledger: + Number(ev?.ledger ?? ev?.inLedger ?? ev?.ledgers ?? 0) || undefined, + invoice_id: String(payload.invoice_id), + payer: payload.payer ? String(payload.payer) : undefined, + asset_code: payload.asset_code ? String(payload.asset_code) : undefined, + asset_issuer: payload.asset_issuer + ? String(payload.asset_issuer) + : undefined, + amount: + payload.amount !== undefined + ? (payload.amount as any).toString() + : undefined, + }); + }, + ); } private coercePaymentRecorded(obj: any): { @@ -177,7 +215,16 @@ export class SorobanEventsService implements OnModuleInit, OnModuleDestroy { params, }; - return await this.postJson(rpc, body); + return traceAsync( + this.logger, + { + operation: "soroban.rpc.getEvents", + category: "network", + slowThresholdMs: this.getSlowNetworkThresholdMs(), + attributes: { contractId, cursor: this.cursor }, + }, + () => this.postJson(rpc, body), + ); } private postJson(rpcUrl: string, body: Json): Promise { @@ -232,4 +279,10 @@ export class SorobanEventsService implements OnModuleInit, OnModuleDestroy { const conf = this.config.get("stellar"); return conf?.sorobanEventTopic || "InvoicePaymentRecorded"; } + + private getSlowNetworkThresholdMs(): number { + return ( + this.config.get("observability.slowNetworkThresholdMs") ?? 500 + ); + } } diff --git a/backend/src/stellar/soroban.integration.spec.ts b/backend/src/stellar/soroban.integration.spec.ts index 20fbb26..dddae91 100644 --- a/backend/src/stellar/soroban.integration.spec.ts +++ b/backend/src/stellar/soroban.integration.spec.ts @@ -4,6 +4,12 @@ import { SorobanService } from "./soroban.service"; import { StellarService } from "./stellar.service"; import { InvoicesService } from "../invoices/invoices.service"; import { ConfigService } from "@nestjs/config"; +import { RequestContextService } from "../observability/request-context.service"; +import { StructuredLogger } from "../observability/structured-logger.service"; +import { + mockRequestContextService, + mockStructuredLogger, +} from "../observability/testing/observability.mock"; describe("Soroban Integration", () => { let horizonWatcher: HorizonWatcherService; @@ -65,13 +71,22 @@ describe("Soroban Integration", () => { provide: ConfigService, useValue: { get: jest.fn((key: string) => { - const config: Record = { + const config: Record = { HORIZON_POLL_INTERVAL: "1000", + "observability.slowNetworkThresholdMs": 500, }; return config[key]; }), }, }, + { + provide: RequestContextService, + useValue: mockRequestContextService, + }, + { + provide: StructuredLogger, + useValue: mockStructuredLogger, + }, ], }).compile(); diff --git a/web/lib/api-client.ts b/web/lib/api-client.ts index 2174755..acfae85 100644 --- a/web/lib/api-client.ts +++ b/web/lib/api-client.ts @@ -4,13 +4,23 @@ const API_URL = process.env.NEXT_PUBLIC_API_URL || 'http://localhost:3001'; let accessToken: string | null = null; +function getOrCreateCorrelationId(): string { + if (typeof crypto !== 'undefined' && typeof crypto.randomUUID === 'function') { + return crypto.randomUUID(); + } + + return `corr-${Date.now()}-${Math.random().toString(36).slice(2, 10)}`; +} + export const apiClient = axios.create({ baseURL: API_URL, }); apiClient.interceptors.request.use((config) => { + config.headers = config.headers ?? {}; + config.headers['X-Correlation-ID'] = getOrCreateCorrelationId(); + if (accessToken != null && accessToken.length > 0) { - config.headers = config.headers ?? {}; config.headers.Authorization = `Bearer ${accessToken}`; } return config;