Nginx で POST データのログをフィルタする

レガシープラットフォームの改善を担当している D. M. です。ログの重要性が高まる昨今皆さんはいかがお過ごしでしょうか。

モチベーション

私の担当するシステムでは、エンドユーザが画面を操作するリクエストや外部システムからの API リクエストを前段の Web サーバが一元的に受け付けています。この状況下でお問い合わせや不具合が発生した場合の調査をしやすくするために GET なり POST なりで受け取ったデータを全てログに出したいというニーズが出てきました。ですが、リクエストにはメアドやパスワードなどあまりログに残したくない情報も流れてきます。今回はそれらを Web サーバがフィルタする仕組みについて取り扱いたいと思います。

対象者

・ Nginx を普通に使っているがそんなに凝ったことはしていない。
・ Nginx ログをいじり倒したい。

やりたいこと

目的は以下の2つです。
・Nginx が GET と POST で受け取ったデータをログ出力したい。
・一部のパラメータは加工してマスク処理をかけたい。（今回は pass の値）
このログを

pass=abc123

こんな感じにしたい。

pass=[FILTERED]

方法のサマリー

Nginx で行うには、結論としては以下の方法があります。

[GET]
rewrite ディレクティブの if でフィルタする。

[POST]
A. map ディレクティブで request_body を別の変数としてフィルタする。
B. Lua スクリプトで簡易的なロジックを組んでフィルタする。

POST に関しては A案または B案のいずれかの方法があり、1番シンプルな方法は A 案の map による変数操作になります。少し凝ったことをやろうとしたときは Lua が利用できます。 Lua 言語は C との親和性が高く、非常に高速に動作する特徴があり、 Nginx の Conf ファイル内に簡易的に記述することができます。最近は Web 関連会社の利用事例が増えています。（例えばメルカリさんとかはここ）
また Apache で行う場合は mod_ext_filter によって、言語にとらわれず外部のスクリプトを定義できます。
今回は処理速度について定評のある Nginx Lua を利用する方法について掘り下げていこうと思います。

実践

やってみたことの詳細を順に説明します。
今回は結果的にいくつか 3rd party module を使ったので、予めいろいろ組み込まれている OpenResty Version 1.11.2.2 を利用しました。

Nginx で GET パラメータのログをフィルタして出力

GET については先人の知恵がありました。素晴らしい。

「Nginx でログに残したくないデータをマスキングする」
http://www.smallstyle.com/20130518.html

if ディレクティブで正規表現をつかって $filtered_request 変数にフィルタした値をセットしてログに出します。 rewrite ができればよいので追加のモジュールのインストールは必要なくデフォルトの nginx でも問題ないです。
アレンジした nginx.conf の内容は以下の通り。
localhost に /hello という URL を用意して GET をログ出力します。

http{
  //最近のログフォーマットは JSON 推しなのでこんな感じにしてみます。
  log_format main '{ "request_uri": "$request_uri", 
    "time_local": "$time_local",
    "filtered_request": "$filtered_request" }' ;
  access_log logs/access.log main;
  ...
  server{
    location /hello {
     ...
      //$request （すなわち GET パラメータを含む）を $filtered_request にコピー
      set $filtered_request $request;
      //正規表現で pass 文字列含む場合を引っ掛ける
      if ($filtered_request ~ (.*)pass=[^&]*(.*)) {
        // pass= の後ろの値だけを書き換える
        set $filtered_request $1pass=[FILTERED_IN_IF]$2;
      }
    }
  }
}

実行。
curl http://localhost/hello?foo=bar&pass=abc123

{ “request_uri”: “/hello?foo=bar&pass=abc123”, “time_local”: “27/Dec/2016:20:04:50 +0900”, “filtered_request”: “GET /hello?foo=bar&pass=[FILTERED_IN_IF]” }

よし！これで GET は大丈夫。

Nginx で POST データをフィルタして出力

POST をログに出す

ただ POST をログ出力するだけをの目的であればググるとわんさか出てきます。 log_format の定義に $request_body を加えるだけ。なんと簡単な。
さっきとほとんど同じです。

log_format main '{ "request_uri": "$request_uri", "time_local": "$time_local", "request_body": "$request_body" }' ;

※デフォルトの Nginx でも動作するのですが、落とし穴として Nginx 内で $request_body 変数を利用できる条件を理解していないと出力することができません。これについては後述します。

POST ログをフィルタする

はじめに失敗した方法です。
とりあえずこれは GET の方法まんまでいいんじゃない？！と軽く考えて $request_body に set, if を使ってみる。

set $filtered_request_body $request_body;
if ($filtered_request_body ~ (.*)pass=[^&]*(.*)) {
  set $filtered_request_body $1pass=[FILTERED]$2;
}

log_format 側も新しい変数 $filtered_request_body を入れちゃいます。

log_format main '{ "request_uri": "$request_uri", "time_local": "$time_local", "filtered_request_body": "$filtered_request_body" } ' ;

結果のログ出力。
curl http://localhost/hello –data ‘foo=bar&pass=abc123’

