x-ctx-id 기반의 로그 분석 가이드

epub 문서를 편집하는 예제를 통해 함수체인의 동작과 디버깅 방법에 대해 설명한다.

../../_images/anlyzlog1.png

epub 편집기능이 추가된 서비스 URL은 다음과 같이 access.log 에 기록된다.

... /sample.epub/epubedit/trim/10-20 ...

위 호출은 내부적으로 복잡한 함수의 연결(=함수체인)을 통해 결과물을 생성한다.

  1. cache epub 다운로드

  2. unzip epub 압축해제

  3. epubedit epub 내 각 이미지 추출

  4. dims 추출된 이미지 변환

  5. epubedit epub 아카이빙

2~5번 과정은 블랙박스에 가려지고 노출되는 origin.log 는 다음과 같다.

... /sample.epub ... 200 ...

이 장에서는 장애상황에서 블랙박스 안의 함수체인의 동작을 access.log 와 origin.log 로 기록/분석하는 표준방안을 설명한다.

../../_images/anlyzlog2.png

함수체인 세션플래그

함수체인의 기본동작은 로그를 기록하지 않는다.

See also

디버깅을 원하는 가상호스트의 함수체인 동작에서 nolog 플래그를 제거하면 함수체인 트랜잭션이 로그에 기록된다.

{
  {
    "hosting": [
      {
        "name": "www.foo.com",
        "functions": {
          "operations": {
            "chaining": {
              "pipe": {
                "flags": "nourlrewrite;nosessionurlrewrite;recursive;reqfilemeta;keepalive=600;"
              }
            }
          }
        }
      }
    ]
  }
}

Important

설정반영을 위해서는 RT 엔진의 API를 다음과 같이 호출한다.

$ curl http://127.0.0.1:10039/conf/reload
{
  "version": "1.0.2",
  "method": "reloadall",
  "status": "OK",
  "result": "accepted"
}

이제 로그상의 함수체인 동작이 다음과 같이 access.log 와 origin.log 에 기록된다.

../../_images/anlyzlog3.png

파란 점선의 집합이 함수체인이다.

피호출 함수(callee) 트랜잭션은 access.log 에, 함수 호출(caller) 트랜잭션은 origin.log 에 각각 기록된다.

Warning

hosting[].functions 가 아닌 functions 의 설정을 변경하면 모든 가상호스트의 함수체인이 기록된다.

x-ctx-id 기본 로깅

컨텍스트 ID( x-ctx-id )는 클라이언트 요청 HTTP 트랜잭션마다 부여되는 UUID 이다.

Note

트랜잭션 ID는 멀티 노드에서도 유일하다.

../../_images/anlyzlog4.png

x-ctx-id 가 단순 트랜잭션 ID와 구분되는 이유는 다음과 같이 요청을 처리하기 위해 동작하는 모든 HTTP 트랜잭션들이 같은 x-ctx-id 를 공유한다는 점이다.

../../_images/anlyzlog5.png

클라이언트와 원본 트랜잭션의 x-ctx-id 는 같다.

따라서 access.log 와 origin.log 의 x-ctx-id 필드 값을 연결하여 트랜잭션의 상관관게를 알아낼 수 있다. 함수체인에서도 x-ctx-id 는 동일하게 적용되는데 아래 클라이언트로부터 파생된 모든 트랜잭션은 서로 session-id 와 tid 가지지만 x-ctx-id 는 동일하다.

../../_images/anlyzlog6.png

access.log 분석

access.log 에는 모든 함수체인이 기록된다.

