Grafana & Graphite でRADIUSのログを可視化してみた 開発編

ネットワーク プログラミング

このエントリは「Grafana & Graphite でRADIUSのログを可視化してみた 概要編」の続きとなります。最初のエントリをご覧になってからお読みください。

miyalog.hatenablog.jp

さてこちらが本編。RADIUS認証ログ可視化ツール Radtail の開発にあたり、苦労した点、工夫した点を語らせて頂きます。

tail -f でログあつめ

いいえ、Cisco NSO じゃないです。

何はともあれ RADIUSサーバーからログを取得できなければ話は始まりません。ログの収集といえば、Fluentd や Logstash 等の定番オープンソースソフトウェアを使うのがセオリーだとは思いますが、下請け作業員がサーバーに入ることすらはばかられるのに、エージェントをインストールするなど天地がひっくり返っても許されません。

import pexpect
with pexpect.spawn('ssh -o "StrictHostKeyChecking=no" foo@10.10.10.10', timeout=10) as exp:
    exp.expect('Password:')
    exp.sendline('admin123')
    exp.expect('\$')

    exp.sendline('tail -F /var/log/radius/accounting.log')
    while True:
        exp.expect('\r\n')
        result = exp.before.decode('euc-jp')

ただ、なんとかサーバーにSSHしてログを覗く許可だけはもらえたので、「人がSSHしていいなら、ツールがSSHしてもいいだろう」という拡大解釈のもと、サーバー上で tail -f もしくは tail -F コマンドを叩いて、大量に吐き出され続けるログを expect で1行ずつ取り出して処理するようにしました。ログインも当然ながら私の公開鍵を登録することもできないので、expect で対話型パスワード認証を行います。まったく、expect は最高だぜ!!。あとは取り出したログをよしなにパース＆整形してやればログの収集・解釈が完了。ちなみに、Radtail というツール名はこの tail を使うことに由来しています。

Tips: tail -f ではなく tail -F オプションを使うことで、ログローテーションされて開いていたファイルがなくなっても、自動でファイルを再オープンして tail を再開してくれます。ただ Solaris 10 を搭載した古いサーバーでは対応していなかったため、一定時間ログが流れてこなかったら開き直すという処理をいれてお茶を濁しました。

マルチプロセス導入への道のり

Graphite データ上書き問題

開発当初、RADIUSサーバーごとにツールを起動し、それぞれでログを Graphite に送信していたのですが、記録されたデータの値が実際より大幅に少ないという不具合が起きました。調べたところ数ヶ月前の設備更改の際にロードバランサーを導入したそうで、同一LACのリクエストが複数のRADIUSサーバーに振り分けらた結果、同じメトリック・同じタイムスタンプのデータが発生します。本来はそれを合算すべきなのですが、それぞれのツールがデータをそのまま Graphite に送信したことでデータが上書きされ、最後に処理したデータのみが残るという後勝ち現象が起きていたのでした。

f:id:miyahan:20161104001347p:plain本来は合計 600 なのだが、最後に送信された 100 で記録されてしまう

例えばMySQLでいうところの、INSERT INTO hoge SET atr='%s', ts=%s, val=%s ON DUPLICATE KEY UPDATE val=val+VALUES(val); みたいなことをやらせたく、こんな設定を入れてみましたが状況は変わりませんでした。

# /etc/carbon/storage-aggregation.conf

[radtail]
pattern = ^radiuslog\.
xFilesFactor = 0
aggregationMethod = sum

どうやら storage-aggregation.conf は、複数のリテンションを設定している場合において、データを丸める方法を指定するファイルであって、受信したデータの集計方法を変えるものではなかったみたいです。アメリカ語から目を背けてきたツケががが。というわけで、Graphite/Carbon に集計機能はありません。つまり自前で集計機能を作る必要が出てきました。

もはや Graphite でそれやる？という話になってきましたが･･･

そしてマルチプロセスへ

真っ先に思いつくのはマルチスレッド化してGraphiteに送るデータのバッファを共有することですが、実は Python のマルチスレッドは GIL(Global Interpreter Lock) という制約によってプロセッサ数に対してスケールしません。ちなみに Ruby にも グローバルVMロック という同様の仕組みがあるそうです。しかしCPU1コアではパワーがまるで足りないため、今回使うことはできませんでした。

そこでマルチコアCPUの恩恵を受けられるマルチプロセスを使うことにしました。Python の multiprocessing モジュールにはプロセス間でデータを共有できる「共有メモリ」や「サーバープロセス」という機能があるのですが、ロックによりパフォーマンスが出しにくいことや、配列などのミュータブルなオブジェクトを扱うのが難しいため不採用。かわりにプロセス間通信機能の multiprocessing.Queue を使うことにしました。

f:id:miyahan:20161104055933p:plain

