Merge pull request #270 from DongHoonYu96/feature-be-#229

[BE] feat#229 모니터링 인터셉터 구현

BE/src/common/interceptor/SocketEventLoggerInterceptor.ts

@@ -0,0 +1,224 @@
+import { firstValueFrom, Observable } from 'rxjs';
+import { CallHandler, ExecutionContext, Injectable, Logger, NestInterceptor } from '@nestjs/common';
+import { ModuleRef } from '@nestjs/core';
+import { Socket } from 'socket.io';
+import { AsyncLocalStorage } from 'async_hooks'; // 이 부분 추가
+
+/**
+ * @class TraceStore
+ * @description 함수 호출 추적을 위한 저장소
+ */
+export class TraceStore {
+  private static instance = new AsyncLocalStorage<TraceContext>();
+
+  static getStore() {
+    return this.instance;
+  }
+}
+
+/**
+ * @class TraceContext
+ * @description 추적 컨텍스트
+ */
+class TraceContext {
+  private depth = 0;
+  private logs: string[] = [];
+
+  increaseDepth() {
+    this.depth++;
+  }
+
+  decreaseDepth() {
+    this.depth--;
+  }
+
+  addLog(message: string) {
+    const indent = '  '.repeat(this.depth);
+    this.logs.push(`${indent}${message}`);
+  }
+
+  getLogs(): string[] {
+    return this.logs;
+  }
+}
+
+// 전역 AsyncLocalStorage 인스턴스
+// export const traceStore = new AsyncLocalStorage<TraceContext>();
+
+/**
+ * @class SocketEventLoggerInterceptor
+ * @description WebSocket 이벤트와 서비스 호출을 로깅하는 인터셉터
+ */
+@Injectable()
+export class SocketEventLoggerInterceptor implements NestInterceptor {
+  private readonly logger = new Logger('SocketEventLogger');
+  private readonly EXECUTION_TIME_THRESHOLD = 1000;
+
+  constructor(private readonly moduleRef: ModuleRef) {}
+
+  intercept(context: ExecutionContext, next: CallHandler): Observable<any> {
+    if (context.getType() !== 'ws') {
+      return next.handle();
+    }
+
+    const startTime = Date.now();
+    const ctx = context.switchToWs();
+    const client: Socket = ctx.getClient();
+    const event = ctx.getData();
+    const className = context.getClass().name;
+    const methodName = context.getHandler().name;
+
+    // 새로운 추적 컨텍스트 시작
+    const traceContext = new TraceContext();
+
+    return new Observable((subscriber) => {
+      // AsyncLocalStorage를 사용하여 추적 컨텍스트 설정
+      TraceStore.getStore().run(traceContext, async () => {
+        try {
+          // 핸들러 실행 전 로그
+          traceContext.addLog(`[${className}.${methodName}] Started`);
+
+          // 원본 핸들러 실행
+          const result = await firstValueFrom(next.handle());
+
+          const executionTime = Date.now() - startTime;
+          const logs = traceContext.getLogs();
+
+          if (executionTime >= this.EXECUTION_TIME_THRESHOLD) {
+            this.logger.warn(
+              '🐢 Slow Socket Event Detected!\n' +
+                logs.join('\n') +
+                `\nTotal Execution Time: ${executionTime}ms`
+            );
+          } else {
+            this.logger.log(
+              '🚀 Socket Event Processed\n' +
+                logs.join('\n') +
+                `\nTotal Execution Time: ${executionTime}ms`
+            );
+          }
+
+          subscriber.next(result);
+          subscriber.complete();
+        } catch (error) {
+          const logs = traceContext.getLogs();
+          this.logger.error(
+            '❌ Socket Event Error\n' + logs.join('\n') + `\nError: ${error.message}`
+          );
+          subscriber.error(error);
+        }
+      });
+    });
+  }
+}
+
+/**
+ * @function Trace
+ * @description 서비스 메서드 추적을 위한 데코레이터
+ */
+export function Trace() {
+  return (target: any, propertyKey: string, descriptor: PropertyDescriptor) => {
+    const originalMethod = descriptor.value;
+
+    descriptor.value = async function (...args: any[]) {
+      const className = target.constructor.name;
+      const startTime = Date.now();
+
+      const traceContext = TraceStore.getStore().getStore();
+      if (traceContext) {
+        traceContext.increaseDepth();
+        traceContext.addLog(`[${className}.${propertyKey}] Started`);
+      }
+
+      try {
+        const result = await originalMethod.apply(this, args);
+
+        if (traceContext) {
+          const executionTime = Date.now() - startTime;
+          traceContext.addLog(`[${className}.${propertyKey}] Completed (${executionTime}ms)`);
+          traceContext.decreaseDepth();
+        }
+
+        return result;
+      } catch (error) {
+        if (traceContext) {
+          const executionTime = Date.now() - startTime;
+          traceContext.addLog(
+            `[${className}.${propertyKey}] Failed (${executionTime}ms): ${error.message}`
+          );
+          traceContext.decreaseDepth();
+        }
+        throw error;
+      }
+    };
+
+    return descriptor;
+  };
+}
+
+/**
+ * @function TraceClass
+ * @description 클래스의 모든 메서드에 추적을 적용하는 데코레이터
+ */
+/**
+ * @class TraceClass
+ * @description 클래스의 모든 메서드에 추적을 적용하는 데코레이터
+ */
+export function TraceClass(
+  options: Partial<{ excludeMethods: string[]; includePrivateMethods: boolean }> = {}
+) {
+  return function classDecorator<T extends { new (...args: any[]): {} }>(constructor: T) {
+    const originalPrototype = constructor.prototype;
+
+    Object.getOwnPropertyNames(originalPrototype).forEach((methodName) => {
+      // 제외할 메서드 체크
+      if (
+        methodName === 'constructor' ||
+        (!options.includePrivateMethods && methodName.startsWith('_')) ||
+        options.excludeMethods?.includes(methodName)
+      ) {
+        return;
+      }
+
+      const descriptor = Object.getOwnPropertyDescriptor(originalPrototype, methodName);
+      if (!descriptor || typeof descriptor.value !== 'function') {
+        return;
+      }
+
+      const originalMethod = descriptor.value;
+
+      descriptor.value = async function (...args: any[]) {
+        const traceContext = TraceStore.getStore().getStore();
+        if (!traceContext) {
+          return originalMethod.apply(this, args);
+        }
+
+        const startTime = Date.now();
+
+        traceContext.increaseDepth();
+        traceContext.addLog(`[${constructor.name}.${methodName}] Started`);
+
+        try {
+          const result = await originalMethod.apply(this, args);
+          const executionTime = Date.now() - startTime;
+
+          traceContext.addLog(`[${constructor.name}.${methodName}] Completed (${executionTime}ms)`);
+          traceContext.decreaseDepth();
+
+          return result;
+        } catch (error) {
+          const executionTime = Date.now() - startTime;
+          traceContext.addLog(
+            `[${constructor.name}.${methodName}] Failed (${executionTime}ms): ${error.message}`
+          );
+          traceContext.decreaseDepth();
+          throw error;
+        }
+      };
+
+      Object.defineProperty(originalPrototype, methodName, descriptor);
+    });
+
+    return constructor;
+  };
+}

