log

/usr/local/m2/setting.json 다음 영역에 대해 기술한다.

{
  "functions": {
    "operations": {
      "log": {
        ...
      }
    }
  }
}

모든 로그는 기록여부를 설정할 수 있으며, 공통속성을 가진다.

Note

전역로그는 log 를 참고한다.

 "xxx" : {
   "enable": true,
   "rolling": {
     "time": 1440,
     "size": 100,
   },
   "retention": 10,
   "compression": false,
   "backup": []
}
rolling

로그 롤링조건을 설정한다. 아래 두 값을 모두 설정하면 두 조건 중 하나라도 만족할 경우 롤링한다.

  • time (단위: Minute) 설정된 시간마다 로그 파일을 롤링한다.

  • size (단위: MB) 설정된 용량마다 로그 파일을 롤링한다.

retention (기본: 10개)

단위 로그파일을 최대 n개 유지한다.

compression (기본: false)

로그가 롤링될 때 압축을 진행한다. 예를 들어 access_20140715_0000.log 파일이 롤링되면 access_20140715_0000.log.gz 로 압축되어 저장된다.

backup (기본: [])

실시간 로그백업 repository ( 로그백업 활성화 참조 )

rolling.time 의 값이 10 이라면 로그는 매 10분에 롤링된다. 예를 들어 서비스를 2:18분에 시작해도 로그는 매 10분인 2:20, 2:30, 2:40에 롤링된다. 마찬가지로 하루에 한번 매일 0시 0분에 롤링하려면 1440(60분 X 24시)으로 rolling.time 값을 설정한다. rolling.time 설정에서 로그는 하루에 한번 무조건 롤링되므로 rolling.time 의 최대값은 1440을 넘을 수 없다.

../../../../_images/log_rolling1.jpg

최대 값인 24시간 ( rolling.time: 1440 )마다 로그가 롤링되도록 설정했다면 다음 그림과 같이 로그가 기록된다.

../../../../_images/log_rolling2.jpg

meta

"meta" : {
  "dir" : "/m2log"
}
dir (기본: /m2log)

해당 디렉토리 하위에 가상호스트 디렉토리를 생성 후 로그를 기록한다. 예를 들어 www.exmaple.com 가상호스트 로그는 아래 경로에 기록된다.

/m2log/www.exmaple.com

access.log

"access" : {
  "enable": true,
  "rolling": {
    "time": 1440
  },
  "retention": 10,
  "compression": false,
  "backup": [],
  "xff": "all",
  "form": "m2",
  "format": null,
  "loopback": false
}
xff (기본: all)

X-Forwarded-For 필드

  • all - 클라이언트가 보낸 XFF(X-Forwarded-For)헤더 값과 클라이언트 IP를 같이 기록한다.

  • clientIp - 클라이언트 IP를 기록한다.

  • trimClientIp - XFF헤더가 없을 경우 클라이언트 IP를, 있는 경우 (클라이언트 IP를 제외한) XFF헤더만을 기록한다.

form (기본: m2)

  • m2 - W3C표준 + 확장필드

  • apache - Apache 형식

  • iis - IIS 형식

  • custom 커스텀 로그

format

사용자정의 로그포맷. 사용자 정의 access.log 참조

loopback (기본: false)

loopback 통신 기록여부

로그필드는 다음과 같다.

#Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-username c-ip cs(User-Agent) sc-status sc-bytes time-taken cs-referer sc-resinfo cs-range sc-cachehit cs-acceptencoding session-id sc-content-length time-response x-transaction-status x-fallback x-ctx-id
2012.06.27 16:52:24 220.134.10.5 GET /web/h.gif - 80 - 61.50.7.9 Chrome/19.0.1084.56 200 98141 5 - Bypass+gzip+SSL3 - TCP_HIT gzip+deflate 7 1273735 10 c - 5d82b102-cfed-4e2c-90bd-985778b63067
2012.06.27 16:52:26 220.134.10.5 GET /favicon.ico - 80 - 61.50.7.9 Chrome/19.0.1084.56 200 949 2 - - - TCP_HIT gzip+deflate 35 14875 11 c - 2b1025d8-cfed-4e2c-90bd-b63067985778
2012.06.27 17:00:06 220.168.0.13 GET /setup.Eexe - 80 - 61.168.0.102  Mozilla/5.0+(Windows+NT+6.1;+WOW64)+AppleWebKit/536.11+(KHTML,+like+Gecko)+Chrome/20.0.1132.57+Safari/536.11 206 20971800 7008 - - 398458880-419430399 TCP_HIT - 41 89764358 7 c - 1025d82b-edcf-c4e2-d90b-778b63067985

