NGINX JavaScript 모듈을 활용한 진단 로깅

Liam Crilly제품 관리 부문 수석 이사

오류 로그를 조정하지 않고 프로덕션 환경에서 문제 해결하기

편집자 – 이 블로그는 로깅과 NGINX 및 NGINX Plus를 다루는 여러 블로그 중 하나입니다. 다음 글도 참조하세요:

• NGINX 및 NGINX Plus를 사용한 애플리케이션 추적
• NGINX 조건부 로깅을 사용한 요청 샘플링

이 글은 NGINX JavaScript 모듈의 사용 사례를 다루는 여러 블로그 글 중 하나이기도 합니다. 전체 목록은 NGINX JavaScript 모듈 사용 사례에서 확인하세요.

NGINX는 모든 규모의 조직이 미션 크리티컬 웹사이트, 애플리케이션 및 API를 운영할 수 있도록 지원합니다. 규모나 배포 인프라 선택과 관계없이 프로덕션 환경을 운영하는 일은 쉽지 않습니다. 이 글에서는 프로덕션 배포 시 겪는 여러 어려움 중 하나인 로깅에 대해 살펴봅니다. 구체적으로는 불필요한 데이터에 파묻히지 않으면서 문제 해결에 필요한 만큼 상세한 로그를 수집하는 균형 잡기에 대해 설명합니다.

로깅 기초

NGINX는 서로 다른 두 가지 로깅 메커니즘을 제공합니다. 하나는 클라이언트 요청을 위한 액세스 로깅이고, 다른 하나는 문제가 발생했을 때 사용하는 오류 로깅입니다. 이러한 메커니즘은 HTTP 모듈과 Stream(TCP/UDP) 모듈 모두에서 사용할 수 있지만, 여기서는 HTTP 트래픽에 중점을 둡니다. (디버그 심각도 수준을 사용하는 세 번째 로깅 메커니즘도 있지만, 여기서는 다루지 않습니다.)

일반적인 기본 NGINX 로깅 구성은 다음과 같습니다.

http {    
                      log_format  main  
                      '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for"';
 
    access_log /var/log/nginx/access.log main; # Log using the 'main' format
    error_log  /var/log/nginx/error.log  warn; # Log up to 'warn' severity level
    ...
}

The log_format 지시문은 구성에 access_log 지시문이 포함된 경우 생성되는 로그 항목의 내용과 구조를 정의합니다. 위 예시는 여러 웹 서버에서 사용하는 Common Log Format(CLF)을 확장한 것입니다. error_log 지시문에서는 기록할 메시지의 심각도 수준을 지정하지만, 고정되어 있는 항목의 내용이나 형식은 지정하지 않습니다. 이에 대해서는 다음 섹션에서 자세히 설명합니다.

NGINX 로깅에서 주목할 만한 다른 측면은 다음과 같습니다:

• 로깅 지시문은 하위 수준의 구성 컨텍스트에 자동으로 상속됩니다. 예를 들어, access_log 지시문을 http 컨텍스트에 지정하면 모든 server{} 블록에 적용됩니다.
• 하위 컨텍스트의 로깅 지시문은 상속된 지시문을 재정의합니다.
• 동일한 컨텍스트에 여러 로깅 지시어가 있을 수 있습니다. 예를 들어, 두 개의 access_log 지시어를 사용하여 표준 CLF 로그 파일과 더 상세한 두 번째 로그를 모두 생성할 수 있습니다.

프로덕션 환경에서의 로깅 현실

일반적으로 액세스 로그는 분석 및 사용 통계를 제공하는 데 사용하고, 오류 로그는 장애 감지 및 문제 해결에 사용합니다. 하지만 프로덕션 시스템을 운영하는 일은 그렇게 간단한 경우가 드뭅니다. 다음은 흔히 겪는 몇 가지 과제입니다:

