feat(server): log http exceptions (#9996)

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),
   },
 };
 

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

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);
     },
   },
 };

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 {

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<Response>();
+    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(),
+    });
+  }
+}

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<any>): Observable<any> {
     const handler = context.switchToHttp();
-    const req = handler.getRequest();
-    const res = handler.getResponse();
+    const req = handler.getRequest<Request>();
+    const res = handler.getResponse<Response>();
 
-    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));
+        }
       }),
     );
   }

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}]`) + ' ';
   }
 }

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<NestExpressApplication>(ApiModule, { bufferLogs: true });
-  const logger = await app.resolve(ILoggerRepository);
+  const logger = await app.resolve<ILoggerRepository>(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');

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));