Slide 1

Slide 1 text

あえてEmbulkを使ってログ監視すると 幸せになれる状況、 およびその導入事例 GMOインターネット株式会社 次世代システム研究室 吉澤 政洋 Embulk Meetup Tokyo #2 2015-12-15

Slide 2

Slide 2 text

1 内容 1. あえてEmbulkを使ってログ監視をすると 幸せになれる状況 2. Embulk + ElasticSearch + Kibana + PostgreSQL による ログ監視の事例

Slide 3

Slide 3 text

2 1. あえて Embulkを使ってログ監視をすると 幸せになれる状況

Slide 4

Slide 4 text

3 1. あえて(Fluentdではなくて) Embulkを使ってログ監視をすると 幸せになれる状況

Slide 5

Slide 5 text

4 ログにまつわる、ありがちな状況 • 最初はログを構造化していたが、次第にルールが徹底されなくなった – エラーコード、エラーメッセージの使い方がバラバラになる – デバッグ用のログファイルの方が重要になる – 知らないうちに新しいログファイルが増えている • 長期間使われることを想定せず作ったため、ログ形式を決めなかった – 単純なルールでパースできない

Slide 6

Slide 6 text

5 まれによくありがちな状況 • 開発プロジェクトに後から参加した • ERRORレベルのログが出ると、アラートメールが飛ぶ • それも大量に飛んでくるが、“ほとんどは”無視していいらしい • 当初の開発者はもういない • 慣れた担当者なら、無視してはいけないメールがわかるらしい • その判断基準はどこにも書かれてない • その担当者は最近いなくなった • 最終的には… • “動かなくなったら、とりあえず再起動するしかない”

Slide 7

Slide 7 text

6 起こりうる問題 (1) • ERRORログを障害検出に使えなくなる – 一般的なログ監視: ERRORレベルのログが発生したらアラートメール送信 – 多すぎるアラートメールは無視される – 障害検出が遅れる – 平均復旧時間(MTTR)が長くなる

Slide 8

Slide 8 text

7 起こりうる問題 (2) • ERRORログを異常検出や傾向把握に使えなくなる – 件数の増減は異常検出や傾向分析に有効 • 機能のリリース後や、設定変更後 – 分析には、ログを分類できている必要がある • ログ形式が統一されているだけではダメ

Slide 9

Slide 9 text

