NGINX JavaScriptモジュールによる診断ログ

NGINX | 2020年9月29日

エラーログを調整せずに本番環境でトラブルシューティング

編集者注 – このブログは、NGINXおよびNGINX Plusのログ記録について解説する一連の記事の1つです。以下も併せてご覧ください。

これは、NGINX JavaScriptモジュールのユースケースを紹介する数多くのブログ記事の1つでもあります。完全な一覧については、「NGINX JavaScriptモジュールのユースケース」をご覧ください。

NGINXは、あらゆる規模の組織がミッションクリティカルなWebサイト、アプリケーション、APIを運用できるよう支援します。規模や導入インフラストラクチャの選択にかかわらず、本番環境での運用は容易ではありません。この記事では、本番環境への導入に伴う難題の1つであるロギングを取り上げます。具体的には、不要なデータに埋もれることなく、トラブルシューティングに必要な詳細ログを適切な量だけ収集するためのバランスについて説明します。

ログの基本

NGINXには、2つの異なるロギングメカニズムがあります。クライアントリクエスト用の「アクセスログ」と、問題発生時の「エラーログ」です。これらのメカニズムはHTTPモジュールとStream（TCP/UDP）モジュールの両方で利用できますが、ここではHTTPトラフィックに焦点を当てます。（このほかに「デバッグ重大度レベル」を使用する3つ目のロギングメカニズムもありますが、ここでは説明しません。）

一般的なデフォルトの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ディレクティブが含まれている場合に作成されるログエントリの内容と構造を定義します。上記の例は、多くのWebサーバーで使用されているCommon Log Format（CLF）を拡張したものです。error_logディレクティブでは、ログに記録するメッセージの重大度レベルを指定します。ただし、エントリの内容や形式は固定されているため、指定できません。詳しくは次のセクションで説明します。

NGINXのログに関するその他の注目点は次のとおりです。

ロギングディレクティブは、下位レベルの設定コンテキストに自動的に継承されます。たとえば、access_logディレクティブをhttpコンテキストで指定すると、すべてのserver{}ブロックに適用されます。
子コンテキストのロギングディレクティブは、継承されたディレクティブをオーバーライドします。
同じコンテキスト内に複数のログ記録ディレクティブを指定できます。たとえば、2つの「access_log」ディレクティブを使用して、標準のCLFログファイルと、より詳細な別のログの両方を作成できます。

本番環境におけるロギングの実態

一般に、アクセスログは分析や利用状況の統計に、エラーログは障害の検出やトラブルシューティングに使用します。しかし、本番環境のシステム運用は、そう単純ではありません。よくある課題には、次のようなものがあります。

アクセスログには、トラブルシューティングに必要な詳細情報が不足している
エラーログは重大度レベル「info」では十分な詳細情報を提供しますが、通常運用には冗長すぎます
エラーログの形式は固定されているため、特に必要な変数を含めるようにカスタマイズすることはできません
エラーログのエントリにはリクエストのコンテキストが含まれていないため、対応するアクセスログのエントリとの照合が困難です

さらに、本番環境でログの詳細情報を追加または削除するためにNGINXの設定を変更する場合、変更管理プロセスを経て、設定を再デプロイする必要が生じることもあります。安全性に問題はありませんが、「なぜ4xx/5xxエラーが急増しているのか」といった稼働中の問題をトラブルシューティングする際には、やや煩雑です。クラスター全体で複数のNGINXインスタンスが同じトラフィックを処理している場合は、当然ながらさらに煩雑になります。

エラー用に2つ目のアクセスログを使用する

リクエストごとに収集するデータを充実させるためにアクセスログの形式をカスタマイズすることは、高度な分析でよく用いられる手法ですが、診断やトラブルシューティングには十分に対応できません。通常、トラブルシューティングでは一般的な分析よりもはるかに多くの情報が必要になるため、メインのアクセスログに両方の役割を持たせるのは不自然な解決策です。メインのアクセスログに多数の変数を追加すると、たまにしか役立たないデータによってログ量が大幅に増加する可能性があります。

代わりに、2つ目のアクセスログを使用し、デバッグが必要なエラーが発生した場合にのみ書き込むことができます。access_logディレクティブでは、ifパラメーターを使用した条件付きロギングがサポートされています。指定した変数がゼロ以外かつ空でない値と評価された場合にのみ、リクエストがログに記録されます。

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には、接続を試行した各サーバーからのレスポンスコードが記録されます。これらの変数に複数のエントリがある場合は、何らかの問題が発生しており、少なくとも1台のアップストリームサーバーに問題がある可能性が高いと判断できます。

リクエストが複数のアップストリームサーバーにプロキシされた場合にも、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 module<.htmla>（njs）を使用して、JSONなどの構造化形式でログエントリを書き込むことで対処できます。JSON形式は、Splunk、LogStash、Graylog、Logglyなどのログ処理システムでも広くサポートされています。log_format構文をJavaScript関数に移すことで、NGINXのすべての変数とnjsの「r」オブジェクトから取得できる追加データにアクセスしながら、ネイティブのJSON構文を利用できます。

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"
   }
}