モチベーション

Apache + PHP で運用している、とあるサービスのとあるエンドポイントについて、POST される際のデータに異常があり、レスポンスに異常が発生しているという体で、どんなデータが POST されているのかをログに残して分析したい。

やりたいこと

  • POST リクエストの内容をログに残したい
  • あくまでも POST リクエストのみを取得し、出来れば、任意のリクエストパスのみをログに残したい

この記事で書けないこと

  • mod_security の詳細
  • mod_security の導入後、Web サービスのパフォーマンスにどのような影響が出たか等

検討

実装各種

以下の実装について導入を検討、検証した。

mod_dumpio

  • Apache License 2.0
  • Apache が受け取ったすべての入力と Apache により送られたすべての出力との、両方もしくはどちらか一方を、 エラーログファイルにログ収集できる
  • 全ての入出力は要らない、必要な入力だけを制御する方法を見つけられずに候補から外す

mod_mruby

  • MIT License
  • Wiki にとても良いサンプルがあった
  • 絶対、mod_mruby 採用だと思った
  • ところが、mod_php と組み合わせて利用すると body のデータが mod_php まで渡せないので PHP で実装されている検証アプリケーションが動かなくなった（涙
  • 引き続き調べたい

mod_security

  • Apache License 2.0
  • Apache のモジュールとして動作する WAF(Web Application Firewall)
  • リクエストフィルタリング、パラメータフィルタリング、監査ログ、HTTPS フィルタリング等の機能がある

mod_mruby をめちゃくちゃ利用したかったんだけど、上述の通り、検証アプリケーションが動かなくなってしまったので、次の候補として考えていた mod_security を利用して POST リクエストをログに残してみたい。

mod_security による POST リクエストのロギング

mod_security について

上述の通り、リクエストやパラメータのフィルタリング、POST 等の通常では取得出来ないログの収集を行うことが出来る。

試した環境

以下の通り、Debian Jessie 上に Apache 2.4.10 と PHP 7.0.20 を導入した環境で試す。

$ cat /etc/debian_version
8.8

$ apache2 -v
Server version: Apache/2.4.10 (Debian)
Server built:   Feb 24 2017 18:40:28

$ /usr/local/bin/php --version
PHP 7.0.20 (cli) (built: Jun 13 2017 22:23:54) ( NTS )
Copyright (c) 1997-2017 The PHP Group
Zend Engine v3.0.0, Copyright (c) 1998-2017 Zend Technologies

検証アプリケーション

FuelPHP で実装した、メモを登録、閲覧、編集等を REST API で操作するアプリケーションを利用する。

#
# メモの登録
#
curl -X POST "http://127.0.0.1/memo/write" -d "memo=aaaaaaaaa"

#
# 全てのメモの一覧を JSON で取得
#
curl -X GET "http://127.0.0.1/memo/all"

#
# メモの内容を修正
#
curl -X POST "http://127.0.0.1/memo/edit/1" -d "memo=areertertertertretertretre"

メモ登録の際に送信する POST データ（memo=xxxxxxxx）の内容がログに記録されるまでがとりあえずのゴール、

mod_security のインストール

apt-get update
apt-get install -y libapache2-modsecurity

以上。

インストールが完了すると以下のように設定ファイル作成される。

$ pwd
/etc/apache2
$ ls -l mods-enabled | grep security
lrwxrwxrwx 1 root root 32 Jun 25 04:19 security2.conf -> ../mods-available/security2.conf
lrwxrwxrwx 1 root root 32 Jun 25 04:19 security2.load -> ../mods-available/security2.load

security2.conf の中身は以下のようになっており、フィルタリング等に必要な設定は /etc/modsecurity/ 以下に拡張子 .conf というファイル名で置けば良さそうだ。

