本番のWebサーバーから、次のエラーがCRITICALとして通知されるようになりました。
Uncaught PHP Exception Aws\Exception\InvalidJsonException: "Unable to encode JSON document UpdateItemInput: Malformed UTF-8 characters, possibly incorrectly encoded" at JsonBody.php line 57
最初は文字化けのバグを疑いましたが、アクセスログと突き合わせていくと、原因は外部からの攻撃でした。ログインの総当たりと脆弱性スキャンの中に、規格外のUTF-8を混ぜたリクエストが含まれていて、それがアプリの処理で例外になっていました。
この記事で書きたいのは、攻撃を見つけたことよりも、そのあとの「被害はなかった」をどう裏付けたかです。調査で一番時間がかかったのはそこでした。送信元の絞り込みと、被害の有無の確かめ方を、確かめられた範囲とあわせて書きます。
※ 社名、サービス名、ホスト名、日付は伏せています。IPアドレスはドキュメント用のアドレス(203.0.113.0/24、198.51.100.0/24)に置き換えています。
環境
- PHP(Symfony)のWebアプリで、セッションをDynamoDBに保存している
- AWS SDK for PHPを使っている
- nginxのアクセスログはLTSV形式で、サイト(vhost)ごとにファイルが分かれている
- Webサーバーは複数台あり、調査はAnsibleのad-hocコマンドで全台に同じgrepを流した
- アプリのエラーログはVectorでSlackに通知している。同じメッセージはホストごと・10分単位で1件にまとめる設定
このエラーは何を言っているのか
AWS SDK for PHPは、DynamoDBへのリクエストを送る前に、パラメータを json_encode でJSONに変換します。変換する値に不正なUTF-8のバイト列が含まれていると変換に失敗し、InvalidJsonException が投げられます。
この例外はDynamoDBから返ってきたエラーではなく、リクエストを組み立てる段階で起きています。AWSには何も送られていません。今回はこの例外がどこでも捕捉されていなかったため、リクエストはそのまま500になっていました。
これは裏を返すと、規格外のバイト列を送るだけで、誰でも狙って500とCRITICAL通知を起こせる状態でもありました。今回の範囲では通知のノイズで済みましたが、例外として捕捉するか、手前の入力検証で弾く必要があります。
残る疑問は、不正なバイト列がどこから入ってきたかです。
送信元をどう絞り込んだか
エラーログにはリクエストの情報がほとんど残っていなかったので、エラーが出た時刻に500を返したリクエストを、アクセスログから探しました。
ansible all -i inventories/prod --limit 'web01,web02,web03,web04' -m shell -a \
"grep -H 'time:<日付>T06:1[48]' /path/to/logs/*.access.log | grep -P '\tstatus:500\t'"
-H を付けてファイル名を出すと、どのサイトへのリクエストかもわかります。結果から次のことがわかりました。
- 500はすべて
POST /loginか、外部サービス連携のログイン画面へのGETだった - 送信元は2つのIPに絞られた
- どちらも未ログインの状態で、UAは同じWindows版のChromeだった
そのうち1件のURLには、次のような文字列が入っていました(一部加工しています)。
/xxxx/login?to=/mypage%C0%A7%C0%A2%252527%252522%5C'%5C\x22
利用者の文字化けで、この並びになることはありません。意図的に作られた入力です。
続けて、2つのIPのリクエスト全体を見ました。GraphQLのエンドポイント探索、ランダムなファイル名での .php や .jsp の探索、URLのパスやUAの欄に入れたSQLインジェクションの試行が並んでいました。ログインの試行は、1日で約1,500件ありました。
%C0%A7 は何の文字か
%C0%A7 は '(0x27)を、%C0%A2 は "(0x22)を、UTF-8の規格では許されない2バイトの形式で書いたものです。冗長な表現(overlong encoding)と呼ばれます。
' = 0x27 = 0b0100111
2バイト形式: 110 00000 10 100111 → 0xC0 0xA7
UTF-8では、1バイトで表せる文字を2バイト以上で書くことは禁止されています。それでもこの形式を送ってくるのは、入力チェックが ' や " をバイト列で探している場合に、そのチェックをすり抜けるためです。後段のデコーダーがこの形式を許して ' と解釈すると、チェックを通った後で引用符になります。
PHPの json_encode はこの形式を不正なUTF-8として扱うので、今回は例外で処理が止まり、引用符として解釈されることはありませんでした。
URLに混ざっている %252527 は、' を三重にURLエンコードしたものです。デコードする回数が、入力チェックと後段の処理で食い違っていることを狙った手口です。
Googlebot は本物だったのか
2つのIPのUAを集計すると、一部のリクエストがGooglebotを名乗っていました。
grep -h -e 'forwardedfor:203.0.113.10' -e 'forwardedfor:198.51.100.20' /path/to/logs/*.access.log \
| grep -oP 'forwardedfor:\S+|ua:[^\t]*' | paste - - | sort | uniq -c | sort -rn
Googleは、Googlebotかどうかを確かめる方法として、IPを逆引きして googlebot.com や google.com などのGoogleのドメインが返ること、そのホスト名を正引きすると元のIPに戻ることを確認する手順を案内しています。
$ host 203.0.113.10
Host 10.113.0.203.in-addr.arpa. not found: 3(NXDOMAIN)
2つのIPとも逆引き自体が存在せず、Googlebotを装っていたことが確定しました。Googlebotを名乗るのは、UAでクローラーを優遇しているサイトの制限をすり抜けるためによく使われる手口です。WAFやWebサーバーに「UAがGooglebotなら許可する」といった設定がある場合は、UAではなくIPで判定するように見直したほうがいいと思います。
「被害はなかった」をどう確かめたか
送信元が攻撃だとわかった後、報告で必ず聞かれるのは「被害はあったのか」です。攻撃の種類ごとに確かめ方が違い、どの方法にも確かめられる範囲の限りがありました。順に書きます。
フォームの送信は完了していないか
POSTの送信先を集計すると、ログインよりも問い合わせフォームへの送信のほうがずっと多く、合計で1万件を超えていました。フォームの送信が受け付けられていれば、運営側に攻撃文字列入りの問い合わせが大量に届いていることになります。
2つのIPからのフォーム送信は、すべて200でした。200だけでは、入力エラーで同じ画面が再表示されたのか、確認画面に進んだのかはわかりません。そこで、同じフォームに対する正規の利用者のステータスと比べました。
grep -h -P '\tmethod:POST\turi:/forms/' /path/to/logs/*.access.log \
| grep -v -e 'forwardedfor:203.0.113.10' -e 'forwardedfor:198.51.100.20' \
| grep -oP 'uri:[^?\t]*|status:\d+' | paste - - | sort | uniq -c | sort -rn
正規の利用者 2つのIP
302 200 302 200
問い合わせフォーム 11 16 0 6,521
正規の利用者は、送信が完了すると302で完了画面に移ります。2つのIPは6,000件以上送って302が1件もないので、完了まで進んだ送信はないと判断しました。
時間差のSQLインジェクションは成功したか
UAの欄には、sleep(15)、waitfor delay '0:0:15'、PG_SLEEP(15)、DBMS_PIPE.RECEIVE_MESSAGE(...,15) が並んでいました。MySQL、SQL Server、PostgreSQL、Oracleの4種類を順に試しています。どれも、攻撃が通るとDBの処理が15秒止まり、その応答の遅れで成否を判定する手口です。
応答が遅れるということは、アクセスログの応答時間を見れば成功したかどうかがわかります。reqtime が14秒以上のリクエストを探しました。
grep -h -e 'forwardedfor:203.0.113.10' -e 'forwardedfor:198.51.100.20' /path/to/logs/*.access.log \
| grep -P '\treqtime:(1[4-9]|[2-9][0-9]|[0-9]{3,})\.'
結果は0件でした。同じIPが過去に来ていた日のログも同じ条件で確認し、こちらも0件でした。
0件という結果には、grepの条件が間違っていて何も拾えていない可能性が残ります。しきい値を2秒に下げて同じコマンドを流し、2秒台のリクエストが出てくることを確かめてから結論にしました。
この方法でわかるのは、時間差の手口が通ったかどうかだけです。-1 OR 5*5=25 のような条件式の手口が通ったかどうかは、応答時間からは判断できません。
ログインに成功していないか
このアプリでは、ログイン中のリクエストについて、アクセスログに会員番号を出しています。2つのIPのリクエストで、会員番号が入った行を探しました。
grep -h -e 'forwardedfor:203.0.113.10' -e 'forwardedfor:198.51.100.20' /path/to/logs/*.access.log \
| grep -P '\tmembernumber:[^\t-]'
0件でした。マイページへのアクセスも、すべて302(ログイン画面への転送)か404で、200はありませんでした。
ただし、総当たりで当たりのIDとパスワードを見つけ、実際のログインは別のIPから行う手口もあります。この確認でわかるのは「このIPからはログインしていない」ところまでです。
集計でハマったところ
調査の途中で、何度か結論を書き直しています。同じ調べ方をする人のために残しておきます。
time: で検索すると reqtime: にも一致する
LTSVから時刻を取り出そうとして grep -oP 'time:\S+' と書いたところ、reqtime:0.038 や apptime:0.039 にも一致して、paste で並べた列がずれました。後読みで除外しています。
grep -oP '(?<!req|app)time:\S+'
値なしの - を、値ありとして数えていた
会員番号が入った行を最初は membernumber:[^\t] で探していて、静的ファイルへのリクエストが大量に出てきました。nginxは値がない項目を - で出力するので、- を除外する必要がありました。
途中の出力を、最新の結果と読み違えた
最終アクセス時刻を確認した時点ではまだ攻撃が続いていたのに、同じ出力を後でもう一度見て「止まった」と判断していました。別のコマンドの結果から、その後も20分ほど続いていたことがわかりました。攻撃が続いているかどうかは、時間をおいて取り直さないとわかりません。
Slackの通知件数は、実際の件数より少ない
通知はホストごと・10分単位で同じメッセージを1件にまとめているので、同じホストで10分以内に出たエラーは1件しか届きません。今回は攻撃が複数台に振り分けられていて、通知の件数はそれなりにありましたが、ログで数えた実際の件数はその数倍でした。件数はログを直接数えています。
やったこと
- 2つのIPを、WAFの拒否リストに追加した
- その日の夜、別のIPから同じ特徴(UA、応答時間、500のレスポンスサイズ)のリクエストが来た。IPも特徴も相手が自由に変えられる以上、1つずつ止める対応はいたちごっこになる。「どのIPから来たか」で止めるのをやめ、「何をしようとしているか」で止める方向に切り替えて、ログイン画面への試行の制限と、入力の文字コードの検証を入れた
おわりに
エラーの原因は、アクセスログと突き合わせた時点でおおよそ見当がつきました。時間がかかったのは、その後の「被害はなかった」の裏付けです。SQLインジェクション、ログイン、フォーム送信では確かめる方法がそれぞれ違い、どの方法にも確かめられる範囲の限りがありました。
報告では、ログで確認できたことと、推測にとどまることを分けて書きました。時間差のSQLインジェクションは成功していない、このIPからのログインはない、フォームの送信は完了していない、の3つは確認済みです。条件式のSQLインジェクションと、別のIPからのログインは、アクセスログだけでは確かめられていません。