Java のスタックトレースや、使うライブラリによっては改行つきでログ出力したりで、１つの意味をもつログが複数行に吐き出されることがありますが、それだと収集しづらいので、強制的に１行にしておくと、fluentd などのログ収集ツールで収集しやすく・運用しやすくなります。
開発時に参照するコンソールにはヒューマンリーダブルなログがよいですが、本番でファイルに出力するログは１行にしてしまい、運用時のログの参照はなんらかのツールを介して行う、というのがよいのではないかと思います。
最近の 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 という文字列に変換すると１行になります。
これだけだとまだスタックトレースには対応できないので、
<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 の場合に困るので タブをスペース４つに変換、
することで１行にできます（すごく長くはなる）。
自前でスタックトレースのフォーマットを定義したので、最後に %nopex を書いて logback が勝手に後ろにスタックトレースをつけてしまうのを抑止します。
これで、
１つのログイベントが１行という単純な形になるので、特に何の工夫をしなくても fluentd に流して elasticsearch に入れる、といったようなことができるようになります。
なお、それなりの Web アプリケーションでこれをやってますが、特にパフォーマンス劣化は感じません。
エラーログ監視も捗る
Zabbix や Nagios で、アプリケーションが吐くログを監視し、ログレベルが ERROR のものを引っ掛け、アラートメールを運用担当者に送る、というようなエラーログ監視を行う場合、ログを１行にしておくとこれが捗る。
ログ監視ツールでは通常は何も設定しないと監視文字列がある行だけをアラートメールします。
これでは HogeHogeException が発生したことはわかるが、詳細がわからない。
アラートメールを受け取り、それからサーバーに入るなどして、ログファイルを探し、日時から該当箇所を見つけてやっと詳細がわかる。
たとえ既知の問題であったとしてもちゃんとログファイルを参照するまではわからないので安心できない。
それが、ログを１行にしておいた場合にはスタックトレースまで含まれた形でアラートメールがくるので、ログファイルを漁らなくても 初動の段階で例外の詳細がわかるのは運用負荷的にとても助かります。
メール中のスタックトレースも当然改行されていないので見づらいので、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 、
とするだけで１行ログにできます。
<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 ...