모든 필드는 공백으로 구분되며 각 필드의 의미는 다음과 같다.

  • date HTTP 트랜잭션이 완료된 날짜

  • time HTTP 트랜잭션이 완료된 시간

  • s-ip 서버 IP

  • cs-method 클라이언트가 보낸 HTTP Method

  • cs-uri-stem 클라이언트가 보낸 URL중 QueryString을 제외한 부분

  • cs-uri-query 클라이언트가 보낸 URL중 QueryString

  • s-port 서버 포트

  • cs-username 클라이언트 username

  • c-ip 클라이언트 IP. XFF설정이 “ON”이라면 X-Forwarded-For헤더 값과 클라이언트 IP를 기록한다.

  • cs(User-Agent) 클라이언트가 보낸 HTTP User-Agent

  • sc-status 서버 응답코드

  • sc-bytes 서버가 보낸 Bytes (헤더 + 컨텐츠)

  • time-taken HTTP트랜잭션이 완료될 때까지 소요된 전체시간(밀리세컨드)

  • cs-referer 클라이언트가 보낸 HTTP Referer

  • sc-resinfo 부가 정보. “+”문자로 구분된다. 압축된 컨텐츠를 서비스했다면 압축옵션(gzip 또는 deflate)이 명시된다. 보안통신이라면 SSL 프로토콜 버전(SSL3, TLS1, TLS1.1, TLS1.2)이 명시된다. 바이패스한 통신이라면 “Bypass”가 명시된다.

  • cs-range 클라이언트가 보낸 Range 헤더를 기록한다.

  • sc-cachehit 캐시 HIT결과

  • cs-acceptencoding 클라이언트가 보낸 Accept-Encoding헤더

  • session-id HTTP 클라이언트 세션 ID (unsigned int64)

  • sc-content-length 서버 응답 Content-Length 헤더 값

  • time-response 응답속도 (밀레세컨드)

  • x-transaction-status HTTP 트랜잭션이 완료 상태 ( c = 완료, x = 중단 )

  • x-fallback fallbacks 처리된 가상호스트 이름

  • x-ctx-id M2 요청(체인함수)의 UUID

Access로그는 전송 성공/실패 여부에 상관없이 모든 HTTP 트랜잭션을 기록한다. HTTP 트랜잭션은 클라이언트가 HTTP요청을 보낼 때 시작된다. M2가 클라이언트에게 응답을 보내기 전에 HTTP연결이 종료된다면 HTTP 트랜잭션 역시 종료된 것으로 간주한다. 로그에는 sc-statussc-bytes 가 0으로 기록된다. 주로 M2가 원본서버로부터 응답을 받기 전에 클라이언트가 연결을 종료하는 경우 이런 로그가 기록된다.

Note

Type이 size 인 경우 파일명에 초 단위까지 명시한다. 이는 설정된 size 까지 1분 안에 도달할 경우 로그가 유실될 우려가 있기 때문이다.

사용자 정의 access.log

access.log 로그형식을 사용자정의 로그로 설정한다.

"access" : {
  "form": "custom",
  "format": "%a %A %b id=%{userid}C %f %h %H \"%{user-agent}i\" %m %P \"%r\" %s %t %T %X %I %O %R %e %S %K"
}
  • form 속성을 custom 으로 설정한다.

  • formate 사용자정의 로그 형식.

    Warning

    JSON 특수문자 처리에 주의한다.

