はじめに

小ネタを。

apacheのログなど1行で完結するログのキーワード監視は、比較的簡単に実現できますよね。
たとえばapacheのエラーログは1行で情報が完結しており、[error]とか[alert][crit]いうキーワードで監視します。

[Wed Oct 11 14:32:52 2000] [error] [client 127.0.0.1] client denied by server configuration: /export/home/live/ap/htdocs/test

Javaでスタックトレース出た時は複数行になりますよね。これはERRORというキーワードで監視すれば良いですね。

2017-2-01 13:33:21 [main] ERROR Unexpected Error
java.lang.NumberFormatException: For input string: "1.1"
        at java.lang.NumberFormatException.forInputString(Unknown Source)
        at java.lang.Integer.parseInt(Unknown Source)
        at java.lang.Integer.<init>(Unknown Source)
        at ExceptionPrintDemo.formatInt(ExceptionPrintDemo.java:7)
        at ExceptionPrintDemo.main(ExceptionPrintDemo.java:14)

ただ、監視ツールでログ監視する場合は1行しか認識できていないのでメールでスタックトレース以下が通知ができません。
「2017-2-01 13:33:21 [main] ERROR Unexpected Error」というメッセージがメールで通知された結果、「お。おう・・・」ってなってログを毎回本番機に見に行ったりしてませんか？

そのほかにも、1行目のキーワードだけではなく、2行目以降のキーワードを合わせて監視したい場合もあるでしょう。
また、古いシステムだと1行目に日付、2行目にエラーコード、3行目にエラーメッセージなんていうのをたまに見かけたりしますがキーワード監視泣かせですね。

20170201 11:12:34
ERR001
○○コードが不正です。
20170201 11:12:34
ERR002
データベースに接続できません

今回はその辺をfluentdを使って解決してみました。
なお、監視ツールはmackerelを使っていますが他の監視ツールでも同じだと思います。

解決策

fluentdを使って1行のjsonに変換し、監視する。

設定手順

fluentdのインストール

1行でインストール。なんか久々に触ったらインストールがものすごく簡単になってますね・・・

curl -L https://toolbelt.treasuredata.com/sh/install-redhat-td-agent2.sh | sh

fluentdの設定

今回はfluentdのtail input pluginを使っています。
tail input pluginは複数行に対応しており、先ほどのログであればこんな感じで書き換えられます。

/etc/td-agent/td-agent.conf

<source>
  type tail
  path /var/log/app/app.log
  pos_file /var/log/td-agent/app/app-log.pos
  tag app.log
  multiline_flush_interval 10s
  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>.*)/
</source>

<match app.log>
  type file
  path /var/log/td-agent/app/app.java.log
  time_slice_wait 10m
</match>

format_firstlineで1つのjsonの切れ目を表す正規表現を書きます。
format1では、time,thread,messageをそれぞれ正規表現でパースしています。
- (?.*)となっているので、スタックトレースの最後まで読み込みます。
multiline_flush_interval 10s
- ログが流れてくるたびにfluentdが動いて解析するのですが、始めはメモリ上にバッファリングされます。
- そして次のログの解析後に押し出される形でバッファリングされたものがflushされるという動きになります。このパラメータは押し出されなくても10secごとにflushしてね。というパラメータになります。
解析後のログは以下のようにフォーマットされます。

/var/log/td-agent/app/app.java.log

2017-02-01T13:33:21+09:00       app.log {"thread":"main","level":"ERROR","message":" Unexpected Error\njava.lang.NumberFormatException: For input string: \"1.1\"\n        at java.lang.NumberFormatException.forInputString(Unknown Source)\n        at java.lang.Integer.parseInt(Unknown Source)\n        at java.lang.Integer.<init>(Unknown Source)\n        at ExceptionPrintDemo.formatInt(ExceptionPrintDemo.java:7)\n        at ExceptionPrintDemo.main(ExceptionPrintDemo.java:14)"}

mackerelの設定

モニタリングサービス（Mackerel、Datadog、New Relic）入門！に始め方が書いてあるのでそちらを参考にしてください。
こんな感じでログ監視設定を行います。通常の使い方でOKです。

[plugin.checks.app-log]
command = '''
  check-log \
    --file-pattern '/var/log/td-agent/app/app.java.log.*.log' \
    --pattern '\"level\":\"ERROR\"' \
    --return
'''

--returnすることでエラー行が出力され、その内容がMackerelに送信されます
td-agentのプロセスが2つあがっていることも併せて監視しておいたほうが良いでしょう。

[plugin.checks.process_td-agent]
command = "check-procs --pattern td-agent -C 2"

その他の設定

td-agent.logのローテートは忘れがちです。設定しておきましょう
https://github.com/treasure-data/td-agent/blob/master/td-agent.logrotate

結果

ちゃんとスタックトレースの内容も出力されていますね

おわりに

fluentdは今回のような使い方であれば更に導入が簡単でおすすめです。
こういうちょっとしたことが工夫できるかどうかが運用設計ではとても大事なのではないでしょうか。

複数行のログをキーワード監視＆通知することで運用を少し改善しよう