{ “request_uri”: “/hello”, “time_local”: “26/Dec/2016:18:47:32 +0900”, “filtered_request_body”: “” }

なんと空文字！！何も出ない！！！
なぜか if の処理を通過してくれません。
で、いろいろ調べた結果 if は通過はしてるんですが、そもそも set $filtered_request_body $request_body のときに request_body が空っぽのようだということがわかりました。一体なぜ。。

Nginx の処理プロセス

ここからは上記の問題の解決編です。まずは Nginx のことをおさらいします。

Nginx 内部の処理順序

Nginx 内部の処理順序ですが、残念ながら公式ページには明確な説明は出ておらず、有志による解説ページがあります。（以前は公式があった模様。）

要約すると以下のようなフェーズを経由します。

1. post-read
2. server-rewrite
3. find-config
4. rewrite
5. post-rewrite
6. preaccess
7. access
8. post-access
9. try-files
10. content
11. log

ざっくり以下のような区分けで理解すると良いかと思います。
1 : http ディレクティブ
2, 3 : server ディレクティブ
4 ～ 10 : location ディレクティブ
※もう少し詳細を知りたい場合は Nginx を ./configure –with-debug でコンパイルすると詳細な処理ログが出るはずです。
※ location 内の if の挙動についてはやや複雑なので以下のページを読むと理解が深まります。
https://www.ruby-forum.com/topic/1084244

set, if の実行タイミング

今回問題となった set ディレクティブと if ディレクティブの実行タイミングですが、これは大枠としては rewrite ディレクティブの一部です。つまり上記のフェーズで言うと 2, 4 のタイミングで実行されます。
公式情報は以下のとおり。
if
http://nginx.org/en/docs/http/ngx_http_rewrite_module.html#if
set
http://nginx.org/en/docs/http/ngx_http_rewrite_module.html#set

$request_body 変数の読み込みタイミング

そもそもですが request_body は通常のリクエスト処理では読み込まれません。

本家の文章を引用します。
http://nginx.org/en/docs/http/ngx_http_core_module.html#var_request_body

The variable’s value is made available in locations processed by the proxy_pass, fastcgi_pass, uwsgi_pass, andscgi_pass directives when the request body was read to a memory buffer.

「この変数の値は proxy_pass 、 fastcgi_pass 、uwsgi_pass, そして scgi_pass ディレクティブを処理する location においてメモリバッファに読み込まれます。」

つまり、全部のリクエストについて無条件に request_body が利用できるわけではなく、 proxy_pass などの後続処理が設定されている location ディレクティブのみという縛りがあるということです。

※処理の流れ的に毎回 proxy_pass など後続処理が必要になるとも限らないと思います。そういう時は echo-nginx-module の echo_read_request_body が有用です。 echo_read_request_body は location 内でしか使うことができないのですが、1行記載するだけで変数が利用可能になります。
echo-nginx-module の情報は以下のとおりです。2016年12月段階での最新版は v0.60 です。今回使った OpenResty にも入っています。
https://github.com/openresty/echo-nginx-module

以上を踏まえると request_body の読み込みは rewrite フェーズの後であることは明白です。
つまり以下の順序です。

1. server rewrite, location rewrite フェーズの処理 (つまり set, if の通過)
2. location フェーズの処理内での request_body 読み込み（※上述の request_body の発火条件を満たした場合に読み込み）

これで上で試した方法では POST データのログが空っぽだった理由が納得いきます。request_body の設定は location ディレクティブ内だった、すなわち、request_body は rewrite フェーズでは空っぽ、次の location の具体的処理である access フェーズ以降で proxy_pass または echo_read_request_body がある場合のみ読み込まれるわけです。

上記を前提として、 POST のフィルタとして採りうる方法は以下のいずれかです。

[POST フィルタ方法 A 案] map ディレクティブを使う

map は変数をフィルタして設定することが可能なディレクティブです。デフォルトで使えます。

map ディレクティブの実行タイミング

map の実行タイミングについて、公式サイトには以下の記述があります。

http://nginx.org/en/docs/http/ngx_http_map_module.html

Since variables are evaluated only when they are used, the mere declaration even of a large number of “map” variables does not add any extra costs to request processing.

「変数は使われたときにのみ評価されるため、単に多くの map 変数宣言をしただけではリクエスト処理に追加の負荷を増やしません。」

使われたときにのみ評価される、これはつまり map 処理は変数をセットした時に始めて呼ばれるという意味と考えることができます。 request_body が設定されたタイミングでフィルタ条件が発火されるわけです。これで set, if のように rewrite フェーズに縛られることなく、変数操作を実行することができそうです。

map ディレクティブの実装

map は http ディレクティブに記載するという制約があり、以下のように書きます。条件部分だけを外出しして include することも可能です。

http{
  ...
  map $request_body $filtered_request_body {
    default $request_body ;
    ~(.*)pass=[^&]*(.*) $1pass=[FILTERED_IN_MAP]$2 ;
  }
  ...
  server{ 
    ...
    location /hello {
      // proxy_pass または echo_read_request_body などの request_body 読み込み条件を満たす
      ...
    }
  }
}

