diff --git a/.env.example b/.env.example index feed148..6041f15 100644 --- a/.env.example +++ b/.env.example @@ -1,6 +1,7 @@ DATABASE_URL="file:./prisma/dev.db" FRONTEND_ORIGIN="http://localhost:5173" PORT=3000 +LOG_LEVEL=info JWT_SECRET="replace-with-a-secret-at-least-32-characters-long" TOKEN_ENCRYPTION_KEY="replace-with-base64-encoded-32-byte-key" TBANK_GRPC_ENDPOINT="invest-public-api.tbank.ru:443" diff --git a/package-lock.json b/package-lock.json index f596c20..0c7fad7 100644 --- a/package-lock.json +++ b/package-lock.json @@ -25,8 +25,10 @@ "class-transformer": "^0.5.1", "class-validator": "^0.15.1", "cookie-parser": "^1.4.7", + "nestjs-pino": "^4.6.1", "passport": "^0.7.0", "passport-jwt": "^4.0.1", + "pino-http": "^11.0.0", "reflect-metadata": "^0.2.2", "rxjs": "^7.8.1" }, @@ -2669,6 +2671,12 @@ "@noble/hashes": "^1.1.5" } }, + "node_modules/@pinojs/redact": { + "version": "0.4.0", + "resolved": "https://registry.npmjs.org/@pinojs/redact/-/redact-0.4.0.tgz", + "integrity": "sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg==", + "license": "MIT" + }, "node_modules/@pkgjs/parseargs": { "version": "0.11.0", "resolved": "https://registry.npmjs.org/@pkgjs/parseargs/-/parseargs-0.11.0.tgz", @@ -4580,6 +4588,15 @@ "dev": true, "license": "MIT" }, + "node_modules/atomic-sleep": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/atomic-sleep/-/atomic-sleep-1.0.0.tgz", + "integrity": "sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==", + "license": "MIT", + "engines": { + "node": ">=8.0.0" + } + }, "node_modules/aws-ssl-profiles": { "version": "1.1.2", "resolved": "https://registry.npmjs.org/aws-ssl-profiles/-/aws-ssl-profiles-1.1.2.tgz", @@ -9252,6 +9269,21 @@ "dev": true, "license": "MIT" }, + "node_modules/nestjs-pino": { + "version": "4.6.1", + "resolved": "https://registry.npmjs.org/nestjs-pino/-/nestjs-pino-4.6.1.tgz", + "integrity": "sha512-nuARXa0xpdJ1lY2+fgycIQr6H3g0VgqAWNK3xMYjOFcj2DoPETNXj0lV3Y86nRuI7BUfQp5PGiVoZvT4dTWbpQ==", + "license": "MIT", + "engines": { + "node": ">= 14" + }, + "peerDependencies": { + "@nestjs/common": "^8.0.0 || ^9.0.0 || ^10.0.0 || ^11.0.0", + "pino": "^7.5.0 || ^8.0.0 || ^9.0.0 || ^10.0.0", + "pino-http": "^6.4.0 || ^7.0.0 || ^8.0.0 || ^9.0.0 || ^10.0.0 || ^11.0.0", + "rxjs": "^7.1.0" + } + }, "node_modules/node-abi": { "version": "3.94.0", "resolved": "https://registry.npmjs.org/node-abi/-/node-abi-3.94.0.tgz", @@ -9369,6 +9401,15 @@ "devOptional": true, "license": "MIT" }, + "node_modules/on-exit-leak-free": { + "version": "2.1.2", + "resolved": "https://registry.npmjs.org/on-exit-leak-free/-/on-exit-leak-free-2.1.2.tgz", + "integrity": "sha512-0eJJY6hXLGf1udHwfNftBqH+g73EU4B504nZeKpz1sYRKafAghwxEJunB2O7rDZkL4PGfsMVnTXZ2EjibbqcsA==", + "license": "MIT", + "engines": { + "node": ">=14.0.0" + } + }, "node_modules/on-finished": { "version": "2.4.1", "resolved": "https://registry.npmjs.org/on-finished/-/on-finished-2.4.1.tgz", @@ -9690,6 +9731,55 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, + "node_modules/pino": { + "version": "10.3.1", + "resolved": "https://registry.npmjs.org/pino/-/pino-10.3.1.tgz", + "integrity": "sha512-r34yH/GlQpKZbU1BvFFqOjhISRo1MNx1tWYsYvmj6KIRHSPMT2+yHOEb1SG6NMvRoHRF0a07kCOox/9yakl1vg==", + "license": "MIT", + "dependencies": { + "@pinojs/redact": "^0.4.0", + "atomic-sleep": "^1.0.0", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^3.0.0", + "pino-std-serializers": "^7.0.0", + "process-warning": "^5.0.0", + "quick-format-unescaped": "^4.0.3", + "real-require": "^0.2.0", + "safe-stable-stringify": "^2.3.1", + "sonic-boom": "^4.0.1", + "thread-stream": "^4.0.0" + }, + "bin": { + "pino": "bin.js" + } + }, + "node_modules/pino-abstract-transport": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/pino-abstract-transport/-/pino-abstract-transport-3.0.0.tgz", + "integrity": "sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg==", + "license": "MIT", + "dependencies": { + "split2": "^4.0.0" + } + }, + "node_modules/pino-http": { + "version": "11.0.0", + "resolved": "https://registry.npmjs.org/pino-http/-/pino-http-11.0.0.tgz", + "integrity": "sha512-wqg5XIAGRRIWtTk8qPGxkbrfiwEWz1lgedVLvhLALudKXvg1/L2lTFgTGPJ4Z2e3qcRmxoFxDuSdMdMGNM6I1g==", + "license": "MIT", + "dependencies": { + "get-caller-file": "^2.0.5", + "pino": "^10.0.0", + "pino-std-serializers": "^7.0.0", + "process-warning": "^5.0.0" + } + }, + "node_modules/pino-std-serializers": { + "version": "7.1.0", + "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-7.1.0.tgz", + "integrity": "sha512-BndPH67/JxGExRgiX1dX0w1FvZck5Wa4aal9198SrRhZjH3GxKQUKIBnYJTdj2HDN3UQAS06HlfcSbQj2OHmaw==", + "license": "MIT" + }, "node_modules/pirates": { "version": "4.0.7", "resolved": "https://registry.npmjs.org/pirates/-/pirates-4.0.7.tgz", @@ -9934,6 +10024,22 @@ } } }, + "node_modules/process-warning": { + "version": "5.1.0", + "resolved": "https://registry.npmjs.org/process-warning/-/process-warning-5.1.0.tgz", + "integrity": "sha512-jQSaVHsPgtyw60e1rQ/A+/ArPEj/S8pS/vFnyGa/gYFXrKk/6RuDkoqVDQ5NI5MmS01698ltlAk0NoDBNLujRw==", + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "MIT" + }, "node_modules/proper-lockfile": { "version": "4.1.2", "resolved": "https://registry.npmjs.org/proper-lockfile/-/proper-lockfile-4.1.2.tgz", @@ -10042,6 +10148,12 @@ "url": "https://github.com/sponsors/ljharb" } }, + "node_modules/quick-format-unescaped": { + "version": "4.0.4", + "resolved": "https://registry.npmjs.org/quick-format-unescaped/-/quick-format-unescaped-4.0.4.tgz", + "integrity": "sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==", + "license": "MIT" + }, "node_modules/range-parser": { "version": "1.3.0", "resolved": "https://registry.npmjs.org/range-parser/-/range-parser-1.3.0.tgz", @@ -10174,6 +10286,15 @@ "url": "https://paulmillr.com/funding/" } }, + "node_modules/real-require": { + "version": "0.2.0", + "resolved": "https://registry.npmjs.org/real-require/-/real-require-0.2.0.tgz", + "integrity": "sha512-57frrGM/OCTLqLOAh0mhVA9VBMHd+9U7Zb2THMGdBUoZVOtGbJzjxsYGDJ3A9AYYCP4hn6y1TVbaOfzWtm5GFg==", + "license": "MIT", + "engines": { + "node": ">= 12.13.0" + } + }, "node_modules/reflect-metadata": { "version": "0.2.2", "resolved": "https://registry.npmjs.org/reflect-metadata/-/reflect-metadata-0.2.2.tgz", @@ -10358,6 +10479,15 @@ "safe-regex2": "bin/safe-regex2.js" } }, + "node_modules/safe-stable-stringify": { + "version": "2.5.0", + "resolved": "https://registry.npmjs.org/safe-stable-stringify/-/safe-stable-stringify-2.5.0.tgz", + "integrity": "sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==", + "license": "MIT", + "engines": { + "node": ">=10" + } + }, "node_modules/safer-buffer": { "version": "2.1.2", "resolved": "https://registry.npmjs.org/safer-buffer/-/safer-buffer-2.1.2.tgz", @@ -10623,6 +10753,15 @@ "node": ">=8" } }, + "node_modules/sonic-boom": { + "version": "4.2.1", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-4.2.1.tgz", + "integrity": "sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q==", + "license": "MIT", + "dependencies": { + "atomic-sleep": "^1.0.0" + } + }, "node_modules/source-map": { "version": "0.7.4", "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.7.4.tgz", @@ -10654,6 +10793,15 @@ "node": ">=0.10.0" } }, + "node_modules/split2": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/split2/-/split2-4.2.0.tgz", + "integrity": "sha512-UcjcJOWknrNkF6PLX83qcHM6KHgVKNkV62Y8a5uYDVv9ydGQVwAHMKqHdJje1VTWpljG0WYpCDhrCdAOYH4TWg==", + "license": "ISC", + "engines": { + "node": ">= 10.x" + } + }, "node_modules/sprintf-js": { "version": "1.0.3", "resolved": "https://registry.npmjs.org/sprintf-js/-/sprintf-js-1.0.3.tgz", @@ -11202,6 +11350,24 @@ "url": "https://github.com/sponsors/isaacs" } }, + "node_modules/thread-stream": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/thread-stream/-/thread-stream-4.2.0.tgz", + "integrity": "sha512-e2zZ96wSChazBsbENf/Pcm/4swHt2cEKQ92rhUjkL9GCKiTDJIaTBenjE/m9DXi0QBmTMDkFDdOomUy20A1tDQ==", + "license": "MIT", + "dependencies": { + "real-require": "^1.0.0" + }, + "engines": { + "node": ">=20" + } + }, + "node_modules/thread-stream/node_modules/real-require": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/real-require/-/real-require-1.0.0.tgz", + "integrity": "sha512-P4nbQYQfePJxRSmY+v/KINxVucm4NF3p3s7pJveMTtom52FR4YGltUQLB8idDXwDDWW+eYrWDFbuzUnjoWHF7g==", + "license": "MIT" + }, "node_modules/tinyglobby": { "version": "0.2.17", "resolved": "https://registry.npmjs.org/tinyglobby/-/tinyglobby-0.2.17.tgz", diff --git a/package.json b/package.json index 08d28af..df8fa3a 100644 --- a/package.json +++ b/package.json @@ -36,8 +36,10 @@ "class-transformer": "^0.5.1", "class-validator": "^0.15.1", "cookie-parser": "^1.4.7", + "nestjs-pino": "^4.6.1", "passport": "^0.7.0", "passport-jwt": "^4.0.1", + "pino-http": "^11.0.0", "reflect-metadata": "^0.2.2", "rxjs": "^7.8.1" }, diff --git a/src/app.module.ts b/src/app.module.ts index d282745..9e60b02 100644 --- a/src/app.module.ts +++ b/src/app.module.ts @@ -1,7 +1,10 @@ import { Module } from '@nestjs/common'; -import { ConfigModule } from '@nestjs/config'; +import { ConfigModule, ConfigService } from '@nestjs/config'; +import { randomUUID } from 'node:crypto'; +import { LoggerModule } from 'nestjs-pino'; import { AuthModule } from './auth/auth.module'; -import { validateEnv } from './config/env.validation'; +import { LoggingModule } from './common/logging/logging.module'; +import { Environment, validateEnv } from './config/env.validation'; import { PrismaModule } from './prisma/prisma.module'; import { TbankConnectionModule } from './tbank/tbank-connection.module'; @@ -11,6 +14,39 @@ import { TbankConnectionModule } from './tbank/tbank-connection.module'; isGlobal: true, validate: validateEnv, }), + LoggerModule.forRootAsync({ + inject: [ConfigService], + useFactory: (config: ConfigService) => ({ + pinoHttp: { + level: config.getOrThrow('LOG_LEVEL'), + messageKey: 'message', + autoLogging: false, + genReqId: (request: unknown, response) => { + const existingId = (request as { id?: unknown }).id; + const requestId = + typeof existingId === 'string' ? existingId : randomUUID(); + response.setHeader('X-Request-ID', requestId); + return requestId; + }, + redact: [ + 'req.headers.authorization', + 'req.headers.cookie', + 'req.body', + ], + serializers: { + req: (request: unknown) => { + const value = request as { id?: unknown; method?: unknown }; + return { + id: typeof value.id === 'string' ? value.id : undefined, + method: + typeof value.method === 'string' ? value.method : undefined, + }; + }, + }, + }, + }), + }), + LoggingModule, PrismaModule, AuthModule, TbankConnectionModule, diff --git a/src/auth/jwt-auth.guard.ts b/src/auth/jwt-auth.guard.ts index 2155290..f183897 100644 --- a/src/auth/jwt-auth.guard.ts +++ b/src/auth/jwt-auth.guard.ts @@ -1,5 +1,21 @@ -import { Injectable } from '@nestjs/common'; +import { ExecutionContext, Injectable } from '@nestjs/common'; import { AuthGuard } from '@nestjs/passport'; +import { RequestContextService } from '../common/logging/request-context.service'; +import { AccessPayload } from './auth.types'; @Injectable() -export class JwtAuthGuard extends AuthGuard('jwt') {} +export class JwtAuthGuard extends AuthGuard('jwt') { + constructor(private readonly requestContext: RequestContextService) { + super(); + } + + async canActivate(context: ExecutionContext): Promise { + const allowed = await super.canActivate(context); + const request = context + .switchToHttp() + .getRequest<{ user?: AccessPayload }>(); + if (request.user?.sub) + this.requestContext.set({ userId: request.user.sub }); + return Boolean(allowed); + } +} diff --git a/src/common/filters/http-exception.filter.spec.ts b/src/common/filters/http-exception.filter.spec.ts index 869131e..f916897 100644 --- a/src/common/filters/http-exception.filter.spec.ts +++ b/src/common/filters/http-exception.filter.spec.ts @@ -6,10 +6,11 @@ describe('HttpExceptionFilter', () => { const status = jest.fn().mockReturnThis(); const type = jest.fn().mockReturnThis(); const json = jest.fn(); + const locals: Record = {}; const filter = new HttpExceptionFilter(); const host = { switchToHttp: () => ({ - getResponse: () => ({ status, type, json }), + getResponse: () => ({ status, type, json, locals }), }), } as unknown as ArgumentsHost; @@ -21,5 +22,8 @@ describe('HttpExceptionFilter', () => { status: 500, code: 'INTERNAL_SERVER_ERROR', }); + expect(locals.publicErrorCode).toBe('INTERNAL_SERVER_ERROR'); + expect(typeof locals.errorStack).toBe('string'); + expect(locals.errorStack).not.toContain('database password: secret'); }); }); diff --git a/src/common/filters/http-exception.filter.ts b/src/common/filters/http-exception.filter.ts index 353b37b..5962da6 100644 --- a/src/common/filters/http-exception.filter.ts +++ b/src/common/filters/http-exception.filter.ts @@ -23,12 +23,24 @@ export class HttpExceptionFilter implements ExceptionFilter { const isValidation = Array.isArray( (payload as { message?: unknown })?.message, ); + const code = isValidation + ? 'VALIDATION_ERROR' + : this.codeFor(status, payload); + (response.locals ??= {}).publicErrorCode = code; + if ( + status >= Number(HttpStatus.INTERNAL_SERVER_ERROR) && + exception instanceof Error + ) + response.locals.errorStack = exception.stack + ?.split('\n') + .slice(1) + .join('\n'); response .status(status) .type('application/problem+json') .json({ status, - code: isValidation ? 'VALIDATION_ERROR' : this.codeFor(status, payload), + code, ...(isValidation ? { errors: this.validationErrors( diff --git a/src/common/logging/logging.module.ts b/src/common/logging/logging.module.ts new file mode 100644 index 0000000..096d005 --- /dev/null +++ b/src/common/logging/logging.module.ts @@ -0,0 +1,15 @@ +import { Global, Module } from '@nestjs/common'; +import { RequestContextService } from './request-context.service'; +import { RequestLoggingMiddleware } from './request-logging.middleware'; +import { StructuredLogger } from './structured-logger.service'; + +@Global() +@Module({ + providers: [ + RequestContextService, + RequestLoggingMiddleware, + StructuredLogger, + ], + exports: [RequestContextService, RequestLoggingMiddleware, StructuredLogger], +}) +export class LoggingModule {} diff --git a/src/common/logging/request-context.service.ts b/src/common/logging/request-context.service.ts new file mode 100644 index 0000000..2b25e10 --- /dev/null +++ b/src/common/logging/request-context.service.ts @@ -0,0 +1,27 @@ +import { Injectable } from '@nestjs/common'; +import { AsyncLocalStorage } from 'node:async_hooks'; + +export type RequestLogContext = { + requestId: string; + clientRequestId?: string; + userId?: string; + brokerageAccountId?: string; +}; + +@Injectable() +export class RequestContextService { + private readonly storage = new AsyncLocalStorage(); + + run(context: RequestLogContext, callback: () => T): T { + return this.storage.run(context, callback); + } + + get(): RequestLogContext | undefined { + return this.storage.getStore(); + } + + set(context: Partial): void { + const current = this.storage.getStore(); + if (current) Object.assign(current, context); + } +} diff --git a/src/common/logging/request-logging.middleware.spec.ts b/src/common/logging/request-logging.middleware.spec.ts new file mode 100644 index 0000000..2c14cfa --- /dev/null +++ b/src/common/logging/request-logging.middleware.spec.ts @@ -0,0 +1,53 @@ +import { EventEmitter } from 'node:events'; +import { RequestLoggingMiddleware } from './request-logging.middleware'; + +describe('RequestLoggingMiddleware', () => { + it('returns a server ID and emits one safe completion event', () => { + const requestContext = { + run: jest.fn((_: unknown, next: () => void) => next()), + }; + const logger = { event: jest.fn() }; + const middleware = new RequestLoggingMiddleware( + requestContext as never, + logger as never, + ); + const response = Object.assign(new EventEmitter(), { + statusCode: 200, + locals: {}, + setHeader: jest.fn(), + }); + const next = jest.fn(); + + const request: { + method: string; + baseUrl: string; + route: { path: string }; + header: jest.Mock; + id?: string; + } = { + method: 'GET', + baseUrl: '/api/v1', + route: { path: '/accounts/:id' }, + header: jest.fn(() => 'a2dc6fbb-5a48-4c3c-9e3e-4fbf4d638a43'), + }; + middleware.use(request as never, response as never, next); + response.emit('finish'); + + expect(response.setHeader).toHaveBeenCalledWith( + 'X-Request-ID', + expect.stringMatching(/^[0-9a-f-]{36}$/i), + ); + expect(request.id).toMatch(/^[0-9a-f-]{36}$/i); + expect(requestContext.run).toHaveBeenCalledWith( + expect.objectContaining({ + clientRequestId: 'a2dc6fbb-5a48-4c3c-9e3e-4fbf4d638a43', + }), + next, + ); + expect(logger.event).toHaveBeenCalledWith( + 'info', + 'http.request.completed', + expect.objectContaining({ route: '/api/v1/accounts/:id', status: 200 }), + ); + }); +}); diff --git a/src/common/logging/request-logging.middleware.ts b/src/common/logging/request-logging.middleware.ts new file mode 100644 index 0000000..312559d --- /dev/null +++ b/src/common/logging/request-logging.middleware.ts @@ -0,0 +1,67 @@ +import { Injectable, NestMiddleware } from '@nestjs/common'; +import type { NextFunction, Request, Response } from 'express'; +import { randomUUID } from 'node:crypto'; +import { RequestContextService } from './request-context.service'; +import { StructuredLogger } from './structured-logger.service'; + +const uuid = + /^[0-9a-f]{8}-[0-9a-f]{4}-[1-8][0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$/i; + +@Injectable() +export class RequestLoggingMiddleware implements NestMiddleware { + constructor( + private readonly requestContext: RequestContextService, + private readonly logger: StructuredLogger, + ) {} + + use(request: Request, response: Response, next: NextFunction): void { + const incoming = request.header('x-request-id'); + const clientRequestId = + incoming && uuid.test(incoming) ? incoming : undefined; + const existingRequestId = (request as Request & { id?: unknown }).id; + const requestId = + typeof existingRequestId === 'string' ? existingRequestId : randomUUID(); + (request as unknown as { id: string }).id = requestId; + const startedAt = performance.now(); + + response.setHeader('X-Request-ID', requestId); + response.on('finish', () => { + const routeRequest: unknown = request; + const routePath = (routeRequest as { route?: { path?: unknown } }).route + ?.path; + const route = + typeof routePath === 'string' + ? `${request.baseUrl}${routePath}` + : ''; + const context = { + method: request.method, + route, + status: response.statusCode, + durationMs: Math.round(performance.now() - startedAt), + ...(response.locals.publicErrorCode + ? { code: response.locals.publicErrorCode as string } + : {}), + ...(response.locals.errorStack + ? { stack: response.locals.errorStack as string } + : {}), + }; + const level = + response.statusCode >= 500 + ? 'error' + : response.statusCode === 429 || + response.statusCode === 401 || + response.statusCode === 403 + ? 'warn' + : 'info'; + this.logger.event(level, 'http.request.completed', context); + }); + + this.requestContext.run( + { + requestId, + ...(clientRequestId ? { clientRequestId } : {}), + }, + next, + ); + } +} diff --git a/src/common/logging/structured-logger.service.spec.ts b/src/common/logging/structured-logger.service.spec.ts new file mode 100644 index 0000000..3dd3a2e --- /dev/null +++ b/src/common/logging/structured-logger.service.spec.ts @@ -0,0 +1,44 @@ +import { StructuredLogger } from './structured-logger.service'; + +describe('StructuredLogger', () => { + const context = { get: jest.fn() }; + const pino = { + debug: jest.fn(), + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + }; + + beforeEach(() => jest.clearAllMocks()); + + it('passes only allowlisted fields to Pino', () => { + context.get.mockReturnValue({ requestId: 'request', token: 'secret' }); + const logger = new StructuredLogger(context as never, pino as never); + + logger.info('event', { + userId: 'user', + brokerageAccountId: 'account', + password: 'secret', + }); + + expect(pino.info).toHaveBeenCalledWith( + { + requestId: 'request', + userId: 'user', + brokerageAccountId: 'account', + }, + 'event', + ); + }); + + it('delegates event levels to Pino', () => { + context.get.mockReturnValue(undefined); + const logger = new StructuredLogger(context as never, pino as never); + + logger.event('debug', 'debug event'); + logger.event('warn', 'warn event'); + + expect(pino.debug).toHaveBeenCalledWith({}, 'debug event'); + expect(pino.warn).toHaveBeenCalledWith({}, 'warn event'); + }); +}); diff --git a/src/common/logging/structured-logger.service.ts b/src/common/logging/structured-logger.service.ts new file mode 100644 index 0000000..7968da5 --- /dev/null +++ b/src/common/logging/structured-logger.service.ts @@ -0,0 +1,65 @@ +import { Injectable, OnApplicationShutdown } from '@nestjs/common'; +import { PinoLogger } from 'nestjs-pino'; +import { RequestContextService } from './request-context.service'; + +type LogLevel = 'debug' | 'info' | 'warn' | 'error'; +type LogContext = Record; + +const allowedFields = new Set([ + 'service', + 'environment', + 'requestId', + 'clientRequestId', + 'userId', + 'brokerageAccountId', + 'method', + 'route', + 'status', + 'durationMs', + 'code', + 'stack', + 'operation', + 'grpcCode', + 'attempts', + 'count', + 'found', +]); + +@Injectable() +export class StructuredLogger implements OnApplicationShutdown { + constructor( + private readonly requestContext: RequestContextService, + private readonly pino: PinoLogger, + ) {} + + info(message: string, context?: LogContext): void { + this.write('info', message, context); + } + + event(level: LogLevel, message: string, context?: LogContext): void { + this.write(level, message, context); + } + + onApplicationShutdown(): void { + this.info('application.stopped'); + } + + private write( + level: LogLevel, + message: string, + context: LogContext = {}, + ): void { + this.pino[level]( + this.safeContext({ ...this.requestContext.get(), ...context }), + message, + ); + } + + private safeContext(context: LogContext): LogContext { + return Object.fromEntries( + Object.entries(context).filter( + ([key, value]) => allowedFields.has(key) && value !== undefined, + ), + ); + } +} diff --git a/src/config/env.validation.spec.ts b/src/config/env.validation.spec.ts index 9f3587c..a83a53c 100644 --- a/src/config/env.validation.spec.ts +++ b/src/config/env.validation.spec.ts @@ -17,9 +17,22 @@ describe('validateEnv', () => { TOKEN_ENCRYPTION_KEY: 'MDEyMzQ1Njc4OWFiY2RlZjAxMjM0NTY3ODlhYmNkZWY=', TBANK_GRPC_ENDPOINT: 'invest-public-api.tbank.ru:443', TBANK_RATE_LIMIT_PER_SECOND: 5, + LOG_LEVEL: 'info', }); }); + it('rejects an unknown log level', () => { + expect(() => + validateEnv({ + DATABASE_URL: 'file:./data.db', + FRONTEND_ORIGIN: 'http://localhost:5173', + JWT_SECRET: 'a-secret-that-is-at-least-thirty-two-characters', + TOKEN_ENCRYPTION_KEY: 'MDEyMzQ1Njc4OWFiY2RlZjAxMjM0NTY3ODlhYmNkZWY=', + LOG_LEVEL: 'trace', + }), + ).toThrow('LOG_LEVEL must be debug, info, warn, or error'); + }); + it('fails fast when required configuration is missing', () => { expect(() => validateEnv({ FRONTEND_ORIGIN: 'http://localhost:5173' }), diff --git a/src/config/env.validation.ts b/src/config/env.validation.ts index e8eb638..ae8b187 100644 --- a/src/config/env.validation.ts +++ b/src/config/env.validation.ts @@ -7,6 +7,7 @@ export interface Environment { TBANK_CA_CERT_PATH?: string; TBANK_GRPC_ENDPOINT: string; TBANK_RATE_LIMIT_PER_SECOND: number; + LOG_LEVEL: 'debug' | 'info' | 'warn' | 'error'; } export function validateEnv(config: Record): Environment { @@ -19,6 +20,7 @@ export function validateEnv(config: Record): Environment { config['TBANK_GRPC_ENDPOINT'] ?? 'invest-public-api.tbank.ru:443'; const tbankRateLimit = config['TBANK_RATE_LIMIT_PER_SECOND'] ?? 5; const tbankCaCertPath = config['TBANK_CA_CERT_PATH']; + const logLevel = config['LOG_LEVEL'] ?? 'info'; if (typeof databaseUrl !== 'string' || !databaseUrl.startsWith('file:')) { throw new Error('DATABASE_URL must be a SQLite file URL'); @@ -76,6 +78,10 @@ export function validateEnv(config: Record): Environment { throw new Error('TBANK_CA_CERT_PATH must be a file path'); } + if (!['debug', 'info', 'warn', 'error'].includes(logLevel as string)) { + throw new Error('LOG_LEVEL must be debug, info, warn, or error'); + } + return { DATABASE_URL: databaseUrl, FRONTEND_ORIGIN: parsedOrigin.origin, @@ -87,5 +93,6 @@ export function validateEnv(config: Record): Environment { : {}), TBANK_GRPC_ENDPOINT: tbankEndpoint, TBANK_RATE_LIMIT_PER_SECOND: parsedTbankRateLimit, + LOG_LEVEL: logLevel as Environment['LOG_LEVEL'], }; } diff --git a/src/main.ts b/src/main.ts index 5942b93..fbe3dba 100644 --- a/src/main.ts +++ b/src/main.ts @@ -1,23 +1,39 @@ -import { ValidationPipe } from '@nestjs/common'; +import { INestApplication, ValidationPipe } from '@nestjs/common'; import { NestFactory } from '@nestjs/core'; import cookieParser from 'cookie-parser'; import { ConfigService } from '@nestjs/config'; import { DocumentBuilder, SwaggerModule } from '@nestjs/swagger'; +import { Logger } from 'nestjs-pino'; import { AppModule } from './app.module'; import { HttpExceptionFilter } from './common/filters/http-exception.filter'; +import { RequestLoggingMiddleware } from './common/logging/request-logging.middleware'; +import { StructuredLogger } from './common/logging/structured-logger.service'; import { Environment } from './config/env.validation'; import { shouldExposeSwagger } from './config/swagger.config'; -async function bootstrap() { - const app = await NestFactory.create(AppModule); +export function configureApp(app: INestApplication): void { const config = app.get>(ConfigService); const frontendOrigin = config.getOrThrow('FRONTEND_ORIGIN'); - app.enableCors({ origin: frontendOrigin, credentials: true }); + app.useLogger(app.get(Logger)); + app.enableCors({ + origin: frontendOrigin, + credentials: true, + exposedHeaders: ['X-Request-ID'], + }); app.setGlobalPrefix('api/v1'); app.use(cookieParser()); + const requestLogging = app.get(RequestLoggingMiddleware); + app.use(requestLogging.use.bind(requestLogging)); app.useGlobalPipes(new ValidationPipe({ transform: true, whitelist: true })); app.useGlobalFilters(new HttpExceptionFilter()); + app.enableShutdownHooks(); +} + +async function bootstrap() { + const app = await NestFactory.create(AppModule, { bufferLogs: true }); + configureApp(app); + const config = app.get>(ConfigService); if (shouldExposeSwagger(process.env['NODE_ENV'])) { const document = SwaggerModule.createDocument( @@ -31,5 +47,9 @@ async function bootstrap() { } await app.listen(config.getOrThrow('PORT')); + app.get(StructuredLogger).info('application.started', { + service: 'wealth-ledger-backend', + environment: process.env['NODE_ENV'] ?? 'development', + }); } -void bootstrap(); +if (require.main === module) void bootstrap(); diff --git a/src/tbank/brokerage-operations.service.spec.ts b/src/tbank/brokerage-operations.service.spec.ts index 3370db4..deec402 100644 --- a/src/tbank/brokerage-operations.service.spec.ts +++ b/src/tbank/brokerage-operations.service.spec.ts @@ -19,10 +19,12 @@ describe('BrokerageOperationsService', () => { getOpenAccounts: jest.fn(), getOperationsByCursor: jest.fn(), }; + const requestContext = { set: jest.fn() }; const service = new BrokerageOperationsService( prisma as never, config as never, tbank as never, + requestContext as never, ); const crypto = TbankCrypto.fromBase64(key); let operationsRequest: unknown; diff --git a/src/tbank/brokerage-operations.service.ts b/src/tbank/brokerage-operations.service.ts index 6f27a8b..be85b87 100644 --- a/src/tbank/brokerage-operations.service.ts +++ b/src/tbank/brokerage-operations.service.ts @@ -5,6 +5,7 @@ import { NotFoundException, } from '@nestjs/common'; import { ConfigService } from '@nestjs/config'; +import { RequestContextService } from '../common/logging/request-context.service'; import { Environment } from '../config/env.validation'; import { PrismaService } from '../prisma/prisma.service'; import { @@ -38,6 +39,7 @@ export class BrokerageOperationsService { private readonly prisma: PrismaService, config: ConfigService, private readonly tbank: TbankClient, + private readonly requestContext: RequestContextService, ) { this.crypto = TbankCrypto.fromBase64( config.getOrThrow('TOKEN_ENCRYPTION_KEY'), @@ -49,6 +51,7 @@ export class BrokerageOperationsService { accountId: string, query: BrokerageOperationsQueryDto, ): Promise { + this.requestContext.set({ userId, brokerageAccountId: accountId }); const range = this.range(query); const key = JSON.stringify({ userId, accountId, ...query, ...range }); const cached = this.pages.get(key); diff --git a/src/tbank/portfolio.service.spec.ts b/src/tbank/portfolio.service.spec.ts index 7b7912e..478e7a3 100644 --- a/src/tbank/portfolio.service.spec.ts +++ b/src/tbank/portfolio.service.spec.ts @@ -23,10 +23,14 @@ describe('PortfolioService', () => { getInstrumentByFigi: jest.fn(), getInstrumentByUid: jest.fn(), }; + const requestContext = { set: jest.fn() }; + const logger = { event: jest.fn() }; const service = new PortfolioService( prisma as never, config as never, tbank as never, + requestContext as never, + logger as never, ); const crypto = TbankCrypto.fromBase64(key); diff --git a/src/tbank/portfolio.service.ts b/src/tbank/portfolio.service.ts index 609aa95..6e62083 100644 --- a/src/tbank/portfolio.service.ts +++ b/src/tbank/portfolio.service.ts @@ -2,12 +2,13 @@ import { BadRequestException, ConflictException, Injectable, - Logger, NotFoundException, ServiceUnavailableException, } from '@nestjs/common'; import { ConfigService } from '@nestjs/config'; import { Environment } from '../config/env.validation'; +import { RequestContextService } from '../common/logging/request-context.service'; +import { StructuredLogger } from '../common/logging/structured-logger.service'; import { PrismaService } from '../prisma/prisma.service'; import { add, @@ -49,7 +50,6 @@ type CachedMetadata = { @Injectable() export class PortfolioService { - private readonly logger = new Logger(PortfolioService.name); private readonly crypto: TbankCrypto; private readonly snapshots = new Map(); private readonly metadata = new Map(); @@ -58,6 +58,8 @@ export class PortfolioService { private readonly prisma: PrismaService, config: ConfigService, private readonly tbank: TbankClient, + private readonly requestContext: RequestContextService, + private readonly logger: StructuredLogger, ) { this.crypto = TbankCrypto.fromBase64( config.getOrThrow('TOKEN_ENCRYPTION_KEY'), @@ -65,6 +67,7 @@ export class PortfolioService { } async get(userId: string, accountId: string): Promise { + this.requestContext.set({ userId, brokerageAccountId: accountId }); const key = `${userId}:${accountId}`; const cached = this.snapshots.get(key); if (cached && Date.now() - cached.storedAt <= freshForMs) @@ -241,16 +244,12 @@ export class PortfolioService { try { const value = await fetch(); this.metadata.set(key, { value, storedAt: Date.now() }); - this.logger.debug({ - event: 'instrument_metadata_resolved', - cacheKey: key, + this.logger.event('debug', 'portfolio.instrument-metadata.resolved', { found: Boolean(value?.name?.trim() || value?.ticker?.trim()), }); return value; } catch (error) { - this.logger.warn({ - event: 'instrument_metadata_failed', - cacheKey: key, + this.logger.event('warn', 'portfolio.instrument-metadata.failed', { code: error instanceof Error && 'response' in error ? ((error as { response?: { code?: string } }).response?.code ?? diff --git a/src/tbank/tbank.client.spec.ts b/src/tbank/tbank.client.spec.ts index ba06ff5..8716601 100644 --- a/src/tbank/tbank.client.spec.ts +++ b/src/tbank/tbank.client.spec.ts @@ -1,4 +1,5 @@ import { ServiceUnavailableException } from '@nestjs/common'; +import { status } from '@grpc/grpc-js'; import { TbankClient } from './tbank.client'; describe('TbankClient operations', () => { @@ -42,4 +43,59 @@ describe('TbankClient operations', () => { error, ); }); + + it('logs success, retry, and final failure with the RPC context', async () => { + jest.useFakeTimers(); + const logger = { event: jest.fn(), info: jest.fn() }; + const client = Object.create(TbankClient.prototype) as TbankClient; + (client as unknown as { logger: unknown }).logger = logger; + (client as unknown as { queue: unknown }).queue = { + size: 0, + run: (operation: () => unknown) => operation(), + }; + const invoke = (...args: [string, unknown, string, object]) => + ( + client as unknown as { + call: ( + token: string, + service: unknown, + method: string, + input: object, + ) => Promise; + } + ).call(...args); + const requestRpc = jest + .fn() + .mockResolvedValueOnce({ ok: true }) + .mockRejectedValueOnce({ code: status.UNAVAILABLE }) + .mockRejectedValueOnce({ code: status.UNAVAILABLE }); + (client as unknown as { request: jest.Mock }).request = requestRpc; + + await expect(invoke('token', {}, 'getPortfolio', {})).resolves.toEqual({ + ok: true, + }); + const failed = invoke('token', {}, 'getPortfolio', {}); + const rejected = expect(failed).rejects.toEqual( + expect.any(ServiceUnavailableException), + ); + await jest.advanceTimersByTimeAsync(1000); + await rejected; + + expect(logger.event).toHaveBeenCalledWith( + 'debug', + 'tbank.rpc.completed', + expect.objectContaining({ operation: 'getPortfolio', attempts: 1 }), + ); + expect(logger.event).toHaveBeenCalledWith( + 'warn', + 'tbank.rpc.retry', + expect.objectContaining({ grpcCode: status.UNAVAILABLE, attempts: 1 }), + ); + expect(logger.event).toHaveBeenCalledWith( + 'error', + 'tbank.rpc.failed', + expect.objectContaining({ grpcCode: status.UNAVAILABLE, attempts: 2 }), + ); + jest.useRealTimers(); + }); }); diff --git a/src/tbank/tbank.client.ts b/src/tbank/tbank.client.ts index 6ed62a6..a8b2e73 100644 --- a/src/tbank/tbank.client.ts +++ b/src/tbank/tbank.client.ts @@ -1,8 +1,4 @@ -import { - Injectable, - Logger, - ServiceUnavailableException, -} from '@nestjs/common'; +import { Injectable, ServiceUnavailableException } from '@nestjs/common'; import { ConfigService } from '@nestjs/config'; import { ChannelCredentials, @@ -17,6 +13,7 @@ import { loadSync } from '@grpc/proto-loader'; import { existsSync, readFileSync } from 'node:fs'; import { join } from 'node:path'; import { Environment } from '../config/env.validation'; +import { StructuredLogger } from '../common/logging/structured-logger.service'; const requestDeadlineMs = 15_000; @@ -129,13 +126,15 @@ class RateLimiter { @Injectable() export class TbankClient { - private readonly logger = new Logger(TbankClient.name); private readonly queue: RateLimiter; private readonly users: TbankClientService; private readonly operations: TbankClientService; private readonly instruments: TbankClientService; - constructor(config: ConfigService) { + constructor( + config: ConfigService, + private readonly logger: StructuredLogger, + ) { const sourceProtoRoot = join(process.cwd(), 'src/tbank/proto/contracts'); const protoRoot = existsSync(sourceProtoRoot) ? sourceProtoRoot @@ -174,14 +173,7 @@ export class TbankClient { this.queue = new RateLimiter( config.getOrThrow('TBANK_RATE_LIMIT_PER_SECOND'), ); - this.logger.log({ - event: 'client_configured', - endpoint, - rateLimitPerSecond: config.getOrThrow( - 'TBANK_RATE_LIMIT_PER_SECOND', - ), - customCa: Boolean(caPath), - }); + this.logger.info('tbank.client.configured'); } async validateToken(token: string): Promise { @@ -242,41 +234,59 @@ export class TbankClient { client: TbankClientService, method: string, request: object, - retry = true, ): Promise { - if (this.queue.size >= 50) - throw new ServiceUnavailableException({ code: 'TBANK_UNAVAILABLE' }); - try { - return await this.queue.run(() => - this.request(token, client, method, request), - ); - } catch (error) { - const code = (error as ServiceError).code; - const retryable = [ - status.UNAVAILABLE, - status.DEADLINE_EXCEEDED, - status.RESOURCE_EXHAUSTED, - ].includes(code); - this.logger.warn({ - event: 'tbank_rpc_failed', - method, - grpcCode: code, - retryable, - ...(method === 'getInstrumentBy' - ? { - instrumentIdType: (request as { idType?: string }).idType, - instrumentId: (request as { id?: string }).id, - } - : {}), + if (this.queue.size >= 50) { + this.logger.event('error', 'tbank.rpc.failed', { + operation: method, + code: 'TBANK_UNAVAILABLE', + attempts: 0, }); - if (retry && retryable) { - await new Promise((resolve) => setTimeout(resolve, 1000)); - return this.call(token, client, method, request, false); - } - if ([status.UNAUTHENTICATED, status.PERMISSION_DENIED].includes(code)) - throw new Error('INVALID_TBANK_TOKEN'); throw new ServiceUnavailableException({ code: 'TBANK_UNAVAILABLE' }); } + + for (let attempts = 1; attempts <= 2; attempts += 1) { + const startedAt = performance.now(); + try { + const response = await this.queue.run(() => + this.request(token, client, method, request), + ); + this.logger.event('debug', 'tbank.rpc.completed', { + operation: method, + attempts, + durationMs: Math.round(performance.now() - startedAt), + }); + return response; + } catch (error) { + const grpcCode = (error as ServiceError).code; + const retryable = [ + status.UNAVAILABLE, + status.DEADLINE_EXCEEDED, + status.RESOURCE_EXHAUSTED, + ].includes(grpcCode); + if (retryable && attempts < 2) { + this.logger.event('warn', 'tbank.rpc.retry', { + operation: method, + grpcCode, + attempts, + durationMs: Math.round(performance.now() - startedAt), + }); + await new Promise((resolve) => setTimeout(resolve, 1000)); + continue; + } + this.logger.event('error', 'tbank.rpc.failed', { + operation: method, + grpcCode, + attempts, + durationMs: Math.round(performance.now() - startedAt), + }); + if ( + [status.UNAUTHENTICATED, status.PERMISSION_DENIED].includes(grpcCode) + ) + throw new Error('INVALID_TBANK_TOKEN'); + throw new ServiceUnavailableException({ code: 'TBANK_UNAVAILABLE' }); + } + } + throw new ServiceUnavailableException({ code: 'TBANK_UNAVAILABLE' }); } private request( diff --git a/src/tbank/upcoming-events.service.spec.ts b/src/tbank/upcoming-events.service.spec.ts index 25fa130..cd2ef6b 100644 --- a/src/tbank/upcoming-events.service.spec.ts +++ b/src/tbank/upcoming-events.service.spec.ts @@ -22,11 +22,15 @@ describe('UpcomingEventsService', () => { getInstrumentByFigi: jest.fn(), }; const moex = { dividends: jest.fn(), bondEvents: jest.fn() }; + const requestContext = { set: jest.fn() }; + const logger = { info: jest.fn(), event: jest.fn() }; const service = new UpcomingEventsService( prisma as never, config as never, tbank as never, moex as never, + requestContext as never, + logger as never, ); const crypto = TbankCrypto.fromBase64(key); diff --git a/src/tbank/upcoming-events.service.ts b/src/tbank/upcoming-events.service.ts index f2b35bd..db33aaf 100644 --- a/src/tbank/upcoming-events.service.ts +++ b/src/tbank/upcoming-events.service.ts @@ -2,11 +2,12 @@ import { BadRequestException, ConflictException, Injectable, - Logger, NotFoundException, } from '@nestjs/common'; import { ConfigService } from '@nestjs/config'; import { Environment } from '../config/env.validation'; +import { RequestContextService } from '../common/logging/request-context.service'; +import { StructuredLogger } from '../common/logging/structured-logger.service'; import { PrismaService } from '../prisma/prisma.service'; import { decimal, formatDecimal, isZero, multiply } from './decimal'; import { MoexBondEvent, MoexClient, MoexDividend } from './moex.client'; @@ -26,13 +27,14 @@ type Position = NonNullable[number]; @Injectable() export class UpcomingEventsService { private readonly crypto: TbankCrypto; - private readonly logger = new Logger(UpcomingEventsService.name); constructor( private readonly prisma: PrismaService, config: ConfigService, private readonly tbank: TbankClient, private readonly moex: MoexClient, + private readonly requestContext: RequestContextService, + private readonly logger: StructuredLogger, ) { this.crypto = TbankCrypto.fromBase64( config.getOrThrow('TOKEN_ENCRYPTION_KEY'), @@ -40,6 +42,7 @@ export class UpcomingEventsService { } async get(userId: string, accountId: string): Promise { + this.requestContext.set({ userId, brokerageAccountId: accountId }); try { const connection = await this.prisma.tbankConnection.findUnique({ where: { userId }, @@ -67,13 +70,8 @@ export class UpcomingEventsService { .filter( (event) => event.date >= window.from && event.date <= window.to, ); - this.logger.log({ - event: 'upcoming_events_calculated', - accountId, - from: window.from, - to: window.to, - positionCount: (portfolio.positions ?? []).length, - eventCount: projected.length, + this.logger.info('upcoming-events.calculated', { + count: projected.length, }); return { accountId, @@ -98,13 +96,8 @@ export class UpcomingEventsService { ): Promise { const ticker = position.ticker?.trim(); const instrument = ticker - ? await this.instrument(token, position).catch((error: unknown) => { - this.logger.warn({ - event: 'upcoming_event_metadata_unavailable', - figi: position.figi?.trim() || null, - ticker, - error: error instanceof Error ? error.message : 'UNKNOWN', - }); + ? await this.instrument(token, position).catch(() => { + this.logger.event('warn', 'upcoming-events.metadata-unavailable'); return null; }) : await this.instrument(token, position); @@ -117,30 +110,16 @@ export class UpcomingEventsService { displayName: instrument?.name?.trim() || resolvedTicker, }; const quantity = decimal(position.quantity ?? {}); - this.logger.debug({ - event: 'upcoming_event_position_resolved', - figi: metadata.figi, - portfolioTicker: ticker || null, - resolvedTicker, - displayName: metadata.displayName, - instrumentType: position.instrumentType?.toLowerCase() || null, - }); if (position.instrumentType?.toLowerCase() === 'share') { const dividends = await this.moex.dividends(resolvedTicker); - this.logger.debug({ - event: 'upcoming_event_source_result', - ticker: resolvedTicker, - source: 'dividends', - eventCount: dividends.length, + this.logger.event('debug', 'upcoming-events.source-result', { + count: dividends.length, }); return dividends.map((event) => this.dividend(metadata, quantity, event)); } const events = await this.moex.bondEvents(resolvedTicker); - this.logger.debug({ - event: 'upcoming_event_source_result', - ticker: resolvedTicker, - source: 'bondization', - eventCount: events.length, + this.logger.event('debug', 'upcoming-events.source-result', { + count: events.length, }); return events.map((event) => this.bond(metadata, quantity, event)); } diff --git a/test/app.e2e-spec.ts b/test/app.e2e-spec.ts index bd1306e..6a0e708 100644 --- a/test/app.e2e-spec.ts +++ b/test/app.e2e-spec.ts @@ -1,11 +1,12 @@ import { Test, TestingModule } from '@nestjs/testing'; -import { INestApplication, ValidationPipe } from '@nestjs/common'; -import cookieParser from 'cookie-parser'; +import { INestApplication } from '@nestjs/common'; import request from 'supertest'; import { App } from 'supertest/types'; import { AppModule } from './../src/app.module'; -import { HttpExceptionFilter } from './../src/common/filters/http-exception.filter'; +import { StructuredLogger } from './../src/common/logging/structured-logger.service'; +import { configureApp } from './../src/main'; import { PrismaService } from './../src/prisma/prisma.service'; +import { AuthService } from './../src/auth/auth.service'; type Authentication = { user: { email: string }; accessToken: string }; type Problem = { code: string }; @@ -19,12 +20,7 @@ describe('Authentication (e2e)', () => { }).compile(); app = moduleFixture.createNestApplication(); - app.setGlobalPrefix('api/v1'); - app.use(cookieParser()); - app.useGlobalPipes( - new ValidationPipe({ transform: true, whitelist: true }), - ); - app.useGlobalFilters(new HttpExceptionFilter()); + configureApp(app); await app.init(); await app.get(PrismaService).session.deleteMany(); await app.get(PrismaService).tbankConnection.deleteMany(); @@ -140,4 +136,48 @@ describe('Authentication (e2e)', () => { expect((body as Problem).code).toBe('TBANK_NOT_CONNECTED'), ); }); + + it('exposes a server request ID and logs one completion event', async () => { + const logger = app.get(StructuredLogger); + const event = jest.spyOn(logger, 'event'); + const response = await request(app.getHttpServer()) + .get('/api/v1/auth/me') + .set('Origin', 'http://localhost:5173') + .expect(401); + + expect(response.headers['x-request-id']).toMatch(/^[0-9a-f-]{36}$/i); + expect(response.headers['access-control-expose-headers']).toContain( + 'X-Request-ID', + ); + expect(event).toHaveBeenCalledTimes(1); + expect(event).toHaveBeenCalledWith( + 'warn', + 'http.request.completed', + expect.objectContaining({ status: 401, code: 'UNAUTHORIZED' }), + ); + }); + + it('records the public code and stack for an unhandled error', async () => { + const logger = app.get(StructuredLogger); + const event = jest.spyOn(logger, 'event'); + jest + .spyOn(app.get(AuthService), 'login') + .mockRejectedValue(new Error('password: secret')); + + await request(app.getHttpServer()) + .post('/api/v1/auth/login') + .send({ email: 'user@example.com', password: 'a secure password' }) + .expect(500) + .expect(({ body }: { body: unknown }) => + expect(body).toEqual({ status: 500, code: 'INTERNAL_SERVER_ERROR' }), + ); + + expect(event).toHaveBeenCalledWith( + 'error', + 'http.request.completed', + expect.objectContaining({ + code: 'INTERNAL_SERVER_ERROR', + }), + ); + }); });