2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/directory - 80 - 121.130.104.227 - 200 58194 1 - http - TCP_HIT - 671 57713 0 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/META-INF/container.xml - 80 - 121.130.104.227 - 200 686 0 - http - TCP_HIT - 672 245 0 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/standard.opf - 80 - 121.130.104.227 - 200 51323 0 - http - TCP_HIT - 673 50847 0 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/mimetype - 80 - 121.130.104.227 - 200 476 1 - http - TCP_HIT - 674 20 0 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/ - 80 - 121.130.104.227 - 500 497 5 - http - TCP_NEGATIVE_HIT - 675 78 0 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/navigation-documents.xhtml - 80 - 121.130.104.227 - 200 1069 5 - http - TCP_HIT - 676 615 0 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/image/ - 80 - 121.130.104.227 - 500 503 6 - http - TCP_NEGATIVE_HIT - 677 84 0 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/image/i-001.jpg/dims/resize/200 - 80 - 121.130.104.227 - 200 25954 6 - http - TCP_HIT - 679 25504 0 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/image/i-002.jpg/dims/resize/200 - 80 - 121.130.104.227 - 510 32969 6 - http - TCP_HIT - 680 32519 0 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/image/i-003.jpg/dims/resize/200 - 80 - 121.130.104.227 - 200 27085 6 - http - TCP_HIT - 681 26635 1 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c
... (생략) ...
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/style/fixed-layout-jp.css - 80 - 121.130.104.227 - 200 590 25 - http - TCP_HIT - 760 134 0 c - 454ecfb6-13d8-496d-b137-8b0d411caa21
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/xhtml/p-001.xhtml - 80 - 121.130.104.227 - 200 1133 24 - http - TCP_HIT - 762 679 0 c - 454ecfb6-13d8-496d-b137-8b0d411caa21
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/xhtml/p-002.xhtml - 80 - 121.130.104.227 - 510 1133 24 - http - TCP_HIT - 763 679 0 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/xhtml/p-003.xhtml - 80 - 121.130.104.227 - 200 1133 24 - http - TCP_HIT - 764 679 0 c - 454ecfb6-13d8-496d-b137-8b0d411caa21
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/xhtml/p-004.xhtml - 80 - 121.130.104.227 - 200 1133 24 - http - TCP_HIT - 765 679 0 c - 454ecfb6-13d8-496d-b137-8b0d411caa21
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/xhtml/p-005.xhtml - 80 - 121.130.104.227 - 200 1133 24 - http - TCP_HIT - 766 679 0 c - 454ecfb6-13d8-496d-b137-8b0d411caa21
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/xhtml/p-006.xhtml - 80 - 121.130.104.227 - 200 1133 24 - http - TCP_HIT - 767 679 0 c - 454ecfb6-13d8-496d-b137-8b0d411caa21
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/xhtml/p-007.xhtml - 80 - 121.130.104.227 - 200 1133 24 - http - TCP_HIT - 768 679 0 c - 454ecfb6-13d8-496d-b137-8b0d411caa21
... (생략) ...
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/META-INF/ - 80 - 121.130.104.227 - 500 501 4 - http - TCP_NEGATIVE_HIT - 842 82 0 c - 454ecfb6-13d8-496d-b137-8b0d411caa21
2022-07-12 05:56:31 10.10.10.10 GET /sample.epub/unzip/_archive_ - 80 - 121.130.104.227 - 206 131557 8 - http 0-131072 TCP_HIT - 883 131073 0 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c
2022-07-12 05:56:31 10.10.10.10 GET /sample.epub/unzip/_archive_ - 80 - 121.130.104.227 - 206 131557 8 - http 0-131072 TCP_HIT - 884 131073 0 c - 454ecfb6-13d8-496d-b137-8b0d411caa21
2022-07-12 05:56:31 10.10.10.10 GET /sample.epub/unzip/_archive_ - 80 - 121.130.104.227 - 206 131557 9 - http 0-131072 TCP_HIT - 885 131073 0 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c
2022-07-12 05:56:31 10.10.10.10 GET /sample.epub/unzip/_archive_ - 80 - 121.130.104.227 - 206 131557 9 - http 0-131072 TCP_HIT - 886 131073 0 c - 2205522a-e8e5-460b-9bb7-cfce368f9dde
2022-07-12 05:56:31 10.10.10.10 GET /sample.epub/unzip/_archive_ - 80 - 121.130.104.227 - 206 131557 8 - http 0-131072 TCP_HIT - 887 131073 0 c - 2205522a-e8e5-460b-9bb7-cfce368f9dde
2022-07-12 05:56:31 10.10.10.10 GET /sample.epub/unzip/_archive_ - 80 - 121.130.104.227 - 206 131557 8 - http 0-131072 TCP_HIT - 888 131073 0 c - b4420ecf-da49-4d20-87c3-cd5ed08f5381
... (생략) ...
2022-07-12 05:56:31 10.10.10.10 GET /sample.epub/unzip/files/item/xhtml/p-042.xhtml - 80 - 121.130.104.227 - 200 1133 354 - http - TCP_REFRESH_MISS - 803 679 352 c - b4420ecf-da49-4d20-87c3-cd5ed08f5381
2022-07-12 05:56:31 10.10.10.10 GET /sample.epub/unzip/files/item/xhtml/p-057.xhtml - 80 - 121.130.104.227 - 200 1133 352 - http - TCP_REFRESH_MISS - 818 679 350 c - b4420ecf-da49-4d20-87c3-cd5ed08f5381
2022-07-12 05:56:31 10.10.10.10 GET /sample.epub/unzip/files/item/xhtml/p-063.xhtml - 80 - 121.130.104.227 - 200 1133 351 - http - TCP_REFRESH_MISS - 824 679 349 c - b4420ecf-da49-4d20-87c3-cd5ed08f5381
... (생략) ...
2022-07-12 05:56:32 10.10.10.10 GET /sample.epub/epubedit/trim/10-20 - 80 - 121.130.104.227 node-fetch/1.0+(+https://github.com/bitinn/node-fetch) 200 1198595 8101 - http - TCP_REFRESH_MISS gzip+deflate 9 1198288 8016 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c

로그분석 원칙은 다음과 같다.

  1. 문제시간대를 특정한다.

  2. 클라이언트가 제일 먼저 호출한 내역이 가장 늦게 남는다. 위 로그 예제에서 클라이언 호출이 가장 마지막에 남았다.

    2022-07-12 05:56:32 10.10.10.10 GET /sample.epub/epubedit/trim/10-20 - 80 - 121.130.104.227 node-fetch/1.0+(+https://github.com/bitinn/node-fetch) 200 1198595 8101 - http - TCP_REFRESH_MISS gzip+deflate 9 1198288 8016 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c

  3. x-ctx-id 값이 15d50ea4-6d0a-408d-acbc-c31e4484956c 인 트랜잭션들 중 200, 206 이 아닌 응답코드를 찾는다. 이 것은 단위 함수가 비정상 상황을 응답했다는 의미이기에 단위 함수의 동작에 문제가 없는지 점검해야 한다. 위 로그 예제에서는 15d50ea4-6d0a-408d-acbc-c31e4484956c 중 페이지 002 를 추출할 수 없는 문제가 발생하였고 이를 로그에서 확인할 수 있다.

    2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/image/i-002.jpg/dims/resize/200 - 80 - 121.130.104.227 - 510 32969 6 - http - TCP_HIT - 680 32519 0 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c
... (생략) ...
2022-07-12 05:56:30 10.10.10.10 GET /sample.epub/unzip/files/item/xhtml/p-002.xhtml - 80 - 121.130.104.227 - 510 1133 24 - http - TCP_HIT - 763 679 0 c - 15d50ea4-6d0a-408d-acbc-c31e4484956c

    i-002.jpg 와 p-002.xhtml 을 추출할 때 단위 함수가 510 Not Extended 로 응답했음을 알 수 있다.

origin.log 분석

access.log 분석 을 통해 함수의 응답코드가 기록되었다면, 함수 호출자(caller) 트랜잭션 로그는 origin.log 에 기록된다.

Note

access.log 는 엔드유저를 기준으로 기록되어 W3C 로그표준을 최대한 유지한다. 따라서 단위 함수의 오류 메시지는 다소 확장성이 용이한 origin.log 에 기록된다.

access.log 를 통해 좁혀진 문제시점에 비정상 응답을 주었는지 확인한다.

#Fields: date time cs-sid cs-tcount c-ip cs-method s-domain cs-uri s-ip sc-status cs-range sc-sock-error sc-http-error sc-content-length cs-requestsize sc-responsesize sc-bytes time-taken time-dns time-connect time-firstbyte time-complete cs-reqinfo cs-acceptencoding sc-cachecontrol s-port sc-contentencoding session-id session-type x-sc-chain-error time-sock-creation x-cs-retry x-cs-extra-field time-request x-response-info x-ctx-id
2022-07-12 05:56:25 38 1 127.0.0.1 GET 127.0.0.1 /sample.epub/unzip/files/item/image/i-001.jpg 127.0.0.1 200 - - - 26386 463 441 26386 2792 0 30 2792 0 http - - 80 - 398 cache,unzip - 0 n - 05:56:22.737 - 454ecfb6-13d8-496d-b137-8b0d411caa21
2022-07-12 05:56:25 38 1 127.0.0.1 GET 127.0.0.1 /sample.epub/unzip/files/item/image/i-001.jpg 127.0.0.1 200 - - - 26386 463 441 26386 2792 0 30 2792 0 http - - 80 - 398 cache,unzip - 0 n - 05:56:22.737 - 15d50ea4-6d0a-408d-acbc-c31e4484956c
2022-07-12 05:56:25 41 1 127.0.0.1 GET 127.0.0.1 /sample.epub/unzip/files/item/image/i-002.jpg 127.0.0.1 510 - - - 18872 463 441 18872 2780 0 17 2779 1 http - - 80 - 401 cache,unzip - 0 n - 05:56:22.750 noexist 15d50ea4-6d0a-408d-acbc-c31e4484956c
2022-07-12 05:56:25 43 1 127.0.0.1 GET 127.0.0.1 /sample.epub/unzip/files/item/image/i-032.jpg 127.0.0.1 200 - - - 29723 463 441 29723 2779 0 16 2779 0 http - - 80 - 403 cache,unzip - 1 n - 05:56:22.751 - 454ecfb6-13d8-496d-b137-8b0d411caa21
2022-07-12 05:56:25 41 1 127.0.0.1 GET 127.0.0.1 /sample.epub/unzip/files/item/image/i-002.jpg 127.0.0.1 510 - - - 18872 463 441 18872 2780 0 17 2779 1 http - - 80 - 401 cache,unzip - 0 n - 05:56:22.750 noexist 454ecfb6-13d8-496d-b137-8b0d411caa21

위 로그를 통해 15d50ea4-6d0a-408d-acbc-c31e4484956c 처리 과정을 알 수 있다.

  • /sample.epub 파일로부터 /unzip/files/item/image/i-002.jpg 파일 추출을 시도했다.

  • i-002.jpg 파일 추출에 대해 unzip 함수는 510 응답을 주었다.

  • cs-reqinfo 필드의 값인 cache,unzip 을 통해 unzip 함수를 호출했다.

  • 510 응답을 준 이유는( x-sc-chain-error 필드) noexist 이다.

  • 454ecfb6-13d8-496d-b137-8b0d411caa21 트랜잭션도 분석이 필요하다.

Note

aws_s3 처럼 독립적인 트랜잭션(우리는 subflow 라고 부릅니다.)을 가지는 경우는 origin.log 에 기록된다. cs-reqinfo 필드를 통해 호출 주체를 알 수 있으며, 동일한 x-ctx-id 를 가진다.

x-ctx-id 확장

x-ctx-id 는 앞서 설명한 바와 같이 클라이언트 HTTP 트랜잭션과 함수체인사이에 전달되며 로그분석에 일관성을 부여한다. x-ctx-id 는 체인함수 확장헤더 중 X-M2X-Forwarded-Context-Id 헤더의 값으로 전달되며, 비표준 헤더이기 때문에 원본서버 요청시에는 전달되지 않는다.

../../_images/anlyzlog7.png

위 그림처럼 원본서버까지 도달한 요청에 대해 일관된 키가 부여되지 않는다면 이를 상호연결하는 것은 매우 어렵다. 이런 경우 forwardContextId 설정을 활성화하여 x-ctx-id 를 전달하면 일관성을 부여할 수 있다.

# functions.network.http.backEnd.headers

"forwardContextId": {
  "enable": true,
  "header": "X-M2X-Forwarded-Context-Id"
}

위와 같이 설정하면 다음 그림처럼 동일한 ID를 공유할 수 있다.

../../_images/anlyzlog8.png

각 주체별 동작은 다음과 같다.

  • M2 (Child) - 클라이언트 요청의 고유한 x-ctx-id 를 생성한다.

  • M2 (Parent) - 전달받은 X-M2X-Forwarded-Context-Id 헤더의 값을 x-ctx-id 로 사용한다.

  • Origin - 웹서버에서 X-M2X-Forwarded-Context-Id 헤더를 access.log에 기록한다.

위와 같은 구성과 실시간 로그 분석 서비스 구축 가이드 를 활용하면 분산환경에서의 통합 트랜잭션 모니터링을 손쉽게 구성할 수 있다.

Note

고객사 인증서버처럼 커스터마이징을 통해 연동되는 서버의 경우 forwardContextId 설정이 적용되지 않는다. x-ctx-id 를 포워딩하고 싶다면 Hooking 함수제작시 개발요건이 전달되어야 한다.