Help us understand the problem. What is going on with this article?

logback で出すログを強制的に1行にして収集しやすく・運用しやすくする

More than 3 years have passed since last update.

Java のスタックトレースや、使うライブラリによっては改行つきでログ出力したりで、1つの意味をもつログが複数行に吐き出されることがありますが、それだと収集しづらいので、強制的に1行にしておくと、fluentd などのログ収集ツールで収集しやすく・運用しやすくなります。

開発時に参照するコンソールにはヒューマンリーダブルなログがよいですが、本番でファイルに出力するログは1行にしてしまい、運用時のログの参照はなんらかのツールを介して行う、というのがよいのではないかと思います。

最近の fluentd の in_tail は複数行のパースに対応しているが

format multiline とし、開始行のパターンを正規表現で書いたりしてがんばって設定することで対応はできます。
が、ちょっと書きづらい。

そこで logback のフォーマット定義で対応してみる

例えば、

<appender ...>
  :
  <pattern>"%d{yyyy/MM/dd HH:mm:ss:SSS}\t%-5level\t[%thread]:\t%msg%n"</pattern>
  :

このような TSV のログフォーマットは、

<appender ...>
  :
  <pattern>"%d{yyyy/MM/dd HH:mm:ss:SSS}\t%-5level\t[%thread]:\t%replace(%msg){'\n','\\\\n'}%n"</pattern>
                                                               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  :

こうして、
%replace%msg (ログメッセージ部分)中の改行を \n という文字列に変換すると1行になります。

これだけだとまだスタックトレースには対応できないので、

<appender ...>
  :
  <pattern>"...\t%replace(%msg){'\n','\\\\n'}\t%replace(%replace(%xEx){'\n','\\\\n'}){'\t','    '}%nopex%n"</pattern>
                                               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  :

さらにこうして、
%replace(%replace(%xEx){'\n','\\\\n'}){'\t',' '} で、
スタックトレース中の改行を \n という文字列に変換、
さらにスタックトレースにはタブが含まれるので TSV の場合に困るので タブをスペース4つに変換、
することで1行にできます(すごく長くはなる)。
自前でスタックトレースのフォーマットを定義したので、最後に %nopex を書いて logback が勝手に後ろにスタックトレースをつけてしまうのを抑止します。

これで、
1つのログイベントが1行という単純な形になるので、特に何の工夫をしなくても fluentd に流して elasticsearch に入れる、といったようなことができるようになります。

なお、それなりの Web アプリケーションでこれをやってますが、特にパフォーマンス劣化は感じません。

エラーログ監視も捗る

Zabbix や Nagios で、アプリケーションが吐くログを監視し、ログレベルが ERROR のものを引っ掛け、アラートメールを運用担当者に送る、というようなエラーログ監視を行う場合、ログを1行にしておくとこれが捗る。

ログ監視ツールでは通常は何も設定しないと監視文字列がある行だけをアラートメールします。
これでは HogeHogeException が発生したことはわかるが、詳細がわからない。
アラートメールを受け取り、それからサーバーに入るなどして、ログファイルを探し、日時から該当箇所を見つけてやっと詳細がわかる。
たとえ既知の問題であったとしてもちゃんとログファイルを参照するまではわからないので安心できない。

それが、ログを1行にしておいた場合にはスタックトレースまで含まれた形でアラートメールがくるので、ログファイルを漁らなくても 初動の段階で例外の詳細がわかるのは運用負荷的にとても助かります。

メール中のスタックトレースも当然改行されていないので見づらいので、Gmail 上では以下のようなブックマークレットで整形して参照するなどの工夫は必要ではありますが。

javascript:(function(){var elms = document.getElementsByClassName("a3s");for(var i=0,l=elms.length;l>i;i++){elms[i].innerHTML = elms[i].innerHTML.replace(/\\n/g, "<br />");}})();

僕のチームでは、オレオレ Chrome エクステンションをつくってアラートメールを Gmail で開くと自動的に見やすくなるように工夫しています。

あと、これも Gmail じゃないと難しいかもしれませんが、詳細つきのアラートメールが Gmail に溜まっていくので、手元で検索できて捗る。
あのときのアレは何だったっけ、この前いつ発生したっけ、というのが よいしょとサーバーに入ってとかしなくてもすぐに手元で調べられる
こういうのは長く続いていく運用作業においては重要だったりします。

運用を楽にするための工夫

こうしたちょっとした工夫で、日々の労力と時間が削減されていて、コスト削減や精神的負担が軽くなっている気がします。
最善のアーキテクチャを設計したり、よいコードを書く、といったことにプラスして「運用を楽にするための工夫」も同じくらい大事だなと改めて思った次第でした。


追記: logback のフォーマット定義部分についてライブラリ化しました

上記のようにフォーマット定義に %replace を書きまくるのもアレだと思ったのでライブラリ化しました。
roundrop/logback-oneline-converter

これを使うと、以下のように conversionRule に定義しておけば、
フォーマット定義で、
%msg のかわりに %msg1L
%ex のかわりに %ex1L
%xEx のかわりに %xEx1L
とするだけで1行ログにできます。

  <conversionRule conversionWord="msg1L" converterClass="com.github.roundrop.logging.logback.OnelineMessageConverter" />
  <conversionRule conversionWord="ex1L" converterClass="com.github.roundrop.logging.logback.OnelineThrowableProxyConverter" />
  <conversionRule conversionWord="xEx1L" converterClass="com.github.roundrop.logging.logback.OnelineExtendedThrowableProxyConverter" />

  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <encoder>
      <pattern>%d{yyyy/MM/dd HH:mm:ss:SSS}\t%-5level\t%msg1L\t%xEx1L%n</pattern>
                                                      ^^^^^^  ^^^^^^
    </encoder>
    :

Output

2016/11/02 14:44:48:276 INFO    [ORM] SQL : SELECT\n    t1.*\nFROM\n    tbl1 t1\n ...
2016/11/02 14:12:40:102 ERROR   error   java.lang.RuntimeException: null\n    at ...
Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away