Merge pull request #15 from topcoder-platform/add-timing-logging

Add timing logging for every call on mcp

Author: vas3a

src/app.module.ts

@@ -6,6 +6,7 @@ import { ToolsModule } from './mcp/tools/tools.module';
 import { GlobalProvidersModule } from './shared/global/globalProviders.module';
 import { ResourcesModule } from './mcp/resources/resources.module';
 import { randomUUID } from 'crypto';
+import { TimingInterceptorMiddleware } from './shared/global/timingInterceptor';
 
 @Module({
   imports: [
@@ -28,5 +29,6 @@ import { randomUUID } from 'crypto';
 export class AppModule implements NestModule {
   configure(consumer: MiddlewareConsumer) {
     consumer.apply(TokenValidatorMiddleware).forRoutes('*');
+    consumer.apply(TimingInterceptorMiddleware).forRoutes('*');
   }
 }

src/mcp/resources/swagger/challenges.resource.ts

@@ -2,6 +2,7 @@ import { Injectable } from '@nestjs/common';
 import { Resource } from '@tc/mcp-nest';
 import axios from 'axios';
 import { Logger } from 'src/shared/global';
+import { LogTime } from 'src/shared/global/logTime.decorator';
 
 const SPEC_URL =
   'https://raw.githubusercontent.com/topcoder-platform/challenge-api-v6/refs/heads/develop/docs/swagger.yaml';
@@ -16,6 +17,7 @@ export class ChallengesApiSwaggerResource {
     description: 'Swagger documentation for the Challenges V6 API',
     mimeType: 'text/yaml',
   })
+  @LogTime('ChallengesApiSwaggerResource')
   async getChallengesApiSwagger() {
     this.logger.debug('Fetching Challenges V6 API Swagger');
     // Fetch the content from the URI and return it.

src/mcp/resources/swagger/identity.resource.ts

@@ -2,6 +2,7 @@ import { Injectable } from '@nestjs/common';
 import { Resource } from '@tc/mcp-nest';
 import axios from 'axios';
 import { Logger } from 'src/shared/global';
+import { LogTime } from 'src/shared/global/logTime.decorator';
 
 const SPEC_URL =
   'https://raw.githubusercontent.com/topcoder-platform/identity-api-v6/refs/heads/develop/doc/swagger.yaml';
@@ -16,6 +17,7 @@ export class IdentityApiSwaggerResource {
     description: 'Swagger documentation for the Identity V6 API',
     mimeType: 'text/yaml',
   })
+  @LogTime('IdentityApiSwaggerResource')
   async getIdentityApiSwagger() {
     this.logger.debug('Fetching Identity V6 API Swagger');
     // Fetch the content from the URI and return it.

src/mcp/resources/swagger/member.resource.ts

@@ -2,6 +2,7 @@ import { Injectable } from '@nestjs/common';
 import { Resource } from '@tc/mcp-nest';
 import axios from 'axios';
 import { Logger } from 'src/shared/global';
+import { LogTime } from 'src/shared/global/logTime.decorator';
 
 const SPEC_URL =
   'https://raw.githubusercontent.com/topcoder-platform/member-api-v6/refs/heads/develop/docs/swagger.yaml';
@@ -16,6 +17,7 @@ export class MemberApiSwaggerResource {
     description: 'Swagger documentation for the Member V6 API',
     mimeType: 'text/yaml',
   })
+  @LogTime('MemberApiSwaggerResource')
   async getMemberApiSwagger() {
     this.logger.debug('Fetching Member V6 API Swagger');
     // Fetch the content from the URI and return it.

src/mcp/resources/swagger/review.resource.ts

@@ -2,6 +2,7 @@ import { Injectable } from '@nestjs/common';
 import { Resource } from '@tc/mcp-nest';
 import axios from 'axios';
 import { Logger } from 'src/shared/global';
+import { LogTime } from 'src/shared/global/logTime.decorator';
 
 const SPEC_URL = 'https://api.topcoder-dev.com/v6/review/api-docs-yaml';
 
@@ -15,6 +16,7 @@ export class ReviewApiSwaggerResource {
     description: 'Swagger documentation for the Review V6 API',
     mimeType: 'text/yaml',
   })
+  @LogTime('ReviewApiSwaggerResource')
   async getReviewApiSwagger() {
     this.logger.debug('Fetching Review V6 API Swagger');
     // Fetch the content from the URI and return it.

src/mcp/tools/challenges/queryChallenges.tool.ts

@@ -5,6 +5,7 @@ import { QUERY_CHALLENGES_TOOL_PARAMETERS } from './queryChallenges.parameters';
 import { TopcoderChallengesService } from 'src/shared/topcoder/challenges.service';
 import { Logger } from 'src/shared/global';
 import { QUERY_CHALLENGES_TOOL_OUTPUT_SCHEMA } from './queryChallenges.output';
+import { LogTime } from 'src/shared/global/logTime.decorator';
 
 @Injectable()
 export class QueryChallengesTool {
@@ -131,6 +132,7 @@ export class QueryChallengesTool {
       readOnlyHint: true,
     },
   })
+  @LogTime('ChallengesTool')
   async queryChallenges(params) {
     return this._queryChallenges(params);
   }

src/mcp/tools/skills/querySkills.tool.ts

@@ -5,6 +5,7 @@ import { Logger } from 'src/shared/global';
 import { QUERY_SKILLS_TOOL_PARAMETERS } from './querySkills.parameters';
 import { QUERY_SKILLS_TOOL_OUTPUT_SCHEMA } from './querySkills.output';
 import { TopcoderSkillsService } from 'src/shared/topcoder/skills.service';
+import { LogTime } from 'src/shared/global/logTime.decorator';
 
 @Injectable()
 export class QuerySkillsTool {
@@ -125,6 +126,7 @@ export class QuerySkillsTool {
       readOnlyHint: true,
     },
   })
+  @LogTime('SkillsTool')
   async querySkills(params) {
     return this._querySkills(params);
   }

src/shared/global/logTime.decorator.ts

@@ -0,0 +1,32 @@
+import { Logger } from '@nestjs/common';
+
+export function LogTime(label?: string) {
+  const logger = new Logger('ExecutionTime');
+
+  return function (
+    target: any,
+    propertyKey: string,
+    descriptor: PropertyDescriptor,
+  ) {
+    const originalMethod = descriptor.value;
+
+    descriptor.value = async function (...args: any[]) {
+      const start = Date.now();
+
+      try {
+        const result = await originalMethod.apply(this, args);
+        const ms = Date.now() - start;
+        logger.log(`${label || propertyKey} executed in ${ms}ms`);
+        return result;
+      } catch (error) {
+        const ms = Date.now() - start;
+        logger.error(
+          `${label || propertyKey} failed after ${ms}ms – ${error.message}`,
+        );
+        throw error;
+      }
+    };
+
+    return descriptor;
+  };
+}

src/shared/global/timingInterceptor.ts

@@ -0,0 +1,25 @@
+import { Injectable, NestMiddleware, Logger } from '@nestjs/common';
+
+import { Request, Response, NextFunction } from 'express';
+
+@Injectable()
+export class TimingInterceptorMiddleware implements NestMiddleware {
+  private logger = new Logger('TimingInterceptor');
+
+  use(request: Request, response: Response, next: NextFunction): void {
+    const { method, originalUrl: url } = request;
+    const start = Date.now();
+    const mcpMethod = request.body?.method;
+    
+    response.on('close', () => {
+      const { statusCode } = response;
+      const duration = Date.now() - start;
+
+      this.logger.log(
+        `${method} ${mcpMethod ? `{${mcpMethod}} ` : ''}${url} ${statusCode} took ${duration}ms`
+      );
+    });
+
+    next();
+  }
+}