From ce3a0c44ac049e5c56cfb5b43a28e323ec0267fe Mon Sep 17 00:00:00 2001 From: Nick Szaunig Date: Thu, 27 Aug 2026 07:29:51 +0200 Subject: [PATCH] feat: globales HTTP-Access-Log und Exception-Logging Bisher waren 4xx-Fehler (falsches Passwort, Validierungsfehler, fehlende Berechtigung) im Log komplett unsichtbar - Nest loggt standardmaessig nur unbehandelte 5xx-Fehler. Ein Login, das aus Infra-Gruenden fehlschlaegt (siehe TLS/Cloudflare-Vorfall), war dadurch allein aus den Logs nicht diagnostizierbar. - AllExceptionsFilter (global): loggt jede Exception mit Methode/Pfad/ Status (4xx als warn, 5xx als error mit Stacktrace). Client-Antwort bleibt unveraendert - HttpExceptions liefern weiter exakt ihren bisherigen Body, unbehandelte Fehler weiter nur eine generische 500-Meldung ohne interne Details. - requestLoggerMiddleware (global): eine Zeile pro Request (Methode, Pfad, Status, Dauer), damit auch erfolgreiche Requests im Log auftauchen - vorher gab's dafuer gar keine Spur. - AuthService.login()/verifyMfaAndLogin(): konkrete Ursache pro Fehlschlag (unbekannter User, deaktiviert, falsches Passwort, falscher MFA-Code) zusaetzlich zum bestehenden Audit-Log-Eintrag. Nirgends werden Passwoerter, Tokens oder Request-Bodies geloggt - nur Methode, Pfad, Status, Dauer und die (bereits client-sichere) Fehlermeldung. Verifiziert: tsc/eslint clean, 304/304 Tests (7 neu), Build clean. --- ApiCore-Backend/src/app.config.ts | 4 + ApiCore-Backend/src/auth/auth.service.spec.ts | 5 +- ApiCore-Backend/src/auth/auth.service.ts | 24 +++++- .../filters/all-exceptions.filter.spec.ts | 70 ++++++++++++++++ .../common/filters/all-exceptions.filter.ts | 60 ++++++++++++++ .../request-logger.middleware.spec.ts | 80 +++++++++++++++++++ .../middleware/request-logger.middleware.ts | 31 +++++++ 7 files changed, 269 insertions(+), 5 deletions(-) create mode 100644 ApiCore-Backend/src/common/filters/all-exceptions.filter.spec.ts create mode 100644 ApiCore-Backend/src/common/filters/all-exceptions.filter.ts create mode 100644 ApiCore-Backend/src/common/middleware/request-logger.middleware.spec.ts create mode 100644 ApiCore-Backend/src/common/middleware/request-logger.middleware.ts diff --git a/ApiCore-Backend/src/app.config.ts b/ApiCore-Backend/src/app.config.ts index cb3a599..1e7a7f6 100644 --- a/ApiCore-Backend/src/app.config.ts +++ b/ApiCore-Backend/src/app.config.ts @@ -2,6 +2,8 @@ import { RequestMethod, ValidationPipe, VersioningType } from '@nestjs/common'; import { NestExpressApplication } from '@nestjs/platform-express'; import helmet from 'helmet'; import cookieParser from 'cookie-parser'; +import { AllExceptionsFilter } from './common/filters/all-exceptions.filter'; +import { requestLoggerMiddleware } from './common/middleware/request-logger.middleware'; export function configureApp(app: NestExpressApplication): void { // Trust the single reverse-proxy hop (K8s ingress) so req.ip reflects the @@ -10,6 +12,8 @@ export function configureApp(app: NestExpressApplication): void { app.set('trust proxy', 1); app.use(helmet()); app.use(cookieParser()); + app.use(requestLoggerMiddleware); + app.useGlobalFilters(new AllExceptionsFilter()); app.enableCors({ origin: process.env.FRONTEND_ORIGIN ?? 'http://localhost:3000', diff --git a/ApiCore-Backend/src/auth/auth.service.spec.ts b/ApiCore-Backend/src/auth/auth.service.spec.ts index d3f0215..cd84bcc 100644 --- a/ApiCore-Backend/src/auth/auth.service.spec.ts +++ b/ApiCore-Backend/src/auth/auth.service.spec.ts @@ -162,9 +162,12 @@ describe('AuthService', () => { expect.objectContaining({ action: 'LOGIN_FAILED', entityId: 'missing@example.com', - userId: undefined, }), ); + const [[recordArg]] = auditLog.record.mock.calls as [ + [{ userId?: string }], + ]; + expect(recordArg).not.toHaveProperty('userId'); }); }); diff --git a/ApiCore-Backend/src/auth/auth.service.ts b/ApiCore-Backend/src/auth/auth.service.ts index d22df0b..b56075d 100644 --- a/ApiCore-Backend/src/auth/auth.service.ts +++ b/ApiCore-Backend/src/auth/auth.service.ts @@ -1,4 +1,4 @@ -import { Injectable, UnauthorizedException } from '@nestjs/common'; +import { Injectable, Logger, UnauthorizedException } from '@nestjs/common'; import { JwtService } from '@nestjs/jwt'; import * as bcrypt from 'bcryptjs'; import * as crypto from 'node:crypto'; @@ -33,6 +33,8 @@ const REFRESH_TOKEN_BYTES = 40; @Injectable() export class AuthService { + private readonly logger = new Logger(AuthService.name); + constructor( private readonly usersService: UsersService, private readonly prisma: PrismaService, @@ -91,17 +93,28 @@ export class AuthService { async login(email: string, password: string): Promise { const user = await this.usersService.findByEmail(email); - if (!user || !user.isActive) { + if (!user) { + this.logger.warn(`Login failed: no user with email ${email}`); await this.auditLog.record({ entityType: 'AuthSession', - entityId: user?.id ?? email, + entityId: email, action: 'LOGIN_FAILED', - userId: user?.id, + }); + throw new UnauthorizedException('Invalid credentials'); + } + if (!user.isActive) { + this.logger.warn(`Login failed: user ${user.id} is deactivated`); + await this.auditLog.record({ + entityType: 'AuthSession', + entityId: user.id, + action: 'LOGIN_FAILED', + userId: user.id, }); throw new UnauthorizedException('Invalid credentials'); } const passwordMatches = await bcrypt.compare(password, user.passwordHash); if (!passwordMatches) { + this.logger.warn(`Login failed: wrong password for user ${user.id}`); await this.auditLog.record({ entityType: 'AuthSession', entityId: user.id, @@ -143,6 +156,9 @@ export class AuthService { code, ); if (!isValid) { + this.logger.warn( + `MFA verification failed: wrong code for user ${user.id}`, + ); await this.auditLog.record({ entityType: 'AuthSession', entityId: user.id, diff --git a/ApiCore-Backend/src/common/filters/all-exceptions.filter.spec.ts b/ApiCore-Backend/src/common/filters/all-exceptions.filter.spec.ts new file mode 100644 index 0000000..e0d6a52 --- /dev/null +++ b/ApiCore-Backend/src/common/filters/all-exceptions.filter.spec.ts @@ -0,0 +1,70 @@ +import { ArgumentsHost, BadRequestException, Logger } from '@nestjs/common'; +import { AllExceptionsFilter } from './all-exceptions.filter'; + +describe('AllExceptionsFilter', () => { + let filter: AllExceptionsFilter; + let jsonMock: jest.Mock; + let statusMock: jest.Mock; + let host: ArgumentsHost; + + afterEach(() => { + jest.restoreAllMocks(); + }); + + beforeEach(() => { + filter = new AllExceptionsFilter(); + jsonMock = jest.fn(); + statusMock = jest.fn().mockReturnValue({ json: jsonMock }); + host = { + switchToHttp: () => ({ + getResponse: () => ({ status: statusMock }), + getRequest: () => ({ + method: 'POST', + originalUrl: '/api/v1/auth/login', + }), + }), + } as unknown as ArgumentsHost; + }); + + it('passes through an HttpException with its own status and body unchanged', () => { + jest.spyOn(Logger.prototype, 'warn').mockImplementation(() => undefined); + const exception = new BadRequestException('Nicht unterstützter Dateityp'); + + filter.catch(exception, host); + + expect(statusMock).toHaveBeenCalledWith(400); + expect(jsonMock).toHaveBeenCalledWith(exception.getResponse()); + }); + + it('collapses a non-HttpException to a generic 500 body, never leaking the real message', () => { + jest.spyOn(Logger.prototype, 'error').mockImplementation(() => undefined); + + filter.catch(new Error('database password is wrong'), host); + + expect(statusMock).toHaveBeenCalledWith(500); + expect(jsonMock).toHaveBeenCalledWith({ + statusCode: 500, + message: 'Internal server error', + }); + }); + + it('logs 5xx errors at error level and 4xx at warn level', () => { + const errorSpy = jest + .spyOn(Logger.prototype, 'error') + .mockImplementation(() => undefined); + const warnSpy = jest + .spyOn(Logger.prototype, 'warn') + .mockImplementation(() => undefined); + + filter.catch(new Error('boom'), host); + expect(errorSpy).toHaveBeenCalled(); + expect(warnSpy).not.toHaveBeenCalled(); + + errorSpy.mockClear(); + warnSpy.mockClear(); + + filter.catch(new BadRequestException('bad input'), host); + expect(warnSpy).toHaveBeenCalled(); + expect(errorSpy).not.toHaveBeenCalled(); + }); +}); diff --git a/ApiCore-Backend/src/common/filters/all-exceptions.filter.ts b/ApiCore-Backend/src/common/filters/all-exceptions.filter.ts new file mode 100644 index 0000000..3e8a6c0 --- /dev/null +++ b/ApiCore-Backend/src/common/filters/all-exceptions.filter.ts @@ -0,0 +1,60 @@ +import { + ArgumentsHost, + Catch, + ExceptionFilter, + HttpException, + HttpStatus, + Logger, +} from '@nestjs/common'; +import type { Request, Response } from 'express'; + +/** + * Replaces Nest's default exception handling so EVERY error - not just + * unhandled 5xx ones - shows up in stdout/kubectl logs. Nest's built-in + * filter only logs uncaught exceptions; a deliberate 4xx throw (wrong + * password, validation failure, permission denied) normally leaves no + * trace anywhere but the HTTP response itself, which made a real incident + * (a login that silently failed for infra reasons far from this code) + * needlessly hard to diagnose from logs alone. + * + * Client-facing behaviour is unchanged: HttpExceptions still return + * exactly the body/status Nest would have produced. Non-HttpException + * errors still collapse to a generic 500 body - the real message and + * stack go to the log, never to the client. + */ +@Catch() +export class AllExceptionsFilter implements ExceptionFilter { + private readonly logger = new Logger('ExceptionFilter'); + + catch(exception: unknown, host: ArgumentsHost): void { + const ctx = host.switchToHttp(); + const response = ctx.getResponse(); + const request = ctx.getRequest(); + + const isHttpException = exception instanceof HttpException; + const status = isHttpException + ? exception.getStatus() + : HttpStatus.INTERNAL_SERVER_ERROR; + const body = isHttpException + ? exception.getResponse() + : { statusCode: status, message: 'Internal server error' }; + const message = + exception instanceof Error ? exception.message : 'Unknown error'; + const context = `${request.method} ${request.originalUrl} -> ${status}`; + // Compared against the literal 500, not HttpStatus.INTERNAL_SERVER_ERROR: + // eslint's no-unsafe-enum-comparison and TS's no-unnecessary-type-assertion + // fight over any cast here, so a plain number sidesteps both cleanly. + const isServerError = status >= 500; + + if (isServerError) { + this.logger.error( + `${context}: ${message}`, + exception instanceof Error ? exception.stack : undefined, + ); + } else { + this.logger.warn(`${context}: ${message}`); + } + + response.status(status).json(body); + } +} diff --git a/ApiCore-Backend/src/common/middleware/request-logger.middleware.spec.ts b/ApiCore-Backend/src/common/middleware/request-logger.middleware.spec.ts new file mode 100644 index 0000000..10ea7ab --- /dev/null +++ b/ApiCore-Backend/src/common/middleware/request-logger.middleware.spec.ts @@ -0,0 +1,80 @@ +import { Logger } from '@nestjs/common'; +import type { NextFunction, Request, Response } from 'express'; +import { requestLoggerMiddleware } from './request-logger.middleware'; + +describe('requestLoggerMiddleware', () => { + afterEach(() => { + jest.restoreAllMocks(); + }); + + function fakeRequest(): Request { + return { method: 'GET', originalUrl: '/api/v1/dashboard' } as Request; + } + + function fakeResponse(statusCode: number): { + res: Response; + finish: () => void; + } { + let finishHandler: () => void = () => undefined; + const res = { + statusCode, + on: (event: string, handler: () => void) => { + if (event === 'finish') { + finishHandler = handler; + } + }, + } as unknown as Response; + return { res, finish: () => finishHandler() }; + } + + it('calls next() immediately without waiting for the response', () => { + const next = jest.fn() as NextFunction; + const { res } = fakeResponse(200); + + requestLoggerMiddleware(fakeRequest(), res, next); + + expect(next).toHaveBeenCalled(); + }); + + it('logs at log level for a 2xx response', () => { + const logSpy = jest + .spyOn(Logger.prototype, 'log') + .mockImplementation(() => undefined); + const { res, finish } = fakeResponse(200); + + requestLoggerMiddleware(fakeRequest(), res, jest.fn()); + finish(); + + expect(logSpy).toHaveBeenCalledWith( + expect.stringContaining('GET /api/v1/dashboard 200'), + ); + }); + + it('logs at warn level for a 4xx response', () => { + const warnSpy = jest + .spyOn(Logger.prototype, 'warn') + .mockImplementation(() => undefined); + const { res, finish } = fakeResponse(401); + + requestLoggerMiddleware(fakeRequest(), res, jest.fn()); + finish(); + + expect(warnSpy).toHaveBeenCalledWith( + expect.stringContaining('GET /api/v1/dashboard 401'), + ); + }); + + it('logs at error level for a 5xx response', () => { + const errorSpy = jest + .spyOn(Logger.prototype, 'error') + .mockImplementation(() => undefined); + const { res, finish } = fakeResponse(500); + + requestLoggerMiddleware(fakeRequest(), res, jest.fn()); + finish(); + + expect(errorSpy).toHaveBeenCalledWith( + expect.stringContaining('GET /api/v1/dashboard 500'), + ); + }); +}); diff --git a/ApiCore-Backend/src/common/middleware/request-logger.middleware.ts b/ApiCore-Backend/src/common/middleware/request-logger.middleware.ts new file mode 100644 index 0000000..75d90f3 --- /dev/null +++ b/ApiCore-Backend/src/common/middleware/request-logger.middleware.ts @@ -0,0 +1,31 @@ +import { Logger } from '@nestjs/common'; +import type { NextFunction, Request, Response } from 'express'; + +const logger = new Logger('HTTP'); + +/** + * One line per request in stdout/kubectl logs: method, path, status, and + * timing - never the body/headers, so passwords and tokens never end up in + * logs. Without this, a normal (non-error) request leaves zero trace, + * which makes "did the request even arrive?" the hardest question to + * answer when something looks broken from outside the cluster. + */ +export function requestLoggerMiddleware( + req: Request, + res: Response, + next: NextFunction, +): void { + const start = Date.now(); + res.on('finish', () => { + const duration = Date.now() - start; + const line = `${req.method} ${req.originalUrl} ${res.statusCode} ${duration}ms`; + if (res.statusCode >= 500) { + logger.error(line); + } else if (res.statusCode >= 400) { + logger.warn(line); + } else { + logger.log(line); + } + }); + next(); +}