本文へ移動

8. ログ

ログレベル、形式、プロファイル、タイミング、取得項目、状態、例

HAProxyの強みの一つは、間違いなく詳細なログです。この種の製品で得られる情報としては、おそらく最もきめ細かく、複雑な環境の問題解決に非常に重要です。通常のログには、クライアントのポート、TCP/HTTPの状態タイマー、終了時の正確なストリーム状態と終了理由、トラフィックをサーバーへ振り向けた判断に関する情報を含み、任意のヘッダーを取得することもできます。

管理者が素早く対応できるよう、発生した内部・外部の問題を明確に示し、異なるレベルのフィルターを使って、複数の送信先へ同時にログを送れます。

  • グローバルなプロセス単位のログ(システムエラー、起動・停止など)
  • インスタンスごとのシステムエラーと内部エラー(リソース不足、不具合など)
  • インスタンスごとの外部の問題(サーバーの稼働・停止、接続数の上限)
  • インスタンスごとの活動(クライアント接続)。接続確立時または終了時に記録します。
  • リクエストごとのログレベル制御。たとえばhttp-request set-log-level silent if sensitive_request

レベルの異なるログを別々のログサーバーへ振り分けることで、複数の運用チームが連携し、問題をできるだけ早く修正できます。たとえば、システム担当はシステム全体のエラーを監視し、アプリケーション担当はサーバーの稼働・停止をリアルタイムで監視し、セキュリティ担当は一時間遅れで活動ログを分析できます。

8.1. ログレベル

TCP接続とHTTP接続について、日付、時刻、送信元IPアドレス、宛先アドレス、接続時間、応答時間、HTTPリクエスト、HTTP応答コード、転送バイト数、ストリームの終了条件、さらには交換したCookieの値まで記録できます。たとえば、特定のユーザーの問題を追跡できます。すべてのメッセージを、最大二つのsyslogサーバーへ送れます。ログのfacilityの詳細は、セクション4.2 の"log"キーワードを参照してください。

8.2. ログ形式

HAProxyは5種類のログ形式をサポートします。複数の形式で共通するフィールドは、以下の節で詳しく説明します。一部は、特定のオプションに固有の指標により、設定に応じて少し変わる場合があります。次の形式をサポートします。

  • デフォルト形式は、非常に基本的で、ほとんど使われません。着信接続を受け入れた時点で、送信元IP:port、宛先IP:port、フロントエンド名という、ごく基本的な情報だけを記録します。このモードはいずれなくなるため、詳しくは説明しません。

  • TCP形式は、より高度です。フロントエンドで"option tcplog"を設定すると有効になります。通常、HAProxyは接続の終了を待ってから記録します。タイマー、接続数、キューサイズなど、はるかに豊富な情報を記録します。純粋なTCPプロキシには、この形式を推奨します。

  • HTTP形式は、HTTPプロキシ用として最も高度です。フロントエンドで"option httplog"を設定すると有効になります。TCP形式と同じ情報に加え、リクエスト、ステータスコード、取得したヘッダーとCookieなど、HTTP固有のフィールドを含みます。HTTPプロキシには、この形式を推奨します。

  • CLF HTTP形式は、HTTP形式と同等ですが、フィールドをCLF形式と同じ順序で並べます。共通フィールドの後に、すべてのタイマー、取得項目、フラグなどを、標準HTTP形式と同じ順序で、一つずつ独立したフィールドに記録します。

  • カスタムログ形式では、独自のログ行を作成できます。

以下の節では、各形式をさらに詳しく説明します。形式は「フィールド」単位で規定します。別途説明がない限り、フィールドは任意の数の空白で区切ったテキストの一部分です。syslogサーバーが行頭にフィールドを挿入する場合があるため、最初のフィールドは、常にプロセス名と識別子を含むものとみなします。

注意:ログ行は非常に長くなることがあるため、以下の例では複数行に分割する場合があります。例のログ行は3つの閉じ山括弧(’>>>’)で始めます。複数行に分ける場合、最後以外の行はバックスラッシュ(’\’)で終え、次の行を二文字分インデントします。

8.2.1. デフォルトのログ形式

特定のオプションを設定しない場合に使う形式です。接続を受け入れると直ちにログを出力します。現在、リクエストの宛先IPとポートを記録する唯一の形式である点に注意してください。

例:

    listen www
        mode http
        log global
        server srv1 127.0.0.1:8000

>>> Feb  6 12:12:09 localhost \
      haproxy[14385]: Connect from 10.0.1.2:33312 to 10.0.3.31:8012 \
      (www/HTTP)

フィールド 形式 上記の例からの抜粋

    1   process_name '[' pid ']:'                            haproxy[14385]:
    2   'Connect from'                                          Connect from
    3   source_ip ':' source_port                             10.0.1.2:33312
    4   'to'                                                              to
    5   destination_ip ':' destination_port                   10.0.3.31:8012
    6   '(' frontend_name '/' mode ')'                            (www/HTTP)

各フィールドの詳細:

  • “source_ip"は、接続を開始したクライアントのIPアドレスです。
  • “source_port"は、接続を開始したクライアントのTCPポートです。
  • “destination_ip"は、クライアントが接続したIPアドレスです。
  • “destination_port"は、クライアントが接続したTCPポートです。
  • “frontend_name"は、接続を受信して処理したフロントエンド(またはリスナー)の名前です。
  • “mode"は、フロントエンドの動作モード(TCPまたはHTTP)です。

UNIXソケットの場合、送信元と宛先のアドレスは"unix:“と表示し、ポートは接続を受け入れたソケットの内部IDを表します(統計で報告するものと同じIDです)。

この非推奨の形式はいずれなくなるため、新規導入で使わないことを推奨します。

8.2.2. TCPログ形式

フロントエンドで"option tcplog"を指定するとTCP形式を使います。純粋なTCPプロキシに推奨する形式で、問題解決に有用な情報を豊富に含みます。タイマーとバイト数を含むため、通常はセッションの終了時にログを出力します。“option logasap"を指定すると早めに出力でき、リモート端末など、長いセッションを使う多くの環境で意味があります。“monitor"ルールにマッチするセッションは、決して記録しません。フロントエンドに"option dontlognull"を指定すると、クライアントとサーバーの間でデータを交換しなかったセッションのログを出さないようにもできます。“option dontlog-normal"を指定すると、成功した接続は記録しません。

TCPログ形式は、内部では次の正確な文字列に基づくカスタムログ形式として定義しています。必要なら、これを基に形式を拡張できます。また、代わりにHAPROXY_TCP_LOG_FMT変数も使えます。使い方は、セクション8.2.6 「カスタムログ形式」を参照してください。

# strict equivalent of "option tcplog"
log-format "%ci:%cp [%t] %ft %b/%s %Tw/%Tc/%Tt %B %ts \
            %ac/%fc/%bc/%sc/%rc %sq/%bq"
# or using the HAPROXY_TCP_LOG_FMT variable
log-format "${HAPROXY_TCP_LOG_FMT}"

CLFログ形式も、内部では次の正確な文字列に基づくカスタムログ形式として定義しています。

# strict equivalent of "option tcplog clf"
log-format "%{Q}o %{-Q}ci - - [%T] \"TCP \" 000 %B \"\" \"\" %cp \
            %ms %ft %b %s %Th %Tw %Tc %Tt %U %ts-- %ac %fc %bc \
            %sc %rc %sq %bq \"\" \"\" "

設定オプションによって、一部のフィールドが少し変わる場合があります。以下では、そのフィールド名の後にアスタリスク(’*’)を付けています。

例:

    frontend fnt
        mode tcp
        option tcplog
        log global
        default_backend bck

    backend bck
        server srv1 127.0.0.1:8000

>>> Feb  6 12:12:56 localhost \
      haproxy[14387]: 10.0.1.2:33313 [06/Feb/2009:12:12:51.443] fnt \
      bck/srv1 0/0/5007 212 -- 0/0/0/0/3 0/0

フィールド 形式 上記の例からの抜粋

    1   process_name '[' pid ']:'                            haproxy[14387]:
    2   client_ip ':' client_port                             10.0.1.2:33313
    3   '[' accept_date ']'                       [06/Feb/2009:12:12:51.443]
    4   frontend_name                                                    fnt
    5   backend_name '/' server_name                                bck/srv1
    6   Tw '/' Tc '/' Tt*                                           0/0/5007
    7   bytes_read*                                                      212
    8   termination_state                                                 --
    9   actconn '/' feconn '/' beconn '/' srv_conn '/' retries*    0/0/0/0/3
   10   srv_queue '/' backend_queue                                      0/0

各フィールドの詳細:

  • “client_ip"は、HAProxyへのTCP接続を開始したクライアントのIPアドレスです。UNIXソケットで接続を受け入れた場合は、IPアドレスを"unix"という語に置き換えます。“accept-proxy"を設定したソケットでPROXYプロトコルを正しく使った場合、または"accept-netscaler-cip"を設定したソケットでNetScaler Client IP挿入プロトコルを正しく使った場合、ログには転送された接続の情報が反映されます。

  • “client_port"は、接続を開始したクライアントのTCPポートです。UNIXソケットで受け入れた場合は、そのソケットのIDに置き換えます。このIDは統計インターフェースでも報告します。

  • “accept_date"は、HAProxyが接続を受信した正確な日時です。システムのバックログで待ちがあった場合、ネットワーク上で観測した日時とはわずかに異なることがあります。通常は、上流のファイアウォールのログに現れる日時と同じです。HTTPモードでは、新しいリクエストを受信できるようになった最初の時点(HTTP/1では前のレスポンスの終了時、HTTP/2では前のリクエストの直後)に、このフィールドをリセットします。

  • “frontend_name"は、接続を受信して処理したフロントエンド(またはリスナー)の名前です。

  • “backend_name"は、サーバーへの接続を管理するために選ばれたバックエンド(またはリスナー)の名前です。切り替えルールを適用していない場合、フロントエンドと同じ名前になります。TCPアプリケーションではよくある構成です。

  • “server_name"は、最後に接続を送ったサーバーの名前です。接続エラーによる再振り分けがあれば、最初のサーバーと異なる場合があります。このサーバーは、リクエストを処理したバックエンドに属します。サーバーに到達する前に接続を中止した場合は、サーバー名の代わりに”<NOSRV>“を示します。

  • “Tw"は、各種キューで待った合計時間をミリ秒で表します。キューに到達する前に接続を中止した場合は、"-1"になることがあります。詳細は後述の「タイマー」を参照してください。

  • “Tc"は、最後のサーバーへの接続確立を待った合計時間を、再試行も含めてミリ秒で表します。接続を確立する前に中止した場合は、"-1"になることがあります。詳細は後述の「タイマー」を参照してください。

  • “Tt"は、接続の受け入れから最後のクローズまでの合計経過時間をミリ秒で表します。すべての処理を含みます。ただし、“option logasap"を指定した場合は例外で、ログを出力した時点で計測を止めます。その場合、最終値はこれより大きくなることを示す’+‘を、値の前に付けます。詳細は後述の「タイマー」を参照してください。

  • “bytes_read"は、ログ出力時点でサーバーからクライアントへ転送した総バイト数です。“option logasap"を指定した場合は、最終値がこれより大きくなる可能性を示す’+‘を、値の前に付けます。64ビットカウンターなので、ログ解析ツールはオーバーフローせずに扱えなければなりません。

  • “termination_state"は、セッション終了時の状態です。セッションの状態、どちら側が終了を引き起こしたか、その理由(タイムアウト、エラーなど)を示します。正常なフラグは”–“で、バッファーにデータを残さず、どちらかの側がセッションを閉じたことを示します。詳細は後述の「切断時のストリーム状態」を参照してください。

  • “actconn"は、セッションを記録した時点の、プロセス全体の同時接続数です。プロセス単位のシステム上限に達したことを検出するのに便利です。たとえば、複数の接続エラーが起きたときにactconnが512に近ければ、システムがプロセスのファイルディスクリプター数を1024に制限し、すべて使い切っている可能性が高いと考えられます。システムの調整方法は、セクション3 「グローバルセクション」を参照してください。

  • “feconn"は、セッションを記録した時点の、フロントエンドの同時接続数です。高負荷を維持するための必要リソース量を見積もり、フロントエンドの"maxconn"に達したことを検出するのに便利です。この値が急増する原因は、ほとんどの場合バックエンドサーバーの混雑ですが、サービス拒否攻撃の場合もあります。

  • “beconn"は、セッションを記録した時点で、バックエンドが扱う同時接続の総数です。サーバー上で有効な同時接続の総数と、キューで待機中の接続数を含みます。アプリケーションの高負荷に対応するため、追加で必要なサーバー数を見積もるのに便利です。この値が急増する原因は、ほとんどの場合バックエンドサーバーの混雑ですが、サービス拒否攻撃の場合もあります。

  • “srv_conn"は、セッションを記録した時点で、そのサーバー上にまだ残る有効な同時接続の総数です。サーバーに設定した"maxconn"を超えることはありません。この値が頻繁に"maxconn"に近づくか等しくなる場合、トラフィック調整が多く発生しています。つまり、サーバーのmaxconnが低すぎるか、最適な応答時間で負荷を処理するだけのサーバー数がありません。一台だけ"srv_conn"が高い場合、通常は、そのサーバーに問題があり、接続の処理が他のサーバーより長くかかっています。

  • “retries"は、このセッションがサーバーへの接続を試みたときの再試行回数です。接続試行と同時にサーバーを停止している場合を除き、通常はゼロでなければなりません。再試行が多い場合、一般にはHAProxyとサーバーの間のネットワーク問題、または新しい接続をキューに入れられないサーバーのシステムバックログの設定不備を示します。このフィールドの前に’+‘が付く場合があり、最初のサーバーで最大再試行回数に達した後、セッションを再振り分けしたことを示します。その場合、ログのサーバー名は最初のサーバーではなく、再振り分け先です。ただし、ハッシュなどによって両者が同じになる場合もあります。したがって、一般的な目安として、再試行回数の前に’+‘がある場合、その回数をログに記載されたサーバーのものとみなすべきではありません。

  • “srv_queue"は、サーバーのキューで、このリクエストより前に処理したリクエストの総数です。サーバーのキューを通らなければゼロです。キューで過ごした時間をキュー内のリクエスト数で割ると、サーバーのおおよその応答時間を見積もれます。セッションを再振り分けして二つのサーバーキューを通った場合、その位置を合算します。再振り分けがない限り、リクエストがサーバーキューとバックエンドキューの両方を通ることはないはずです。

  • “backend_queue"は、バックエンドのグローバルキューで、このリクエストより前に処理したリクエストの総数です。グローバルキューを通らなければゼロです。平均キュー長を見積もることができ、サーバーの"maxconn"で割れば、不足するサーバー数に容易に換算できます。再振り分けがあると、セッションがバックエンドのキューを二度通る場合があり、その位置を合算します。再振り分けがない限り、リクエストがサーバーキューとバックエンドキューの両方を通ることはないはずです。

