Hardening奮闘記 サービス提供って難しい[本番編]
猪野 裕司
![Hardening奮闘記 サービス提供って難しい[本番編]](/assets/rtc/prod-rtc-blog/wp-content/uploads/2017/07/25100133/a11b4bb3ba448d1fa402ac3dc62cc91f.jpg)
インシデントレスポンスグループ 猪野です。
この記事は[準備編]と２部作になっており、＜前回のリンク＞ から読んでいただけると幸いです。
前日からガチハードニング！！
競技前日 6/22の朝空港へ向かう際の出来事でした。競技環境にてフルパケットキャプチャのOSS Molochが不定期にキャプチャ停止する問題を、我々はcronでモグラ叩き戦法という水際作戦で乗り越えようと考え、弊社セキュリティオペレーションセンターの清水が圧倒的当事者意識で上記問題のあらゆる原因を検討していました。
（Slack上のやりとり）
清水「もしかして、今回の環境ってジャンボパケット？」
市田「え、確認できてないですが、まさか」
清水「molochのパケットキャプチャ用のバッファが16KBしかないんではないか、という気がしてます＜これからソース読む。めっけた」
猪野・市田「素晴らしい！！」
Molochはデフォルトで16kBまでのパケットフレームにしか対応しておらず、 MTU1500以上のいわゆるジャンボフレーム/ジャンボパケットを扱う際にはConfig設定を入れなければなりませんでした。そのパラメーターはconfig.iniにはデフォルトで記載されていない「snapLen」という隠しパラメーターです。
羽田空港に到着してゲートをくぐるや否や、検証機のチューニングをします。
ソースコードによると
|
1 |
> moloch.h uint32_t snaplen; /* max length saved portion of each pkt */> config.c config.snapLen = moloch_config_int(keyfile, "snapLen", 16384, 1, MOLOCH_PACKET_MAX_LEN); |
デフォルト16,384 Byteで最大値は128KBでした。ソースコードの読み込みが甘かったようです。どうやらこのパラメーターは一つ前の0.18.2から追加された真新しいものでした。とりあえず倍の snapLen=32768 で設定を入れてみましたが33370 Bでまた落ちたので、競技環境の設定が64KBであると想定し、ちょっと余裕を持たせてsnapLen=81920で再度設定を入れ直して飛行機に乗りました。
夕方、沖縄のホテルで確認するとエラー停止しなくなっていました！ただ、以下のようにジャンボフレームを捕まえるtcpdumpを設定しても、半日取高ありませんでした。
|
1 |
sudo bash -c "nohup tcpdump -i eth1 greater 1500 -w bigpkt_eth1.pcap > /data/moloch/tcpdump2.log &" |
下記のエラーが出たのでどうやらsnaplenの最大値は65536 (64K) のようです。下記のように設定を変更して再度様子を見ます。
|
1 |
Jun 22 17:40:10 config.c:188 moloch_config_int(): INFO: Reseting snapLen since 81920 is greater then the max 65536 |
無事、キャプチャ停止も解決したことだし、30分したらMPの懇親会に向かおうと気を抜いていたら、Viewerからパケットペイロードが全く見えない事象が発生していることに気がつきました！
|
1 |
Jun 22 17:40:10 config.c:188 moloch_config_int(): INFO: Reseting snapLen since 81920 is greater then the max 65536 |
パケットが生成されていない?!またもやキャプチャ障害か！エラーはなく以下のInfoがあるだけです。
|
1 |
Jun 22 18:10:14 writer-simple.c:391 writer_simple_init(): INFO: Reseting pcapWriteSize to 262144 since it must be a multiple of 4096 |
全然原因がわからないまま、懇親会に行けずトラブルシュートしていたら、
|
1 |
Jun 22 17:40:10 config.c:188 moloch_config_int(): INFO: Reseting snapLen since 81920 is greater then the max 65536 |
とpcapファイルにデータが書かれました！Viewerでもデータが見えるようになっていました。そのあともソースコードを読みながら状況を確認していると以下のことが判明しました。
・MolochはPcapファイルにはブロック単位でしか書き込まず、ElasticSearchのMetaDataから紐付けてペイロードを見るにはpcapファイルを参照する
・したがって、ブロック単位である262143を超えた流量が流れてこないとファイル書き出しが発生せず、Viewerからもその部分のパケットペイロードが読み込めない
単にパケット流量が少ないだけでした！これが直近のパケットペイロードが見えない原因でした。メモリから参照してくれていると勝手に認識してしまっていました。Molochはその瞬間のパケット流量をリアルタイムで確認できないため、流量が少ない場合にキャプチャ状況の把握が難しくなるのが弱点です。
なお、表示までのspanを短くするにはconfig.iniのpcapWriteSize = 262143を下げれば良いのですが、検証する時間がないのと逆にディスクI/Oが増えることでの負荷を懸念して、いじらずに当日を迎えました。
当日発生したタイムスリップ問題
6/23当日、気合をいれて二人で色違いの「かりゆし」を着て出陣しました。（左：猪野、右：市田）
自分たちが欲しかったサービス！確実に売れるはず！と自信を持って参加したのですが・・・
最初の２時間、まったく売れませんでした m(_ _)m 緊急値下げをして２チームからご購入！
プレ活動と称して、プレイヤーとしてのノウハウを売り込み、やっとのことで２チームから購入していただきました。さて、これから本番、構築・運用スタートです。
VMで各チームに配っていただいたので、サービスを購入してもらった後は、
1. 運営にて Moloch VM 起動
2. 各チームのFWにてNAT設定を入れてもらい、我々がアクセスできるようにする
3. リモートからチューニングして、正常性確認
の手順で配布を実施予定でした。このStep 2. NAT設定で問題が起きます。
今回Hardening 1010 CashFlowでは、昨年のpfsenseのようなFWソフトウェアではなく、CentOS7のfirewalldにて設定を入れねばなりませんでした。FWの設定は各チームのビジネスを止めかねないので、各チームにお願いしていましたが、NAT設定がなかなか入らずサポートできない状況が続きました。LinuxなのでIP tablesの設定を教えたりもしたのですが、なぜか設定が反映されませんでした。そこで急ぎfirewalldでの設定コマンドを調べて伝えたところ、なんとかリモートアクセスできました。
サービスを購入してくれた2チームのうちの一つ、チーム10にはここまで３時間もかかってしまい、申し訳なく思っています。後ほど検証して分かったことは、CentOS7ではfirewalldとiptablesでNAT設定を入れられるのですが、firewalldデーモンがiptablesコマンドで実行した設定を上書きして元に戻してしまうようで、一度firewalldを停止させてiptablesの設定を入れてから起動する必要があったようです。しかし、firewalldを停止するとビジネスが止まるため、firewalldプロセスがアクティブ状態でも設定が反映できるfirewalldコマンドでpriorityパラメータを足してNAT設定を入れることが求められました。
うまくいったNAT設定はこちらです。
|
1 2 |
firewall-cmd --permanent --direct --add-rule ipv4 nat POSTROUTING_direct 0 -s 192.168.0.126 -o eth0 -j SNAT --to 10.2.xx.126 firewall-cmd --permanent --direct --add-rule ipv4 nat PREROUTING_direct 0 -d 10.2.xx.126 -i eth0 -j DNAT --to 192.168.0.126 |
ところが、リモートアクセスしてみたら２チームともおかしな事象が起こっています！！
Metadata/pcapの保存時刻が約半日後の「未来」を指している！
パケットキャプチャはできていたのですが、キャプチャ時刻が未来にずれており、検索ができません。時刻を未来にずらしていくとログが発見できる状態でした。OSの時間を疑ったのですが、timedatectlの結果も正しく、NTPも正常に動いていました。
色々と調査しているとはじめに作成されたpcapの作成時刻がなぜか翌日の6月24日になっています。（Hardening当日は6月23日です）
|
1 |
rw-r-----. 1 nobody daemon 0 Jun 24 2017 moloch-170624-00000198.pcap |
/data/moloch/logs/capture.log 等のログファイルには正しい時間で書き出されていました。
|
1 |
>Jun 23 17:47:32 http.c:263 moloch_http_curlm_check_multi_info(): 1/5 ASYNC 200 http://127.0.0.1:9200/stats/stat/moloch 665/132 0ms 40ms |
しばらくすると、
|
1 2 |
-rw-r-----. 1 nobody daemon 1535115264 Jun 23 18:12 moloch-170623-00000593.pcap -rw-r-----. 1 nobody daemon 3172204544 Jun 23 18:12 moloch-170623-00000594.pcap |
とpcapファイルへの書き込みは正しい時間で書き込まれるようになっていました。
ここで、はじめに作成したpcapが が未来時間となっていたため、検索ができなくなったという仮説が生まれました。そこで、使えなくなったDBやpcapを消去したり、サービスを再起動したり、パラメーターをチューニングしたりとあの手この手を使いましたが、結局時刻ずれは最後まで治りませんでした。OSSを使うのと使いこなすには大きな隔たりがあり、OSSの厳しさを身を持って体感した1日でした。
しかも翌日Softning Dayで確認してみると、今度は正常にキャプチャしているではないですか！時刻ずれの原因を様々なログを遡って見てみると、Moloch Pcap内の各パケットのタイムスタンプ がずれたタイムゾーンで記録されている現象が確認できました。2017/06/23 07:43:49(UTC)で記録されるべき時刻が16:43:49(ローカルタイム)で記録され、Molochはさらに+9時間後の25:43:49と解釈してしまうのです。
そこで、CentOS7の前提を確認しながらいろいろ議論を重ね 、時刻が未来を指し示してしまった原因を推定しました。
CentOS7の前提
・CentOSのSystemdがデーモンを明確な依存関係が定義されていない場合は、依存関係なしとして並列起動する
・ntpdやchronydは、ネットワークサービスに依存するとして定義されているので、ネットワークが起動してから起動する
・MolochCapture.serviceの起動は、マルチユーザーモードとして起動したよ、というルールにのみ依存していたため、 ntpdやchronydには依存しない形で時刻同期を待たずに起動する
・リブートやパワーオンでCentOSが起動した直後のシステムクロックは、RTCから読み取って起動する
・ntpdやchronydが起動して上位NTPサーバーに時計合わせするまでは、RTCから共有された時刻情報でOSは動作している
・この際、CentOSは、RTCからの時刻はUTCだと定義されている（そもそもRTCからの情報にはタイムゾーンと言う物がない）
想定される原因
・当該環境ではRTCはJSTのタイムゾーンで定義された時刻情報が設定されていた
・CentOSが起動した直後は、タイムゾーンが設定されていない状態で起動する。その後、ntpで時刻同期が出来た時点で正しいタイムゾーンになるが、Cron設定したMolochCaptureがすでに異なるタイムゾーンで起動して、pcapファイルやメタデータの処理を未来時刻で開始してしまった。Ntpdによる時刻同期を待った上で 、MolochCaptureを起動させるべきであった
これが今回のトラブルの本当の原因であるかは競技環境へアクセスできない我々には確認するすべがありません。しかし、秋のハードニングではきっと無事Molochを提供できると信じています。
最後に
今回初のマーケットプレイスで参加させていただき、１ヶ月半という短期間で通常では得られない経験とプレッシャーを得ることができました。もともと検証しようとしていたMolochでしたが、 Hardeningで出品すると決まってからは急ピッチで理解が進みました。
Hardening Project運営の皆様、競技中に購入していただいた２チームの皆様に深く感謝を申し上げます。
関連リンク
https://wasforum.jp/hardening-project/
https://github.com/Recruit-CSIRT/moloch-hardening