From d2771473d91d2c8b083e9fdb6c36285970eea8e7 Mon Sep 17 00:00:00 2001 From: Sergey Krylov Date: Tue, 20 Oct 2026 21:44:20 +0300 Subject: [PATCH] feat: log unhandled errors and pretty dev output (WealthLedger/backend#120) --- package-lock.json | 107 ++++++++++++++++++ package.json | 1 + .../filters/http-exception.filter.spec.ts | 44 +++++-- src/common/filters/http-exception.filter.ts | 29 +++++ src/common/logging/logging.module.ts | 5 + .../logging/structured-logger.service.ts | 3 + src/main.ts | 2 +- test/app.e2e-spec.ts | 13 ++- 8 files changed, 193 insertions(+), 11 deletions(-) diff --git a/package-lock.json b/package-lock.json index cbae37b..d549c20 100644 --- a/package-lock.json +++ b/package-lock.json @@ -65,6 +65,7 @@ "eslint-plugin-sonarjs": "4.2.1", "globals": "17.12.0", "jest": "30.5.1", + "pino-pretty": "13.2.0", "release-it": "21.0.2", "supertest": "7.2.2", "ts-jest": "29.4.12", @@ -6900,6 +6901,13 @@ "integrity": "sha512-dOy+3AuW3a2wNbZHIuMZpTcgjGuLU/uBL/ubcZF9OXbDo8ff4O8yVp5Bf0efS8uEoYo5q4Fx7dY9OgQGXgAsQA==", "license": "MIT" }, + "node_modules/colorette": { + "version": "2.0.20", + "resolved": "https://registry.npmjs.org/colorette/-/colorette-2.0.20.tgz", + "integrity": "sha512-IfEDxwoWIjkeXL1eXcDiow4UbKjhLdq6/EuSVR9GMN7KVH3r9gQ83e73hsz1Nd1T3ijd5xv1wcWRYO+D6kCI2w==", + "dev": true, + "license": "MIT" + }, "node_modules/combined-stream": { "version": "1.0.8", "resolved": "https://registry.npmjs.org/combined-stream/-/combined-stream-1.0.8.tgz", @@ -7453,6 +7461,16 @@ "node": ">= 20" } }, + "node_modules/dateformat": { + "version": "4.6.3", + "resolved": "https://registry.npmjs.org/dateformat/-/dateformat-4.6.3.tgz", + "integrity": "sha512-2P0p0pFGzHS5EMnhdxQi7aJN+iMheud0UhG4dlE1DLAlvL8JHjJJTX/CSm4JXwV0Ka5nGk3zC5mcb5bUQUxxMA==", + "dev": true, + "license": "MIT", + "engines": { + "node": "*" + } + }, "node_modules/debug": { "version": "4.4.3", "resolved": "https://registry.npmjs.org/debug/-/debug-4.4.3.tgz", @@ -8868,6 +8886,13 @@ ], "license": "MIT" }, + "node_modules/fast-copy": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/fast-copy/-/fast-copy-4.2.0.tgz", + "integrity": "sha512-WSlnvPXaMdUjFdgxPkovE4e5aslybVod4TNKrEKKyoA8GoHZzbDLlhDXZOvqjtFgjtOHd9TYCstkUcGXy1+SEA==", + "dev": true, + "license": "MIT" + }, "node_modules/fast-decode-uri-component": { "version": "1.0.1", "resolved": "https://registry.npmjs.org/fast-decode-uri-component/-/fast-decode-uri-component-1.0.1.tgz", @@ -9598,6 +9623,13 @@ "node": ">= 0.4" } }, + "node_modules/help-me": { + "version": "5.0.0", + "resolved": "https://registry.npmjs.org/help-me/-/help-me-5.0.0.tgz", + "integrity": "sha512-7xgomUX6ADmcYzFik0HzAxh/73YlKR9bmFzf51CZwR+b6YtzU2m0u49hQCqV6SvlqIqsaxovfwdvbnsw3b/zpg==", + "dev": true, + "license": "MIT" + }, "node_modules/hookified": { "version": "1.15.1", "resolved": "https://registry.npmjs.org/hookified/-/hookified-1.15.1.tgz", @@ -10722,6 +10754,16 @@ "jiti": "lib/jiti-cli.mjs" } }, + "node_modules/joycon": { + "version": "3.1.1", + "resolved": "https://registry.npmjs.org/joycon/-/joycon-3.1.1.tgz", + "integrity": "sha512-34wB/Y7MW7bzjKRjUKTa46I2Z7eV62Rkhva+KkopW7Qvv/OSWBqvkSY7vusOPrNuZcUG3tApvdVgNB8POj3SPw==", + "dev": true, + "license": "MIT", + "engines": { + "node": ">=10" + } + }, "node_modules/js-tokens": { "version": "4.0.0", "resolved": "https://registry.npmjs.org/js-tokens/-/js-tokens-4.0.0.tgz", @@ -12378,6 +12420,54 @@ "process-warning": "^5.0.0" } }, + "node_modules/pino-pretty": { + "version": "13.2.0", + "resolved": "https://registry.npmjs.org/pino-pretty/-/pino-pretty-13.2.0.tgz", + "integrity": "sha512-jjghD1ML+Di/WxjJDz6j6Y4FT7hIXOlb8h27AyJ+ohtAXJXH4PS/xkv7si+RCCIW59HMgZsMKTDgzdr0RhuRrg==", + "dev": true, + "license": "MIT", + "dependencies": { + "colorette": "^2.0.7", + "dateformat": "^4.6.3", + "fast-copy": "^4.0.0", + "fast-safe-stringify": "^2.1.1", + "help-me": "^5.0.0", + "joycon": "^3.1.1", + "minimist": "^1.2.6", + "on-exit-leak-free": "^2.1.2", + "pino-abstract-transport": "^3.0.0", + "pump": "^3.0.3", + "secure-json-parse": "^4.1.0", + "sonic-boom": "^5.0.0", + "strip-json-comments": "^5.0.3" + }, + "bin": { + "pino-pretty": "bin.js" + } + }, + "node_modules/pino-pretty/node_modules/sonic-boom": { + "version": "5.0.2", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-5.0.2.tgz", + "integrity": "sha512-/JEruzo6yhNVhsLblTRchgTQHIt7SsdJP0YyrfWaNKjIOQDfrdZv9gwYraYCAsmKV39/LAdV31FLL5NCDpoL/A==", + "dev": true, + "license": "MIT", + "dependencies": { + "atomic-sleep": "^1.0.0" + } + }, + "node_modules/pino-pretty/node_modules/strip-json-comments": { + "version": "5.0.3", + "resolved": "https://registry.npmjs.org/strip-json-comments/-/strip-json-comments-5.0.3.tgz", + "integrity": "sha512-1tB5mhVo7U+ETBKNf92xT4hrQa3pm0MZ0PQvuDnWgAAGHDsfp4lPSpiS6psrSiet87wyGPh9ft6wmhOMQ0hDiw==", + "dev": true, + "license": "MIT", + "engines": { + "node": ">=14.16" + }, + "funding": { + "url": "https://github.com/sponsors/sindresorhus" + } + }, "node_modules/pino-std-serializers": { "version": "7.1.0", "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-7.1.0.tgz", @@ -13321,6 +13411,23 @@ "node": "^14.0.0 || >=16.0.0" } }, + "node_modules/secure-json-parse": { + "version": "4.1.1", + "resolved": "https://registry.npmjs.org/secure-json-parse/-/secure-json-parse-4.1.1.tgz", + "integrity": "sha512-lnd81MQEZKjhW/Gd2TQqdd4XP6QYNdDW/EP+I7nTrFHP9y2LmaGPIHk9xsnzcOiEr1c39c/e84xFgGviQKBTRw==", + "dev": true, + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "BSD-3-Clause" + }, "node_modules/semver": { "version": "7.8.5", "resolved": "https://registry.npmjs.org/semver/-/semver-7.8.5.tgz", diff --git a/package.json b/package.json index 936dc91..4f9dab3 100644 --- a/package.json +++ b/package.json @@ -95,6 +95,7 @@ "eslint-plugin-sonarjs": "4.2.1", "globals": "17.12.0", "jest": "30.5.1", + "pino-pretty": "13.2.0", "release-it": "21.0.2", "supertest": "7.2.2", "ts-jest": "29.4.12", diff --git a/src/common/filters/http-exception.filter.spec.ts b/src/common/filters/http-exception.filter.spec.ts index 231cddb..6ff348d 100644 --- a/src/common/filters/http-exception.filter.spec.ts +++ b/src/common/filters/http-exception.filter.spec.ts @@ -1,24 +1,29 @@ -import { ArgumentsHost } from '@nestjs/common'; +import { ArgumentsHost, BadRequestException } from '@nestjs/common'; +import { StructuredLogger } from '../logging/structured-logger.service'; import { HttpExceptionFilter } from './http-exception.filter'; describe('HttpExceptionFilter', () => { - it('does not expose internal error details', () => { + const setup = () => { const status = jest.fn().mockReturnThis(); const type = jest.fn().mockReturnThis(); const json = jest.fn(); const locals: Record = {}; - const filter = new HttpExceptionFilter(); + const logger = { event: jest.fn() }; + const filter = new HttpExceptionFilter(logger as unknown as StructuredLogger); const host = { switchToHttp: () => ({ getResponse: () => ({ status, type, json, locals }), }), } as unknown as ArgumentsHost; + return { filter, host, status, type, json, locals, logger }; + }; - filter.catch( - new Error('operation failed\npassword: SYNTHETIC_AUDIT_SECRET'), - host, - ); + it('logs unhandled errors with name and stack frames but never the message', () => { + const { filter, host, status, type, json, locals, logger } = setup(); + const error = new Error('operation failed\npassword: SYNTHETIC_AUDIT_SECRET'); + + filter.catch(error, host); expect(status).toHaveBeenCalledWith(500); expect(type).toHaveBeenCalledWith('application/problem+json'); @@ -27,6 +32,29 @@ describe('HttpExceptionFilter', () => { code: 'INTERNAL_SERVER_ERROR', }); expect(locals.publicErrorCode).toBe('INTERNAL_SERVER_ERROR'); - expect(locals.errorStack).toBeUndefined(); + expect(logger.event).toHaveBeenCalledTimes(1); + const [level, event, fields] = logger.event.mock.calls[0] as [string, string, Record]; + expect(level).toBe('error'); + expect(event).toBe('http.request.unhandled'); + expect(fields).toMatchObject({ code: 'INTERNAL_SERVER_ERROR', errorName: 'Error' }); + expect(JSON.stringify(fields)).not.toContain('SYNTHETIC_AUDIT_SECRET'); + expect(String(fields['errorStack']).split('\n').every((line) => line.startsWith(' at '))).toBe(true); + }); + + it('logs field pointers without values for validation errors', () => { + const { filter, host, status, logger, locals } = setup(); + const exception = new BadRequestException({ + message: [ + { property: 'amount', constraints: { isPositive: 'amount must be positive' }, value: -42 }, + { property: 'amount', constraints: { min: 'amount too small' }, value: -42 }, + ], + }); + + filter.catch(exception, host); + + expect(status).toHaveBeenCalledWith(400); + expect(locals.invalidFields).toBe('#/amount'); + expect(logger.event).not.toHaveBeenCalled(); + expect(JSON.stringify(locals)).not.toContain('-42'); }); }); diff --git a/src/common/filters/http-exception.filter.ts b/src/common/filters/http-exception.filter.ts index 2130736..6f292f8 100644 --- a/src/common/filters/http-exception.filter.ts +++ b/src/common/filters/http-exception.filter.ts @@ -10,9 +10,12 @@ import { } from '@nestjs/common'; import { HttpErrorCode } from '../error-code'; +import { StructuredLogger } from '../logging/structured-logger.service'; @Catch() export class HttpExceptionFilter implements ExceptionFilter { + constructor(private readonly logger: StructuredLogger) {} + catch(exception: unknown, host: ArgumentsHost): void { const context = host.switchToHttp(); const response = context.getResponse(); @@ -31,6 +34,18 @@ export class HttpExceptionFilter implements ExceptionFilter { : this.codeFor(status, payload); response.locals ??= {}; response.locals.publicErrorCode = code; + if (isValidation) { + response.locals.invalidFields = [ + ...new Set( + this.validationErrors( + (payload as { message: ValidationError[] }).message, + ).map((error) => error.pointer), + ), + ].join(','); + } + if (!(exception instanceof HttpException)) { + this.logUnhandled(exception, code); + } response .status(status) .type('application/problem+json') @@ -47,6 +62,20 @@ export class HttpExceptionFilter implements ExceptionFilter { }); } + // ponytail: stack содержит текст message в первой строке; оставляем только кадры, message не пишем. + private logUnhandled(exception: unknown, code: string): void { + const error = exception instanceof Error ? exception : undefined; + const frames = (error?.stack ?? '') + .split('\n') + .filter((line) => line.startsWith(' at ')) + .join('\n'); + this.logger.event('error', 'http.request.unhandled', { + code, + errorName: error?.name ?? typeof exception, + errorStack: frames, + }); + } + private codeFor(status: number, payload: unknown): string { if (typeof payload === 'object' && payload !== null && 'code' in payload) { const code = (payload as { code?: unknown }).code; diff --git a/src/common/logging/logging.module.ts b/src/common/logging/logging.module.ts index 5d115e8..c7cb9b2 100644 --- a/src/common/logging/logging.module.ts +++ b/src/common/logging/logging.module.ts @@ -24,6 +24,7 @@ function completion(request: Request, response: Response, value: { responseTime: status: response.statusCode, durationMs: Math.round(value.responseTime), ...(typeof response.locals.publicErrorCode === 'string' ? { code: response.locals.publicErrorCode } : {}), + ...(typeof response.locals.invalidFields === 'string' ? { invalidFields: response.locals.invalidFields } : {}), }; } @@ -31,6 +32,10 @@ export function loggingOptions(config: ConfigService): Option return { level: config.getOrThrow('LOG_LEVEL'), messageKey: 'message', + // ponytail: development-only pretty output; production never loads pino-pretty. + ...(process.env['NODE_ENV'] === 'development' + ? { transport: { target: 'pino-pretty', options: { colorize: true, singleLine: true, messageKey: 'message' } } } + : {}), genReqId: (_request, response) => { const id = randomUUID(); response.setHeader('X-Request-ID', id); diff --git a/src/common/logging/structured-logger.service.ts b/src/common/logging/structured-logger.service.ts index a05baaa..03f628f 100644 --- a/src/common/logging/structured-logger.service.ts +++ b/src/common/logging/structured-logger.service.ts @@ -14,9 +14,12 @@ const allowedFields = new Set([ 'count', 'durationMs', 'environment', + 'errorName', + 'errorStack', 'found', 'grpcCode', 'headersReceived', + 'invalidFields', 'method', 'networkMs', 'operation', diff --git a/src/main.ts b/src/main.ts index b96d24c..58b866a 100644 --- a/src/main.ts +++ b/src/main.ts @@ -37,7 +37,7 @@ export function configureApp(app: INestApplication): void { exceptionFactory: (message) => new BadRequestException({ message }), }), ); - app.useGlobalFilters(new HttpExceptionFilter()); + app.useGlobalFilters(new HttpExceptionFilter(app.get(StructuredLogger))); app.enableShutdownHooks(); } diff --git a/test/app.e2e-spec.ts b/test/app.e2e-spec.ts index a2c9204..1d5aa8e 100644 --- a/test/app.e2e-spec.ts +++ b/test/app.e2e-spec.ts @@ -561,8 +561,17 @@ describe('Authentication (e2e)', () => { expect(body).toEqual({ status: 500, code: 'INTERNAL_SERVER_ERROR' }), ); - const completed = logs.filter((entry) => entry.requestId === response.headers['x-request-id']); - expect(completed).toEqual([ + const related = logs.filter((entry) => entry.requestId === response.headers['x-request-id']); + expect(related).toEqual([ + expect.objectContaining({ + requestId: response.headers['x-request-id'], + clientRequestId, + code: 'INTERNAL_SERVER_ERROR', + level: 50, + message: 'http.request.unhandled', + errorName: 'Error', + errorStack: expect.stringContaining(' at ') as unknown, + }), expect.objectContaining({ requestId: response.headers['x-request-id'], clientRequestId,