8.2.3. HTTPログ形式

HTTP形式は、HTTPプロキシに最も適した、最も完全な形式です。フロントエンドで"option httplog"を指定すると有効になります。TCP形式と同じ情報に、HTTP固有の機能を追加します。TCP形式と同様、通常はストリーム終了時に出力しますが、“option logasap"を指定した場合は例外です。これを指定する意味があるのは、一般にはダウンロードサイトだけです。“monitor"ルールにマッチするストリームは、決して記録しません。フロントエンドに"option dontlognull"を指定すると、クライアントがデータを送らなかったストリームを記録しないようにもできます。“option dontlog-normal"を指定すると、成功した接続は記録しません。

HTTPログ形式は、内部では次の正確な文字列に基づくカスタムログ形式として定義しています。必要なら、これを基に形式を拡張できます。また、代わりにHAPROXY_HTTP_LOG_FMT変数も使えます。使い方は、セクション8.2.6 「カスタムログ形式」を参照してください。

# strict equivalent of "option httplog"
log-format "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC \
            %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r"
# or using the HAPROXY_HTTP_LOG_FMT variable
log-format "${HAPROXY_HTTP_LOG_FMT}"

CLFログ形式も、内部では次の正確な文字列に基づくカスタムログ形式として定義しています。

# strict equivalent of "option httplog clf"
log-format "%{+Q}o %{-Q}ci - - [%trg] %r %ST %B \"\" \"\" %cp \
            %ms %ft %b %s %TR %Tw %Tc %Tr %Ta %tsc %ac %fc \
            %bc %sc %rc %sq %bq %CC %CS %hrl %hsl"

ほとんどのフィールドはTCPログと共通ですが、異なるものもあります。一部は、設定オプションによって少し変わる場合があります。以下では、そのフィールド名の後にアスタリスク(’*’)を付けています。

例:

    frontend http-in
        mode http
        option httplog
        log global
        default_backend bck

    backend static
        server srv1 127.0.0.1:8000

>>> Feb  6 12:14:14 localhost \
      haproxy[14389]: 10.0.1.2:33317 [06/Feb/2009:12:14:14.655] http-in \
      static/srv1 10/0/30/69/109 200 2750 - - ---- 1/1/1/1/0 0/0 {1wt.eu} \
      {} "GET /index.html HTTP/1.1"

フィールド 形式 上記の例からの抜粋

    1   process_name '[' pid ']:'                            haproxy[14389]:
    2   client_ip ':' client_port                             10.0.1.2:33317
    3   '[' request_date ']'                      [06/Feb/2009:12:14:14.655]
    4   frontend_name                                                http-in
    5   backend_name '/' server_name                             static/srv1
    6   TR '/' Tw '/' Tc '/' Tr '/' Ta*                       10/0/30/69/109
    7   status_code                                                      200
    8   bytes_read*                                                     2750
    9   captured_request_cookie                                            -
   10   captured_response_cookie                                           -
   11   termination_state                                               ----
   12   actconn '/' feconn '/' beconn '/' srv_conn '/' retries*    1/1/1/1/0
   13   srv_queue '/' backend_queue                                      0/0
   14   '{' captured_request_headers* '}'                   {haproxy.1wt.eu}
   15   '{' captured_response_headers* '}'                                {}
   16   '"' http_request '"'                      "GET /index.html HTTP/1.1"

各フィールドの詳細:

  • “client_ip"は、HAProxyへのTCP接続を開始したクライアントのIPアドレスです。UNIXソケットで接続を受け入れた場合は、IPアドレスを"unix"という語に置き換えます。“accept-proxy"を設定したソケットでPROXYプロトコルを正しく使った場合、または"accept-netscaler-cip"を設定したソケットでNetScaler Client IP挿入プロトコルを正しく使った場合、ログには転送された接続の情報が反映されます。

  • “client_port"は、接続を開始したクライアントのTCPポートです。UNIXソケットで受け入れた場合は、そのソケットのIDに置き換えます。このIDは統計インターフェースでも報告します。

  • “request_date"は、HTTPリクエストの最初のバイトをHAProxyが受信した正確な日時です(ログフィールド%tr)。

  • “frontend_name"は、接続を受信して処理したフロントエンド(またはリスナー)の名前です。

  • “backend_name"は、サーバーへの接続を管理するために選ばれたバックエンド(またはリスナー)の名前です。切り替えルールを適用していない場合、フロントエンドと同じ名前になります。

  • “server_name"は、最後に接続を送ったサーバーの名前です。接続エラーによる再振り分けがあれば、最初のサーバーと異なる場合があります。このサーバーは、リクエストを処理したバックエンドに属します。サーバーに到達する前にリクエストを中止した場合は、サーバー名の代わりに”<NOSRV>“を示します。統計サブシステムがリクエストを処理した場合は、"<STATS>“を示します。

  • “TR"は、最初のバイトを受信してから、クライアントの完全なHTTPリクエストを待った合計時間をミリ秒で表します(ボディーは含みません)。完全なリクエストを受信する前に接続を中止した場合や、不正なリクエストを受信した場合は、"-1"になることがあります。リクエストは通常、一つのパケットに収まるため、この値は常に非常に小さいはずです。大きい値は、一般にはクライアントとHAProxyの間のネットワーク問題、またはリクエストの手入力を示します。詳細はセクション8.4 「イベントのタイミング」を参照してください。

  • “Tw"は、各種キューで待った合計時間をミリ秒で表します。キューに到達する前に接続を中止した場合は、"-1"になることがあります。詳細はセクション8.4 「イベントのタイミング」を参照してください。

  • “Tc"は、最後のサーバーへの接続確立を待った合計時間を、再試行も含めてミリ秒で表します。接続を確立する前にリクエストを中止した場合は、"-1"になることがあります。詳細はセクション8.4 「イベントのタイミング」を参照してください。

  • “Tr"は、サーバーから完全なHTTPレスポンスを待った合計時間をミリ秒で表します(データは含みません)。完全なレスポンスを受信する前にリクエストを中止した場合は、"-1"になることがあります。通常はサーバーのリクエスト処理時間に一致しますが、クライアントからサーバーへ送るデータ量の影響を受ける場合があります。“GET"リクエストでこの値が大きければ、一般にはサーバーの過負荷を示します。詳細はセクション8.4 「イベントのタイミング」を参照してください。

  • “Ta"は、HAProxy内でリクエストが有効だった時間で、最初のリクエストバイトの受信から、最後のレスポンスバイトの送信までの合計経過時間をミリ秒で表します。ハンドシェイク(Thを参照)とアイドル時間(Tiを参照)以外の、すべての処理を含みます。ただし、“option logasap"を指定した場合は例外で、ログを出力した時点で計測を止めます。その場合、最終値はこれより大きくなることを示す’+‘を、値の前に付けます。詳細はセクション8.4 「イベントのタイミング」を参照してください。

  • “status_code"は、クライアントへ返したHTTPステータスコードです。通常はサーバーが設定しますが、サーバーに到達できない場合や、HAProxyがレスポンスをブロックした場合は、HAProxyが設定することもあります。

  • “bytes_read"は、ログ出力時点でクライアントへ転送した総バイト数です。HTTPヘッダーも含みます。“option logasap"を指定した場合は、最終値がこれより大きくなる可能性を示す’+‘を、値の前に付けます。64ビットカウンターなので、ログ解析ツールはオーバーフローせずに扱えなければなりません。

  • “captured_request_cookie"は、クライアントのリクエストにそのCookieが含まれていたことを示す、任意の"name=value"エントリーです。Cookie名と最大長は、フロントエンド設定の"capture cookie"文で定義します。未設定の場合は、単一のダッシュ(’-’)です。取得できるCookieは一つだけで、一般にはクライアントとサーバーのセッションIDの交換を追跡し、アプリケーションの不具合によるクライアント間のセッション混同を検出するために使います。詳細は後述の「HTTPヘッダーとCookieの取得」を参照してください。

  • “captured_response_cookie"は、サーバーがレスポンスでCookieを返したことを示す、任意の"name=value"エントリーです。Cookie名と最大長は、フロントエンド設定の"capture cookie"文で定義します。未設定の場合は、単一のダッシュ(’-’)です。取得できるCookieは一つだけで、一般にはクライアントとサーバーのセッションIDの交換を追跡し、アプリケーションの不具合によるクライアント間のセッション混同を検出するために使います。詳細は後述の「HTTPヘッダーとCookieの取得」を参照してください。

  • “termination_state"は、ストリーム終了時の状態です。TCPログと同様に、ストリームの状態、どちら側が終了を引き起こしたか、その理由(タイムアウト、エラーなど)を示し、最後の二文字にはCookieの永続性に関する操作の情報を含みます。正常なフラグは”–“で始まり、バッファーにデータを残さず、どちらかの側がストリームを閉じたことを示します。詳細は後述の「切断時のストリーム状態」を参照してください。

  • “actconn"は、ストリームを記録した時点の、プロセス全体の同時接続数です。プロセス単位のシステム上限に達したことを検出するのに便利です。たとえば、複数の接続エラーが起きたときにactconnが512または1024に近ければ、システムがプロセスのファイルディスクリプター数を1024に制限し、すべて使い切っている可能性が高いと考えられます。システムの調整方法は、セクション3 「グローバルセクション」を参照してください。

  • “feconn"は、ストリームを記録した時点の、フロントエンドの同時接続数です。高負荷を維持するための必要リソース量を見積もり、フロントエンドの"maxconn"に達したことを検出するのに便利です。この値が急増する原因は、ほとんどの場合バックエンドサーバーの混雑ですが、サービス拒否攻撃の場合もあります。

  • “beconn"は、ストリームを記録した時点で、バックエンドが扱う同時接続の総数です。サーバー上で有効な同時接続の総数と、キューで待機中の接続数を含みます。アプリケーションの高負荷に対応するため、追加で必要なサーバー数を見積もるのに便利です。この値が急増する原因は、ほとんどの場合バックエンドサーバーの混雑ですが、サービス拒否攻撃の場合もあります。

  • “srv_conn"は、ストリームを記録した時点で、そのサーバー上にまだ残る有効な同時接続の総数です。サーバーに設定した"maxconn"を超えることはありません。この値が頻繁に"maxconn"に近づくか等しくなる場合、トラフィック調整が多く発生しています。つまり、サーバーのmaxconnが低すぎるか、最適な応答時間で負荷を処理するだけのサーバー数がありません。一台だけ"srv_conn"が高い場合、通常は、そのサーバーに問題があり、リクエストの処理が他のサーバーより長くかかっています。

  • “retries"は、このストリームがサーバーへの接続を試みたときの再試行回数です。接続試行と同時にサーバーを停止している場合を除き、通常はゼロでなければなりません。再試行が多い場合、一般にはHAProxyとサーバーの間のネットワーク問題、または新しい接続をキューに入れられないサーバーのシステムバックログの設定不備を示します。このフィールドの前に’+‘が付く場合があり、最初のサーバーで最大再試行回数に達した後、ストリームを再振り分けしたことを示します。その場合、ログのサーバー名は最初のサーバーではなく、再振り分け先です。ただし、ハッシュなどによって両者が同じになる場合もあります。したがって、一般的な目安として、再試行回数の前に’+‘がある場合、その回数をログに記載されたサーバーのものとみなすべきではありません。

  • “srv_queue"は、サーバーのキューで、このリクエストより前に処理したリクエストの総数です。サーバーのキューを通らなければゼロです。キューで過ごした時間をキュー内のリクエスト数で割ると、サーバーのおおよその応答時間を見積もれます。ストリームを再振り分けして二つのサーバーキューを通った場合、その位置を合算します。再振り分けがない限り、リクエストがサーバーキューとバックエンドキューの両方を通ることはないはずです。

  • “backend_queue"は、バックエンドのグローバルキューで、このリクエストより前に処理したリクエストの総数です。グローバルキューを通らなければゼロです。平均キュー長を見積もることができ、サーバーの"maxconn"で割れば、不足するサーバー数に容易に換算できます。再振り分けがあると、ストリームがバックエンドのキューを二度通る場合があり、その位置を合算します。再振り分けがない限り、リクエストがサーバーキューとバックエンドキューの両方を通ることはないはずです。

  • “captured_request_headers"は、フロントエンドの"capture request header"文によって、リクエストから取得したヘッダーの一覧です。複数のヘッダーを取得でき、縦棒(’|’)で区切ります。取得を有効にしていない場合、波括弧も現れないため、後続フィールドの位置がずれます。このフィールドは空白を含む場合があるので、使わない場合より高度なログパーサーが必要である点に注意してください。詳細は後述の「HTTPヘッダーとCookieの取得」を参照してください。

  • “captured_response_headers"は、フロントエンドの"capture response header"文によって、レスポンスから取得したヘッダーの一覧です。複数のヘッダーを取得でき、縦棒(’|’)で区切ります。取得を有効にしていない場合、波括弧も現れないため、後続フィールドの位置がずれます。このフィールドは空白を含む場合があるので、使わない場合より高度なログパーサーが必要である点に注意してください。詳細は後述の「HTTPヘッダーとCookieの取得」を参照してください。

  • “http_request"は、メソッド、リクエスト、HTTPバージョン文字列を含む、完全なHTTPリクエスト行です。印字できない文字は符号化します(後述の「印字できない文字」を参照)。常に最後のフィールドで、必ず引用符で囲み、引用符を含められる唯一のフィールドです。新しいフィールドを追加する場合は、この前に追加します。リクエストが大きく、標準のsyslogバッファー(1024文字)に収まらない場合、このフィールドは切り詰められることがあります。そのため、必ず最後に置かなければなりません。