$ cat security2.conf

        # Default Debian dir for modsecurity's persistent data
        SecDataDir /var/cache/modsecurity

        # Include all the *.conf files in /etc/modsecurity.
        # Keeping your local configuration in that directory
        # will allow for an easy upgrade of THIS file and
        # make your life easier
        IncludeOptional /etc/modsecurity/*.conf

POST データをロギングする為の mod_security の設定

ドキュメント等を見ながら以下のような設定を作成した。

$ pwd
/etc/modsecurity

$ cat mod_security_rule.conf
SecRuleEngine On
SecRequestBodyAccess On

SecAuditLog /var/log/apache2/post-request.log
SecAuditLogParts ABCFHZ
SecRule REQUEST_METHOD "POST" "id:100000,phase:2,nolog,pass"
SecRule REQUEST_URI "^\/memo/write$" "id:100001,ctl:auditEngine=On"

各ディレクティブについては以下の通り。

ディレクティブ 値 概要
SecRuleEngine On 後述のルールエンジンを有効にする
SecRequestBodyAccess ON POST のフィルタリングを有効にする（これを有効にしないと POST リクエストの中身は覗けない）
SecAuditLog /var/log/apache2/post-request.log 監査ログのパスを指定（このファイルに POST リクエストの中身が記録される）
SecRule REQUEST_METHOD “@beginsWith POST” “id:100000,phase:2,nolog,pass” REQUEST_METHOD という変数の値が POST で始まる場合にアクション "id:100000,phase:2,nolog,pass" を実行する
SecRule REQUEST_URI “^\/memo/write$” “id:100001,ctl:auditEngine=On” 同様にREQUEST_URIという変数に ^\/memo/write$が含まれている場合にアクション id:100001,ctl:auditEngine=On を実行する

その他のディレクティブ等については、以下の重厚なリファレンスを確認すること。

SpiderLabs/ModSecurity
ModSecurity is an open source, cross platform web application firewall (WAF) engine for Apache, IIS and Nginx that is developed by Trustwave's SpiderLabs. It has a robust event-based programmin...
GitHub

github.com

尚、SecRule は以下のような書式となる。

SecRule VARIABLES OPERATOR [ACTIONS]

例えば…

SecRule REQUEST_METHOD "@beginsWith POST" "id:100000,phase:2,nolog,pass"

だと、以下のような意味となる。

  • 検索対象は REQUEST_METHOD
  • "@beginsWith POST" は REQUEST_METHOD の値が POSTで始まる場合のリクエストを対象
  • ユニークな ID 100000 を付与
  • プロセスフェーズ phase の 2 を付与（2 は request フェーズで 4 が response となり 5 が logging となる）

（引き続き、調べて書く）

動かしてみる

  • メモを登録する
$ curl -X POST "http://127.0.0.1/memo/write" -d "memo=hogehoge" -i
HTTP/1.1 200 OK
Date: Sun, 25 Jun 2017 07:06:23 GMT
Server: Apache/2.4.10 (Debian)
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: POST, GET, OPTIONS, DELETE, PUT
Access-Control-Max-Age: 1000
Access-Control-Allow-Headers: x-requested-with, Content-Type, origin, authorization, accept, client-security-token
X-Powered-By: PHP/7.0.20
Content-Length: 0
Content-Type: text/html; charset=UTF-8
  • メモが登録されていることを確認する
$ curl -s GET "http://127.0.0.1/memo/all" | jq '.[]|select(.memo|contains("hogehoge"))'
{
  "id": "26",
  "memo": "hogehoge",
  "created_at": "2017-06-25 16:06:23",
  "updated_at": "2017-06-25 16:06:23"
}
  • POST したデータがログに記録されていることを確認する
--95a03a77-A--
[25/Jun/2017:07:06:23 +0000] WU9g76wRAAMAAAAWsgQAAAAH 172.17.0.1 43092 172.17.0.3 80
--95a03a77-B--
POST /memo/write HTTP/1.1
Host: 127.0.0.1
User-Agent: curl/7.43.0
Accept: */*
Content-Length: 13
Content-Type: application/x-www-form-urlencoded

--95a03a77-C--
memo=hogehoge
--95a03a77-F--
HTTP/1.1 200 OK
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: POST, GET, OPTIONS, DELETE, PUT
Access-Control-Max-Age: 1000
Access-Control-Allow-Headers: x-requested-with, Content-Type, origin, authorization, accept, client-security-token
X-Powered-By: PHP/7.0.20
Content-Length: 0
Content-Type: text/html; charset=UTF-8

--95a03a77-H--
Message: Warning. Pattern match "^\\/memo/write$" at REQUEST_URI. [file "/etc/modsecurity/mod_security_rule.conf"] [line "9"] [id "100001"]
Apache-Handler: application/x-httpd-php
Stopwatch: 1498374383196210 456570 (- - -)
Stopwatch2: 1498374383196210 456570; combined=89, p1=0, p2=84, p3=0, p4=0, p5=4, sr=0, sw=1, l=0, gc=0
Producer: ModSecurity for Apache/2.8.0 (http://www.modsecurity.org/).
Server: Apache/2.4.10 (Debian)
Engine-Mode: "ENABLED"

--95a03a77-Z--

上記の通り、--95a03a77-C-- パート以下に POST データが記録されている。

  • POST するんだけど、ログ取得対象では無いエンドポイントについてはログは記録されないことを確認する
$ curl -X POST "http://127.0.0.1/memo/edit/26" -d "memo=fugafuga" -i
HTTP/1.1 200 OK
Date: Sun, 25 Jun 2017 07:11:49 GMT
Server: Apache/2.4.10 (Debian)
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: POST, GET, OPTIONS, DELETE, PUT
Access-Control-Max-Age: 1000
Access-Control-Allow-Headers: x-requested-with, Content-Type, origin, authorization, accept, client-security-token
X-Powered-By: PHP/7.0.20
Content-Length: 0
Content-Type: text/html; charset=UTF-8

メモが更新されていることを確認。

$ curl -s GET "http://127.0.0.1/memo/all" | jq '.[]|select(.memo|contains("fugafuga"))'
{
  "id": "26",
  "memo": "fugafuga",
  "created_at": "2017-06-25 16:06:23",
  "updated_at": "2017-06-25 16:11:50"
}

ログは記録されていないことを確認。

$ sudo grep "fugafuga" /var/log/apache2/post-request.log
$

以上

mod_mruby でとても良いサンプルがあったのに、mod_mruby が利用出来なかったのは残念だったけど、mod_security を使うことで通常のアクセスログやエラーログだけで解析することが難しい Web アプリケーションの不具合等を調査する為の情報収集が簡単に行えるのは素晴らしい。（mod_security の本来の使い方では無いかもしれないが）

今後、実際のアプリケーション環境に mod_security を導入し、パフォーマンスへの影響等について引き続き検証を行いたい。

元記事はこちら

「Apache の mod_security を使って POST リクエストの内容をログに残す試み」