BE/src/game/game.gateway.ts

@@ -23,7 +23,9 @@ import { GameRoomService } from './service/game.room.service';
 import { WsJwtAuthGuard } from '../auth/guard/ws-jwt-auth.guard';
 import { GameActivityInterceptor } from './interceptor/gameActivity.interceptor';
 import { KickRoomDto } from './dto/kick-room.dto';
+import { SocketEventLoggerInterceptor } from '../common/interceptor/SocketEventLoggerInterceptor';
 
+@UseInterceptors(SocketEventLoggerInterceptor)
 @UseInterceptors(GameActivityInterceptor)
 @UseFilters(new WsExceptionFilter())
 @WebSocketGateway({
@@ -43,6 +45,15 @@ export class GameGateway {
     private readonly gameRoomService: GameRoomService
   ) {}
 
+  @SubscribeMessage('slowEvent')
+  async handleSlowEvent(@ConnectedSocket() client: Socket): Promise<void> {
+    // 의도적으로 지연 발생시키는 테스트 코드
+    await this.gameService.longBusinessLogic();
+    await new Promise((resolve) => setTimeout(resolve, 1500));
+    // 실제 로직
+    // ...
+  }
+
   @SubscribeMessage(SocketEvents.CREATE_ROOM)
   @UsePipes(new GameValidationPipe(SocketEvents.CREATE_ROOM))
   async handleCreateRoom(

BE/src/game/service/game.chat.service.ts

@@ -6,7 +6,9 @@ import { ChatMessageDto } from '../dto/chat-message.dto';
 import { REDIS_KEY } from '../../common/constants/redis-key.constant';
 import SocketEvents from '../../common/constants/socket-events';
 import { Server } from 'socket.io';
+import { TraceClass } from '../../common/interceptor/SocketEventLoggerInterceptor';
 
+@TraceClass()
 @Injectable()
 export class GameChatService {
   private readonly logger = new Logger(GameChatService.name);
@@ -61,14 +63,16 @@ export class GameChatService {
 
       // 죽은 사람의 채팅은 죽은 사람끼리만 볼 수 있도록 처리
       const players = await this.redis.smembers(REDIS_KEY.ROOM_PLAYERS(gameId));
-      await Promise.all(players.map(async (playerId) => {
-        const playerKey = REDIS_KEY.PLAYER(playerId);
-        const isAlive = await this.redis.hget(playerKey, 'isAlive');
+      await Promise.all(
+        players.map(async (playerId) => {
+          const playerKey = REDIS_KEY.PLAYER(playerId);
+          const isAlive = await this.redis.hget(playerKey, 'isAlive');
 
-        if (isAlive === '0') {
-          server.to(playerId).emit(SocketEvents.CHAT_MESSAGE, chatMessage);
-        }
-      }));
+          if (isAlive === '0') {
+            server.to(playerId).emit(SocketEvents.CHAT_MESSAGE, chatMessage);
+          }
+        })
+      );
     });
   }
 }

BE/src/game/service/game.room.service.ts

@@ -12,7 +12,9 @@ import { UpdateRoomQuizsetDto } from '../dto/update-room-quizset.dto';
 import { Cron, CronExpression } from '@nestjs/schedule';
 import { Socket } from 'socket.io';
 import { KickRoomDto } from '../dto/kick-room.dto';
+import { TraceClass } from '../../common/interceptor/SocketEventLoggerInterceptor';
 
+@TraceClass()
 @Injectable()
 export class GameRoomService {
   private readonly logger = new Logger(GameRoomService.name);

BE/src/game/service/game.service.ts

@@ -10,7 +10,9 @@ import { Server } from 'socket.io';
 import { mockQuizData } from '../../../test/mocks/quiz-data.mock';
 import { QuizCacheService } from './quiz.cache.service';
 import { RedisSubscriberService } from '../redis/redis-subscriber.service';
+import { Trace, TraceClass } from '../../common/interceptor/SocketEventLoggerInterceptor';
 
+@TraceClass()
 @Injectable()
 export class GameService {
   private readonly logger = new Logger(GameService.name);
@@ -158,4 +160,11 @@ export class GameService {
       await this.redis.del(roomLeaderboardKey);
     }
   }
+
+  @Trace()
+  async longBusinessLogic() {
+    this.logger.verbose('longBusinessLogic start');
+    await new Promise((resolve) => setTimeout(resolve, 1000));
+    this.logger.verbose('longBusinessLogic end');
+  }
 }

BE/src/game/service/quiz.cache.service.ts

@@ -5,7 +5,9 @@ import { Redis } from 'ioredis';
 import { mockQuizData } from '../../../test/mocks/quiz-data.mock';
 import { REDIS_KEY } from '../../common/constants/redis-key.constant';
 import { QuizSetService } from '../../quiz-set/service/quiz-set.service';
+import { TraceClass } from '../../common/interceptor/SocketEventLoggerInterceptor';
 
+@TraceClass()
 @Injectable()
 export class QuizCacheService {
   private readonly quizCache = new Map<string, any>();