8.2.4. HTTPSログ形式

HTTPS形式は、SSL上のHTTP接続に最も適しています。HTTP形式(セクション8.2.3 を参照)を拡張し、SSL関連情報を追加します。フロントエンドで"option httpslog"を指定すると有効になります。TCP形式やHTTP形式と同様、“option logasap"を指定しない限り、通常はストリーム終了時にログを出力します。“monitor"ルールにマッチするストリームは、決して記録しません。フロントエンドに"option dontlognull"を指定すると、クライアントがデータを送らなかったストリームを記録しないようにもできます。“option dontlog-normal"を指定すると、成功した接続は記録しません。

HTTPSログ形式は、内部では次の正確な文字列に基づくカスタムログ形式として定義しています。必要なら、これを基に形式を拡張できます。また、代わりにHAPROXY_HTTPS_LOG_FMT変数も使えます。使い方は、セクション8.2.6 「カスタムログ形式」を参照してください。

# strict equivalent of "option httpslog"
log-format "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC \
           %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r \
           %[fc_err]/%[ssl_fc_err,hex]/%[ssl_c_err]/\
           %[ssl_c_ca_err]/%[ssl_fc_is_resumed] %[ssl_fc_sni]/%sslv/%sslc"
# or using the HAPROXY_HTTPS_LOG_FMT variable
log-format "${HAPROXY_HTTPS_LOG_FMT}"

基本的にはHTTP形式(セクション8.2.3 を参照)の末尾に新しいフィールドを追加したものです。ここでは、新しいフィールド(17行目と18行目)を詳しく説明します。HTTPのフィールドは、HTTPの節を参照してください。

例:

    frontend https-in
        mode http
        option httpslog
        log global
        bind *:443 ssl crt mycerts/srv.pem ...
        default_backend bck

    backend static
        server srv1 127.0.0.1:8000 ssl crt mycerts/clt.pem ...

>>> Feb  6 12:14:14 localhost \
      haproxy[14389]: 10.0.1.2:33317 [06/Feb/2009:12:14:14.655] https-in \
      static/srv1 10/0/30/69/109 200 2750 - - ---- 1/1/1/1/0 0/0 {1wt.eu} \
      {} "GET /index.html HTTP/1.1" 0/0/0/0/0 \
      1wt.eu/TLSv1.3/TLS_AES_256_GCM_SHA384

フィールド 形式 上記の例からの抜粋

    1   process_name '[' pid ']:'                              haproxy[14389]:
    2   client_ip ':' client_port                               10.0.1.2:33317
    3   '[' request_date ']'                        [06/Feb/2009:12:14:14.655]
    4   frontend_name                                                 https-in
    5   backend_name '/' server_name                               static/srv1
    6   TR '/' Tw '/' Tc '/' Tr '/' Ta*                         10/0/30/69/109
    7   status_code                                                        200
    8   bytes_read*                                                       2750
    9   captured_request_cookie                                              -
   10   captured_response_cookie                                             -
   11   termination_state                                                 ----
   12   actconn '/' feconn '/' beconn '/' srv_conn '/' retries*      1/1/1/1/0
   13   srv_queue '/' backend_queue                                        0/0
   14   '{' captured_request_headers* '}'                     {haproxy.1wt.eu}
   15   '{' captured_response_headers* '}'                                  {}
   16   '"' http_request '"'                        "GET /index.html HTTP/1.1"
   17   fc_err '/' ssl_fc_err '/' ssl_c_err
        '/' ssl_c_ca_err '/' ssl_fc_is_resumed                       0/0/0/0/0
   18   ssl_fc_sni '/' ssl_version
        '/' ssl_ciphers                  1wt.eu/TLSv1.3/TLS_AES_256_GCM_SHA384

各フィールドの詳細:

  • “fc_err"は、フロントエンド側の接続状態です。“fc_err"サンプル取得関数に対応します。詳細は、“fc_err"と"fc_err_str"サンプル取得関数を参照してください。

  • “ssl_fc_err"は、フロントエンドから見た接続で最初に発生したSSLエラースタックの、最後のエラーです。たとえばSSLハンドシェイクのエラー検出に使えます。問題がなければ0です。詳細は、“ssl_fc_err"サンプル取得関数の説明を参照してください。

  • “ssl_c_err"は、クライアント証明書の検証処理の状態です。無視するエラーであれば、検証エラーコードがゼロでなくても、ハンドシェイクが成功する場合があります。“ssl_c_err"サンプル取得関数と"crt-ignore-err"オプションを参照してください。

  • “ssl_c_ca_err"は、クライアント証明書チェーンの検証処理の状態です。無視するエラーであれば、検証エラーコードがゼロでなくても、ハンドシェイクが成功する場合があります。“ssl_c_ca_err"サンプル取得関数と"ca-ignore-err"オプションを参照してください。

  • “ssl_fc_is_resumed"は、受信したTLSセッションを、状態を保持するキャッシュまたは状態を持たないチケットで再開した場合に真です。TLSセッションは複数のリクエストで共有できることを忘れないでください。

  • “ssl_fc_sni"は、使う証明書を選ぶため、クライアントが提示したSNI(Server Name Indication)です。通常は、接続の最初のリクエストのホスト名と一致します。このフィールドがない場合、クライアントがSNIを送らなかった可能性があり、haproxyはデフォルト証明書を使うか、strict-sniの場合は接続を拒否します。

  • “ssl_version"は、フロントエンドのSSLバージョンです。

  • “ssl_ciphers"は、接続で使ったSSL暗号です。

8.2.5. エラーログ形式

SSLハンドシェイクや不正なPROXYプロトコルヘッダーが原因で着信接続に失敗すると、“error-log-format"行で専用のエラーログ形式を定義していない限り、HAProxyは短い固定形式の行で記録します。デフォルトのレベルはLOG_INFOですが、バックエンドで"log-separate-errors"を設定している場合はLOG_ERRです。“dontlognull"を設定していれば、データを交換しなかった接続(プローブなど)は記録しません。

デフォルトの形式は次のとおりです。

  >>> Dec  3 18:27:14 localhost \
        haproxy[6103]: 127.0.0.1:56059 [03/Dec/2012:17:35:10.380] frt/f1: \
        Connection error during SSL handshake

項目    形式                                  上記の例からの抜粋
    1   process_name '[' pid ']:'                             haproxy[6103]:
    2   client_ip ':' client_port                            127.0.0.1:56059
    3   '[' accept_date ']'                       [03/Dec/2012:17:35:10.380]
    4   frontend_name "/" bind_name ":"                              frt/f1:
    5   message                        Connection error during SSL handshake

これらのフィールドは、接続失敗のデバッグに役立つ最小限の情報だけを提供します。

“error-log-format"ディレクティブを使うと、上記の従来の形式は使わず、すべてのエラーログ行が定義した形式に従います。