ログを収集・解釈する "Collector" プロセスをサーバー台数分、ログを集計・記録する "Aggregator" プロセスを１つ生成し、Collector から Aggregator へはキューを使ってデータを渡すようにしました。

各 Collect プロセスは、Aggregate プロセスへ好きなタイミングでどんどんメッセージを送信していきます。メッセージは Queue に格納されていき、Aggregator はキューからFIFOでメッセージを取り出し処理していきます。このようにそれぞれのプロセスが非同期に動作することでCPUパワーを余すことなく活用できるようになりました。

それにしても multiprocessing モジュールを呼ぶだけで並列処理が簡単に書けるなんて、PHP しかわからない自分は魔法にしか見えません。軽いカルチャーショックです。。。え、普通？

defaultdict で簡単集計

各 Collector から送られてくるデータの集計は、タイムスタンプ・アトリビュートで階層化された辞書(連想配列のようなもの)をバッファとして用意し、そこに値を代入したり加算していくようにしました。具体的にはこんな感じ

buf[デートタイム][LACホスト名][LACポート名][イベントタイプ] = イベント数

で、当初はいちいちキーの存在をチェックし初期化していたのですが、collections.defaultdict という自動で初期化を行ってくれる辞書モジュールを見つけ、コードを書き直したところデータの追加が1行で済むようになり、実行速度も3割ほど高速になりました。テキトーに連想配列を使うことに慣れている私のようなゆるふわPHPerにはありがたいモジュールですね。

# Before : キーの存在を確認して初期化

buf = {}
if '2017/1/1 00:00:00' not in buf:
    buf['2017/1/1 00:00:00'] = {}
if 'ootemachi-bas01' not in buf['2017/1/1 00:00:00']:
    buf['2017/1/1 00:00:00']['ootemachi-bas01'] = {}
if 'access-accept' in buf['2017/1/1 00:00:00']['ootemachi-bas01']:
    buf['2017/1/1 00:00:00']['ootemachi-bas01']['slot1']['access-accept'] += 10
else:
    buf['2017/1/1 00:00:00']['ootemachi-bas01']['slot1']['access-accept'] = 10

# After : defaultdict を使って自動初期化

from collections import defaultdict
buf = defaultdict(lambda: defaultdict(lambda: defaultdict(lambda: defaultdict(int))))

buf['2017/1/1 00:00:00']['ootemachi-bas01']['slot1']['access-accept'] += 10

パフォーマンスチューニング

四苦八苦しながらどうにか動くまでにこぎ着けたものの、今度はパフォーマンスの問題に直面しました。プロトタイプはCPU使用率が Collect プロセスで 30〜60%、Aggregate プロセスで 60〜100% と高く、ログがバーストした際に集計処理がおいつかずキューが溢れてしまう問題が発生しました。

「推測するな、計測せよ」という格言があるように、私もそれに倣うことにしました。

ベンチマークで現状把握

まず現状把握とチューニングの効果確認のために、100万行のダミーデータを用意しベンチマークスクリプトを書いて実行してみました。

f:id:miyahan:20161116173013p:plain

すでに問題が見えてきましたね。これから試行錯誤しながらこのタイムを縮めることを目指していきます。

プロファイリングで原因特定

次に問題箇所の特定のため、プロファイリングを行います。Python には標準で cProfile というプロファイリングライブラリがバンドルされています。今回は、さらにそれをグラフ化する Python Call Graph (pycallgraph) というツールを使ってみました。なおプロファイリングにあたり下記サイトを参考にさせていただきました。

なお、Python Call Graph のコマンドラインは、出力形式を指定しても反映されないバグがあるらしく、今回は Python スクリプト内から呼び出すようにしました。

f:id:miyahan:20161116175615p:plainPython Call Graphの実行結果 / オリジナルサイズのPDFはコチラ

おお、なんかカッコイイ･･･！Python Call Graph は、呼ばれたモジュール・メソッドの関係、実行された回数・時間を可視化してくれます。また時間がかかっているメソッドを色づけしてくれるため、問題箇所を一目で把握することができます。グラフをみると datetime および multiprocessing モジュールで多くの時間が費やされているようです。

さらに問題となっているコードを特定するため、line_profiler というツールを使ってみます。すると2カ所、処理に時間ががかっているコードを発見しました。

f:id:miyahan:20161112020142p:plain1カ所目：datetime.strptime() でログの日時文字列をパースしているところ

f:id:miyahan:20161112020134p:plain2カ所目：multiprocessing.Queue.get() でキューを取り出しているところ

datetime.strptime 対策

まず1カ所目、datetime.strptime が遅い問題は、同メソッドの使用をやめ、下記のように自分でスプリットしてから datetime に渡すように書き換えたところ4倍以上高速になりました！

