diff --git a/package-lock.json b/package-lock.json index cbae37b..408fe13 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", @@ -6301,18 +6302,18 @@ } }, "node_modules/body-parser": { - "version": "2.3.0", - "resolved": "https://registry.npmjs.org/body-parser/-/body-parser-2.3.0.tgz", - "integrity": "sha512-2cGmJupaNgg+QUwVLAucDuWuoMZ6EX9iHDRswZ5lsNYEmwPaRknMPCLZz07yTzVq/83p4o/wzbDZbBrTvGGTIw==", + "version": "2.4.0", + "resolved": "https://registry.npmjs.org/body-parser/-/body-parser-2.4.0.tgz", + "integrity": "sha512-Ifk1KcLrxaGt1occQagQNFNNOqRt1LFuehEnHHzB8Z6cRgIxRU1TBaiIsUiCdA+gy5PL7Y1IX31DNKkRmxtXjQ==", "license": "MIT", "dependencies": { "bytes": "^3.1.2", - "content-type": "^2.0.0", + "content-type": "^2.1.0", "debug": "^4.4.3", "http-errors": "^2.0.1", - "iconv-lite": "^0.7.2", + "iconv-lite": "^0.7.3", "on-finished": "^2.4.1", - "qs": "^6.15.2", + "qs": "^6.16.1", "raw-body": "^3.0.2", "type-is": "^2.1.0" }, @@ -6325,9 +6326,9 @@ } }, "node_modules/body-parser/node_modules/content-type": { - "version": "2.0.0", - "resolved": "https://registry.npmjs.org/content-type/-/content-type-2.0.0.tgz", - "integrity": "sha512-j/O/d7GcZCyNl7/hwZAb606rzqkyvaDctLmckbxLzHvFBzTJHuGEdodATcP3yIRoDrLHkIATJuvzbFlp/ki2cQ==", + "version": "2.1.0", + "resolved": "https://registry.npmjs.org/content-type/-/content-type-2.1.0.tgz", + "integrity": "sha512-mj7UPXE0jaqaOsukNZRUEfEi2AcL7C/vwmwcHV0O97eO1E1pxBZuyjlZrx5seTaNBg1U6+o35wpa35Qfcc+7ag==", "license": "MIT", "engines": { "node": ">=18" @@ -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", @@ -8927,9 +8952,9 @@ } }, "node_modules/fast-uri": { - "version": "3.1.8", - "resolved": "https://registry.npmjs.org/fast-uri/-/fast-uri-3.1.8.tgz", - "integrity": "sha512-GZMtZUTNRpOVIECoXwLNZS5xUGE+mVNbTB8h/7Rwh2TFWcBQiPzTgyZi05BF9UMZKkLJv8XBRJTlU7zg8+ZfMg==", + "version": "3.1.9", + "resolved": "https://registry.npmjs.org/fast-uri/-/fast-uri-3.1.9.tgz", + "integrity": "sha512-hS/0Wt3Ya043oKXs0sIxrMpKQITXhMLIrVAKKXi4gozGC9v7YRWVnXIZzjNPTO02M9BdxLCWqK1yRXgNziVyJQ==", "funding": [ { "type": "github", @@ -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", @@ -9818,9 +9850,9 @@ } }, "node_modules/ip-address": { - "version": "10.7.2", - "resolved": "https://registry.npmjs.org/ip-address/-/ip-address-10.7.2.tgz", - "integrity": "sha512-7H/2gFSIitxc0hG3nOI1glS8QLo/EHBFFLk8vEUjXY/xu0AdL8jZ9U1IzO2PUm0d2D/ofQcAifb0g6OBkt8U7w==", + "version": "10.7.4", + "resolved": "https://registry.npmjs.org/ip-address/-/ip-address-10.7.4.tgz", + "integrity": "sha512-DWBMKyeM25D70nrIiTkgQth59/G+naKOTep6huF9j+GmeK3DMD60Zvxg5d5qQnz+38AHgou6ean2LECX+lrKDg==", "dev": true, "license": "MIT", "engines": { @@ -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", @@ -11492,9 +11534,9 @@ "license": "MIT" }, "node_modules/multer": { - "version": "2.4.0", - "resolved": "https://registry.npmjs.org/multer/-/multer-2.4.0.tgz", - "integrity": "sha512-7dqa0ZcFfzbefdTuIkzOSMvZWC0J7FLqBOjJUZvDCXShIURWKxAyTT1wHhnE5q19c7jOJf43IYYKjBmZVZmvhg==", + "version": "2.5.0", + "resolved": "https://registry.npmjs.org/multer/-/multer-2.5.0.tgz", + "integrity": "sha512-BsqOzYGVq49JcW2IzoSAxeKYRevb+dGGPPWleOR8Lrlk4igwxu1/9pwSXlByhCb7MVZDrNJFC0IBP5/O5nLYRw==", "license": "MIT", "dependencies": { "append-field": "^1.0.0", @@ -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", @@ -12811,9 +12901,9 @@ "license": "MIT" }, "node_modules/qs": { - "version": "6.16.0", - "resolved": "https://registry.npmjs.org/qs/-/qs-6.16.0.tgz", - "integrity": "sha512-h6fhOIaRrID2CbEY2fqs+7t+UXZo+MLAnU5gRIq85uFtdiUPCdsApMlHhXogKVM4HM2DVbIjGNTTYH2OcmP1vA==", + "version": "6.16.1", + "resolved": "https://registry.npmjs.org/qs/-/qs-6.16.1.tgz", + "integrity": "sha512-5Px6J7rfHBAGUhNQ3es4YzcOdBBw0SDcVtThJml4RdnKw4tKs2epA0kPZ+K8X+WiHktT93RHVcQ/3ym5aTCgtg==", "license": "BSD-3-Clause", "dependencies": { "es-define-property": "^1.0.1", @@ -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", @@ -14536,9 +14643,9 @@ } }, "node_modules/undici": { - "version": "7.29.1", - "resolved": "https://registry.npmjs.org/undici/-/undici-7.29.1.tgz", - "integrity": "sha512-RYONW2MeafgYlkVOKYKkA/Ag7BmXqgIWCa8t1m0JcxrQg9pI9lEqRhAOruOBCbAohOa/gkCF+iPi9hrgvTzu6Q==", + "version": "7.30.1", + "resolved": "https://registry.npmjs.org/undici/-/undici-7.30.1.tgz", + "integrity": "sha512-03KrMbjIFDWQR5RNPrSw3bd1r12JpyFQl9/yxjUbJtqkjmllqC5lFjZh6ujeuJCKr8EOQvRW872Oy/az+nLYxg==", "license": "MIT", "engines": { "node": ">=20.18.1" diff --git a/package.json b/package.json index 936dc91..716199f 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", @@ -106,15 +107,24 @@ }, "overrides": { "proxy-addr": "2.0.8", + "express": { + "body-parser": "2.4.0" + }, "@nestjs/platform-express": { - "multer": "2.4.0" + "multer": "2.5.0" + }, + "ajv": { + "fast-uri": "3.1.9" }, "@prisma/config@7.10.0": { "deepmerge-ts": "8.0.2" }, "release-it": { "basic-ftp": "6.2.1", - "undici": "7.29.1" + "undici": "7.30.1" + }, + "socks": { + "ip-address": "10.7.4" }, "prisma": { "mysql2": "3.24.4" 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..7dc8fb3 100644 --- a/test/app.e2e-spec.ts +++ b/test/app.e2e-spec.ts @@ -32,6 +32,7 @@ describe('Authentication (e2e)', () => { pinoHttp: { ...loggingOptions(config), level: 'info', + transport: undefined, stream: { write: (line: string) => logs.push(JSON.parse(line) as Record) }, }, assignResponse: true, @@ -539,7 +540,14 @@ describe('Authentication (e2e)', () => { 'X-Request-ID', ); expect(logs.filter((entry) => entry.requestId === response.headers['x-request-id'])).toEqual([ - expect.objectContaining({ level: 40, message: 'http.request.completed', status: 401, code: 'UNAUTHORIZED' }), + expect.objectContaining({ + level: 40, + message: 'http.request.completed', + method: 'GET', + route: '/api/v1/auth/me', + status: 401, + code: 'UNAUTHORIZED', + }), ]); }); @@ -551,7 +559,7 @@ describe('Authentication (e2e)', () => { new Error('operation failed\npassword: SYNTHETIC_AUDIT_SECRET'), ); - const response = await request(app.getHttpServer()) + await request(app.getHttpServer()) .post('/api/v1/auth/login') .set('X-Request-ID', clientRequestId) .send({ email: 'user@example.com', password: 'a secure password' }) @@ -561,17 +569,30 @@ 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([ - expect.objectContaining({ - requestId: response.headers['x-request-id'], - clientRequestId, - status: 500, - code: 'INTERNAL_SERVER_ERROR', - level: 50, - message: 'http.request.completed', - }), - ]); + expect(logs).toEqual( + expect.arrayContaining([ + expect.objectContaining({ + method: 'POST', + route: '/api/v1/auth/login', + status: 500, + code: 'INTERNAL_SERVER_ERROR', + level: 50, + message: 'http.request.completed', + }), + ]), + ); + expect(logs).toEqual( + expect.arrayContaining([ + expect.objectContaining({ + clientRequestId, + code: 'INTERNAL_SERVER_ERROR', + level: 50, + message: 'http.request.unhandled', + errorName: 'Error', + errorStack: expect.stringContaining(' at ') as unknown, + }), + ]), + ); expect(JSON.stringify(logs)).not.toContain( 'SYNTHETIC_AUDIT_SECRET', );