feat(server): correlation id via injected logger (#8823)

* feat(server): correlation id via injected logger

* feat: cid response header

server/package-lock.json

@@ -48,6 +48,7 @@
         "luxon": "^3.4.2",
         "mnemonist": "^0.39.8",
         "nest-commander": "^3.11.1",
+        "nestjs-cls": "^4.3.0",
         "nestjs-otel": "^5.1.5",
         "openid-client": "^5.4.3",
         "pg": "^8.11.3",
@@ -10685,6 +10686,20 @@
         "node": ">=16"
       }
     },
+    "node_modules/nestjs-cls": {
+      "version": "4.3.0",
+      "resolved": "https://registry.npmjs.org/nestjs-cls/-/nestjs-cls-4.3.0.tgz",
+      "integrity": "sha512-MVTun6tqCZih8AJXRj8uBuuFyJhQrIA9m9fStiQjbBXUkE3BrlMRvmLzyw8UcneB3xtFFTfwkAh5PYKRulyaOg==",
+      "engines": {
+        "node": ">=16"
+      },
+      "peerDependencies": {
+        "@nestjs/common": "> 7.0.0 < 11",
+        "@nestjs/core": "> 7.0.0 < 11",
+        "reflect-metadata": "*",
+        "rxjs": ">= 7"
+      }
+    },
     "node_modules/nestjs-otel": {
       "version": "5.1.5",
       "resolved": "https://registry.npmjs.org/nestjs-otel/-/nestjs-otel-5.1.5.tgz",
@@ -22266,6 +22281,12 @@
         }
       }
     },