# Before
logtime = datetime.datetime.strptime(row[0], "%Y%m%d%H%M%S.%f")

# After
logtime = datetime(
    year=int(row[0][0:4]),
    month=int(row[0][4:6]),
    day=int(row[0][6:8]),
    hour=int(row[0][8:10]),
    minute=int(row[0][10:12]),
    second=int(row[0][12:14])
)

なお本件は次のエントリで詳しく紹介しています。ぜひ併せてご覧ください。

multiprocessing.Queue 対策

次に2カ所目の multiprocessing.Queue.get() に時間がかかっている問題は完全に私の設計ミスです。よくよく考えてみればプロセス間通信（かつ排他制御付き）のコストが高いのは当たり前の話で、それを毎秒1万回もやっていたらそりゃ重いわけです。

そこでメッセージをリスト(配列)に格納していき、それを1秒ごとプロセス間で交換するように仕様変更したところCPU使用率が軽減できました。

チューニングの効果

f:id:miyahan:20161104060843p:plain

まずはベンチマークの結果から。最初は28秒かかっていた処理が、8秒と3.5倍以上の高速化に成功しました！

f:id:miyahan:20161112022223p:plain CPU使用率（最適化前）

f:id:miyahan:20161112022227p:plain CPU使用率（最適化後）

また実際のツール動作時のCPU使用率もご覧の通り激減しています。たびたび100%に張り付いていた Aggregate プロセスは 20〜30% に落ち、処理が追いつかなくなる問題は解消しました。サーバーリソース的にもにっこり。

f:id:miyahan:20161129014201p:plainオリジナルサイズのPDFはコチラ

ちなみに、最適化したソースに対し PyCallGraph を実行するとこうなりました。重たい strptime の使用をやめたことで呼び出されるモジュールが激減していますね。

Graphite 書き込み間に合わない問題

ツールがある程度動くようになり会社の本番サーバー(VMware vSphere Hypervisor / CentOS6)にデプロイしてみたところ、ツールを起動してから10分程度経つとデータが記録されなくなる不具合が起きました。結論だけいうと、本番サーバーのストレージ (1krpm SAS HDD x 2 RAID1) のI/O性能がヘボすぎてディスクフラッシュが追いつかないというものでした。（開発に使っていたPCはSSDなので問題にならなかった）

当初はログを1秒単位で集計(＝マイクロ秒を切り捨て)しており、1万メトリック/秒 くらいのトラフィックがありました。そこで集計単位を10秒に伸ばしたところ、トラフィックが 5000メトリック/秒に減少。しかしそれでもギリギリどうにかついて行っている状態で、ちょっとでもバックグラウンド処理（ログローテーション、メンテナンススクリプトの実行等）が走ったり、他のVMが活動し出すとフラッシュが全く追いつかず、どんどんバッファが貯まっていってしまいます。

f:id:miyahan:20161116180949p:plain 図：本番サーバー 調子よいとき

f:id:miyahan:20161116181011p:plain 図：本番サーバー 調子わるいとき

carbon-cache の設定をいじってチューニングしようとしたものの、全く効果はありませんでした。詳しい検証内容は次のエントリでまとめています。併せてご覧ください。

結局サーバーのスペック不足はどうしようもなく、ツールの実行は本番サーバー、データの記録(carbon-cache)はそこらへんの作業用パソコンつなげた USB SSDという暫定運用をしています。つまりだれかがそのPCを再起動したりスリープさせるとツールが止まるということです。(´- ω -`)

おわりに

軽い気持ちで始めたツール開発。しかしふたを開けてみればフレームワークすら使えないゆるふわPHPerにはあまりに過剰な挑戦でした。やりたいことはログを整形してDBに記録するだけとシンプルなのに、いざ開発を始めると多くの問題や課題が出てきて、そのたびに1日中ググったり、風呂や布団の中で悶々とシステム設計について脳内会議を開いたり、ときに teratail などの質問サイトにもお世話になりました。

初めての Python モジュール/クラス使用、初めてのリアルタイムデータ処理、初めてのGBクラスの大量データ処理、初めての並列処理/マルチプロセス設計、初めてのデーモン開発･･･

でも、おかげさまで実用的なツールができあがりましたし、自身のスキルもかなり向上しました。そしてなにより

ツール作るの楽しい ✌('ω'✌ )三✌('ω')✌三( ✌'ω')✌

これですな。

今回ツールを作るうえで、

  • Graphite のデータ活用法（関数の使いこなし、APIを使った外部ツールとの連携等）
  • 統計データから異常状態・特異点を見つける方法

といった領域のスキル・ノウハウが足りませんでした。Advent Calender をはじめ、NetOpsCoding の定期イベントやSlack、ML 等で知見をシェアいただけると大変助かります。よろしくお願いします。