フィルタするための正規表現は、上述の GET の if ディレクティブと同じノリで書けました。先人の知恵に感謝！

実際結果も問題ありませんでした。
curl http://localhost/hello –data ‘foo=bar&pass=abc123’

{ “request_uri”: “/hello”, “time_local”: “27/Dec/2016:10:24:56 +0900”, “filtered_request_body”: “foo=bar&pass=[FILTERED_IN_MAP]” }

[POST フィルタ方法 B 案] Lua スクリプトで変数を直接修正する

lua_nginx_module で Lua 言語のスクリプトを実行できます。2016年12月段階の最新版は v0.10.7 で、今回使った OpenResty にも入っています。以下の公式ページに API の詳細な解説があります。
https://github.com/openresty/lua-nginx-module
日本語の解説としては以下の記事が非常に詳しいです。
「lua-nginx-module を使いこなす」
http://qiita.com/kz_takatsu/items/e94805a8e3cc285f9b33

Lua スクリプトの実行タイミング

Lua を実行するフェーズは [X-phase]_by_lua_block ディレクティブを利用することで実装者が任意のタイミングを指定可能です。（ [X-phase] には nginx の処理フェーズが入る）公式ドキュメントには [X-phase]_by_lua_block それぞれの実行タイミングが明示されており、概ね指定したフェーズの最後に実行されているようです。例えば rewrite_by_lua_block の実行タイミングは rewrite tail となっており、 rewrite フェーズの終わりに動きます。
なので、今回の request_body ログ操作は location rewrite フェーズ以降＋ log フェーズ以前に変数操作を行えば良いということになりますので access フェーズ = access_by_lua_block でフィルタを実行すれば問題なさそうです。

Lua スクリプトの実装

今回利用した Lua の API のは以下のとおりです。

ngx.req.read_body()
上述のとおりリクエストボディの読み込みはデフォルトでは発火しないので、この ngx.req.read_body で明示的な読み込みを指示する必要があります。

ngx.req.get_post_args()
POST された値を取り出し操作できます。

ngx.req.get_method()
HTTPメソッドを取得できます。これにより POST の場合だけ処理するように条件分岐します。（下手に GET リクエストでは処理させないようにします）

実際のコードです。 location ディレクティブ内に実装しています。スクリプトを外出しして include も可能です。

access_by_lua_block {
  //全リクエストで処理するのを防ぐため POST かどうかチェックする
  method_name = ngx.req.get_method()
  if method_name == "POST" then
    
    // request_body を明示的に読み込む
    ngx.req.read_body()
    // POST の値があるかチェック
    local args, err = ngx.req.get_post_args()
    // 何もないとき
    if not args then
      //ログで利用する filtered_request_body に任意の値 null を入れる
      ngx.var.filtered_request_body = "null"
      return
    end
    
    // POST をループして変数を置換
    for key, val in pairs(args) do
      // POST に pass の値があればフィルタで置換する
      if key == "pass" then
        ngx.var.filtered_request_body = ngx.var.filtered_request_body .. "&" .. key .. "=[FILTERED_IN_LUA]"
      else
        //ここは ngx.req.get_post_args() の公式ドキュメント内のサンプルを参考に実装
        if type(val) == "table" then
          ngx.var.filtered_request_body = ngx.var.filtered_request_body .. "&" .. table.concat(key , val, "=" )
        else
          ngx.var.filtered_request_body = ngx.var.filtered_request_body .. "&" .. key .. "=" .. val
        end
      end
    end
  end 
}

実行結果。
curl http://localhost/hello –data ‘foo=bar&pass=abc123’

{ “request_uri”: “/hello”, “time_local”: “27/Dec/2016:22:06:01 +0900”, “filtered_request_body”: “&foo=bar&pass=[FILTERED_IN_LUA]” }

Web サーバにそこまで複雑な役割を担わせたくないという意見もあると思います。独自ロジック実装はパフォーマンス劣化とバグ発生の懸念もあります。ですがもう一歩なにかやりたいというときの手段として頭の片隅に置いていただけると良い選択肢になるのではないでしょうか。

今後の課題

パフォーマンスについては多くのサイトの検証で良い結果が出ているため私はあまり懸念していないのですが、もし Lua のロジックが複雑になり、かつ大量アクセスを捌くゲームやアドのような環境に適用する場合は、独自にベンチマークを出したほうが良いかと思っています。
また POST 以外に時間変数の加工も簡易的に可能です。 Nginx のログはデフォルトでは時間のフォーマットが time_local, time_iso8601 の2種類しか指定できず、ここは Apache に比べて劣っています。 Lua を使えばこの時間変数のログを自由にカスタマイズすることができます。以前担当した案件では Nginx ログ内の時間フォーマットが気に入らなかったので、ログ転送の fluentd のプラグインで書き換える実装をしたりしましたが、いま思えば Lua でやったほうが全然処理効率が良かったかもしれません。

最後に

次世代システム研究室では、アプリケーション開発や設計を行うアーキテクトを募集しています。アプリケーション開発者の方、次世代システム研究室にご興味を持って頂ける方がいらっしゃいましたら、ぜひ募集職種一覧からご応募をお願いします。