+    "nestjs-cls": {
+      "version": "4.3.0",
+      "resolved": "https://registry.npmjs.org/nestjs-cls/-/nestjs-cls-4.3.0.tgz",
+      "integrity": "sha512-MVTun6tqCZih8AJXRj8uBuuFyJhQrIA9m9fStiQjbBXUkE3BrlMRvmLzyw8UcneB3xtFFTfwkAh5PYKRulyaOg==",
+      "requires": {}
+    },
     "nestjs-otel": {
       "version": "5.1.5",
       "resolved": "https://registry.npmjs.org/nestjs-otel/-/nestjs-otel-5.1.5.tgz",

server/package.json

@@ -72,6 +72,7 @@
     "luxon": "^3.4.2",
     "mnemonist": "^0.39.8",
     "nest-commander": "^3.11.1",
+    "nestjs-cls": "^4.3.0",
     "nestjs-otel": "^5.1.5",
     "openid-client": "^5.4.3",
     "pg": "^8.11.3",

server/src/app.module.ts

@@ -5,9 +5,10 @@ import { 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';
+import { ClsModule } from 'nestjs-cls';
 import { OpenTelemetryModule } from 'nestjs-otel';
 import { commands } from 'src/commands';
-import { bullConfig, bullQueues, immichAppConfig } from 'src/config';
+import { bullConfig, bullQueues, clsConfig, immichAppConfig } from 'src/config';
 import { controllers } from 'src/controllers';
 import { databaseConfig } from 'src/database.config';
 import { entities } from 'src/entities';
@@ -19,10 +20,8 @@ import { services } from 'src/services';
 import { ApiService } from 'src/services/api.service';
 import { MicroservicesService } from 'src/services/microservices.service';
 import { otelConfig } from 'src/utils/instrumentation';
-import { ImmichLogger } from 'src/utils/logger';
 
-const providers = [ImmichLogger];
-const common = [...services, ...providers, ...repositories];
+const common = [...services, ...repositories];
 
 const middleware = [
   FileUploadInterceptor,
@@ -34,6 +33,7 @@ const middleware = [
 const imports = [
   BullModule.forRoot(bullConfig),
   BullModule.registerQueue(...bullQueues),
+  ClsModule.forRoot(clsConfig),
   ConfigModule.forRoot(immichAppConfig),
   EventEmitterModule.forRoot(),
   OpenTelemetryModule.forRoot(otelConfig),

server/src/config.ts

@@ -1,8 +1,10 @@
 import { RegisterQueueOptions } from '@nestjs/bullmq';
 import { ConfigModuleOptions } from '@nestjs/config';
 import { QueueOptions } from 'bullmq';
+import { Request, Response } from 'express';
 import { RedisOptions } from 'ioredis';
 import Joi from 'joi';
+import { CLS_ID, ClsModuleOptions } from 'nestjs-cls';
 import { LogLevel } from 'src/entities/system-config.entity';
 import { QueueName } from 'src/interfaces/job.interface';
 
@@ -69,3 +71,17 @@ export const bullConfig: QueueOptions = {
 };
 
 export const bullQueues: RegisterQueueOptions[] = Object.values(QueueName).map((name) => ({ name }));
+
+export const clsConfig: ClsModuleOptions = {
+  middleware: {
+    mount: true,
+    generateId: true,
+    setup: (cls, req: Request, res: Response) => {
+      const headerValues = req.headers['x-immich-cid'];
+      const headerValue = Array.isArray(headerValues) ? headerValues[0] : headerValues;
+      const cid = headerValue || cls.get(CLS_ID);
+      cls.set(CLS_ID, headerValue);
+      res.header('x-immich-cid', cid);
+    },
+  },
+};

server/src/interfaces/logger.interface.ts

@@ -0,0 +1,15 @@
+import { LogLevel } from 'src/entities/system-config.entity';
+
+export const ILoggerRepository = 'ILoggerRepository';
+
+export interface ILoggerRepository {
+  setContext(message: string): void;
+  setLogLevel(level: LogLevel): void;
+
+  verbose(message: any, ...args: any): void;
+  debug(message: any, ...args: any): void;
+  log(message: any, ...args: any): void;
+  warn(message: any, ...args: any): void;
+  error(message: any, ...args: any): void;
+  fatal(message: any, ...args: any): void;
+}

server/src/main.ts

@@ -8,20 +8,21 @@ import sirv from 'sirv';
 import { ApiModule, ImmichAdminModule, MicroservicesModule } from 'src/app.module';
 import { WEB_ROOT, envName, excludePaths, isDev, serverVersion } from 'src/constants';
 import { LogLevel } from 'src/entities/system-config.entity';
+import { ILoggerRepository } from 'src/interfaces/logger.interface';
 import { WebSocketAdapter } from 'src/middleware/websocket.adapter';
 import { ApiService } from 'src/services/api.service';
 import { otelSDK } from 'src/utils/instrumentation';
-import { ImmichLogger } from 'src/utils/logger';
 import { useSwagger } from 'src/utils/misc';
 
 async function bootstrapMicroservices() {
-  const logger = new ImmichLogger('ImmichMicroservice');
+  otelSDK.start();
+
   const host = String(process.env.HOST || '0.0.0.0');
   const port = Number(process.env.MICROSERVICES_PORT) || 3002;
-
-  otelSDK.start();
   const app = await NestFactory.create(MicroservicesModule, { bufferLogs: true });
-  app.useLogger(app.get(ImmichLogger));
+  const logger = app.get(ILoggerRepository);
+  logger.setContext('ImmichMicroservice');
+  app.useLogger(logger);
   app.useWebSocketAdapter(new WebSocketAdapter(app));
 
   await app.listen(port, host);
@@ -30,14 +31,15 @@ async function bootstrapMicroservices() {
 }
 
 async function bootstrapApi() {
-  const logger = new ImmichLogger('ImmichServer');
+  otelSDK.start();
+
   const host = String(process.env.HOST || '0.0.0.0');
   const port = Number(process.env.SERVER_PORT) || 3001;
-
-  otelSDK.start();
   const app = await NestFactory.create<NestExpressApplication>(ApiModule, { bufferLogs: true });
+  const logger = app.get(ILoggerRepository);
 
-  app.useLogger(app.get(ImmichLogger));
+  logger.setContext('ImmichServer');
+  app.useLogger(logger);
   app.set('trust proxy', ['loopback', 'linklocal', 'uniquelocal']);
   app.set('etag', 'strong');
   app.use(cookieParser());

server/src/middleware/auth.guard.ts

@@ -1,6 +1,7 @@
 import {
   CanActivate,
   ExecutionContext,
+  Inject,
   Injectable,
   SetMetadata,
   applyDecorators,
@@ -11,8 +12,8 @@ import { ApiBearerAuth, ApiCookieAuth, ApiOkResponse, ApiQuery, ApiSecurity } fr
 import { Request } from 'express';
 import { IMMICH_API_KEY_NAME } from 'src/constants';
 import { AuthDto } from 'src/dtos/auth.dto';
+import { ILoggerRepository } from 'src/interfaces/logger.interface';
 import { AuthService, LoginDetails } from 'src/services/auth.service';
-import { ImmichLogger } from 'src/utils/logger';
 import { UAParser } from 'ua-parser-js';
 
 export enum Metadata {
@@ -79,12 +80,13 @@ export interface AuthRequest extends Request {
 
 @Injectable()
 export class AuthGuard implements CanActivate {
-  private logger = new ImmichLogger(AuthGuard.name);
-
   constructor(
+    @Inject(ILoggerRepository) private logger: ILoggerRepository,
     private reflector: Reflector,
     private authService: AuthService,
-  ) {}
+  ) {
+    this.logger.setContext(AuthGuard.name);
+  }
 
   async canActivate(context: ExecutionContext): Promise<boolean> {
     const targets = [context.getHandler(), context.getClass()];

server/src/middleware/error.interceptor.ts

@@ -2,17 +2,20 @@ import {
   CallHandler,
   ExecutionContext,
   HttpException,
+  Inject,
   Injectable,
   InternalServerErrorException,
   NestInterceptor,
 } from '@nestjs/common';
 import { Observable, catchError, throwError } from 'rxjs';
-import { ImmichLogger } from 'src/utils/logger';
+import { ILoggerRepository } from 'src/interfaces/logger.interface';
 import { isConnectionAborted, routeToErrorMessage } from 'src/utils/misc';
 
 @Injectable()
 export class ErrorInterceptor implements NestInterceptor {
-  private logger = new ImmichLogger(ErrorInterceptor.name);
+  constructor(@Inject(ILoggerRepository) private logger: ILoggerRepository) {
+    this.logger.setContext(ErrorInterceptor.name);
+  }
 
   intercept(context: ExecutionContext, next: CallHandler<any>): Observable<any> {
     return next.handle().pipe(

server/src/repositories/index.ts

@@ -11,6 +11,7 @@ import { IDatabaseRepository } from 'src/interfaces/database.interface';
 import { IEventRepository } from 'src/interfaces/event.interface';
 import { IJobRepository } from 'src/interfaces/job.interface';
 import { ILibraryRepository } from 'src/interfaces/library.interface';
+import { ILoggerRepository } from 'src/interfaces/logger.interface';
 import { IMachineLearningRepository } from 'src/interfaces/machine-learning.interface';
 import { IMediaRepository } from 'src/interfaces/media.interface';
 import { IMemoryRepository } from 'src/interfaces/memory.interface';
@@ -41,6 +42,7 @@ import { DatabaseRepository } from 'src/repositories/database.repository';
 import { EventRepository } from 'src/repositories/event.repository';
 import { JobRepository } from 'src/repositories/job.repository';
 import { LibraryRepository } from 'src/repositories/library.repository';
+import { LoggerRepository } from 'src/repositories/logger.repository';
 import { MachineLearningRepository } from 'src/repositories/machine-learning.repository';
 import { MediaRepository } from 'src/repositories/media.repository';
 import { MemoryRepository } from 'src/repositories/memory.repository';
@@ -71,6 +73,7 @@ export const repositories = [
   { provide: IDatabaseRepository, useClass: DatabaseRepository },
   { provide: IEventRepository, useClass: EventRepository },
   { provide: IJobRepository, useClass: JobRepository },
+  { provide: ILoggerRepository, useClass: LoggerRepository },
   { provide: ILibraryRepository, useClass: LibraryRepository },
   { provide: IKeyRepository, useClass: ApiKeyRepository },
   { provide: IMachineLearningRepository, useClass: MachineLearningRepository },

server/src/repositories/logger.repository.ts

@@ -0,0 +1,27 @@
+import { Injectable } from '@nestjs/common';
+import { ClsService } from 'nestjs-cls';
+import { LogLevel } from 'src/entities/system-config.entity';
+import { ILoggerRepository } from 'src/interfaces/logger.interface';
+import { ImmichLogger } from 'src/utils/logger';
+
+@Injectable()
+export class LoggerRepository extends ImmichLogger implements ILoggerRepository {
+  constructor(private cls: ClsService) {
+    super(LoggerRepository.name);
+  }
+
+  protected formatContext(context: string): string {
+    let formattedContext = super.formatContext(context);
+
+    const correlationId = this.cls?.getId();
+    if (correlationId && this.isLevelEnabled(LogLevel.VERBOSE)) {
+      formattedContext += `[${correlationId}] `;
+    }
+
+    return formattedContext;
+  }
+
+  setLogLevel(level: LogLevel): void {
+    ImmichLogger.setLogLevel(level);
+  }
+}

server/src/services/auth.service.spec.ts

@@ -8,6 +8,7 @@ import { UserEntity } from 'src/entities/user.entity';
 import { IKeyRepository } from 'src/interfaces/api-key.interface';
 import { ICryptoRepository } from 'src/interfaces/crypto.interface';
 import { ILibraryRepository } from 'src/interfaces/library.interface';
+import { ILoggerRepository } from 'src/interfaces/logger.interface';
 import { ISharedLinkRepository } from 'src/interfaces/shared-link.interface';
 import { ISystemConfigRepository } from 'src/interfaces/system-config.interface';
 import { IUserTokenRepository } from 'src/interfaces/user-token.interface';
@@ -23,6 +24,7 @@ import { IAccessRepositoryMock, newAccessRepositoryMock } from 'test/repositorie
 import { newKeyRepositoryMock } from 'test/repositories/api-key.repository.mock';
 import { newCryptoRepositoryMock } from 'test/repositories/crypto.repository.mock';
 import { newLibraryRepositoryMock } from 'test/repositories/library.repository.mock';
+import { newLoggerRepositoryMock } from 'test/repositories/logger.repository.mock';
 import { newSharedLinkRepositoryMock } from 'test/repositories/shared-link.repository.mock';
 import { newSystemConfigRepositoryMock } from 'test/repositories/system-config.repository.mock';
 import { newUserTokenRepositoryMock } from 'test/repositories/user-token.repository.mock';
@@ -60,6 +62,7 @@ describe('AuthService', () => {
   let cryptoMock: jest.Mocked<ICryptoRepository>;
   let userMock: jest.Mocked<IUserRepository>;
   let libraryMock: jest.Mocked<ILibraryRepository>;
+  let loggerMock: jest.Mocked<ILoggerRepository>;
   let configMock: jest.Mocked<ISystemConfigRepository>;
   let userTokenMock: jest.Mocked<IUserTokenRepository>;
   let shareMock: jest.Mocked<ISharedLinkRepository>;
@@ -92,12 +95,23 @@ describe('AuthService', () => {
     cryptoMock = newCryptoRepositoryMock();
     userMock = newUserRepositoryMock();
     libraryMock = newLibraryRepositoryMock();
+    loggerMock = newLoggerRepositoryMock();
     configMock = newSystemConfigRepositoryMock();
     userTokenMock = newUserTokenRepositoryMock();
     shareMock = newSharedLinkRepositoryMock();
     keyMock = newKeyRepositoryMock();
 
-    sut = new AuthService(accessMock, cryptoMock, configMock, libraryMock, userMock, userTokenMock, shareMock, keyMock);
+    sut = new AuthService(
+      accessMock,
+      cryptoMock,
+      configMock,
+      libraryMock,
+      loggerMock,
+      userMock,
+      userTokenMock,
+      shareMock,
+      keyMock,
+    );
   });
 
   it('should be defined', () => {

server/src/services/auth.service.ts

@@ -43,12 +43,12 @@ import { IAccessRepository } from 'src/interfaces/access.interface';
 import { IKeyRepository } from 'src/interfaces/api-key.interface';
 import { ICryptoRepository } from 'src/interfaces/crypto.interface';
 import { ILibraryRepository } from 'src/interfaces/library.interface';
+import { ILoggerRepository } from 'src/interfaces/logger.interface';
 import { ISharedLinkRepository } from 'src/interfaces/shared-link.interface';
 import { ISystemConfigRepository } from 'src/interfaces/system-config.interface';
 import { IUserTokenRepository } from 'src/interfaces/user-token.interface';
 import { IUserRepository } from 'src/interfaces/user.interface';
 import { HumanReadableSize } from 'src/utils/bytes';
-import { ImmichLogger } from 'src/utils/logger';
 
 export interface LoginDetails {
   isSecure: boolean;
@@ -76,7 +76,6 @@ interface ClaimOptions<T> {
 export class AuthService {
   private access: AccessCore;
   private configCore: SystemConfigCore;
-  private logger = new ImmichLogger(AuthService.name);
   private userCore: UserCore;
 
   constructor(
@@ -84,6 +83,7 @@ export class AuthService {
     @Inject(ICryptoRepository) private cryptoRepository: ICryptoRepository,
     @Inject(ISystemConfigRepository) configRepository: ISystemConfigRepository,
     @Inject(ILibraryRepository) libraryRepository: ILibraryRepository,
+    @Inject(ILoggerRepository) private logger: ILoggerRepository,
     @Inject(IUserRepository) private userRepository: IUserRepository,
     @Inject(IUserTokenRepository) private userTokenRepository: IUserTokenRepository,
     @Inject(ISharedLinkRepository) private sharedLinkRepository: ISharedLinkRepository,
@@ -92,6 +92,7 @@ export class AuthService {
     this.access = AccessCore.create(accessRepository);
     this.configCore = SystemConfigCore.create(configRepository);
     this.userCore = UserCore.create(cryptoRepository, libraryRepository, userRepository);
+    this.logger.setContext(AuthService.name);
 
     custom.setHttpOptionsDefaults({ timeout: 30_000 });
   }

server/src/services/system-config.service.spec.ts

@@ -16,11 +16,13 @@ import {
 } from 'src/entities/system-config.entity';
 import { IEventRepository, ServerEvent } from 'src/interfaces/event.interface';
 import { QueueName } from 'src/interfaces/job.interface';
+import { ILoggerRepository } from 'src/interfaces/logger.interface';
 import { ISearchRepository } from 'src/interfaces/search.interface';
 import { ISystemConfigRepository } from 'src/interfaces/system-config.interface';
 import { SystemConfigService } from 'src/services/system-config.service';
 import { ImmichLogger } from 'src/utils/logger';
 import { newEventRepositoryMock } from 'test/repositories/event.repository.mock';
+import { newLoggerRepositoryMock } from 'test/repositories/logger.repository.mock';
 import { newSystemConfigRepositoryMock } from 'test/repositories/system-config.repository.mock';
 
 const updates: SystemConfigEntity[] = [
@@ -156,13 +158,15 @@ describe(SystemConfigService.name, () => {
   let sut: SystemConfigService;
   let configMock: jest.Mocked<ISystemConfigRepository>;
   let eventMock: jest.Mocked<IEventRepository>;
+  let loggerMock: jest.Mocked<ILoggerRepository>;
   let smartInfoMock: jest.Mocked<ISearchRepository>;
 
   beforeEach(() => {
     delete process.env.IMMICH_CONFIG_FILE;
     configMock = newSystemConfigRepositoryMock();
     eventMock = newEventRepositoryMock();
-    sut = new SystemConfigService(configMock, eventMock, smartInfoMock);
+    loggerMock = newLoggerRepositoryMock();
+    sut = new SystemConfigService(configMock, eventMock, loggerMock, smartInfoMock);
   });
 
   it('should work', () => {

server/src/services/system-config.service.ts

@@ -22,22 +22,23 @@ import {
   ServerAsyncEventMap,
   ServerEvent,
 } from 'src/interfaces/event.interface';
+import { ILoggerRepository } from 'src/interfaces/logger.interface';
 import { ISearchRepository } from 'src/interfaces/search.interface';
 import { ISystemConfigRepository } from 'src/interfaces/system-config.interface';
-import { ImmichLogger } from 'src/utils/logger';
 
 @Injectable()
 export class SystemConfigService {
-  private logger = new ImmichLogger(SystemConfigService.name);
   private core: SystemConfigCore;
 
   constructor(
     @Inject(ISystemConfigRepository) private repository: ISystemConfigRepository,
     @Inject(IEventRepository) private eventRepository: IEventRepository,
+    @Inject(ILoggerRepository) private logger: ILoggerRepository,
     @Inject(ISearchRepository) private smartInfoRepository: ISearchRepository,
   ) {
     this.core = SystemConfigCore.create(repository);
     this.core.config$.subscribe((config) => this.setLogLevel(config));
+    this.logger.setContext(SystemConfigService.name);
   }
 
   async init() {
@@ -130,7 +131,7 @@ export class SystemConfigService {
     const envLevel = this.getEnvLogLevel();
     const configLevel = logging.enabled ? logging.level : false;
     const level = envLevel ?? configLevel;
-    ImmichLogger.setLogLevel(level);
+    this.logger.setLogLevel(level);
     this.logger.log(`LogLevel=${level} ${envLevel ? '(set via LOG_LEVEL)' : '(set via system config)'}`);
   }
 

server/src/utils/logger.ts

@@ -4,6 +4,7 @@ import { LogLevel } from 'src/entities/system-config.entity';
 
 const LOG_LEVELS = [LogLevel.VERBOSE, LogLevel.DEBUG, LogLevel.LOG, LogLevel.WARN, LogLevel.ERROR, LogLevel.FATAL];
 
+// TODO move implementation to logger.repository.ts
 export class ImmichLogger extends ConsoleLogger {
   private static logLevels: LogLevel[] = [LogLevel.LOG, LogLevel.WARN, LogLevel.ERROR, LogLevel.FATAL];
 

server/test/repositories/logger.repository.mock.ts

@@ -0,0 +1,15 @@
+import { ILoggerRepository } from 'src/interfaces/logger.interface';
+
+export const newLoggerRepositoryMock = (): jest.Mocked<ILoggerRepository> => {
+  return {
+    setLogLevel: jest.fn(),
+    setContext: jest.fn(),
+
+    verbose: jest.fn(),
+    debug: jest.fn(),
+    log: jest.fn(),
+    warn: jest.fn(),
+    error: jest.fn(),
+    fatal: jest.fn(),
+  };
+};