위 예제의 경우 다음과 같이 Access로그가 기록된다. (#Fields는 기록하지 않는다.)

192.168.0.88 192.168.0.12 163276 id=winesoft; image.jpg example.com HTTP "M2" GET 80 "GET /m2/image.jpg?type=png HTTP/1.1" 200 2014-04-03 21:21:54 1 C 204 163276 1 2571978 TCP_MISS HTTP/1.1
192.168.0.88 192.168.0.12 63276 id=winesoft; vod.mp4 example.com HTTP "M2" POST 80 "GET /m2/vod.mp4?start=10 HTTP/1.1" 200 2014-04-03 21:21:54 12 C 304 363276 2 2571979 TCP_REFRESH_HIT HTTP/1.1
192.168.0.88 192.168.0.12 3634276 id=m2; news.html example.com HTTPS "M2" GET 443 "GET /news.html HTTP/1.1" 200 2014-04-03 21:21:54 30 X 156 2632576 1 2571980 TCP_MISS HTTP/1.1
192.168.0.88 192.168.0.12 6332476 id=winesoft; style.css example.com HTTP "M2" HEAD 80 "GET /style.css HTTP/1.1" 200 2014-04-03 21:21:54 10 X 234 653276 2 2571981 TCP_REFRESH_HIT HTTP/1.1
192.168.0.88 192.168.0.12 6276 id=m2; ui.js example.com HTTP "M2" GET 80 "GET /ui.js HTTP/1.1" 200 2014-04-03 21:21:54 1 X 233 63276 1 2571982 TCP_MISS HTTP/1.1
192.168.0.88 192.168.0.12 626 id=winesoft; hls.m4u8 example.com HTTP "M2" GET 80 "GET /hls.m4u8 HTTP/1.1" 200 2014-04-03 21:21:54 2 X 124 6312333276 2 2571983 TCP_REFRESH_HIT HTTP/1.1

Apache로그 형식 을 기반으로 개발되었으며 일부 확장필드가 있다. 각 필드의 구분자에는 제한이 없지만 Space를 사용할 경우, User-Agent처럼 Space가 포함될 수 있는 필드는 따옴표(”…”)로 묶어서 설정한다.

형식문자열

예제

설명

%...a

192.168.0.66

클라이언트 IP

%...A

192.168.0.14

서버IP 주소

%...b

84646

HTTP헤더를 제외한 서버가 전송한 양 ( bytes )

%...B

28215

전송 대역폭( bytes ) = HTTP헤더를 제외한 전송 바이트수 / 소요시간

%...c

84173

응답 Content-Length 헤더 값

%...{Foo}C

a=b; c=d;

서버가 수신한 요청의 Foo 쿠키의 내용 %{id=}c 로 입력하면 Cookie 헤더 에서 id 에 해당하는 값을 기록

%...D

12

요청을 처리하는데 걸린 시간 ( 밀리세컨드 )

%...e

1

M2가 부여한 세션ID

%...E

5d82b102-cfed-4e2c-90bd-985778b63067

x-ctx-id - M2함수체인 트랜잭션 UUID

Important

로그분석을 위해서 이 필드는 반드시 포함시킬 것을 권장한다. ( x-ctx-id 기반의 로그 분석 가이드 참조)

%...f

sample.mp4

요청 URL이 /video/sample.mp4 라면 sample.mp4를 기록

%...g

19/Jul/2012:17:58:58 +0900

Apache 시간 형식

%...G

(문자열)

%...{Foo}i 와 같지만 공백을 + 로 치환.

%...h

example.com

Host 헤더의 값

%...H

http

요청 프로토콜 = http , https , http2

%...{Foo}i

(문자열)

서버가 수신한 요청에서 Foo 헤더의 내용 %{User-Agent}i 로 입력 할 경우 User-Agent 헤더의 값을 기록

%...I

87489

요청헤더를 포함한 수신바이트 ( bytes )

%...j

200-1000

클라이언트 요청 Range 헤더

%...k

gzip+deflate

클라이언트 요청 Accespt-Encoding 헤더

%...K

HTTP/1.1

요청 HTTP 버전

%...{Foo}l

(문자열)

서버가 송신한 응답의 Foo 헤더의 내용

%{Server}l 로 입력 할 경우 응답헤더 중 Server 값을 기록

%...L

a.com+b.com+c.com

fallbacks 처리된 가상호스트 이름

%...m

GET

요청 HTTP 메소드 = GET , POST , HEAD , OPTIONS

%...n

-

미사용 옵션값을 그대로 기록한다.

%...o

(문자열)

%...{Foo}l 와 동일하나 공백을 + 로 치환하지 않음

%...O

4993377

응답헤더를 포함한 송신바이트

%...P

80

서버 포트

%...q

Id=10&value=20

쿼리스트링

%...{Id}Q

Id=10

쿼리스트링 키의 값

%...r

GET /img.jpg HTTP/1.1

HTTP 요청패킷의 첫번째 줄

%...R

2

응답시간 ( 밀리세컨드 )

%...s

200

응답코드

%...S

TCP_HIT

캐싱엔진 HIT 결과

%...t

2014-01-01 15:27:02

M2 기본 시간형식

%...{format}t

2014-08-07 06:12:23

Format에 정의된 날짜 형식 %{%Y-%m-%d %H:%M:%S}T 로 입력하면 2014-08-07 06:12:23 으로 기록.

%...T

10

소요시간 ( )

%...u

/img/img.jpg?a=b

요청 URL 전체

%...U

/img/img.jpg

쿼리스트링을 제외한 URL

%...x

c

%...X 와 동일하나 소문자

%...X

C

트랜잭션이 완료되었을 때의 상태 - X 응답이 완료되기 전에 종료 - C 응답이 완료 되었음

%...y

488

요청 HTTP 헤더 크기

%...z

362

응답 HTTP 헤더 크기

설정한 필드의 값이 존재하지 않으면 - 로 표기한다. 형식이 잘못되었다면 M2 기본 포맷 "form": "M2" 으로 동작한다.

위 표에서 각 필드의 …에는 (e.g. “%h %U %r %b) 아무것도 명시하지 않거나, 기록 조건을 명시할 수 있다(조건을 만족하지 않으면 - 로 기록). 조건은 HTTP 상태코드 목록으로 설정하거나 !로 NOT 조건을 설정할 수 있다.

다음 예제는 400 Bad Request 오류 또는 501 Not Implemented 오류 일 때만 User-agent 헤더를 기록한다.

"%400,501{User-agent}i"

다음 예제는 정상적인 상태가 아닌 모든 요청에 대해 Referer 헤더를 로그에 남긴다.

"%!200,304,302{Referer}i"

origin.log

"origin" : {
  "enable": true,
  "rolling": {
    "time": 1440
  },
  "retention": 10,
  "compression": false,
  "backup": [],
  "loopback": true
}
loopback (기본: false)

loopback 통신 기록여부

로그필드는 다음과 같다.

#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 x-sc-chain-info time-sock-creation x-cs-retry x-cs-extra-field time-request x-ctx-id
2012.06.27 17:40:00 357 899 192.168.0.13 GET i.example.com /t/2.gif 115.71.9.136 200 - - - 3874 197 271 3874 20 0 0 17 3 - gzip+deflate - 80 gzip 7 cache
2012.06.27 17:40:00 357 900 192.168.0.13 GET i.example.com /ex1.gif 115.71.9.136 200 - - - 5673 223 272 5673 24 0 0 21 3 - - - 80 - 8 cache
2012.06.27 17:40:00 357 901 192.168.0.13 GET i.example.com /exB.jpg 115.71.9.136 200 - - - 8150 189 273 8150 13 0 0 9  4 Bypass - - 80 - 7 cache
#[ERROR:01] 2012.06.27 17:40:01 220.73.216.5 220.73.216.5 GET /web/nmb/img/main/v1/h1.gif 1824 Connect-Timeout - 11 cache
2012.06.27 17:40:00 357 901 192.168.0.13 GET i.example.com /exB1.jpg 115.71.9.136 200 - - - 8150 189 273 8150 13 0 0 9 4 - max-age=3600 80 - 12 cache
2012.06.27 17:40:00 357 901 192.168.0.13 GET i.example.com /exB2.jpg 115.71.9.136 200 - - - 8150 189 273 8150 13 0 0 9 4 - no-cache 80 - 35 cache
2012.06.27 17:40:00 357 901 192.168.0.13 GET i.example.com /exB3.jpg 115.71.9.136 200 - - - 8150 189 273 8150 13 0 0 9 4 - - 80 - 35 cache

원본서버에 장애가 발생했다면 #[ERROR:xx]로 시작하는 에러 로그가 기록된다. 모든 필드는 공백으로 구분되며 각 필드의 의미는 다음과 같다.

../../../../_images/time_taken.jpg

원본 시간측정 구간

  • date HTTP 트랜잭션이 완료된 날짜

  • time HTTP 트랜잭션이 완료된 시간

  • cs-sid 세션의 고유ID. 같은 세션을 통해 처리된(재사용된) HTTP 트랜잭션은 같은 값을 가진다.

  • cs-tcount 트랜잭션 카운트. 이 HTTP 트랜잭션이 현재 세션에서 몇 번째로 처리된 트랜잭션인지 기록한다. 같은 cs-sid 값을 가지는 트랜잭션이라면 이 값은 중복될 수 없다.

  • c-ip M2의 IP

  • cs-method 원본서버에게 보낸 HTTP Method

  • s-domain 원본서버 도메인

  • cs-uri 원본서버에게 보낸 URI

  • s-ip 원본서버 IP

  • sc-status 원본서버 HTTP 응답코드

  • cs-range 원본서버에게 보낸 Range요청 값

  • sc-sock-error 소켓 에러코드

    • Connect-Timeout 연결 시간초과

    • Receive-Timeout 수신대기 시간 초과

    • Server-Close 원본에서의 연결종료

    • Client-Close M2에서의 연결종료 (바이패스 중 클라이언트가 먼저 연결을 종료하는 경우)

    • Non-Existent-Domain 연결할 Domain이 존재하지 않음

  • sc-http-error 원본서버가 4xx 또는 5xx응답을 줬을 때 응답코드를 기록

  • sc-content-length 원본서버가 보낸 Content Length

  • cs-requestsize (단위: Bytes) 원본서버로 보낸 HTTP 요청 헤더 크기

  • sc-responsesize (단위: Bytes) 원본서버가 응답한 HTTP 헤더 크기

  • sc-bytes (단위: Bytes) 수신한 컨텐츠 크기(헤더 제외)

  • time-taken (단위: ms) HTTP 트랜잭션이 완료될 때까지 소요된 전체시간. 세션 재사용이 아니라면 소켓 접속시간까지 포함한다.

  • time-dns (단위: ms) DNS쿼리에 소요된 시간

  • time-connect (단위: ms) 원본서버와 소켓 Established까지 소요된 시간

  • time-firstbyte (단위: ms) 요청을 보내고 응답이 올때까지 소요된 시간

  • time-complete (단위: ms) 첫 응답부터 완료될 때까지 소요된 시간

  • cs-reqinfo 부가 정보. “+”문자로 구분한다. 바이패스한 통신이라면 Bypass , Instant 바이패스라면 Bypass/instant 로 기록된다.

  • cs-acceptencoding 원본서버에 압축된 컨텐츠를 요청하면 “gzip+deflate”로 기록된다.

  • sc-cachecontrol 원본서버가 보낸 cache-control헤더

  • s-port 원본서버 포트

  • sc-contentencoding 원본서버가 보낸 Content-Encoding헤더

  • session-id 원본서버 요청을 발생시킨 HTTP 클라이언트 세션 ID (unsigned int64)

  • session-type 원본서버에 요청한 세션 타입

    • cache 캐싱용도로 사용된 세션

    • recovery recovery 에서 복구용도로 사용된 세션

    • healthcheck health-checkers 가 사용한 세션

  • x-sc-chain-error 체인함수 에러

  • x-sc-chain-info 체인함수 정보메시지

  • time-sock-creation (단위: ms) - 소켓 생성 소요시간

  • x-cs-retry - 해당 세션 Retry 상태 (Retry 시 y , Retry 하지 않았다면 n )

  • x-cs-extra-field -

  • time-request 원본서버 요청시간. 시간:분:초.밀리세컨드 (hh:mm:ss.SSS) 양식

  • x-ctx-id 클라이언트 요청 트랜잭션 UUID

Note

정상적인 서비스 상태라면 time-connect 필드의 값이 sessionconnectTimeout (기본: 3초) 보다 클 수 없다. 하지만 비정상적인 네트워크 상태에서 소켓 유실과 재시도 시나리오로 인해 time-connect 가 11초, time-complete 이 21초로 기록되는 상황이 발생할 수 있다.

  • (1st) 첫 번째 트랜잭션이 완료되고 해당 세션은 재사용 풀에 들어간다.

  • 네트워크 또는 원본서버 문제가 발생한다.

  • 네트워크 문제를 스위치 또는 TCP/IP 커널이 감지하지 못한다.

  • (2nd) 두 번째 트랜잭션이 시도 되며 (1st) 세션을 재사용한다.

  • (2nd) HTTP 클라이언트는 이미 연결된 상태로 판단, 요청 헤더를 세션으로 보낸다. 하지만 네트워크 문제로 패킷이 전달되지 못한다.

  • (2nd) HTTP 클라이언트는 응답이 오지 않아 receiveTimeout (기본: 10초) 으로 판단한다. 이미 10초가 경과되었다.

  • (2nd) HTTP 클라이언트는 트랜잭션이 성립되지 않은 것으로 판단, 현재 세션을 폐기하고 신규 소켓으로 연결을 시도한다.

  • (2nd) HTTP 클라이언트는 1초만에 새로운 연결을 획득한다. 하지만 앞서 10초 기다린 시간과 이 1초를 더해 11초의 time-connect 를 기록한다. time-connect 는 최초 시점부터 “connected” 시점까지를 기록한다.

  • (2nd) HTTP 클라이언트는 다시 요청 헤더를 보내지만 서버는 답이 없다.

  • (2nd) HTTP 클라이언트는 응답이 오지 않아 receiveTimeout (기본: 10초) 으로 판단한다. 신규 소켓이 사용되었기에 트랜잭션 실패로 판단한다.

  • (2nd) HTTP 클라이언트는 트랜잭션을 기록한다.

    • time-connect 11초

    • time-complete 21초

    • x-cs-retry y

dns.log

원본서버 주소가 Domain으로 설정되었다면 Resolving결과를 기록한다.

"dns" : {
  "enable": true,
  "rolling": {
    "size": 10
  },
  "retention": 10,
  "compression": false,
  "backup": []
}

로그필드는 다음과 같다.

#Fields: date time domain ttl ip-list ip-count time-taken result
2014-07-30 12:10:33 example.com 157 173.194.127.15,173.194.127.23,173.194.127.24,173.194.127.31 4 5007 success
2014-07-30 12:10:38 example.com 152 173.194.127.23,173.194.127.24,173.194.127.31,173.194.127.15 4 9 success
2014-07-30 12:11:03 example.com 127 173.194.127.31,173.194.127.15,173.194.127.23,173.194.127.24 4 15007 success
2014-07-30 12:12:53 example.com 17 173.194.127.15,173.194.127.23,173.194.127.24,173.194.127.31 4 6 success
2014-07-30 12:23:16 test.com 0 - 0 10008 fail
2014-07-30 12:23:21 test.com 0 - 0 5007 fail
2014-07-30 12:23:26 test.com 0 - 0 5011 fail
2014-07-30 12:24:38 example.com 152 173.194.127.23,173.194.127.24,173.194.127.31,173.194.127.15 4 9 success
2014-07-30 12:25:03 example.com 127 173.194.127.31,173.194.127.15,173.194.127.23,173.194.127.24 4 15007 success

모든 필드는 공백으로 구분되며 각 필드의 의미는 다음과 같다.

  • date 날짜

  • time 시간

  • domain 대상 Domain

  • ttl 레코드 유효시간(Time To Live)

  • ip-list IP 리스트

  • ip-count IP 개수

  • time-taken 수행시간

  • result success 또는 fail

monitoring.log

5분 평균 통계를 기록한다.

"monitoring": {
  "enable": false,
  "rolling": {
    "time": 60
  },
  "retention": 10,
  "compression": false,
  "backup": [],
  "form": "json"
}
form

로그형태 json 또는 xml