From 0f976edf96af551731ca689fea269fc7ada6a632 Mon Sep 17 00:00:00 2001 From: Jason Rasmussen Date: Wed, 5 Jun 2024 17:07:47 -0400 Subject: [PATCH] feat(server): log http exceptions (#9996) --- e2e/src/responses.ts | 10 +++++ server/src/app.module.ts | 4 +- server/src/config.ts | 5 ++- server/src/dtos/auth.dto.ts | 1 + .../src/middleware/http-exception.filter.ts | 37 +++++++++++++++++++ server/src/middleware/logging.interceptor.ts | 27 ++++++++++++-- server/src/repositories/logger.repository.ts | 15 +++++--- server/src/workers/api.ts | 6 +-- server/src/workers/microservices.ts | 4 +- 9 files changed, 91 insertions(+), 18 deletions(-) create mode 100644 server/src/middleware/http-exception.filter.ts diff --git a/e2e/src/responses.ts b/e2e/src/responses.ts index b7dcfca1ee..efa01e6850 100644 --- a/e2e/src/responses.ts +++ b/e2e/src/responses.ts @@ -5,51 +5,61 @@ export const errorDto = { error: 'Unauthorized', statusCode: 401, message: 'Authentication required', + correlationId: expect.any(String), }, forbidden: { error: 'Forbidden', statusCode: 403, message: expect.any(String), + correlationId: expect.any(String), }, wrongPassword: { error: 'Bad Request', statusCode: 400, message: 'Wrong password', + correlationId: expect.any(String), }, invalidToken: { error: 'Unauthorized', statusCode: 401, message: 'Invalid user token', + correlationId: expect.any(String), }, invalidShareKey: { error: 'Unauthorized', statusCode: 401, message: 'Invalid share key', + correlationId: expect.any(String), }, invalidSharePassword: { error: 'Unauthorized', statusCode: 401, message: 'Invalid password', + correlationId: expect.any(String), }, badRequest: (message: any = null) => ({ error: 'Bad Request', statusCode: 400, message: message ?? expect.anything(), + correlationId: expect.any(String), }), noPermission: { error: 'Bad Request', statusCode: 400, message: expect.stringContaining('Not found or no'), + correlationId: expect.any(String), }, incorrectLogin: { error: 'Unauthorized', statusCode: 401, message: 'Incorrect email or password', + correlationId: expect.any(String), }, alreadyHasAdmin: { error: 'Bad Request', statusCode: 400, message: 'The server already has an admin', + correlationId: expect.any(String), }, }; diff --git a/server/src/app.module.ts b/server/src/app.module.ts index 40fa95aefc..2d7f038a67 100644 --- a/server/src/app.module.ts +++ b/server/src/app.module.ts @@ -1,7 +1,7 @@ import { BullModule } from '@nestjs/bullmq'; import { Module, OnModuleInit, ValidationPipe } from '@nestjs/common'; import { ConfigModule } from '@nestjs/config'; -import { APP_GUARD, APP_INTERCEPTOR, APP_PIPE } from '@nestjs/core'; +import { APP_FILTER, APP_GUARD, APP_INTERCEPTOR, APP_PIPE } from '@nestjs/core'; import { EventEmitterModule } from '@nestjs/event-emitter'; import { ScheduleModule, SchedulerRegistry } from '@nestjs/schedule'; import { TypeOrmModule } from '@nestjs/typeorm'; @@ -15,6 +15,7 @@ import { entities } from 'src/entities'; import { AuthGuard } from 'src/middleware/auth.guard'; import { ErrorInterceptor } from 'src/middleware/error.interceptor'; import { FileUploadInterceptor } from 'src/middleware/file-upload.interceptor'; +import { HttpExceptionFilter } from 'src/middleware/http-exception.filter'; import { LoggingInterceptor } from 'src/middleware/logging.interceptor'; import { repositories } from 'src/repositories'; import { services } from 'src/services'; @@ -26,6 +27,7 @@ const common = [...services, ...repositories]; const middleware = [ FileUploadInterceptor, + { provide: APP_FILTER, useClass: HttpExceptionFilter }, { provide: APP_PIPE, useValue: new ValidationPipe({ transform: true, whitelist: true }) }, { provide: APP_INTERCEPTOR, useClass: LoggingInterceptor }, { provide: APP_INTERCEPTOR, useClass: ErrorInterceptor }, diff --git a/server/src/config.ts b/server/src/config.ts index 5fbaa25e6d..f1f89f3e32 100644 --- a/server/src/config.ts +++ b/server/src/config.ts @@ -6,6 +6,7 @@ import { Request, Response } from 'express'; import { RedisOptions } from 'ioredis'; import Joi from 'joi'; import { CLS_ID, ClsModuleOptions } from 'nestjs-cls'; +import { ImmichHeader } from 'src/dtos/auth.dto'; import { ConcurrentQueueName, QueueName } from 'src/interfaces/job.interface'; export enum TranscodePolicy { @@ -419,11 +420,11 @@ export const clsConfig: ClsModuleOptions = { mount: true, generateId: true, setup: (cls, req: Request, res: Response) => { - const headerValues = req.headers['x-immich-cid']; + const headerValues = req.headers[ImmichHeader.CID]; const headerValue = Array.isArray(headerValues) ? headerValues[0] : headerValues; const cid = headerValue || cls.get(CLS_ID); cls.set(CLS_ID, cid); - res.header('x-immich-cid', cid); + res.header(ImmichHeader.CID, cid); }, }, }; diff --git a/server/src/dtos/auth.dto.ts b/server/src/dtos/auth.dto.ts index c7f7893e20..679c944320 100644 --- a/server/src/dtos/auth.dto.ts +++ b/server/src/dtos/auth.dto.ts @@ -19,6 +19,7 @@ export enum ImmichHeader { SESSION_TOKEN = 'x-immich-session-token', SHARED_LINK_KEY = 'x-immich-share-key', CHECKSUM = 'x-immich-checksum', + CID = 'x-immich-cid', } export enum ImmichQuery { diff --git a/server/src/middleware/http-exception.filter.ts b/server/src/middleware/http-exception.filter.ts new file mode 100644 index 0000000000..0d6de8b276 --- /dev/null +++ b/server/src/middleware/http-exception.filter.ts @@ -0,0 +1,37 @@ +import { ArgumentsHost, Catch, ExceptionFilter, HttpException, Inject } from '@nestjs/common'; +import { Response } from 'express'; +import { ClsService } from 'nestjs-cls'; +import { ILoggerRepository } from 'src/interfaces/logger.interface'; + +@Catch(HttpException) +export class HttpExceptionFilter implements ExceptionFilter { + constructor( + @Inject(ILoggerRepository) private logger: ILoggerRepository, + private cls: ClsService, + ) { + this.logger.setContext(HttpExceptionFilter.name); + } + + catch(exception: HttpException, host: ArgumentsHost) { + const ctx = host.switchToHttp(); + const response = ctx.getResponse(); + const status = exception.getStatus(); + + this.logger.debug(`HttpException(${status}) ${JSON.stringify(exception.getResponse())}`); + + let responseBody = exception.getResponse(); + // unclear what circumstances would return a string + if (typeof responseBody === 'string') { + responseBody = { + error: 'Unknown', + message: responseBody, + statusCode: status, + }; + } + + response.status(status).json({ + ...responseBody, + correlationId: this.cls.getId(), + }); + } +} diff --git a/server/src/middleware/logging.interceptor.ts b/server/src/middleware/logging.interceptor.ts index ee8161d9c7..366ed06a5d 100644 --- a/server/src/middleware/logging.interceptor.ts +++ b/server/src/middleware/logging.interceptor.ts @@ -1,7 +1,21 @@ import { CallHandler, ExecutionContext, Inject, Injectable, NestInterceptor } from '@nestjs/common'; +import { Request, Response } from 'express'; import { Observable, finalize } from 'rxjs'; import { ILoggerRepository } from 'src/interfaces/logger.interface'; +const maxArrayLength = 100; +const replacer = (key: string, value: unknown) => { + if (key.toLowerCase().includes('password')) { + return '********'; + } + + if (Array.isArray(value) && value.length > maxArrayLength) { + return [...value.slice(0, maxArrayLength), `...and ${value.length - maxArrayLength} more`]; + } + + return value; +}; + @Injectable() export class LoggingInterceptor implements NestInterceptor { constructor(@Inject(ILoggerRepository) private logger: ILoggerRepository) { @@ -10,18 +24,23 @@ export class LoggingInterceptor implements NestInterceptor { intercept(context: ExecutionContext, next: CallHandler): Observable { const handler = context.switchToHttp(); - const req = handler.getRequest(); - const res = handler.getResponse(); + const req = handler.getRequest(); + const res = handler.getResponse(); - const { method, ip, path } = req; + const { method, ip, url } = req; const start = performance.now(); + return next.handle().pipe( finalize(() => { const finish = performance.now(); const duration = (finish - start).toFixed(2); const { statusCode } = res; - this.logger.verbose(`${method} ${path} ${statusCode} ${duration}ms ${ip}`); + + this.logger.debug(`${method} ${url} ${statusCode} ${duration}ms ${ip}`); + if (req.body && Object.keys(req.body).length > 0) { + this.logger.verbose(JSON.stringify(req.body, replacer)); + } }), ); } diff --git a/server/src/repositories/logger.repository.ts b/server/src/repositories/logger.repository.ts index 0f82c6ee0f..1527965b49 100644 --- a/server/src/repositories/logger.repository.ts +++ b/server/src/repositories/logger.repository.ts @@ -30,17 +30,20 @@ export class LoggerRepository extends ConsoleLogger implements ILoggerRepository } protected formatContext(context: string): string { - let formattedContext = super.formatContext(context); + let prefix = LoggerRepository.appName || ''; + if (context) { + prefix += (prefix ? ':' : '') + context; + } const correlationId = this.cls?.getId(); - if (correlationId && this.isLevelEnabled(LogLevel.VERBOSE)) { - formattedContext += `[${correlationId}] `; + if (correlationId) { + prefix += `~${correlationId}`; } - if (LoggerRepository.appName) { - formattedContext = LogColor.blue(`[${LoggerRepository.appName}] `) + formattedContext; + if (!prefix) { + return ''; } - return formattedContext; + return LogColor.yellow(`[${prefix}]`) + ' '; } } diff --git a/server/src/workers/api.ts b/server/src/workers/api.ts index 96f06ffc9c..0a2e29a0da 100644 --- a/server/src/workers/api.ts +++ b/server/src/workers/api.ts @@ -20,10 +20,10 @@ async function bootstrap() { const port = Number(process.env.IMMICH_PORT) || 3001; const app = await NestFactory.create(ApiModule, { bufferLogs: true }); - const logger = await app.resolve(ILoggerRepository); + const logger = await app.resolve(ILoggerRepository); - logger.setAppName('ImmichServer'); - logger.setContext('ImmichServer'); + logger.setAppName('Api'); + logger.setContext('Bootstrap'); app.useLogger(logger); app.set('trust proxy', ['loopback', 'linklocal', 'uniquelocal']); app.set('etag', 'strong'); diff --git a/server/src/workers/microservices.ts b/server/src/workers/microservices.ts index de198d2e27..50c82ae7d9 100644 --- a/server/src/workers/microservices.ts +++ b/server/src/workers/microservices.ts @@ -11,8 +11,8 @@ export async function bootstrap() { const app = await NestFactory.create(MicroservicesModule, { bufferLogs: true }); const logger = await app.resolve(ILoggerRepository); - logger.setAppName('ImmichMicroservices'); - logger.setContext('ImmichMicroservices'); + logger.setAppName('Microservices'); + logger.setContext('Bootstrap'); app.useLogger(logger); app.useWebSocketAdapter(new WebSocketAdapter(app));