Issue

AWS Cloudfront에서 몇몇 로그의 로깅 항목인 ‘ms’에 시간 측정이 잘못되는 이슈가 발생했다.

{
    "traceId": "40cd1af2-5895-402f-a8f7-5b8afb443d6f",
    "method": "GET",
    "url": "/v1/ping",
    "authorization": "Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJoc3QiOiI5OTk5NSIsInJvbCI6IkhPU1BJVEFMIiwidXNyIjoianVuZyIsImlhdCI6MTcyMDEzNzYxMywiZXhwIjoxNzIwNzQyNDEzfQ.dGyzGLcjy48GjU8LC_4MtqCZasbCnISUDEb1-ZlJ444",
    "body": {},
    "hospitalId": "99995",
    "role": "HOSPITAL",
    "crmUser": "jung",
    "instanceId": "i-00fdcfbcae4fa6191",
    "rss": "742.15 MB",
    "heapTotal": "88.48 MB",
    "heapUsed": "85.10 MB",
    "external": "18.42 MB",
    "arrayBuffers": "0.13 MB",
    "level": "info",
    "message": "[request] {{}}",
    "timestamp": "2024-07-05T00:00:13.870Z",
    **"ms": "+15m"**
}

{
    "traceId": "40cd1af2-5895-402f-a8f7-5b8afb443d6f",
    "statusCode": 200,
    "method": "GET",
    "executionTime": "472ms",
    "url": "/v1/ping",
    "authorization": "Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJoc3QiOiI5OTk5NSIsInJvbCI6IkhPU1BJVEFMIiwidXNyIjoianVuZyIsImlhdCI6MTcyMDEzNzYxMywiZXhwIjoxNzIwNzQyNDEzfQ.dGyzGLcjy48GjU8LC_4MtqCZasbCnISUDEb1-ZlJ444",
    "request": {},
    "response": {
        "hospitalId": "99995",
        "databaseHospitalId": "99995",
        "organizationId": "99999997"
    },
    "hospitalId": "99995",
    "role": "HOSPITAL",
    "crmUser": "jung",
    "instanceId": "i-00fdcfbcae4fa6191",
    "rss": "746.32 MB",
    "heapTotal": "91.23 MB",
    "heapUsed": "87.49 MB",
    "external": "18.45 MB",
    "arrayBuffers": "0.16 MB",
    "level": "info",
    "message": "[response] {\"hospitalId\":\"99995\",\"databaseHospitalId\":\"99995\",\"organizationId\":\"99999997\"}",
    "timestamp": "2024-07-05T00:00:14.341Z",
    **"ms": "+471ms"**
}

위에서는 ‘ms’에 2024-07-05T00:00:14.341Z -2024-07-05T00:00:13.870Z = +471ms 정확한 값이 들어갔지만 아래와 같이 2024-07-05T02:08:08.976Z - 2024-07-05T02:07:56.326Z ≠ +13인 경우도 발생하는 것을 확인했다.

{
    "traceId": "70bdbd51-02bf-4f81-a1de-1dc134d5ca9f",
    "statusCode": 201,
    "method": "POST",
    "executionTime": "25ms",
    "url": "/v1/messages/sends/3214943/receivers:check?offset=0&limit=1",
    "authorization": "Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJoc3QiOiI5OTk5NyIsInJvbCI6IkhPU1BJVEFMIiwidXNyIjoiTm90TG9naW4iLCJpYXQiOjE3MjAxNDUyMTYsImV4cCI6MTcyMDc1MDAxNn0.sOTzYqnIcIHTcIdsm-JDa0iJfiQziguNnTleFYWoUzk",
    "request": {
        "message": "",
        "messageType": "SMS"
    },
    "response": {
        "items": [],
        "totalSize": 0,
        "offset": 0,
        "limit": 1
    },
    "hospitalId": "99997",
    "role": "HOSPITAL",
    "crmUser": "NotLogin",
    "instanceId": "i-0aec6082df2630d1b",
    "rss": "1123.52 MB",
    "heapTotal": "94.23 MB",
    "heapUsed": "90.73 MB",
    "external": "19.56 MB",
    "arrayBuffers": "0.43 MB",
    "level": "info",
    "message": "[response] {\"items\":[],\"totalSize\":0,\"offset\":0,\"limit\":1}",
    **"timestamp": "2024-07-05T02:07:56.326Z",**
    "ms": "+25ms"
}

{
    "traceId": "8a4fdc3a-5c0c-483d-bb8a-b6948042d9f5",
    "method": "GET",
    "url": "/v1/messages/sends/3214943/receivers?offset=0&limit=100&message=%25EB%25AC%25B8%25EC%259E%2590%2520%25EB%25B0%259C%25EC%2586%25A1%2520%25ED%2585%258C%25EC%258A%25A4%25ED%258A%25B8%25ED%2585%258C%25EC%",
    "authorization": "Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJoc3QiOiI5OTk5NyIsInJvbCI6IkhPU1BJVEFMIiwidXNyIjoiTm90TG9naW4iLCJpYXQiOjE3MjAxNDUyMTYsImV4cCI6MTcyMDc1MDAxNn0.sOTzYqnIcIHTcIdsm-JDa0iJfiQziguNnTleFYWoUzk",
    "body": {},
    "hospitalId": "99997",
    "role": "HOSPITAL",
    "crmUser": "NotLogin",
    "instanceId": "i-00fdcfbcae4fa6191",
    "rss": "805.85 MB",
    "heapTotal": "92.82 MB",
    "heapUsed": "89.57 MB",
    "external": "18.55 MB",
    "arrayBuffers": "0.25 MB",
    "level": "info",
    "message": "[request] {{}}",
    **"timestamp": "2024-07-05T02:08:08.976Z",**
    "ms": "+13s"
}

Problem

현재 사내에서 AWS Cloudfront로 로그를 보내는 winston 로거는 STATS logger와 API logger가 있다. 두 인스턴스가 ms를 따로 측정하기 때문에 교차여 cloudwatch에 로그를 보낸경우 ms가 잘못 측정되는 문제가 발생한 것이다.

Solution

따라서 LoggerService의 공유 변수를 통해 두 인스턴스에 대한 ms를 측정하는 방식으로 개발했다.

@Injectable()
export class LoggerService {
  private lastTimeStamp: number = new Date().getTime();

  getMsSinceLastLog() {
    const currentTimestamp = new Date().getTime();
    const diffTimeStamp = currentTimestamp - this.lastTimeStamp;
    const this.lastTimeSTAMP = currentTimestamp;
    return `${diffTimeStamp}ms`;
  }

  createCustomMsFormat() {
    return winston.format((info) => {
      // eslint-disable-next-line no-param-reassign
      info.ms = this.getMsSinceLastLog();
      return info;
    })();
  }
}

사실 로거 그룹을 나눠서 따로 보관하는 것이 바람직해 보인다