以下は、十分に網羅的なerror-log-formatの例です。送信元アドレスとポート、接続のaccept()日時、フロントエンド名、プロセスとそのフロントエンドの有効な接続数、フロント接続に関するhaproxy内部のエラー識別子、16進数のOpenSSLエラー番号(“openssl errstr"へコピーして完全に解読できます)、クライアント証明書の抽出状態(0はエラーなし)、CAを使ったクライアント証明書の検証状態(0はエラーなし)、接続が新規か再開かを示す真偽値、クライアントが任意で提示したサーバー名表示(SNI)、SSLバージョン名、接続で使ったSSL暗号があればそれも報告します。バックエンドの接続エラーは、ここでは決して報告しません。バックエンド接続が失敗する場合、それ以前にストリームは正常に進んでいるため、通常のトラフィックログに記録するからです(option httplogまたはoption httpslogを参照)。

# detailed frontend connection error log
error-log-format "%ci:%cp [%tr] %ft %ac/%fc %[fc_err]/\
      %[ssl_fc_err,hex]/%[ssl_c_err]/%[ssl_c_ca_err]/%[ssl_fc_is_resumed] \
      %[ssl_fc_sni]/%sslv/%sslc"

8.2.6. カスタムログ形式

もともと、カスタムログ形式はログの生成だけに使っていました。しかし、複雑な複数の式を組み合わせて文字列を作る際に便利なため、以前は文字列だけを引数に取っていた多くのディレクティブでも採用され、現在はカスタムログ形式の定義も受け付けます。この文書では、こうした引数を通常”<fmt>“と示します。ここで説明する"log-format"ディレクティブの引数と、まったく同じ方法で定義します。

ログについては、デフォルトの形式で不十分なら、新しい形式を非常に細かく定義できます。ただし、一から作るのは必ずしも簡単ではないため、まず既存形式(“option tcplog”、“option httplog”、“option httpslog”)を見て、要望に最も近いものを選び、対応する"log-format"文字列をコピーして調整することを強く推奨します。

設定上、カスタムログ形式の定義は単一の引数です。したがって、バックスラッシュ(’\’)でエスケープするか、定義全体を引用符で囲まない限り、空白やタブを含められません。全体を引用符で囲む方法を推奨します。引用符のない形式文字列は、バックスラッシュが一つ欠けるだけで、形式が黙って切り詰められることがあり、誤りが多いことが分かっているため、現在は推奨しません。引用符が使えるようになる3年前の1.5-dev9以降、ログ形式が広く採用されたため、こうした設定は今もよく見かけますが、引用符で囲んだ文字列に変換し、バックスラッシュを取り除くことを推奨します。

ログ形式の定義は、テキストと空白で区切った任意の数のログ形式項目で構成します。項目は’%‘で始めます。’%‘そのものを出力するには、前にもう一つ’%‘を付け、’%%‘にしなければなりません。

ログ形式の項目には、別名またはサンプル式を使えます。

項目を角括弧(’[’ .. ‘]’)で囲むと、サンプル式のルールとして使います(セクション7.3 を参照)。クライアントSSL証明書のDNなど、あまり一般的でない情報を追加したり、スティックテーブルにエントリーを保存する際に使うキーを記録したりするのに便利です。ヘッダー操作や変数など、ログ以外のアクションでもよく使います。

それ以外で、項目が英数字の名前なら、別名です(使用可能な別名は下表を参照)。

項目は波括弧(’{}’)で引数を取れます。複数の引数は、波括弧内でカンマ区切りにします。フラグの前に’+‘または’-‘を付けると、追加または削除できます(使用可能なフラグは後述)。

特殊な別名”%o"は、そのフラグを、同じ形式文字列の他のすべての項目へ伝播できます。特に、引用符で囲む形式(“Q”)や、エスケープする形式(“E”)に便利です。

特殊な別名”%OG"は、ログの生成元(いつ、どこで生成したか)を、人が読める形式で取得できます。“option logasap"で特に便利です。ログ形式の式をいつ、どこで評価するかにより、一部のログ変数やサンプル取得関数が不完全な値を返したり、異なる動作をしたりするためです。次の値があります。

  • “sess_error”:セッションのエラー処理中にログを生成しました。
  • “sess_killed”:セッションの中止中にログを生成しました(生成途中のセッションを強制終了)。
  • “txn_accept”:フロントエンドの接続を受け入れた直後にログを生成しました。
  • “txn_request”:クライアントのリクエストを受信した後にログを生成しました。
  • “txn_connect”:バックエンドの接続を確立した後にログを生成しました。
  • “txn_response”:サーバーのレスポンス処理中にログを生成しました。
  • “txn_close”:クローズ前の最後のトランザクション段階でログを生成しました。
  • “unspec”:不明または未指定です。"%OG"が関係するのはログ出力時だけです。

項目には、任意で’()‘を使って名前を付けられます。名前は’%‘の直後、引数の前に指定しなければなりません。“json"や"cbor"などの符号化フラグを設定すると、自動的にキー名として使います。符号化フラグがないデフォルトの場合、項目名は無視します。また、名前の後に’:type’を付けると、出力を特定の型に強制できます。形式は%(itemname:itemtype)aliasnameまたは%(itemname:itemtype)[expr]で、itemtypeは’str’、‘sint’、‘bool’のいずれかです。型の指定が意味を持つのは、符号化方式を使う場合だけです。空の名前を指定して、無名の項目の出力型を強制することもできます。%(:itemtype)という形式で、たとえば、符号化を全体に設定していない場合に使います。詳細は以下のフラグ定義を参照してください。

カスタムログ形式は当初、ログ専用だったため、表示できない文字や安全でない文字(ASCIIコード32~126の範囲外と、その他の一部)は、使う場所に応じて特別に扱います。端末の出力を読みにくくする危険なコードを送らないよう、ログで具体的に何を行うかは、セクション8.6 で説明します。ヘッダーフィールド、ヘルスチェック、レスポンスのペイロードを作る場合は規則が緩く、HTTPヘッダーフィールドで禁止する文字だけを、’%‘を先頭に付けた16進符号に置き換えます。通常は問題ありませんが、文字をそのまま再現したい場合は、出力に影響することがあります。たとえば、エラーページや完全なレスポンスのペイロードを作る際に、改行が”%0A"と表示される場合です。

注意:設定ディレクティブ"log-format”、“log-format-sd”、“unique-id-format"では、空白を区切りとみなし、まとめます。

注意:RFC5424のsyslogメッセージ形式では、PARAM-VALUE内の’"’、’\’、’]‘は、前に’\‘を付けてエスケープするべきです(詳細はhttps://tools.ietf.org/html/rfc5424#section-6.3.3 を参照)。その場合は、“E"フラグの使用を検討してください。

次の項目フラグをサポートします(項目の引数で有効・無効にできます)。

  • Q:文字列を引用符で囲みます。
  • X:16進表現にします(IP、ポート、%Ts、%rt、%pid)。
  • E:文字列内の’"’、’\’、’]‘を、前に’\‘を付けてエスケープします(RFC5424の構造化データログ形式を想定しています)。
  • bin:バイナリデータを維持しようとします。バイナリデータを出力するサンプル式で、元のデータを保つのに便利です。ただし、NULLバイトを含む表示できない文字を生成し得る点に注意してください。ほとんどのsyslog受信先は、そうした文字を想定していません。したがって、主にset-var-fmt、リング、バイナリに対応するログ受信先での使用を想定しています。このオプションは、%oで全体に設定する場合だけ有効で、個々の項目に設定しても無視します。
  • json:値を自動的にJSON形式に符号化します(全体に設定した場合、名前のあるログ形式項目だけが対象です)。不完全な数値(logasap使用時の’%B’など)は、符号化しない場合には通常’+‘を付けますが、そのまま符号化します。また、’+E’オプションは無視します。セクション8.6 で説明するように、32..126の範囲外の文字は、JSONのエスケープシーケンスを使ってバイトごとにエスケープします。そのため、入力にかかわらず出力は表示可能なASCIIだけになります。これは有効なUTF-8シーケンスにも適用され、デコード後には非ASCIIテキストが個々のバイトとして現れます。たとえば、0xC3 0xA9で符号化したU+00E9は”\u00C3\u00A9"としてログに記録します。このようなテキストを保持するには、以下の"utf8"を参照してください。
  • utf8:“json"と組み合わせると、有効な複数バイトのUTF-8シーケンスをエスケープせずに出力できます。C1制御文字(U+0080からU+009F)は引き続きエスケープし、そのコードポイントで表します。不正なシーケンスはバイトごとにエスケープし、出力が常に有効なUTF-8になるようにします。有効なUTF-8をそのまま出力するため、クライアントが特殊な文字を使い、端末やログビューアーでのログ行の表示を変える可能性があります。たとえば、文字方向の変更、ゼロ幅文字、行や段落の区切り文字などです。そのため、信頼できるソースからの内容、またはログを端末に表示しない場合にだけ使用することを推奨します。“json"なしでは効果がありません。
  • cbor:値を自動的にCBOR形式に符号化します(全体に設定した場合、名前のあるログ形式項目だけが対象です)。デフォルトでは、stdoutに表示でき、通常のsyslog受信先でも使えるよう、CBORデータを16進形式で表します。jsonと同様、不完全な数値はそのまま符号化し、’+E’を無視します。’+bin’と組み合わせると、生のバイナリCBORペイロードを直接生成します。表示できない文字を生成する点に注意してください。したがって、主にset-var-fmt、リング、バイナリに対応するログ受信先での使用を想定しています。

例:

log-format %T\ %t\ Some\ Text
log-format %{+Q}o\ %t\ %s\ %{-Q}r

log-format-sd %{+Q,+E}o\ [exampleSDID@1234\ header=%[capture.req.hdr(0)]]

log-format "%{+json}o %(request)r %(custom_expr)[str(custom)]"
log-format "%{+json,+utf8}o %(request)r %(custom_expr)[str(custom)]"
log-format "%{+cbor}o %(request)r %(custom_expr)[str(custom)]"

現在定義されている別名は、下表を参照してください。

  +---+------+------------------------------------------------------+---------+
  | R | 別名 | フィールド名(説明は8.2.2と8.2.3)                   | 型      |
  |   |      | 代替となるサンプル取得                               |         |
  +===+======+======================================================+=========+
  |   | %o   | 特別:以降の全項目にフラグを適用                     |         |
  +---+------+------------------------------------------------------+---------+
  |                          日付形式                                         |
  +---+------+------------------------------------------------------+---------+
  |   | %T   | 受け入れ日時、UTC + タイムゾーン                     |         |
  |   |      | %[accept_date,utime("%d/%b/%Y:%H:%M:%S %z")]         | 日付    |
  +---+------+------------------------------------------------------+---------+
  |   | %Tl  | 受け入れ日時、ローカル + タイムゾーン                |         |
  |   |      | %[accept_date,ltime("%d/%b/%Y:%H:%M:%S %z")]         | 日付    |
  +---+------+------------------------------------------------------+---------+
  |   | %Ts  | 受け入れ日時、UNIXタイムスタンプ                     | 数値    |
  |   |      | %[accept_date]                                       |         |
  +---+------+------------------------------------------------------+---------+
  |   | %t   | 受け入れ日時、ローカル(ミリ秒精度)                 |         |
  |   |      | %[accept_date(ms),ms_ltime("%d/%b/%Y:%H:%M:%S.%3N")] | 日付    |
  +---+------+------------------------------------------------------+---------+
  |   | %ms  | 受け入れ日時のミリ秒部分                             |         |
  |   |      | %[accept_date(ms),ms_utime("%3N")]                   | 数値    |
  +---+------+------------------------------------------------------+---------+
  | H | %tr  | リクエスト日時、ローカル(ミリ秒精度)               |         |
  |   |      | %[request_date(ms),ms_ltime("%d/%b/%Y:%H:%M:%S.%3N")]| 日付    |
  +---+------+------------------------------------------------------+---------+
  | H | %trg | リクエスト日時、UTC + タイムゾーン                   |         |
  |   |      | %[request_date,utime("%d/%b/%Y:%H:%M:%S %z")]        | 日付    |
  +---+------+------------------------------------------------------+---------+
  | H | %trl | リクエスト日時、ローカル + タイムゾーン              |         |
  |   |      | %[request_date,ltime("%d/%b/%Y:%H:%M:%S %z")]        | 日付    |
  +---+------+------------------------------------------------------+---------+
  |                          時間計測のイベント                               |
  +---+------+------------------------------------------------------+---------+
  | H | %Ta  | リクエストの稼働時間(TRから終了まで)               |         |
  |   |      | %[txn.timer.total]                                   | 数値    |
  +---+------+------------------------------------------------------+---------+
  |   | %Tc  | Tc                                                   |         |
  |   |      | %[bc.timer.connect]                                  | 数値    |
  +---+------+------------------------------------------------------+---------+
  |   | %Td  | Td = Tt - (Tq + Tw + Tc + Tr)                        |         |
  |   |      | %[res.timer.data]                                    | 数値    |
  +---+------+------------------------------------------------------+---------+
  |   | %Th  | 接続のハンドシェイク時間(SSL、PROXYプロトコル)     |         |
  |   |      | %[fc.timer.handshake]                                | 数値    |
  +---+------+------------------------------------------------------+---------+
  | H | %Ti  | HTTPリクエスト前の待機時間                           |         |
  |   |      | %[req.timer.idle]                                    | 数値    |
  +---+------+------------------------------------------------------+---------+
  | H | %Tq  | Th + Ti + TR                                         |         |
  |   |      | %[req.timer.tq]                                      | 数値    |
  +---+------+------------------------------------------------------+---------+
  | H | %TR  | 先頭の1バイトからリクエスト全体の受信までの時間      |         |
  |   |      | %[req.timer.hdr]                                     | 数値    |
  +---+------+------------------------------------------------------+---------+
  | H | %Tr  | Tr(応答時間)                                       |         |
  |   |      | %[res.timer.hdr]                                     | 数値    |
  +---+------+------------------------------------------------------+---------+
  |   | %Tt  | Tt                                                   |         |
  |   |      | %[fc.timer.total]                                    | 数値    |
  +---+------+------------------------------------------------------+---------+
  |   | %Tu  | Tu                                                   |         |
  |   |      | %[txn.timer.user]                                    | 数値    |
  +---+------+------------------------------------------------------+---------+
  |   | %Tw  | Tw                                                   |         |
  |   |      | %[req.timer.queue]                                   | 数値    |
  +---+------+------------------------------------------------------+---------+
  |                          その他                                           |
  +---+------+------------------------------------------------------+---------+
  |   | %B   | bytes_read(サーバーからクライアントへ)             | 数値    |
  |   |      | %[res.bytes_in]                                      |         |
  +---+------+------------------------------------------------------+---------+
  | H | %CC  | captured_request_cookie                              | 文字列  |
  +---+------+------------------------------------------------------+---------+
  | H | %CS  | captured_response_cookie                             | 文字列  |
  +---+------+------------------------------------------------------+---------+
  |   | %H   | hostname                                             | 文字列  |
  |   |      | %[hostname]                                          |         |
  +---+------+------------------------------------------------------+---------+
  | H | %HM  | HTTPメソッド(例:POST)                             | 文字列  |
  |   |      | %[method]
  +---+------+------------------------------------------------------+---------+
  | H | %HP  | クエリー文字列を除いたHTTPリクエストURI              | 文字列  |
  +---+------+------------------------------------------------------+---------+
  | H | %HPO | HTTPパスのみ(ホストとクエリー文字列を除く)         | 文字列  |
  +---+------+------------------------------------------------------+---------+
  | H | %HQ  | HTTPリクエストURIのクエリー文字列(例:?bar=baz)    | 文字列  |
  |   |      | ?%[query]                                            |         |
  +---+------+------------------------------------------------------+---------+
  | H | %HU  | HTTPリクエストURI(例:/foo?bar=baz)                | 文字列  |
  +---+------+------------------------------------------------------+---------+
  | H | %HV  | HTTPバージョン(例:HTTP/1.0)                       | 文字列  |
  |   |      | HTTP/%[req.ver]                                      |         |
  +---+------+------------------------------------------------------+---------+
  |   | %ID  | unique-id                                            | 文字列  |
  |   |      | %[unique-id]                                         |         |
  +---+------+------------------------------------------------------+---------+
  |   | %ST  | status_code                                          | 数値    |
  |   |      | %[txn.status]                                        |         |
  +---+------+------------------------------------------------------+---------+
  |   | %U   | bytes_uploaded(クライアントからサーバーへ)         | 数値    |
  |   |      | %[req.bytes_in]                                      |         |
  +---+------+------------------------------------------------------+---------+
  |   | %ac  | actconn                                              |         |
  |   |      | %[act_conn]                                          | 数値    |
  +---+------+------------------------------------------------------+---------+
  |   | %b   | backend_name                                         |         |
  |   |      | %[be_name]                                           | 文字列  |
  +---+------+------------------------------------------------------+---------+
  |   | %bc  | beconn(バックエンドの同時接続数)                   | 数値    |
  |   |      | %[be_conn]                                           |         |
  +---+------+------------------------------------------------------+---------+
  |   | %bi  | backend_source_ip(接続元アドレス)                  |         |
  |   |      | %[bc_src]                                            | IP      |
  +---+------+------------------------------------------------------+---------+
  |   | %bp  | backend_source_port(接続元アドレス)                |         |
  |   |      | %[bc_src_port]                                       | 数値    |
  +---+------+------------------------------------------------------+---------+
  |   | %bq  | backend_queue                                        | 数値    |
  |   |      | %[bc_be_queue]                                       |         |
  +---+------+------------------------------------------------------+---------+
  |   | %ci  | client_ip(受け入れたアドレス)                      |         |
  |   |      | %[src]                                               | IP      |
  +---+------+------------------------------------------------------+---------+
  |   | %cp  | client_port(受け入れたアドレス)                    |         |
  |   |      | %[src_port]                                          | 数値    |
  +---+------+------------------------------------------------------+---------+
  |   | %f   | frontend_name                                        | 文字列  |
  |   |      | %[fe_name]                                           |         |
  +---+------+------------------------------------------------------+---------+
  |   | %fc  | feconn(フロントエンドの同時接続数)                 | 数値    |
  |   |      | %[fe_conn]                                           |         |
  +---+------+------------------------------------------------------+---------+
  |   | %fi  | frontend_ip(受け入れるアドレス)                    |         |
  |   |      | %[dst]                                               | IP      |
  +---+------+------------------------------------------------------+---------+
  |   | %fp  | frontend_port(受け入れるアドレス)                  |         |
  |   |      | %[dst_port]                                          | 数値    |
  +---+------+------------------------------------------------------+---------+
  |   | %ft  | frontend_name_transport(SSLは末尾に'~')            | 文字列  |
  +---+------+------------------------------------------------------+---------+
  |   | %lc  | frontend_log_counter                                 | 数値    |
  +---+------+------------------------------------------------------+---------+
  |   | %hr  | captured_request_headers、デフォルト形式             | 文字列  |
  +---+------+------------------------------------------------------+---------+
  |   | %hrl | captured_request_headers、CLF形式                    | 文字列  |
  |   |      |                                                      | リスト  |
  +---+------+------------------------------------------------------+---------+
  |   | %hs  | captured_response_headers、デフォルト形式            | 文字列  |
  +---+------+------------------------------------------------------+---------+
  |   | %hsl | captured_response_headers、CLF形式                   | 文字列  |
  |   |      |                                                      | リスト  |
  +---+------+------------------------------------------------------+---------+
  | L | %OG  | 人が読める形式のログ生成元                           | 文字列  |
  +---+------+------------------------------------------------------+---------+
  |   | %pid | PID                                                  |         |
  |   |      | %[pid]                                               | 数値    |
  +---+------+------------------------------------------------------+---------+
  | H | %r   | http_request                                         | 文字列  |
  +---+------+------------------------------------------------------+---------+
  |   | %rc  | retries                                              | 数値    |
  |   |      | %[txn.redispatched,iif(+,)]%[txn.conn_retries]       |         |
  +---+------+------------------------------------------------------+---------+
  |   | %rt  | request_counter(HTTPリクエストまたはTCPセッション) | 数値    |
  |   |      | %[txn.id32]                                          |         |
  +---+------+------------------------------------------------------+---------+
  |   | %s   | server_name                                          | 文字列  |
  |   |      | %[srv_name]                                          |         |
  +---+------+------------------------------------------------------+---------+
  |   | %sc  | srv_conn(サーバーの同時接続数)                     | 数値    |
  +---+------+------------------------------------------------------+---------+
  |   | %si  | server_IP(宛先アドレス)                            |         |
  |   |      | %[bc_dst]                                            | IP      |
  +---+------+------------------------------------------------------+---------+
  |   | %sp  | server_port(宛先アドレス)                          |         |
  |   |      | %[bc_dst_port]                                       | 数値    |
  +---+------+------------------------------------------------------+---------+
  |   | %sq  | srv_queue                                            | 数値    |
  |   |      | %[bc_srv_queue]                                      |         |
  +---+------+------------------------------------------------------+---------+
  | S | %sslc| ssl_ciphers(例:AES-SHA)                           |         |
  |   |      | %[ssl_fc_cipher]                                     | 文字列  |
  +---+------+------------------------------------------------------+---------+
  | S | %sslv| ssl_version(例:TLSv1)                             |         |
  |   |      | %[ssl_fc_protocol]                                   | 文字列  |
  +---+------+------------------------------------------------------+---------+
  |   | %ts  | termination_state                                    | 文字列  |
  |   |      | %[txn.sess_term_state]                               |         |
  +---+------+------------------------------------------------------+---------+
  | H | %tsc | termination_state、Cookieの状態を含む                | 文字列  |
  +---+------+------------------------------------------------------+---------+
R = 制約:H = mode httpのみ; S = SSLのみ; L = ログのみ

8.3. 高度なログオプション

よく求められる高度なログ機能でも、各種オプションを見るだけでは見つけにくいものがあります。よりよいログを実現するいくつかのオプションを、ここで案内します。使用方法の詳細は、キーワードリファレンスを参照してください。

8.3.1. 外部テストのログを無効にする

監視ツールがHAProxyのヘルスチェックを行うのは一般的です。LVSや商用製品などのレイヤー3ロードバランサーの場合もあれば、Nagiosなどの本格的な監視システムの場合もあります。テストが非常に頻繁だと、そのチェックのログを無効にする方法がよく求められます。三つの方法があります。

  • さまざまな送信元からの単なるTCPプローブなら、フロントエンドで"option dontlognull"を設定し、データを交換しない接続を記録しない方法がよく使われます。ポートスキャンも記録しなくなるため、それが望ましいかは場合によります。

  • 送信元ネットワーク、パス、User-Agentなど、さまざまな条件で"http-request set-log-level silent"アクションを使えます。

  • 既知のURIでテストする場合は、“monitor-uri"で監視専用のURIとして宣言します。このリクエストを送ったホストには、ヘルスチェックの結果だけを返し、リクエストを記録しません。

8.3.2. ストリームの終了を待たずに記録する

接続終了時に記録する問題点は、リモート端末のセッションや大きなファイルのダウンロードなど、非常に長いストリームの途中で何が起きているか分からないことです。フロントエンドに"option logasap"を指定すると回避できます。HAProxyは、データ転送を始める直前、可能な限り早く記録します。TCPではサーバーへの接続状態を記録し、HTTPではサーバーのヘッダーを処理した直後に記録します。この場合、報告するバイト数は、クライアントへ送ったヘッダーのバイト数です。通常のログと混同しないよう、合計時間とバイト数の前に’+‘を付け、実際の値は確実にこれより大きいことを示します。

8.3.3. エラー時にログレベルを上げる

ログファイルからエラーを監視しやすくするなど、通常のトラフィックとエラーログを分けると便利な場合があります。“log-separate-errors"を使うと、エラー、タイムアウト、再試行、再振り分け、HTTPステータス5xxを経験した接続のsyslogレベルを、“info"から"err"に上げます。syslogデーモンが別ファイルに保存しやすくなります。ただし、ログの順序を変えないため、通常のトラフィックファイルにもエラーを残すことが非常に重要です。また、“notice"より高いレベルをすべて"admin"ファイルに保存する設定がすでにある場合、“err"は"notice"より高いので注意してください。

8.3.4. 成功した接続のログを無効にする

最初は奇妙に思えるかもしれませんが、大規模なサイトでは毎秒何千ものログを扱い、長期間そのまま保持したり、その中からエラーを見つけたりするのが困難な場合があります。フロントエンドで"dontlog-normal"を設定すると、正常な接続をすべて記録しません。ここで正常とは、エラー、タイムアウト、再試行、再振り分けがない接続です。HTTPではステータスコードも確認し、5xxレスポンスは正常とみなさず、記録します。ただし、有用な情報の大半がログから失われるため、この方法は強く非推奨とします。他に選択肢がない場合だけ使ってください。

8.3.5. ログプロファイル

“log-format”、“log-format-sd”、“error-log-format”、“log-tag"などにより、グローバルまたはプロキシ単位でログ形式を設定できますが、ログの送信先にできるだけ近い単位、つまり"log"ディレクティブごとに設定したい場合もあります。

そこで使うのが、設定内のどこにでも定義できる"log-profile"セクションです。このセクションは、特定のlogディレクティブで出力するログの構成方法を記述する、さまざまなキーワードを受け付けます。

“log"ディレクティブから、特定のlog-profileを名前で選べます。同じプロファイルを、複数の"log"ディレクティブで使えます。

log-profile <name> <name>で識別する新しいログプロファイルを作成します。

log-tag <string> “log-tag"でグローバルまたはプロキシ単位に設定したsyslogのログタグを上書きします。

on <step> [drop] [format <fmt>] [sd <sd_fmt>] <step>のログ段階で通常使う、ログ行生成用のlog-format文字列を上書きします。<fmt>は、<step>に応じて"log-format"または"error-log-format"を、<sd_fmt>は"log-format-sd"を上書きします。両方を組み合わせられます。

特殊キーワード"drop"は、指定した<step>でログを出力しないことを指定します。“format"や"sd"を先に定義していても、それらより優先します。

<step>には次の値を指定できます。

  • “accept”:フロントエンドの接続を受け入れた直後に生成するログのlog-formatを上書きします。
  • “request”:クライアントのリクエストを受信した後に生成するログのlog-formatを上書きします。
  • “connect”:バックエンドの接続を確立した後に生成するログのlog-formatを上書きします。
  • “response”:サーバーのレスポンス処理中に生成するログのlog-formatを上書きします。
  • “close”:トランザクション(txn)の最後の段階で生成するログのlog-formatを上書きします。
  • “error”:トランザクションエラーによって生成するログのerror-log-formatを上書きします。
  • “any”:より具体的な段階の上書きを宣言していない限り、すべてのログ段階でlog-formatとerror-log-formatの両方を上書きします。

追加の<step>値については、“do-log"アクションを参照してください。

この設定が意味を持つのは、HTTP/TCPプロキシなど、“log-format"を使う意味がある文脈の"log"ディレクティブだけです。それ以外では、単に無視します。

例:

log-profile myprof

  log-tag "custom-tag"

  on error format "%ci: error"
  on connect drop
  on any sd "custom-sd"

listen myproxy
  mode http
  option httplog
  log-tag "normal"

  log stdout format rfc5424 local0
  # success:
  # <134>1 2024-06-12T10:09:11.823400+02:00 - normal 224482 - - 127.0.0.1:53594 [12/Jun/2024:10:09:11.814] myproxy myproxy/<NOSRV> 0/-1/-1/-1/0 200 49 - - LR-- 1/1/0/0/0 0/0 "GET / HTTP/1.1"
  #
  # error:
  # <134>1 2024-06-12T10:09:44.810929+02:00 - normal 224482 - - 127.0.0.1:59258 [12/Jun/2024:10:09:44.426] myproxy myproxy/<NOSRV> -1/-1/-1/-1/384 400 0 - - CR-- 1/1/0/0/0 0/0 "<BADREQ>"

  log 127.0.0.1:514 format rfc5424 profile myprof local0
  # success:
  # <134>1 2024-06-12T10:09:11.823428+02:00 - custom-tag 224482 - custom-sd 127.0.0.1:53594 [12/Jun/2024:10:09:11.814] myproxy myproxy/<NOSRV> 0/-1/-1/-1/0 200 49 - - LR-- 1/1/0/0/0 0/0 "GET / HTTP/1.1"
  #
  # error:
  # <134>1 2024-06-12T10:09:51.566524+02:00 - custom-tag 224482 - - 127.0.0.1: error

8.4. イベントのタイミング

タイマーは、ネットワーク問題の診断に大きく役立ちます。すべての値をミリ秒(ms)で報告します。ストリームの終了フラグと組み合わせて使うべきです。フロントエンドで"option tcplog"を設定したTCPモードでは、3つの測定点を"Tw/Tc/Tt"形式で報告し、HTTPモードでは5つを"TR/Tw/Tc/Tr/Ta"形式で報告します。さらに、“Th”、“Ti”、“Tq"の三つの測定値もあります。

HTTPモードのイベントのタイミング:

           最初のリクエスト                   2番目のリクエスト
      |<-------------------------------->|<-------------- ...
      t         tr                       t    tr ...
   ---|----|----|----|----|----|----|----|----|--
     : Th   Ti   TR   Tw   Tc   Tr   Td: Ti   ...
     :<---- Tq ---->:                  :
     :<-------------- Tt -------------->:
     :<--        -----Tu--------------->:
               :<--------- Ta --------->:

TCPモードのイベントのタイミング:

          TCPセッション
      |<----------------->|
      t                   t
   ---|----|----|----|----|---
      | Th   Tw   Tc   Td |
      |<------ Tt ------->|
  • Th:TCP接続を受け入れ、低レベルプロトコルのハンドシェイクを実行する合計時間です。現在の対象はproxy-protocolとSSLです。接続の生存期間全体で、一度だけ発生し得ます。大きな値は、クライアントが接続だけを先に確立して何も送っていない、適切な時間内のハンドシェイク完了を妨げるネットワーク問題(MTU問題など)がある、またはSSLハンドシェイクの計算コストが非常に高かったことを示す場合があります。最初のリクエストの前だけに報告するため、全リクエストで平均して、償却した値を求めても問題ありません。二番目以降のリクエストでは、常にゼロです。

    このタイマーは、ログ形式の別名では%Th、サンプル取得関数ではfc.timer.handshakeです。

  • Ti:HTTPリクエストの前のアイドル時間です(HTTPモードのみ)。ハンドシェイクの終了から、HTTPリクエストの最初のバイトまでを計測します。keep-aliveで二番目のリクエストを扱う場合、前のレスポンスの送信終了後に計測を始めます。HTTP/2などの多重化プロトコルでは、前のリクエストの直後に始めます。一部のブラウザーは、後のリクエストの遅延を減らすため、先にサーバーへの接続を確立し、必要になるまで待機させます。この待ち時間をアイドル時間として報告します。-1は、接続上で何も受信しなかったことを示します。

    このタイマーは、ログ形式の別名では%Ti、サンプル取得関数ではreq.timer.idleです。

  • TR:クライアントのリクエストを受信する合計時間です(HTTPモードのみ)。最初のバイトを受信してから、HTTPヘッダーの終端を示す空行をプロキシが受信するまでです。"-1"は、ヘッダーの終端を一度も確認しなかったことを示します。クライアントが早期に閉じたり、タイムアウトしたりすると起こります。ほとんどのリクエストは一つのパケットに収まるため、通常は非常に短い時間です。大きな値は、テストでリクエストを手入力したことを示す場合があります。

    このタイマーは、ログ形式の別名では%TR、サンプル取得関数ではreq.timer.hdrです。

  • Tq:接続の受け入れ、または前のレスポンスの最後のバイトを送信してから、クライアントのリクエストを受信するまでの合計時間です(HTTPモードのみ)。Th + Ti + TRに厳密に一致しますが、いずれかが-1なら、これも-1です。HTTP keep-aliveやブラウザーの事前接続機能が登場する前には、非常に便利なタイマーでした。現在は、アイドル時間が報告の大きな雑音になるため、代わりにTRを使うことを推奨します。

    このタイマーは、ログ形式の別名では%Tq、サンプル取得関数ではreq.timer.tqです。

  • Tw:接続枠を待ち、キューで過ごした合計時間です。バックエンドキューとサーバーキューの両方を含み、キューサイズと、サーバーが先行リクエストを完了する時間によります。"-1"は、キューに到達する前にリクエストを強制終了したことを示し、通常は不正または拒否したリクエストで起こります。

    このタイマーは、ログ形式の別名では%Tw、サンプル取得関数ではreq.timer.queueです。

  • Tc:サーバーへのTCP接続を確立する合計時間です。プロキシが接続要求を送ってからサーバーが応答確認するまで、つまりTCP SYNから、それに対応して返ってくるSYN/ACKまでの時間です。"-1"は、接続が一度も確立しなかったことを示します。

    このタイマーは、ログ形式の別名では%Tc、サンプル取得関数ではbc.timer.connectです。

  • Tr:サーバーの応答時間です(HTTPモードのみ)。サーバーへのTCP接続の確立から、サーバーが完全なレスポンスヘッダーを送るまでの時間です。データ転送のネットワーク負荷を除いた、リクエスト処理時間そのものを示します。ただし、POSTリクエストなどでクライアントがサーバーへデータを送る間も、すでに計測は進んでいるため、見かけの応答時間がゆがむ場合があります。そのため、信頼できないネットワークの背後にいるクライアントからのPOSTでは、このフィールドを過信しないのが賢明です。"-1"は、最後のレスポンスヘッダー(空行)を一度も確認しなかったことを示します。多くの場合、サーバーがリクエストを処理する前にサーバータイムアウトになったか、不正なレスポンスを返したためです。

    このタイマーは、ログ形式の別名では%Tr、サンプル取得関数ではres.timer.hdrです。

  • Td:レスポンスのペイロードを、最後のバイトをクライアントへ送るまで転送した合計時間です。HTTPでは、最後のレスポンスヘッダーの後(Trの後)から始まります。

    送ったデータがクライアントに届いた保証はなく、カーネルやネットワーク内で止まっている場合があります。

    このタイマーは、ログ形式の別名では%Td、サンプル取得関数ではres.timer.dataです。

  • Ta:HTTPリクエストの合計有効時間です。プロキシがリクエストヘッダーの最初のバイトを受信してから、レスポンスボディーの最後のバイトを送るまでです。“logasap"を指定した場合は例外で、(TR+Tw+Tc+Tr)だけになり、前に’+‘が付きます。このフィールドから、他の有効なタイマーを引くことで、データ転送時間"Td"を求められます。

Td = Ta - (TR + Tw + Tc + Tr)
値が"-1"のタイマーは、この式から除かなければなりません。"Ta"が負になることはありません。

このタイマーは、ログ形式の別名では%Ta、サンプル取得関数ではtxn.timer.totalです。
  • Tt:ストリームの合計持続時間です。プロキシが受け入れてから、両端が閉じるまでを計測します。“logasap"を指定した場合は例外で、(Th+Ti+TR+Tw+Tc+Tr)だけになり、前に’+‘が付きます。このフィールドから、他の有効なタイマーを引くことで、データ転送時間"Td"を求められます。
Td = Tt - (Th + Ti + TR + Tw + Tc + Tr)
値が"-1"のタイマーは、この式から除かなければなりません。TCPモードでは、"Ti"、"Tq"、"Tr"も除く必要があります。"Tt"が負になることはなく、HTTPでは単純に(Th+Ti+Ta)と等しくなります。

このタイマーは、ログ形式の別名では%Tt、サンプル取得関数ではfc.timer.totalです。
  • Tu:クライアントから見た推定合計時間です。プロキシの受け入れから両端が閉じるまでの時間から、アイドル時間を除きます。リクエスト間のkeep-alive待ち時間に影響されず、利用者が感じるエンドツーエンド時間を概算するのに便利です。両方向のネットワーク遅延が同じと仮定するため、あくまで利用者から見た時間の推定です。“logasap"を指定した場合は例外で、(Th+TR+Tw+Tc+Tr)だけになり、前に’+‘が付きます。

    このタイマーは、ログ形式の別名では%Tu、サンプル取得関数ではtxn.timer.userです。

これらのタイマーは、問題の原因を示す貴重な手掛かりになります。TCPプロトコルは再送間隔を3、6、12…秒と規定しているため、3sの倍数に近い値は、ほぼ常にネットワーク問題(配線、ネゴシエーション、混雑)によるパケット損失に関係すると判断できます。また、“Ta"や"Tt"が設定のタイムアウト値に近ければ、タイムアウトによりストリームを中止したことを示す場合が多くあります。

よくあるケース:

  • “Th"や"Ti"が3000に近ければ、クライアントとプロキシの間でおそらくパケットを失っています。ローカルネットワークでは非常にまれですが、遠隔ネットワークのクライアントが大きなリクエストを送る場合には起こり得ます。ネットワークに原因がなくても、通常より大きな値が現れる場合があります。攻撃中やリソース不足が解消した直後に、HAProxyが数ミリ秒で何千もの接続を受け入れることがあります。その処理は、他の接続の処理をどうしても少し遅らせるため、数千の新規接続を一度に受け入れた後、数十ミリ秒程度のリクエスト時間を計測する場合があります。“Ti"は追加リクエストを待つ時間を測るため、keep-aliveモードでは長いアイドル時間が表示されることがあります。

  • “Tc"が3000に近ければ、サーバー接続の段階で、サーバーとプロキシの間のおそらくパケットを失っています。この値は常に非常に小さいはずで、ローカルネットワークなら1 ms、遠隔ネットワークでも数十ms未満などです。

  • “Tr"がほぼ常に3000未満で、ときどき平均値に3000を加えたような値が現れる場合、プロキシとサーバーの間でおそらくパケットを失っています。

  • バイト数が少ないのに"Ta"が大きい場合、一般には、HAProxyがトンネルモードで動作し、クライアントとサーバーがkeep-aliveに合意したまま、どちらも接続を閉じないためです。解決するには、フロントエンドまたはバックエンドで、keep-aliveやcloseを制御するHTTPオプションを指定する必要があります。サーバーの"maxconn"で接続を調整する場合、既存の接続が解放されるまで新しい接続を送れないため、‘Ta’や’Tt’をできるだけ小さくすることが重要です。

その他の注目すべきHTTPログの例(‘xx’は無視してよい任意の値):

TR/Tw/Tc/Tr/+Ta  フロントエンドに"option logasap"があり、データ転送段階の前に
                 ログを出力しました。"Ta"は実際より短くなりますが、それ以外の
                 タイマーはすべて有効です。

-1/xx/xx/xx/Ta   クライアントが時間内にリクエストを完送できなかったか、
                 早すぎる段階で中断しました。ストリームの終了フラグを確認し、
                 次に"timeout http-request"と"timeout client"の設定を確認します。

TR/-1/xx/xx/Ta   リクエストを処理できませんでした。サーバーが動作していない、
                 リクエストが不正、ACLルールで禁止されているなどの可能性があります。
                 ストリームの終了フラグを確認します。

TR/Tw/-1/xx/Ta   サーバーへの接続を確立できませんでした。サーバーが明示的に
                 拒否したか、Ta-(TR+Tw) ms後にタイムアウトしました。
                 ストリームの終了フラグを確認し、次に"timeout connect"の設定を
                 確認します。tarpitアクションでも似たパターンを返す場合があり、
                 その場合は、"Tw"がクライアント接続を開いたままにした時間に
                 等しくなる点に注意してください。

TR/Tw/Tc/-1/Ta   サーバーは接続を受け入れましたが、時間内に完全なレスポンスを
                 返さなかったか、Ta-(TR+Tw+Tc) ms後に予期せず接続を閉じました。
                 ストリームの終了フラグを確認し、次に"timeout server"の設定を
                 確認します。

8.5. 切断時のストリーム状態

TCPログとHTTPログは、有効な接続数の直前の"termination_state"フィールドで、ストリーム終了の指標を示します。TCPでは2文字、HTTPでは4文字に拡張し、各文字に固有の意味があります。

  • 最初の文字は、ストリームの終了を引き起こした最初のイベントを示すコードです。
C: クライアントがTCPセッションを予期せず中断しました。

S: サーバーがTCPセッションを予期せず中断したか、明示的に拒否しました。

P: プロキシがストリームまたはセッションを途中で中断しました。
    接続数の制限を適用した、DENYフィルターにマッチした、または
    情報漏洩につながり得る危険なサーバーレスポンスの不備
    (キャッシュ可能なCookieなど)を、セキュリティ検査が検出して
    遮断したことが理由です。

L: HAProxyがストリームをローカルで処理しました。

R: プロキシのリソース(メモリー、ソケット、送信元ポートなど)が
    枯渇しました。通常は接続段階で発生し、正確なエラーの写しが
    システムログにあるはずです。発生したら、非常に重大な異常と
    みなさなければならず、あらゆる手段で、できるだけ早く修正すべきです。

I: 自己検査中に、プロキシが内部エラーを特定しました。決して発生すべき
    ではないもので、ほぼ間違いなく不具合なので、このフラグを含むログは
    すべて報告することを推奨します。メモリー破損が原因の場合に備え、
    このような事象の後は、予防的にプロセスを再起動するのも賢明です。

D: サーバーの停止を検出し、停止時にはすべての接続を切る設定に
    なっていたため、HAProxyがストリームを終了させました。

U: アクティブサーバーの稼働を検出し、稼働開始時にはバックアップ接続を
    すべて切る設定になっていたため、HAProxyがこのバックアップサーバーの
    ストリームを終了させました。

K: HAProxyを操作する管理者が、ストリームを明示的に終了させました。

c: クライアントのデータ送信または受信を待つ間に、クライアント側の
    タイムアウトが満了しました。

s: サーバーのデータ送信または受信を待つ間に、サーバー側の
    タイムアウトが満了しました。

-: ストリームが正常に完了し、クライアントとサーバーの両方が、
    バッファーにデータを残さず閉じました。
  • 二番目の文字は、閉じた時点のTCPまたはHTTPストリームの状態です。
R: プロキシが、クライアントからの完全で有効なリクエストを待っていました
    (HTTPモードのみ)。どのサーバーへも、何も送っていません。

Q: プロキシが、接続枠をキューで待っていました。サーバーに'maxconn'
    パラメーターが設定されている場合だけに起こります。また、停止中の
    サーバーへの接続試行に失敗し、その後の再振り分けでグローバルキューに
    入った場合も起こります。再振り分けの記録がなければ、どのサーバーへも
    接続を試みていません。

C: プロキシが、サーバーへの接続確立を待っていました。サーバーは、
    多くても接続の試行に気づいた程度です。

H: プロキシが、サーバーからの完全で有効なレスポンスヘッダーを
    待っていました(HTTPのみ)。

D: ストリームは、データ転送段階にありました。

L: サーバーは既に完了していましたが、プロキシはまだ最後のデータを
    クライアントへ送っていました。最後のパケットを受信中にクライアントが
    停止した場合だけに起こるため、非常にまれです。

T: リクエストをtarpitで引き延ばしました。"timeout tarpit"の全期間、
    またはクライアントが閉じるまで、クライアントとの接続を開いたままに
    しました。どちらも、その時間を"Tw"タイマーに記録します。

-: データ転送の終了後、ストリームが正常に完了しました。
  • 三番目の文字は、クライアントが永続性Cookieを送ったかどうかを示します(HTTPモードのみ)。
N: クライアントはCookieを送りませんでした。通常は新規訪問者の場合なので、
    ログ内のこのフラグの出現回数を数えると、一般に、サイトの訪問状況の
    傾向を把握できます。

I: クライアントが、既知のサーバーに一つもマッチしない不正なCookieを
    送りました。最近の設定変更、HTTP/HTTPSサイト間でのCookieの混在、
    永続性の条件付きの無視、攻撃などが原因の場合があります。

D: クライアントが送ったCookieは、停止しているサーバーを指定していました。
    "option persist"を使っていれば、そのサーバーへ振り向け、設定して
    いなければ、別のサーバーへ再振り分けしました。

V: クライアントは有効なCookieを送り、対応するサーバーへ振り向けられました。

E: クライアントが送ったCookieは有効でしたが、最終日時がCookieの
    "maxidle"パラメーターで許可するものより古いため、期限切れとみなし、
    無視しました。Cookieがない場合と同じように、リクエストを再振り分けします。

O: クライアントが送ったCookieは有効でしたが、最初の日時がCookieの
    "maxlife"パラメーターで許可するものより古いため、古すぎるとみなし、
    無視しました。Cookieがない場合と同じように、リクエストを再振り分けします。

U: Cookieはありましたが、他のサーバー選択方法(通常は"use-server"ルール)を
    代わりに使ったため、サーバーの選択には使いませんでした。

-: 該当しません(設定にCookieがありません)。
  • 最後の文字は、サーバーが返した永続性Cookieに、どのような操作を行ったかを示します(HTTPモードのみ)。
N: サーバーはCookieを送らず、挿入もしていません。

I: サーバーはCookieを送らず、プロキシが挿入しました。"cookie insert"
    モードでは、サーバーがCookieを送っても、上書きして、ここには"I"と
    記録する点に注意してください。

U: クライアントが提示したCookieの最終日時を、プロキシが更新しました。
    "maxidle"を指定したinsertモードの場合だけに起こります。Cookieにある
    日時とは異なる日時に活動があるたびに起こります。再振り分けなど、
    他の変更があれば、代わりにCookieを挿入したものとして記録します。

P: サーバーがCookieを送り、そのまま転送しました。

R: サーバーが送ったCookieを、プロキシが書き換えました。
    "cookie rewrite"または"cookie prefix"モードで起こります。

D: サーバーが送ったCookieを、プロキシが削除しました。

-: 該当しません(設定にCookieがありません)。

最初の二つのフラグを組み合わせると、ストリームやセッションの終了時に何が起きていたか、なぜ終了したかについて、多くの情報を得られます。サーバーの飽和、ネットワーク問題、ローカルシステムのリソース不足、攻撃などの検出に役立ちます。

よくある終了フラグの組み合わせを以下に示します。見つけて理解しやすいよう、アルファベット順で、大文字の直後に対応する小文字を置いています。

フラグ 理由

 --   正常終了。

 CC   サーバーへの接続を確立する前に、クライアントが中止しました。
      HAProxyが停止したばかりのサーバー(または未チェックのサーバー)に
      接続しようとし、サーバーの応答または"timeout connect"の満了を
      待つ間に、クライアントが中止した場合などに起こります。

 CD   データ転送中に、クライアントが予期せず中止しました。
      ブラウザーのクラッシュ、クライアントとHAProxyの間の機器による
      能動的な切断、両者の間の経路問題、またはサーバーとクライアントの
      keep-aliveストリームをクライアントが先に終了したことが原因になり得ます。

 cD   "timeout client"の間、クライアントがデータを送信も確認応答もしませんでした。
      多くの場合、クライアント側のネットワーク障害、またはクライアントが
      正常な手順を踏まずにネットワークを離れたことが原因です。

 CH   サーバーの応答開始を待つ間に、クライアントが中止しました。
      サーバーの応答が遅すぎるか、クライアントが「停止」ボタンを
      押すのが早すぎた可能性があります。

 cH   POSTリクエストでクライアントのデータを待つ間に、"timeout client"が満了しました。
      最大サイズのパケットを運べないPPPoEネットワークに対し、TCP MSSが
      大きすぎる場合に起こることがあります。クライアントタイムアウトが
      サーバータイムアウトより短く、サーバーの応答が遅すぎる場合も起こります。

 CQ   十分な空き枠があるサーバーを待ち、ストリームがキューに入っている間に、
      クライアントが中止しました。すべてのサーバーが飽和していたか、
      割り当てたサーバーの応答が遅すぎた可能性があります。

 CR   完全なHTTPリクエストを送る前に、クライアントが中止しました。
      最も可能性が高いのは、telnetクライアントで手入力したリクエストを
      早く中止しすぎた場合です。HTTPステータスは、おそらく400です。HAProxyとクライアントの
      接続をIDSが切断した場合にも起こります。"option http-ignore-probes"で、
      データ転送のない接続を無視できます。

 cR   クライアントが完全なHTTPリクエストを送る前に、"timeout http-request"が満了しました。
      最大サイズのパケットを運べないPPPoEネットワークに対し、クライアントの
      TCP MSSが大きすぎる、リクエストの手入力が遅すぎる、末尾の空行を
      入れ忘れた場合などに起こります。HTTPステータスは、おそらく408です。
      注意:最近の一部のブラウザーは、利用者が再訪する場合に備え、最近訪問した
      サイトへ先回りして接続する「事前接続」機能を実装しています。そのため、
      多数の接続が作られ、先にタイムアウトすれば408 Request Timeout、
      ブラウザーが先に閉じれば400 Bad Requestになります。ログを埋め、
      エラーカウンターを増やし、一部のブラウザーの一部の版では、エラーコードを
      表示することさえ報告されています。フロントエンドに"option http-ignore-probes"を
      追加すると、データ転送がゼロの接続を完全に無視し、この望ましくない影響を
      回避できます。ただし、接続の問題を抱える利用者のエラーも確実に隠します。

 CT   ストリームをtarpitしている間に、クライアントが中止しました。
      誤ったtarpitルールがないことを確かめるため、有効なリクエストで起きていないか
      確認することが重要です。多発する場合は、少数の攻撃者のためにリソースを
      消費しないよう、"timeout tarpit"を、報告される平均"Tw"に近づけて
      下げることが有効な場合があります。

 LC   HAProxyがリクエストを捕捉し、ローカルで処理しました。
      リクエストをサーバーへ送っていません。server行の"redir"パラメーターによる
      リダイレクトの場合だけに起こります。

 LR   HAProxyがリクエストを捕捉し、ローカルで処理しました。
      リクエストをサーバーへ送っていません。一般には、リダイレクトを返した、
      HTTP return文を処理した、またはアプレット(統計、キャッシュ、Prometheus
      エクスポーター、Luaアプレットなど)が処理したことを示します。

 LH   HAProxyがレスポンスを捕捉し、ローカルで処理しました。
      一般には、リダイレクトを返したか、HTTP return文を処理したことを示します。

 SC   サーバーまたはHAProxyとの間の機器が、TCP接続を明示的に拒否しました
      (プロキシがTCP RSTまたはICMPメッセージを受信)。状況によっては、
      ネットワークスタックがサーバーに到達できないことを伝えた場合もあります
      (経路がない、ローカルネットワークでARP応答がないなど)。
      HTTPモードでは、ステータスはおそらく502または503です。

 sC   サーバーへの接続が完了する前に、"timeout connect"が満了しました。
      HTTPモードでは、ステータスはおそらく503または504です。

 SD   データ転送中に、サーバーとの接続がエラーで切れました。
      通常は、データ交換中に、HAProxyがサーバーからRSTを、または途中の機器から
      ICMPメッセージを受信したことを示します。サーバーのクラッシュや、
      途中の機器のネットワーク問題が原因になり得ます。

 sD   データ転送段階で、"timeout server"の間、サーバーがデータを送信も
      確認応答もしませんでした。多くの場合、サーバーの手前のL4機器
      (ファイアウォール、ロードバランサーなど)のタイムアウトが短すぎるか、
      クライアントとサーバーのkeep-aliveセッションがHAProxy側で先に期限切れに
      なったことが原因です。

 SH   サーバーがHTTPレスポンスヘッダーをすべて送る前に中断したか、
      リクエストの処理中にクラッシュしました。この時点でサーバーが中断する
      ことは非常にまれなので、ログを調べ、クラッシュの有無と原因を確認する
      のが賢明です。ログに記録したリクエストから、問題のある少数の
      リクエスト群が分かり、アプリケーションの不具合を示せる場合があります。
      IDSがHAProxyとサーバーの間の接続を切ったことが原因の場合もあります。

 sH   サーバーがレスポンスヘッダーを返す前に、"timeout server"が
      満了しました。最も一般的な異常で、トランザクションが長すぎることを
      示します。おそらく、サーバーやデータベースの飽和が原因です。
      当面の回避策は"timeout server"の設定を大きくすることですが、
      応答時間が長いためにユーザーの使い勝手が悪くなることを忘れては
      なりません。長期的な解決策は、アプリケーションの修正だけです。

 sQ   ストリームがキューで待ちすぎて、期限切れになりました。頻発する
      場合は、"timeout queue"と"timeout connect"の設定を調べて対処して
      ください。短時間に大量に発生することが多い場合、I/Oやデータベースの
      混雑による、該当サーバー全体の問題、または外部からの攻撃による
      飽和を示している可能性があります。

 PC   サーバーへの接続を試みる際に、プロセスのソケット数の上限に達した
      ため、プロキシが接続の確立を拒否しました。再発しないよう、設定で
      グローバルの"maxconn"パラメーターを大きくできます。
      非常にまれな状態で、グローバルの"ulimit-n"パラメーターを手動で
      固定した場合に起こることがあります。

 PD   サーバーがヘッダーを送信した後、リクエストまたはレスポンス内の、
      不正な形式のchunkedエンコードされたメッセージをプロキシが遮断しました。
      ほとんどの場合、サーバーからクライアントへの不正なメッセージを示します。
      HAProxyは2GB - 1(2147483647バイト)までのチャンクサイズをサポートします。
      それより大きなサイズは、すべてエラーとみなします。

 PH   レスポンスが不正、不完全、危険(キャッシュ制御)、またはセキュリティ
      フィルターにマッチしたため、プロキシがサーバーのレスポンスを遮断しました。
      いずれの場合も、クライアントへHTTP 502エラーを送ります。考えられる
      原因の一つは、許可されない文字を含むHTTPヘッダー名の構文エラーです。
      また、非常にまれですが、サーバーが応答する前に、構文が不正なため、
      クライアントからのchunked-encodingリクエストを遮断する場合もあります。
      この場合、クライアントへHTTP 400エラーを送り、ログにも記録します。
      最後に、レスポンスのHTTPヘッダーの書き換え失敗が原因の場合もあります。
      この場合はHTTP 500エラーを送ります(詳細は"tune.maxrewrite"と
      "http-response strict-mode"を参照してください)。

 PR   プロキシがクライアントのHTTPリクエストを遮断しました。HTTP構文が
      不正な場合はクライアントへHTTP 400エラーを返し、denyフィルターに
      マッチした場合はHTTP 403エラーを返します。リクエストのHTTPヘッダーの
      書き換え失敗が原因の場合もあり、その場合はHTTP 500エラーを送ります
      (詳細は"tune.maxrewrite"と"http-request strict-mode"を参照してください)。

 PT   プロキシがクライアントのリクエストを遮断し、接続をtarpitで引き延ばして
      から、500サーバーエラーを返しました。サーバーへは何も送っていません。
      "Tw"タイマーフィールドに記録した時間だけ、接続を開いたままにしました。

 RC   ローカルリソース(メモリー、ソケット、送信元ポート)が枯渇し、
      サーバーへの接続を確立できませんでした。不足したものは、エラーログで
      正確に分かります。非常にまれで、適切なシステム調整でしか解決できません。

最後の二つのフラグの組み合わせから、クライアント、サーバー、HAProxyが永続性をどう扱ったかについて、多くの情報が得られます。ユーザーから再認証が必要になるという苦情があるとき、切断の問題を解決するうえで非常に重要です。よく見られるフラグは次のとおりです。

--   永続性Cookieが有効になっていません。

NN   クライアントはCookieを送らず、レスポンスにも挿入しませんでした。
     たとえば、"postonly"を設定したinsertモードでGETリクエストを
     受けた場合に起こります。

II   クライアントが無効なサーバーを指定するCookieを送り、レスポンスには
     有効なCookieを挿入しました。通常は、設定から"server"エントリーを
     削除した場合に起こります。他のサーバーが知らないCookieの値を、
     クライアントが提示できるためです。

NI   クライアントはCookieを送らず、レスポンスに挿入しました。通常は、
     "insert"モードで、各ユーザーの最初のリクエストの際に起こるため、
     実際のユーザー数を容易に数える方法になります。

VN   クライアントはCookieを送り、レスポンスには挿入しませんでした。
     クライアントが既にCookieを持つ場合の、大半のレスポンスで起こります。

VU   クライアントが送ったCookieの最終訪問日時が完全には最新でないため、
     レスポンスに更新したCookieを付けました。日時がまったくない場合や、
     日時はあるものの"maxidle"パラメーターが設定されておらず、Cookieを
     期限なしへ切り替えられる場合にも起こります。

EI   クライアントが送ったCookieの最終訪問日時が"maxidle"パラメーターに
     対して古すぎるため、Cookieを無視し、レスポンスに新しいCookieを
     挿入しました。

OI   クライアントが送ったCookieの最初の訪問日時が"maxlife"パラメーターに
     対して古すぎるため、Cookieを無視し、レスポンスに新しいCookieを
     挿入しました。

DI   Cookieが指定するサーバーは停止していたため、新しいサーバーを選び、
     レスポンスに新しいCookieを付けました。

VI   Cookieが指定するサーバーは停止とはされていませんでしたが、到達できません
     でした。再振り分けにより別のサーバーを選び、レスポンスで通知しました。

8.6. 印字できない文字

ログを読む際に、ログ解析ツールや端末に問題を起こさないよう、印字できない文字をそのままログファイルへ送ることはありません。ASCIIコードを二桁の16進表現にし、先頭に’#‘を付けます。エスケープせずに記録できるのは、32以上126以下の文字だけです。当然、エスケープ文字’#‘自体も、曖昧にならないよう”#23"へエンコードします。文字’"‘も同様に”#22"へ変換し、ヘッダーを記録するときは’{’、’|’、’}‘も変換します。

これはcborの符号化には適用しません。cborは、安全な16進数の数字、または正しく区切ったバイナリブロックをすでに使用します。これらのブロックは端末へ送るのではなく、CBORパーサーが処理します。

jsonの符号化では、代わりにJSONのエスケープシーケンスを使用します。+utf8オプションを指定すると、有効な複数バイトのUTF-8シーケンスもそのまま出力します(セクション8.2.6 の"utf8"フラグを参照)。

空白文字(’ ‘)はヘッダー内でエンコードしないため、空白の数でフィールドの位置を判断するツールでは問題が起こる場合があります。空白を含む典型的なヘッダーは"User-Agent"です。

最後に、syslog-ngなど、一部のsyslogデーモンは、引用符(’"’)をバックスラッシュ(’\’)でエスケープすることが確認されています。ログの他の場所に引用符が現れることはないため、逆変換は安全に行えます。

8.7. HTTP Cookieの取得

Cookieを取得すると、ユーザーセッション全体を追跡しやすくなります。フロントエンドで"capture cookie"文を使うと実現できます。詳細はセクション4.2 を参照してください。取得できるCookieは一つだけで、リクエスト(“Cookie:“ヘッダー)とレスポンス(“Set-Cookie:“ヘッダー)で、同じCookieを同時に調べます。それぞれの値は、HTTPログの"captured_request_cookie"と"captured_response_cookie"の位置に記録します(HTTPログ形式についてはセクション8.2.3 を参照)。いずれかのCookieがなければ、値の代わりにダッシュ(’-’)を記録します。たとえば、ユーザーが新しいセッションへ移ると、サーバーが新しいCookieを割り当てるため、容易に検出できます。サーバーが意図せずクライアントに誤ったCookieを設定し、セッションが混線した場合も検出できます。

例:

# capture the first cookie whose name starts with "ASPSESSION"
capture cookie ASPSESSION len 32

# capture the first cookie whose name is exactly "vgnvisitor"
capture cookie vgnvisitor= len 32

“http-request"と"http-response"ルールで、Cookieを"txn"スコープの変数へ代入すれば、より高度な取得が可能です。“req.cook"と"res.cook"サンプル取得関数(セクション7.3.6 )で、リクエストまたはレスポンスからCookieの値を取り出し、“set-var"または"set-var-fmt"アクション(セクション4.3 )で変数へ代入できます。その後、カスタムlog-formatで、これらの変数を希望する位置へ配置できます(セクション8.2.6 )。

8.8. HTTPヘッダーの取得(従来の方法)

ヘッダーの取得は、上位のプロキシが設定した一意のリクエスト識別子、仮想ホスト名、User-Agent、POSTのContent-Length、リファラーなどの追跡に役立ちます。レスポンスでは、長さ、サーバーがキャッシュに求めた動作、リダイレクト先のオブジェクトの位置などの情報を調べられます。

ヘッダーの取得には二つの方法があります。現在の方法では、取得するヘッダー、または"req.hdr_names”、“req.hdrs”、“res.hdr_names”、“res.hdrs"が返す複合サンプルから変数を設定します(可能な方法すべてについてはセクション7.3.6 を参照)。“http-request"と"http-response"ルールセットの"set-var"と"set-var-fmt"アクション(セクション4.3 )で、これらを"txn"スコープの変数へ代入し、カスタムログ形式から参照できます(セクション8.2.6 )。HTTPヘッダーの取得には、この方法を推奨します。

http-requestルールと変数より前からある、従来の方法もあります。ログ形式を調整する必要がなく、古い"capture"ルールセットを使い、ログの記録だけでなく、HTTPトランザクションの間ずっとリクエストの情報を伝える代用手段としても、長年使われてきました。この節では、その方法を説明します。

従来のヘッダー取得には、フロントエンドの"capture request header"文と"capture response header"文を使います。詳細は、セクション4.2 の定義を参照してください。

リクエストヘッダーとレスポンスヘッダーを同時に含められます。存在しないヘッダーは空文字列として記録し、同じヘッダーが複数回現れる場合は、最後のものだけを記録します。リクエストヘッダーは、宣言した順序で波括弧’{‘と’}‘の中にまとめ、空白を入れずに縦線’|‘で区切ります。レスポンスヘッダーも同じ表現ですが、リクエストヘッダーのブロックの後に空白を置いて表示します。これらのブロックは、ログ内のHTTPリクエストの直前に表示します。

特別な場合として、TCPフロントエンドでHTTPヘッダーの取得を指定できます。その後、リクエストをHTTPバックエンドへ切り替える場合に、そのバックエンドが解析するヘッダーをログに記録できるようにするためです。

例:

# This instance chains to the outgoing proxy
listen proxy-out
    mode http
    option httplog
    option logasap
    log global
    server cache1 192.168.1.1:3128

    # log the name of the virtual server
    capture request  header Host len 20

    # log the amount of data uploaded during a POST
    capture request  header Content-Length len 10

    # log the beginning of the referrer
    capture request  header Referer len 20

    # server name (useful for outgoing proxies only)
    capture response header Server len 20

    # logging the content-length is useful with "option logasap"
    capture response header Content-Length len 10

    # log the expected cache behavior on the response
    capture response header Cache-Control len 8

    # the Via header will report the next proxy's name
    capture response header Via len 20

    # log the URL location during a redirection
    capture response header Location len 20
    >>> Aug  9 20:26:09 localhost \
          haproxy[2022]: 127.0.0.1:34014 [09/Aug/2004:20:26:09] proxy-out \
          proxy-out/cache1 0/0/0/162/+162 200 +350 - - ---- 0/0/0/0/0 0/0 \
          {fr.adserver.yahoo.co||http://fr.f416.mail.} {|864|private||} \
          "GET http://fr.adserver.yahoo.com/"
    >>> Aug  9 20:30:46 localhost \
          haproxy[2022]: 127.0.0.1:34020 [09/Aug/2004:20:30:46] proxy-out \
          proxy-out/cache1 0/0/0/182/+182 200 +279 - - ---- 0/0/0/0/0 0/0 \
          {w.ods.org||} {Formilux/0.1.8|3495|||} \
          "GET http://trafic.1wt.eu/ HTTP/1.1"
    >>> Aug  9 20:30:46 localhost \
          haproxy[2022]: 127.0.0.1:34028 [09/Aug/2004:20:30:46] proxy-out \
          proxy-out/cache1 0/0/2/126/+128 301 +223 - - ---- 0/0/0/0/0 0/0 \
          {www.sytadin.equipement.gouv.fr||http://trafic.1wt.eu/} \
          {Apache|230|||http://www.sytadin.} \
          "GET http://www.sytadin.equipement.gouv.fr/ HTTP/1.1"

8.9. ログの例

以下は、説明を添えた実際のログの例です。一部は手作業で作成しています。読みやすくするため、syslog部分は除いています。ログの読み解き方を説明することだけが目的です。

>>> haproxy[674]: 127.0.0.1:33318 [15/Oct/2003:08:31:57.130] px-http &#92;
      px-http/srv1 6559/0/7/147/6723 200 243 - - ---- 5/3/3/1/0 0/0 &#92;
      "HEAD / HTTP/1.0"

=> 'telnet'で手入力した、長いリクエスト(6.5秒)です。サーバーは
   147 msで応答し、セッションは正常に終了しました('----')。

>>> haproxy[674]: 127.0.0.1:33319 [15/Oct/2003:08:31:57.149] px-http &#92;
      px-http/srv1 6559/1230/7/147/6870 200 243 - - ---- 324/239/239/99/0 &#92;
      0/9 "HEAD / HTTP/1.0"

=> 上と同じですが、リクエストはグローバルキューで、他の9件の
   リクエストの後ろに並び、1230 ms待ちました。
    >>> haproxy[674]: 127.0.0.1:33320 [15/Oct/2003:08:32:17.654] px-http \
          px-http/srv1 9/0/7/14/+30 200 +243 - - ---- 3/3/3/1/0 0/0 \
          "GET /image.iso HTTP/1.0"
=> 長いデータ転送のリクエストです。"logasap"オプションを指定していたため、
   データ転送の直前にログを出力しました。サーバーは14 msで応答し、
   243バイトのヘッダーをクライアントへ送っています。接続の受け入れから
   データの最初のバイトまでの合計時間は30 msです。

>>> haproxy[674]: 127.0.0.1:33320 [15/Oct/2003:08:32:17.925] px-http &#92;
      px-http/srv1 9/0/7/14/30 502 243 - - PH-- 3/2/2/0/0 0/0 &#92;
      "GET /cgi-bin/bug.cgi? HTTP/1.0"

=> プロキシがサーバーのレスポンスを遮断しました。"http-response deny"
   ルールによる場合、レスポンスの形式が不正でHTTPに準拠しない場合、または
   キャッシュされるおそれのある機密情報を遮断した場合があります。
   レスポンスは"502 bad gateway"へ置き換えます。フラグ("PH--")から、
   502を返すと判断したのは、サーバーではなくHAProxyだと分かります。

>>> haproxy[18113]: 127.0.0.1:34548 [15/Oct/2003:15:18:55.798] px-http &#92;
      px-http/`<NOSRV>` -1/-1/-1/-1/8490 -1 0 - - CR-- 2/2/2/0/0 0/0 ""

=> クライアントはリクエストを完了せず、プロキシがリクエストヘッダーを
   待つ間("-R--")に、8.5秒後に自ら中断しました("C---")。
   どのサーバーへも、何も送っていません。

>>> haproxy[18113]: 127.0.0.1:34549 [15/Oct/2003:15:19:06.103] px-http &#92;
     px-http/`<NOSRV>` -1/-1/-1/-1/50001 408 0 - - cR-- 2/2/2/0/0 0/0 ""

=> クライアントはリクエストを完了せず、プロキシがリクエストヘッダーを
   待つ間("-R--")に、50秒後にタイムアウトで中断しました("c---")。
   どのサーバーへも何も送っていませんが、プロキシはクライアントへ
   408応答コードを送れました。

>>> haproxy[18989]: 127.0.0.1:34550 [15/Oct/2003:15:24:28.312] px-tcp &#92;
      px-tcp/srv1 0/0/5007 0 cD 0/0/0/0/0 0/0

=> "option tcplog"で出力したログです。クライアントは5秒後に
   タイムアウトしました("c----")。

>>> haproxy[18989]: 10.0.0.1:34552 [15/Oct/2003:15:26:31.462] px-http &#92;
      px-http/srv1 3183/-1/-1/-1/11215 503 0 - - SC-- 205/202/202/115/3 &#92;
      0/0 "HEAD / HTTP/1.0"

=> リクエストの完了に3秒かかり(おそらくネットワークの問題)、
   サーバーへの接続は2秒ずつ4回試みた後で失敗しました('SC--')。
   設定は'retries 3'で、再振り分けはありません(あれば"/+3"になります)。
   クライアントへステータスコード503を返しました。このサーバーには115接続、
   このプロキシには202接続、プロセス全体には205接続ありました。
   既に確立した接続が多すぎるため、サーバーが接続を拒否した可能性があります。