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.
This commit is contained in:
1 parent
05876838b0
commit
ce3a0c44ac
7 files changed
+269
-5
No files matched your search
@@ -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',
|
||||
|
||||
@@ -162,9 +162,12 @@ describe('AuthService', () => {
|
||||
expect.objectContaining({
|
||||
action: 'LOGIN_FAILED',
|
||||
entityId: '[email protected]',
|
||||
userId: undefined,
|
||||
}),
|
||||
);
|
||||
const [[recordArg]] = auditLog.record.mock.calls as [
|
||||
[{ userId?: string }],
|
||||
];
|
||||
expect(recordArg).not.toHaveProperty('userId');
|
||||
});
|
||||
});
|
||||
|
||||
|
||||
@@ -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<LoginResult> {
|
||||
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,
|
||||
|
||||
@@ -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();
|
||||
});
|
||||
});
|
||||
@@ -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<Response>();
|
||||
const request = ctx.getRequest<Request>();
|
||||
|
||||
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);
|
||||
}
|
||||
}
|
||||
@@ -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'),
|
||||
);
|
||||
});
|
||||
});
|
||||
@@ -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();
|
||||
}
|
||||
Reference in new issue
Block a user