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

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

編集者– このブログは、NGINX と NGINX Plus を使用したログ記録について説明するブログの 1 つです。 こちらもご覧ください:

• NGINX と NGINX Plus によるアプリケーション トレース
• NGINX 条件付きログによるリクエストのサンプリング

これは、NGINX JavaScript モジュールの使用例に関する数多くのブログの 1 つでもあります。 完全なリストについては、 「NGINX JavaScript モジュールの使用例」を参照してください。

NGINX は、あらゆる規模の組織がミッションクリティカルな Web サイト、アプリケーション、API を実行できるように支援します。 規模やデプロイメント インフラストラクチャの選択に関係なく、運用環境で実行するのは簡単ではありません。 この記事では、本番環境へのデプロイメントで難しいことの 1 つであるログ記録について説明します。 具体的には、不要なデータで溢れかえることなく、トラブルシューティングのために適切な量の詳細なログを収集するバランスの取れた行為について説明します。

ログ記録の基本

NGINX は、クライアント要求のアクセス ログと、問題が発生した場合のエラー ログという2 つの異なるログ メカニズムを提供します。 これらのメカニズムは HTTP モジュールとストリーム (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
    ...
}

log_formatディレクティブは、 access_logディレクティブが構成に含まれている場合に作成されるログ エントリの内容と構造を記述します。 上記の例は、多くの Web サーバーで使用されているCommon Log Format (CLF) の拡張です。 error_logディレクティブでは、ログに記録するメッセージの重大度レベルを指定しますが、エントリの内容や形式は固定されており、指定できません。 詳細は、次のセクションで説明します。

NGINX ロギングのその他の注目すべき点は次のとおりです。

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

生産現場でのログ記録の現実

一般的に言えば、アクセス ログを使用して分析と使用状況の統計を提供し、エラー ログを使用して障害の検出とトラブルシューティングを行う必要があります。 しかし、生産システムを実行するのはそれほど簡単ではありません。 よくある課題は次のとおりです。

• アクセスログにはトラブルシューティングに必要な詳細が不足している
• エラーログは、情報重大度レベルでは詳細な情報を提供しますが、通常の操作には冗長すぎます。
• エラーログの形式は固定されており、特に興味のある変数を含めるようにカスタマイズすることはできません。
• エラーログのエントリにはリクエストのコンテキストが含まれておらず、対応するアクセスログエントリと一致させることが困難です。

さらに、本番環境でログの詳細を追加または削除するために NGINX 設定を変更する場合、変更管理プロセスを経て、構成を再展開する必要がある場合もあります。 完全に安全ですが、「なぜ急上昇が見られるのか」などのライブの問題をトラブルシューティングするときにはやや面倒です。 4xx / 5「xxエラーですか?」。 もちろん、クラスター全体で同じトラフィックを処理する NGINX インスタンスが複数ある場合は、この問題はさらに大きくなります。

エラー用の2番目のアクセスログの使用

アクセス ログの形式をカスタマイズして、各リクエストで収集されたデータを充実させることは、分析を強化するための一般的なアプローチですが、診断やトラブルシューティングには適していません。 メイン アクセス ログに 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変数をマップブロックに渡して$is_error変数の値を決定し、その値がaccess_logディレクティブのifパラメータによって評価されます。 $is_errorが次のように評価された場合1access_debug.logファイルに特別なログエントリを書き込みます。

ただし、この構成では、リクエスト処理中に発生したエラーは検出されず、最終的に解決されるため、ステータスは200わかりました。 そのような例の 1 つは、NGINX が複数のアップストリーム サーバー間で負荷分散を行う場合です。 選択したサーバーでエラーが発生した場合、NGINX はproxy_next_upstreamディレクティブで設定された条件に従って、リクエストを次のサーバーに渡します。 上流サーバーの1つが正常に応答すれば、クライアントは成功応答を受信し、ステータスとともにログに記録されます。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

ここでは、別のマップブロックを使用して、 $upstream_status内のカンマ ( , ) の存在に応じて値が決まる新しい変数 ( $multi_upstreams ) を生成します。 カンマは、ステータス コードが複数あることを意味し、したがって、複数のアップストリーム サーバーに遭遇したことを意味します。 この新しい変数は、 $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形式は、次のようなログ処理システムでも広くサポートされています。 スプランク、 ログスタッシュ、 グレイログ、 そして ログリー。 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;

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(ゲートウェイタイムアウト) 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 日間の無料トライアルを開始するか、弊社にお問い合わせの上、ユースケースについてご相談ください。