読者です 読者をやめる 読者になる 読者になる

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

NetOps プログラミング

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

きっかけ

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

f:id:miyahan:20161104004823p:plain

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

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

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

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

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


Radtail 概要

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

www.slideshare.net

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

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

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

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

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

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

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

f:id:miyahan:20161104002147p:plain

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


サービス障害の見え方

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

LAGサイレント故障

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

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

f:id:miyahan:20161116202127p:plainf: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分もかかってしまうのが課題です・・・。

まとめ

  • グラフ化することで状況を “点” ではなく “線” で捉えることができ、直感的に異常が起きたことを把握できる
  • タイムアウトによるセッション切断を待つこと無く、接続・切断要求が途絶えることで異常に気づくことができる

今後の展望

今回ログをリアルタイムに処理し可視化することで、サービスの提供状況を簡単に・素早く・確実に把握できることがわかりました。ただそれは保守者が能動的にダッシュボードを開かなければならず、サイレント故障に対しては全くの無力です。

現在、異常の自動検出の方法を模索中です。Grafana で「ヤバいホスト Top 10」みたいなダッシュボードを作ってみても良いでしょうし、別にスクリプトを定期的に走らせて Graphite の API を叩いてデータを取り出して精査してアラートを出すのも良いかもしれません。

一番の問題はどうやって異常と判断するかです。数分〜十分単位の起伏があるうえ、1日の生活変動(朝7時頃に起床、午後7時頃に帰宅により増える)や曜日変動(休日は家に居るので変動が少ない)があり一概にしきい値や変動率を適用できません。このへん学問的な話になってくるので勉強が必要ですね。


なんだか業務改善事例の発表ようになってしまいましたが、最も語りたかったのは開発の苦労話で、後半エントリで述べています。ぜひ引き継ぎご覧ください。

miyalog.hatenablog.jp