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

NetOpsCoding Advent Calendar 2016 @ Qiita 12/6 のエントリです。サービスの異常を素早く一目で把握できるよう、RADIUSサーバーのログを可視化するツールを作ったお話をします。

きっかけ

おはようございます！(午後6時)　とある通信会社の委託でネットワークの監視業務をしている夜勤作業員です。（エンジニアじゃないよ）

f:id:miyahan:20161104004823p:plain

具体的にはこんな感じのCiscoの古い教科書によく載っているようなインターネットには直接繋がっていないネットワーク（いわゆる閉鎖網）を見ているのですが、サービスの正常性を確認する方法として、各ルーターにTelnetし show pppoe session といったコマンドを叩いて、お客様のPPPoEセッションやLAC〜LNS間のL2TPトンネルが確立しているかをチェックします。ただこの作業は、

障害の影響が広いときに何十台ものLAC/LNSを確認するのが辛い
機種によってはCPUが弱く、コマンドの結果が表示されるまで数分待たされて辛い
コマンドではその時点の状態しか確認できず、切れたセッションなどが見えず辛い
目grep辛い、というか無理

などなど多くの難点を抱えており、確認作業が大幅に遅れたり、見落としによるヒューマンエラーを起こしお客様からクレームを受けるなど問題が山積みでした。

過去にルーターに自動でログインしコマンドを叩き、結果をいい感じにグラフィカルに表示するWebアプリを作ってそれなりの効果があったのですが、大きな障害では結局ツールをルータの台数分実行しなければいけなかったり、ルーターのCUIが遅い問題は如何ともし難く即時性に欠けるなど課題が残っていました。

そこでRADIUSサーバーの認証ログ・接続ログを使えないか？思い立ち、サービスの異常を素早く一目で把握すべく、ログを可視化するツール、名付けて「Radtail」（ラドテイル）を作ってみました。

Radtail 概要

ところで、先日行われた NetOpsCoding#3 で、日本Microsoft 北島さんの発表、Monitoring Intelligence に感銘を受け、それからというもの Grafana + Graphite をいじくり回しています。

Monitoring Intelligence from netopscoding

www.slideshare.net

そんなわけで今回、データの収集・解析を自作の Python スクリプトで行いつつ、データの蓄積・描写にここぞとばかりと Graphite・Grafana を採用しました。

f:id:miyahan:20161116185907p:plain Radtail システム構成図

本ツールはマルチプロセス構成になっており、親プロセスである Control process、ログを収集する Collect process (サーバー台数分起動)、ログを集約・集計し Graphite に送信する Aggregate process が動作しています。

おおまかな流れは次の通りです

RADIUSサーバーにSSHし、tail -F コマンドでログをリアルタイムに出力させる
出力されたログをパースし、さらにIPアドレスの逆引き等を行いデータを補完する
データを Aggregate process のキューへ送信する
キューバッファからデータを取り出し集計する
10秒ごとにデータを Graphite に送信する

なおツールは Supervisord を使ってデーモン化しています。

その結果を Grafana で描写させるとこうなります。いまのところ認証ログ(Access Accept / Reject)および、接続ログ(Accounting Start / Stop)を取り扱っています。

f:id:miyahan:20161104002147p:plain

いや～もう、こんなかっちょいいグラフが出るだけで既に大満足です。

carbon-cache のチューニング完了。分解能を1秒から10秒にして負荷を下げた。
というわけで、RADIUSサーバからログを tail -F で読み込んで、エンドユーザーの利用状況をリアルタイムに把握できるツール完成！！！ #Grafana #Graphite pic.twitter.com/HMHHXiPj1e
— Miyahan (@miyahancom) 2016年9月22日

サービス障害の見え方

ではこのツールでサービス障害はどのように見えるのでしょうか

LAGサイレント故障

LAC 〜配下のL2スイッチ間は ACT - SBY モードのリンクアグリゲーションで構成しており、障害検出時に SBY 側に切り替わるようになっています。しかしログやコマンド上では正常に見えるのに、実はフレーム転送できていないというサイレント故障が起きることがまれによくあります。この事象が ACT 側で起きると、全てのパケットが故障した ACT 側に吸い込まれて二度と出てこないというブラックホール状態に陥り、当然お客様は通信できなくなってしまいます。

ツール試運用中にちょうどこの事象が起きたので、その際のスクリーンショットをご紹介します。

f:id:miyahan:20161116202127p:plain f:id:miyahan:20161116202130p:plain LAC全体のグラフと該当LAGのみにフィルタしたグラフ

5:14 から接続要求がゼロになっているので、ここから障害が発生したもとの推測されます。その5分後、5:19 にPPPのキープアライブタイムアウトが発生し切断処理が行われています。その後、関連部署からの連絡で障害を認知し、5:41 に保守者がLAGのアクティブポートを手動切り替えしサービスが回復しています。

もし Graphite のデータを定期的にチェックしアラートを出す手段を確立できれば、このようなサイレント故障をお客様や関連部門からのクレームではなく、監視部門が先に発見し対処することが出来るかもしれません。

ラインカード自己診断NG発生/回復

配下のL2スイッチでラインカードの自己診断NGのアラートが出て、数分後に自然回復するということがよくあります。この手のアラートは、主信号（お客様の通信）に影響がある場合と無い場合があり、もし影響があった場合は速やかにお客様に対しサービス中断発生の連絡をしなければなりません。つまり、なるべく早くサービス影響の有無を判断する必要があります。

サービス中断がある場合のグラフを示します

f:id:miyahan:20161116205432p:plain

アラートは 18:57 に発生しました。その瞬間から接続・切断処理が途絶えており、通信に影響があると判断できます。その後アラートは 18:59 に消えました。グラフを見ると 18:59:20 頃からお客様からの再接続要求が来て、切断と接続のイベント数がスパイクしています。

もしこれがコマンドによる確認だと、18:59:20 以降にお客様のPPPセッションが張り直されるまでサービス中断に気づくことができません。冒頭で述べた CLI が遅いルーターの場合はコマンドの結果が全て表示されるまで5分程度かかるため、障害発見まで10分を要してしまいます。

つまりこのツールを使うことで、サービス中断の確認作業が10分から10秒に短縮できるのです！

天災・広域停電

f:id:miyahan:20161124172629p:plain

2016年11月22日 5時59分、福島県沖で最大震度5弱の地震が起き、各地で停電・瞬低が発生しましたが、今回作ったツールがこの影響をとらえました。地震発生から5分後の 6:04 に一気にタイムアウトによる切断処理が起きています。その後ちょろちょろと再接続されていき、15分ほどで平常通りに戻っています。

これはうまく使えば広域障害の検出・把握に使えそうですね。ただ現状だとサーバーが非力で、このグラフを出すのに3分もかかってしまうのが課題です･･･。