• 액세스 로그에는 문제 해결에 필요한 세부 정보가 충분하지 않습니다
• 오류 로그는 info 심각도 수준에서 충분히 상세한 정보를 제공하지만, 일반적인 운영 환경에서는 지나치게 상세합니다.
• 오류 로그 형식은 고정되어 있으므로 특별히 관심 있는 변수를 포함하도록 사용자 지정할 수 없습니다.
• 오류 로그 항목에는 요청의 컨텍스트가 포함되지 않아 해당 액세스 로그 항목과 연결하기 어렵습니다.

또한 프로덕션 환경에서 로깅 세부 정보를 추가하거나 제거하기 위해 NGINX 구성을 변경하려면 변경 관리 절차를 거쳐 구성을 다시 배포해야 할 수도 있습니다. 전적으로 안전한 방법이지만, “왜 4xx/5xx 오류가 급증하는가?”와 같은 실시간 문제를 해결할 때는 다소 번거롭습니다. 물론 클러스터 전반에서 여러 NGINX 인스턴스가 동일한 트래픽을 처리하는 경우에는 이러한 어려움이 더욱 커집니다.

오류용 보조 액세스 로그 사용

각 요청에서 수집되는 데이터를 보강하기 위해 액세스 로그 형식을 사용자 지정하는 것은 고급 분석에 흔히 사용되는 접근 방식이지만, 진단이나 문제 해결 용도로 확장하기에는 적합하지 않습니다. 기본 액세스 로그에 두 가지 역할을 맡기는 것은 억지스러운 해결책입니다. 일반적인 분석보다 문제 해결에 훨씬 더 많은 정보가 필요하기 때문입니다. 기본 액세스 로그에 수많은 변수를 추가하면 가끔만 유용한 데이터로 인해 로그 용량이 급격히 증가할 수 있습니다.

대신 두 번째 액세스 로그를 사용하여 디버깅이 필요한 오류가 발생한 경우에만 기록할 수 있습니다. access_log 지시문은 if 매개변수를 사용한 조건부 로깅을 지원합니다. 지정된 변수의 값이 0이 아니고 비어 있지 않은 경우에만 요청이 기록됩니다.

map $status $is_error {    
    400     1; # Bad request, including expired client cert
    495     1; # Client cert error
    502     1; # Bad gateway (no upstream server could be selected)
    504     1; # Gateway timeout (couldn't connect to selected upstream)
    default 0;
}

access_log /var/log/nginx/access_debug.log access_debug if=$is_error; # Diagnostic logging
access_log /var/log/nginx/access.log main;

이 구성을 사용하면 $status 변수를 map 블록에 전달하여 $is_error 변수의 값을 결정한 다음, access_log 지시문의 if 매개변수로 해당 값을 평가합니다. $is_error의 값이 1로 평가되면 access_debug.log 파일에 특수 로그 항목을 기록합니다.

하지만 이 구성은 요청 처리 도중에 발생했지만 최종적으로 해결되어 상태가 200 OK가 되는 오류를 감지하지 못합니다. NGINX가 여러 업스트림 서버 간에 부하를 분산하는 경우가 그 예입니다. 선택된 서버에서 오류가 발생하면 NGINX는 proxy_next_upstream 지시문에 구성된 조건에 따라 요청을 다음 서버로 전달합니다. 업스트림 서버 중 하나라도 성공적으로 응답하면 클라이언트는 성공 응답을 받고, 이 응답은 상태 200으로 기록됩니다. 하지만 재시도로 인해 사용자 경험이 저하될 가능성이 높으며, 업스트림 서버가 비정상 상태라는 사실을 즉시 알아차리기 어려울 수 있습니다. 어쨌든 로그에는 200으로 기록되었으니까요.

NGINX가 여러 업스트림 서버로 프록시를 시도하면 해당 서버의 주소가 모두 $upstream_addr 변수에 기록됩니다. 다른 $upstream_* 변수도 마찬가지입니다. 예를 들어 $upstream_status 변수에는 연결을 시도한 각 서버의 응답 코드가 기록됩니다. 따라서 이러한 변수에 여러 항목이 표시되면 문제가 발생했다는 뜻이며, 업스트림 서버 중 하나 이상에 문제가 있을 가능성이 높습니다.

요청이 여러 업스트림 서버로 프록시된 경우에도 access_debug.log에 기록하도록 해보면 어떨까요?

