あえてEmbulkを使ってログ監視すると幸せになれる状況、およびその導入事例 / Embulk Meetup Tokyo #2

Embulk Meetup Tokyo #2 の LT で発表しました。
意味のある情報を取り出せないログが大量にある場合に、Embulkを活用したログ監視システムを導入し、サービスの現状把握および改善活動に繋げた事例の紹介です。

1. あえてEmbulkを使ってログ監視すると 幸せになれる状況、 およびその導入事例 GMOインターネット株式会社 次世代システム研究室 吉澤 政洋 Embulk Meetup Tokyo #2 2015-12-15
2. 1 内容 1. あえてEmbulkを使ってログ監視をすると 幸せになれる状況 2. Embulk + ElasticSearch + Kibana + PostgreSQL による ログ監視の事例
3. 2 1. あえて Embulkを使ってログ監視をすると 幸せになれる状況
4. 3 1. あえて（Fluentdではなくて） Embulkを使ってログ監視をすると 幸せになれる状況
5. 4 ログにまつわる、ありがちな状況 • 最初はログを構造化していたが、次第にルールが徹底されなくなった – エラーコード、エラーメッセージの使い方がバラバラになる – デバッグ用のログファイルの方が重要になる – 知らないうちに新しいログファイルが増えている • 長期間使われることを想定せず作ったため、ログ形式を決めなかった – 単純なルールでパースできない
6. 5 まれによくありがちな状況 • 開発プロジェクトに後から参加した • ERRORレベルのログが出ると、アラートメールが飛ぶ • それも大量に飛んでくるが、“ほとんどは”無視していいらしい • 当初の開発者はもういない • 慣れた担当者なら、無視してはいけないメールがわかるらしい • その判断基準はどこにも書かれてない • その担当者は最近いなくなった • 最終的には… • “動かなくなったら、とりあえず再起動するしかない”
7. 6 起こりうる問題 (1) • ERRORログを障害検出に使えなくなる – 一般的なログ監視： ERRORレベルのログが発生したらアラートメール送信 – 多すぎるアラートメールは無視される – 障害検出が遅れる – 平均復旧時間（MTTR）が長くなる
8. 7 起こりうる問題 (2) • ERRORログを異常検出や傾向把握に使えなくなる – 件数の増減は異常検出や傾向分析に有効 • 機能のリリース後や、設定変更後 – 分析には、ログを分類できている必要がある • ログ形式が統一されているだけではダメ
9. 8 意味のある分類ができない例 • よくあるコード try { // Do something } catch (Exception e) { logger.error("must not happen", e); }
10. 9 意味のある分類ができない例 • エラーの種類を特定するための情報が、ログごとに違う場所に入っている [日時] [ログレベル] [クラス名] [メソッド名] [行番号] [エラーメッセージ] [例外クラス名1]: [例外メッセージ1] at [スタックトレース1.1] at [スタックトレース1.2] (中略) Caused by: [例外クラス名2]: [例外メッセージ2] at [スタックトレース2.1] at [スタックトレース2.2] (後略) エラーメッセージは一意か？ 直前の例外メッセージで 特定できるか？ スタックトレースをさらに 追う必要があるか？
11. 10 必要なこと • そのシステムでは何が正常で、何が異常かを判断できるようにする • トラブルが起こる前に、その判断基準を作る
12. 11 このような状況で必要なもの • ログから、「意味のある部分だけを取り出して、構造化できる」パーサ • 独自のパーサを書くには、試行錯誤を重ねる必要がある • パーサがあれば検索、集計できる • リアルタイム性は優先度低い
13. 12 パース結果の検索
14. 13 パース結果の集計
15. 14 ログと言えば
16. 15 Fluentdでの複数行ログのパース • in_tail input plugin (multiline parser plugin) を使う – http://docs.fluentd.org/articles/in_tail – 正規表現で設定するため、複雑な処理は書きづらい • 自作の parser plugin を書く – Parser クラスを継承して実装
17. 16 in_tail input plugin (format multiline) format multiline format_firstline /¥d{4}-¥d{1,2}-¥d{1,2}/ format1 /^(?<time>¥d{4}-¥d{1,2}-¥d{1,2} ¥d{1,2}:¥d{1,2}:¥d{1,2}) ¥[(?<thread>.*)¥] (?<level>[^¥s]+)(?<message>.*)/ Configuration:
18. 17 in_tail input plugin (format multiline) 2013-3-03 14:27:33 [main] ERROR Main - Exception javax.management.RuntimeErrorException: null at Main.main(Main.java:16) ~[bin/:na] 2013-03-03 14:27:33 +0900 zimbra.mailbox: {"thread":"main","level":"ERROR","message":" Main - Exception¥njavax.management.RuntimeErrorException: null¥n at Main.main(Main.java:16) ~[bin/:na]”} Input: Output:
20. 19 Embulkのメリット • わかりやすい動作 – サーバ1台、プロセス1個で動き、ログの最後まで読み込んだら止まる – 試行錯誤を重ねる必要がある時は嬉しい • プラグイン構造 – Fluentd と同様に、独自の parser plugin を書く仕組みがある – input/output/filter plugin が多数あり、ログ分析でよく必要になる処理は 開発不要 • パーサの開発支援機能 – embulk preview, embulk guess など
21. 20 2. Embulk + ElasticSearch + Kibana + PostgreSQL によるログ監視の事例
22. 21 事例 • コンシューマ向けのWebアプリケーション • プロジェクトに参加した時点では、アラートメールが毎日大量に発生 • 今回紹介するログ監視システムにより、状況を可視化し、調査 • （私はこの調査の終了後に別プロジェクトへ異動） • 調査結果を活用し、現在は根本的なアプリ改修に着手中
23. 22 事例 • ログ監視システムの構築時期 – 2015年5月末 • 使用したバージョン – Embulk 0.6.11 • 規模 – Webサーバ： 10台未満 – 取り込むログの件数： いくつかの条件で絞り、平均 2,000〜3,000 件/日
24. 23 目指した運用（どこまで頑張るか） 1. ログの検索 • 毎日 • ERRORログの件数/日を確認 • 直近数日の件数が急増していたら、ログを検索して原因調査 2. ログの集計 • 数週間〜1ヶ月に1回 • ログの種類ごとに、ERRORログの件数/日を集計、確認 • 特定の種類のログが急増、または新たに現れるようになっていたら、 ログを検索して原因調査
25. 24 gzip decoder plugin myapp parser plugin elasticsearch output plugin table: myapp_abst file input plugin gzip decoder plugin myapp parser plugin postgresql output plugin file input plugin myapp abstract filter plugin Servers PC Log Monitoring System index: myapp
26. 25 ログの検索
27. 26 gzip decoder plugin file input plugin Servers Log Monitoring System ログファイルのコピー • パーサ開発のために、ログファイルを転送 • 監視対象のログファイルは日付や時間単位でローテートするように なっている必要あり
28. 27 parserプラグインの開発 • 複数行のログをパースするparserプラグインを実装 • ログが独自形式のため、guessは実装せず • previewや、標準出力（outputプラグイン）で結果を確認 gzip decoder plugin myapp parser plugin file input plugin Servers Log Monitoring System
29. 28 parserプラグインの開発 [日時] [ログレベル] [クラス名] [メソッド名] [行番号] [エラーメッセージ] [例外クラス名1]: [例外メッセージ1] at [スタックトレース1.1] at [スタックトレース1.2] (中略) Caused by: [例外クラス名2]: [例外メッセージ2] at [スタックトレース2.1] at [スタックトレース2.2] (中略) timestamp log_level_name class_name method_name line_number message second_line caused_by_class_name third_line caused_by_message
30. 29 ElasticSearchの設定 • indexを事前に設定 • Kibanaで、表のcolumnや、円グラフのsliceとして使いたい項目 （ホスト名など）は、要素解析の対象外とする必要あり → 試行錯誤しやすくするため、suffix が “_name” なら一律で対象外 gzip decoder plugin myapp parser plugin elasticsearch output plugin file input plugin Servers Log Monitoring System index: myapp
31. 30 gzip decoder plugin myapp parser plugin elasticsearch output plugin file input plugin Servers Log Monitoring System index: myapp Kibanaの設定 • ERRORログの確認に適した形に、ダッシュボードを設定 PC
32. 31 Kibanaのダッシュボード設定 ERRORレベルのログ件数 / 日 （サービス別、ホスト別） ERRORレベルのログ総計 （表形式、円グラフ形式） ログのクロス集計結果 （クラス名、メソッド名、 エラーメッセージなどの軸で ログ件数を集計）
33. 32 確認手順 ② 特に急増しているログの クラス名、メソッド名、エラーメッセージ などを調べる ③ Discover 画面に移動し、 該当ログの詳細を確認する ① 直近数日でログが急増しているか、 もし急増しているなら どのサービス、どのホストかを調べる
34. 33 Kibanaの不便な点 • Dashboardでエラーの原因を絞り込んだあとで、 Discoverメニューでそのログの詳細を閲覧したい • 検索条件（クラス名など）を自分で入力し直す必要がある 検索条件
35. 34 ログの集計
36. 35 EmbulkとPostgreSQLの設定 • outputプラグインを変えて、PostgreSQLにログを流し込む • 先ほど作ったparserプラグインをそのまま使える • テーブル定義は自動生成される（カラム変更は自動でない） • 今回は、PostgreSQL固有の機能は使用せず gzip decoder plugin myapp parser plugin postgresql output plugin file input plugin Log Monitoring System Servers table: myapp
37. 36 Embulkのfilterプラグインの開発 • 集計のために、ログの抽象度を上げるfilterプラグインを開発 • 例： "Login Error: userId=xxxxxxx" → "Login Error" • postgresql inputプラグインには「前回読んだところの続きから読む」 機能はないため、出力先テーブルを毎回作り直し(mode: replace) gzip decoder plugin myapp parser plugin postgresql output plugin file input plugin Log Monitoring System Servers table: myapp myapp abstract filter plugin postgresql output plugin postgresql input plugin table: myapp_abst PC
38. 37 クロス集計（Excelのピボットテーブル） class_name method_name message second_line 月ごとの発生件数 毎月発生している ERRORログ ある月から急に 発生し始めたERRORログ
39. 38 開発後のプラグイン配置最適化 • filterプラグインの開発が完了したら、負荷を減らすためにfilterプラグイン の実行場所を変更 → 毎回のテーブル作り直しを不要に table: myapp_abst gzip decoder plugin myapp parser plugin postgresql output plugin file input plugin myapp abstract filter plugin PC Log Monitoring System Servers
40. 39 gzip decoder plugin myapp parser plugin elasticsearch output plugin table: myapp_abst file input plugin gzip decoder plugin myapp parser plugin postgresql output plugin file input plugin myapp abstract filter plugin Servers PC Log Monitoring System index: myapp
41. 40 コード量 • 期間 – Rubyで書いた作りかけのパーサがある状態から、 プラグイン開発および環境構築まで1週間ほどで完了 • 開発物 – Embulkプラグイン2個（いずれもRuby） – 後日、共通処理をembulk-filter-insertプラグインとして切り出し • ホスト名やサービス名の挿入に利用 • id:sonots のembulk-filter-columnに似たプラグイン • 最終的なコード量 – Parserプラグイン： 172行 – Filterプラグイン： 85行 • 一度やり方が分かれば、非常に手軽に実装できた
42. 41 プラグイン開発時に、面倒に感じた点 • サーバ／サービスごとにEmbulkの設定ファイルを分ける必要あり – ログファイルのファイル名に、サーバ名やサービス名が含まれているとファイ ルのprefixが変わる • ファイル名から情報を取り出せない – サーバ名やサービス名を、何らかの手段でEmbulkに渡す必要あり – 自作のfilterプラグイン（embulk-filter-insert）で挿入 • あくまで一時しのぎであり、長期的にはFluentdなどを用いた リアルタイムなログ分析・可視化が望ましい
43. 42 まとめ
44. 43 まとめ • アラートメールを無視し始めるのは、システムの正常／異常を ログから判断できなくなっている徴候 • 「意味のある部分」がわからなくなったログに対するパーサを 短時間で作るには、Embulkが便利 • Embulk + ElasticSearch + Kibana + PostgreSQL の組合せで、 ログ監視の改善プロセスを、徐々に回せるようになる
45. 44 本日の元ネタ • ERRORログが多すぎるWebアプリに出会ったら http://recruit.gmo.jp/engineer/jisedai/blog/struggle-against-too-many-errors/ • 謎の独自ERRORログをEmbulk + Elasticsearch + Kibana + PostgreSQLで 監視する：運用設計からシステム構築まで http://recruit.gmo.jp/engineer/jisedai/blog/embulk-elasticsearch-kibana- postgresql/
46. 45 http://recruit.gmo.jp/engineer/jisedai/ We are hiring!