feat: log unhandled errors and pretty dev output (WealthLedger/backend#120)

2026-10-24 14:31:27 +03:00
parent d1f6969dc7
commit d2771473d9
8 changed files with 193 additions and 11 deletions
@@ -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",
@@ -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",
@@ -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<string, unknown> = {};
-    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<string, unknown>];
+    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');
  });
 });
@@ -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<Response>();
@@ -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;
@@ -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<Environment, true>): 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);
@@ -14,9 +14,12 @@ const allowedFields = new Set([
  'count',
  'durationMs',
  'environment',
+  'errorName',
+  'errorStack',
  'found',
  'grpcCode',
  'headersReceived',
+  'invalidFields',
  'method',
  'networkMs',
  'operation',
@@ -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();
 }

@@ -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,