map $upstream_status $multi_upstreams {    
"~,"    1; # Has a comma
    default 0;
} 

map $status $is_error {
    400     1; # Bad request, including expired client cert
    495     1; # Client cert error
    502     1; # Bad gateway (no upstream server could be selected)
    504     1; # Gateway timeout (couldn't connect to selected upstream)
    default $multi_upstreams; # If we tried more than one upstream server
}

access_log /var/log/nginx/access_debug.log access_debug if=$is_error; # Diagnostic logging
access_log /var/log/nginx/access.log main; # Regular logging

여기서는 또 다른 map 블록을 사용하여 $multi_upstreams라는 새 변수를 생성합니다. 이 변수의 값은 $upstream_status에 쉼표(,)가 있는지 여부에 따라 달라집니다. 쉼표가 있다는 것은 상태 코드가 두 개 이상이며, 따라서 둘 이상의 업스트림 서버를 거쳤다는 의미입니다. 이 새 변수는 $status가 나열된 오류 코드 중 하나가 아닐 때 $is_error의 값을 결정합니다.

이제 일반 액세스 로그와 오류가 발생한 요청이 기록되는 특수 access_debug.log 파일이 준비되었지만, 아직 access_debug 로그 형식은 정의하지 않았습니다. 이제 문제를 진단하는 데 필요한 모든 데이터가 access_debug.log 파일에 기록되도록 하겠습니다.

JavaScript를 활용한 JSON 로깅

진단 데이터를 access_debug.log에 기록하는 것은 어렵지 않습니다. NGINX는 HTTP 처리와 관련된 100개 이상의 변수를 제공하며, 필요한 만큼 변수를 캡처하는 특수한 log_format 지시어를 정의할 수 있습니다. 하지만 이러한 용도로 단순한 로그 형식을 구성하는 데에는 몇 가지 단점이 있습니다.

• 사용자 지정 형식이므로 로그 파서가 이를 읽을 수 있도록 학습시켜야 합니다
• 항목이 매우 길어질 수 있어 실시간 문제 해결 중에는 사람이 읽기 어려울 수 있습니다.
• 항목을 해석하려면 로그 형식을 계속 참조해야 합니다
• “모든 요청 헤더”와 같은 비결정적 값은 로그에 기록할 수 없습니다.

이러한 문제는 NGINX JavaScript 모듈<.htmla>(njs)을 사용하여 로그 항목을 JSON과 같은 구조화된 형식으로 작성함으로써 해결할 수 있습니다. JSON 형식은 Splunk, LogStash, Graylog, Loggly와 같은 로그 처리 시스템에서도 널리 지원됩니다. log_format 구문을 JavaScript 함수로 이전하면 기본 JSON 구문을 활용하면서 모든 NGINX 변수와 njs ‘r’ 객체의 추가 데이터에 액세스할 수 있습니다.

js_import conf.d/json_log.js;js_set $json_debug_log json_log.debugLog;

log_format access_debug escape=none $json_debug_log; # Offload to njs 
access_log /var/log/nginx/access_debug.log access_debug if=$is_error;

The js_import 지시문은 JavaScript 코드가 포함된 파일을 지정하고 해당 파일을 모듈로 가져옵니다. 코드 자체는 여기에서 확인할 수 있습니다. access_debug 로그 형식을 사용하는 액세스 로그 항목을 작성할 때마다 $json_debug_log 변수가 평가됩니다. 이 변수는 js_set 지시문에 정의된 대로 debugLog JavaScript 함수를 실행하여 평가됩니다.

이 JavaScript 코드와 NGINX 구성을 함께 사용하면 다음과 같은 진단 로그가 생성됩니다.