8 意味のある分類ができない例 • よくあるコード try { // Do something } catch (Exception e) { logger.error("must not happen", e); }

Slide 10

Slide 10 text

9 意味のある分類ができない例 • エラーの種類を特定するための情報が、ログごとに違う場所に入っている [日時] [ログレベル] [クラス名] [メソッド名] [行番号] [エラーメッセージ] [例外クラス名1]: [例外メッセージ1] at [スタックトレース1.1] at [スタックトレース1.2] (中略) Caused by: [例外クラス名2]: [例外メッセージ2] at [スタックトレース2.1] at [スタックトレース2.2] (後略) エラーメッセージは一意か? 直前の例外メッセージで 特定できるか? スタックトレースをさらに 追う必要があるか?

Slide 11

Slide 11 text

10 必要なこと • そのシステムでは何が正常で、何が異常かを判断できるようにする • トラブルが起こる前に、その判断基準を作る

Slide 12

Slide 12 text

11 このような状況で必要なもの • ログから、「意味のある部分だけを取り出して、構造化できる」パーサ • 独自のパーサを書くには、試行錯誤を重ねる必要がある • パーサがあれば検索、集計できる • リアルタイム性は優先度低い

Slide 13

Slide 13 text

12 パース結果の検索

Slide 14

Slide 14 text

13 パース結果の集計

Slide 15

Slide 15 text

14 ログと言えば

Slide 16

Slide 16 text

15 Fluentdでの複数行ログのパース • in_tail input plugin (multiline parser plugin) を使う – http://docs.fluentd.org/articles/in_tail – 正規表現で設定するため、複雑な処理は書きづらい • 自作の parser plugin を書く – Parser クラスを継承して実装

Slide 17

Slide 17 text

16 in_tail input plugin (format multiline) format multiline format_firstline /¥d{4}-¥d{1,2}-¥d{1,2}/ format1 /^(?

Slide 18

Slide 18 text

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:

Slide 19

Slide 19 text

18

Slide 20

Slide 20 text

19 Embulkのメリット • わかりやすい動作 – サーバ1台、プロセス1個で動き、ログの最後まで読み込んだら止まる – 試行錯誤を重ねる必要がある時は嬉しい • プラグイン構造 – Fluentd と同様に、独自の parser plugin を書く仕組みがある – input/output/filter plugin が多数あり、ログ分析でよく必要になる処理は 開発不要 • パーサの開発支援機能 – embulk preview, embulk guess など

Slide 21

Slide 21 text

20 2. Embulk + ElasticSearch + Kibana + PostgreSQL によるログ監視の事例

Slide 22

Slide 22 text

21 事例 • コンシューマ向けのWebアプリケーション • プロジェクトに参加した時点では、アラートメールが毎日大量に発生 • 今回紹介するログ監視システムにより、状況を可視化し、調査 • (私はこの調査の終了後に別プロジェクトへ異動) • 調査結果を活用し、現在は根本的なアプリ改修に着手中

Slide 23

Slide 23 text

22 事例 • ログ監視システムの構築時期 – 2015年5月末 • 使用したバージョン – Embulk 0.6.11 • 規模 – Webサーバ: 10台未満 – 取り込むログの件数: いくつかの条件で絞り、平均 2,000〜3,000 件/日

Slide 24

Slide 24 text

23 目指した運用(どこまで頑張るか) 1. ログの検索 • 毎日 • ERRORログの件数/日を確認 • 直近数日の件数が急増していたら、ログを検索して原因調査 2. ログの集計 • 数週間〜1ヶ月に1回 • ログの種類ごとに、ERRORログの件数/日を集計、確認 • 特定の種類のログが急増、または新たに現れるようになっていたら、 ログを検索して原因調査

Slide 25

Slide 25 text

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

Slide 26

Slide 26 text

25 ログの検索

Slide 27

Slide 27 text

26 gzip decoder plugin file input plugin Servers Log Monitoring System ログファイルのコピー • パーサ開発のために、ログファイルを転送 • 監視対象のログファイルは日付や時間単位でローテートするように なっている必要あり

Slide 28

Slide 28 text

27 parserプラグインの開発 • 複数行のログをパースするparserプラグインを実装 • ログが独自形式のため、guessは実装せず • previewや、標準出力(outputプラグイン)で結果を確認 gzip decoder plugin myapp parser plugin file input plugin Servers Log Monitoring System

Slide 29

Slide 29 text

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

Slide 30

Slide 30 text

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

Slide 31

Slide 31 text

30 gzip decoder plugin myapp parser plugin elasticsearch output plugin file input plugin Servers Log Monitoring System index: myapp Kibanaの設定 • ERRORログの確認に適した形に、ダッシュボードを設定 PC

Slide 32

Slide 32 text

31 Kibanaのダッシュボード設定 ERRORレベルのログ件数 / 日 (サービス別、ホスト別) ERRORレベルのログ総計 (表形式、円グラフ形式) ログのクロス集計結果 (クラス名、メソッド名、 エラーメッセージなどの軸で ログ件数を集計)

Slide 33

Slide 33 text

32 確認手順 ② 特に急増しているログの クラス名、メソッド名、エラーメッセージ などを調べる ③ Discover 画面に移動し、 該当ログの詳細を確認する ① 直近数日でログが急増しているか、 もし急増しているなら どのサービス、どのホストかを調べる

Slide 34

Slide 34 text

33 Kibanaの不便な点 • Dashboardでエラーの原因を絞り込んだあとで、 Discoverメニューでそのログの詳細を閲覧したい • 検索条件(クラス名など)を自分で入力し直す必要がある 検索条件

Slide 35

Slide 35 text

34 ログの集計

Slide 36

Slide 36 text

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

Slide 37

Slide 37 text

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

Slide 38

Slide 38 text

37 クロス集計(Excelのピボットテーブル) class_name method_name message second_line 月ごとの発生件数 毎月発生している ERRORログ ある月から急に 発生し始めたERRORログ

Slide 39

Slide 39 text

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

Slide 40

Slide 40 text

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

Slide 41

Slide 41 text

40 コード量 • 期間 – Rubyで書いた作りかけのパーサがある状態から、 プラグイン開発および環境構築まで1週間ほどで完了 • 開発物 – Embulkプラグイン2個(いずれもRuby) – 後日、共通処理をembulk-filter-insertプラグインとして切り出し • ホスト名やサービス名の挿入に利用 • id:sonots のembulk-filter-columnに似たプラグイン • 最終的なコード量 – Parserプラグイン: 172行 – Filterプラグイン: 85行 • 一度やり方が分かれば、非常に手軽に実装できた

Slide 42

Slide 42 text

41 プラグイン開発時に、面倒に感じた点 • サーバ/サービスごとにEmbulkの設定ファイルを分ける必要あり – ログファイルのファイル名に、サーバ名やサービス名が含まれているとファイ ルのprefixが変わる • ファイル名から情報を取り出せない – サーバ名やサービス名を、何らかの手段でEmbulkに渡す必要あり – 自作のfilterプラグイン(embulk-filter-insert)で挿入 • あくまで一時しのぎであり、長期的にはFluentdなどを用いた リアルタイムなログ分析・可視化が望ましい

Slide 43

Slide 43 text

42 まとめ

Slide 44

Slide 44 text

43 まとめ • アラートメールを無視し始めるのは、システムの正常/異常を ログから判断できなくなっている徴候 • 「意味のある部分」がわからなくなったログに対するパーサを 短時間で作るには、Embulkが便利 • Embulk + ElasticSearch + Kibana + PostgreSQL の組合せで、 ログ監視の改善プロセスを、徐々に回せるようになる

Slide 45

Slide 45 text

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/

Slide 46

Slide 46 text

45 http://recruit.gmo.jp/engineer/jisedai/ We are hiring!