$ tail --lines=1 /var/log/nginx/access_debug.log | jq{
   "timestamp": "2020-09-21T11:25:55+00:00",
   "connection": {
      "request_count": 1,
      "elapsed_time": 0.555,
      "pipelined": false,
      "ssl": {
         "protocol": "TLSv1.2",
         "cipher": "ECDHE-RSA-AES256-GCM-SHA384",
         "session_id": "b302f76a70dfec92f6bd72de5732692481ebecbbc69a4d81c900ae4dc928485c",
         "session_reused": false,
         "client_cert": {
            "status": "NONE"
         }
      }
   },
   "request": {
      "client": "127.0.0.1",
      "port": 443,
      "host": "foo.example.com",
      "method": "GET",
      "uri": "/one",
      "http_version": 1.1,
      "bytes_received": 87,
      "headers": {
         "Host": "foo.example.com:443",
         "User-Agent": "curl/7.64.1",
         "Accept": "*/*"
      }
   },
   "upstreams": [
      {
         "server_addr": "10.37.0.71",
         "server_port": 443,
         "connect_time": null,
         "header_time": null,
         "response_time": 0.551,
         "bytes_sent": 0,
         "bytes_received": 0,
         "status": 504
      },
      {
         "server_addr": "10.37.0.72",
         "server_port": 443,
         "connect_time": 0.004,
         "header_time": 0.004,
         "response_time": 0.004,
         "bytes_sent": 92,
         "bytes_received": 4161,
         "status": 200
      }
   ],
   "response": {
      "status": 200,
      "bytes_sent": 186,
      "headers": {
         "Content-Type": "text/html",
         "Content-Length": "4161"
      }
   }
}

JSON 형식을 사용하면 전체 HTTP 연결(SSL/TLS 포함), 요청, 업스트림 및 응답과 관련된 정보를 각각 별도의 객체로 구성할 수 있습니다. 첫 번째 업스트림(10.37.0.71)이 상태 코드 504 (Gateway Timeout)을 반환한 후 NGINX가 다음 업스트림(10.37.0.72)을 시도했고, 이 업스트림은 성공적으로 응답했습니다. 0.5초의 타임아웃(upstreams 객체의 첫 번째 요소에서 response_time으로 표시됨)이 이 성공적인 응답의 전체 지연 시간(connection 객체에서 elapsed_time으로 표시됨) 중 대부분을 차지합니다.

다음은 만료된 클라이언트 인증서로 인해 발생한 클라이언트 오류의 (일부가 생략된) 로그 항목 예시입니다.

{   
"timestamp": "2020-09-22T10:20:50+00:00",
   "connection": {
      "ssl": {
         "protocol": "TLSv1.2",
         "cipher": "ECDHE-RSA-AES256-GCM-SHA384",
         "session_id": "30711efbe047c38a98c2209cc4b5f196988dcf2d7f1f2c269fde7269c370432e",
         "session_reused": false,
         "client_cert": {
            "status": "FAILED:certificate has expired",
            "serial": "1006",
            "fingerprint": "0c47cc4bd0fefbc2ac6363345cfbbf295594fe8d",
            "subject": "emailAddress=liam@nginx.com,CN=test01,OU=Demo CA,O=nginx,ST=CA,C=US",
            "issuer": "CN=Demo Intermediate CA,OU=Demo CA,O=nginx,ST=CA,C=US",
            "starts": "Sep 20 12:00:11 2019 GMT",
            "expires": "Sep 20 12:00:11 2020 GMT",
            "expired": true,
         ...
   "response": {
      "status": 400,
      "bytes_sent": 283,
      "headers": {
      "Content-Type": "text/html",
      "Content-Length": "215"
   }
}

요약

오류가 발생한 경우에만 상세한 진단 데이터를 생성함으로써, 별도의 재구성 없이도 실시간으로 문제를 해결할 수 있습니다. JavaScript 코드는 마지막 바이트가 클라이언트에 전송된 후 로깅 단계에서 오류가 감지된 경우에만 실행되므로, 성공한 요청에는 영향을 주지 않습니다.

전체 구성은 GitHub에서 확인할 수 있습니다. 여러분의 환경에서 직접 사용해 보세요. 아직 NGINX Plus를 사용하고 있지 않다면 지금 30일 무료 평가판을 시작하거나 사용 사례에 대해 논의하려면 문의해 주세요.

작성자 소개

Liam Crilly제품 관리 부문 수석 이사

Liam Crilly의 다른 블로그 게시물