久し振りに触ることになった Java アプリケーション。
2021 年は log4j の脆弱性問題が話題になりましたが、ログライブラリは何を使うのがベストプラクティスとなるのでしょうか。
logback だから安心というわけではないですが、最近は slf4j と logback の組み合わせをよく目にします。
まずは JSON 形式でのログ出力を目指してみましょう。
利用するライブラリ
slf4j や logback のライブラリには種類が多く、依存関係まで含めると複雑です。
今回は以下のライブラリを gradle の dependencies で設定します。
org.slf4j:slf4j-api:1.7.36
ch.qos.logback:logback-classic:1.2.10
net.logstash.logback:logstash-logback-encoder:7.0.1
最新情報は、slf4j や logback の github を参考にしてください。
JSON 出力に関しては logstash-logback-encoder の役割なんですけどね。
gradle の設定を Kotlin DSL で書くとこんな感じ。
1 2 3 | implementation("org.slf4j:slf4j-api:1.7.36") implementation("ch.qos.logback:logback-classic:1.2.10") implementation("net.logstash.logback:logstash-logback-encoder:7.0.1") |
logback-classic を定義しておけば logback-core も入りそうですが、公式では core の指定がされてそうですね。
過去に implementation について調べたことがありますが、gradle のバージョンも上がっているので今は何がベストになるのかな。
logbackの設定ファイル
では早速、logback の設定をしていきましょう。
logback の設定は logback.xml に定義して、「src/main/resources」配下に配備します。
(なくでも動作しますが、デフォルトでこのディレクトリを参照してくれます)
ログ出力例
LogstashEncoder を組み込んだ標準的な設定のままログ出力を行うと、以下のような JSON 文字列が吐き出されます。
(試しに WARN レベルで出力してみます)
1 2 3 4 5 6 7 8 9 | { "timestamp":"2022-03-01T00:00:00.000", "version":"1", "message":"わ～ん", "logger_name":"xxx.xxx.LogTest", "thread_name":"main", "level":"WARN", "level_value":30000 } |
ログの中身は収集先でフィルタリングすればいいのですが、あらかじめ以下が決まっているなら調整しておきましょう。
・不要な項目
・出力フォーマット
日付のフォーマットは変えたいケースが多いでしょうし、見た目的に邪魔な項目もあったりしますよね。
ログの調整
では、logback.xml を少しずつ調整してみましょう。
まず、タイムゾーンは「UTC」ではなく「JST」とします。
タイムスタンプはミリ秒までにしましたが、さらに後ろに「+09:00」を足す形式でもいいかも。
ログの出力項目については LogstashEncoder を利用してカスタマイズしています。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 | <?xml version="1.0" encoding="UTF-8"?> <configuration> <!-- Property --> <property name="TIME_ZONE" value="Asia/Tokyo" /> <property name="TIMESTAMP_PATTERN" value="yyyy-MM-dd'T'HH:mm:ss.SSS" /> <property name="SEPARATOR" value="UNIX" /> <!-- Console Appender --> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder class="net.logstash.logback.encoder.LogstashEncoder"> <timeZone>${TIME_ZONE}</timeZone> <timestampPattern>${TIMESTAMP_PATTERN}</timestampPattern> <fieldNames> <timestamp>time</timestamp> <version>[ignore]</version> <logger>[ignore]</logger> <thread>[ignore]</thread> <levelValue>[ignore]</levelValue> </fieldNames> <lineSeparator>${SEPARATOR}</lineSeparator> </encoder> </appender> <root level="DEBUG"> <appender-ref ref="STDOUT" /> </root> </configuration> |
少し厄介なのは「fieldNames」の領域で、各項目には以下の特徴があります。
・項目の中に定義した文字列が項目名になる
・[ignore]を定義すると出力されない
・実際の項目名と少し異なるものがある
例えば「timestamp」のところは「time」にしたい、version は非表示にしたいとかですね。
以下の場合、「message」は「message」のままで出力されます。
1 2 3 4 5 | <timestamp>time</timestamp> <version>[ignore]</version> <logger>[ignore]</logger> <thread>[ignore]</thread> <levelValue>[ignore]</levelValue> |
ちなみに、デフォルトの名前と設定の項目名が異なるものがいくつかあります。
| ログの項目名 | 設定の項目名 |
|---|---|
| logger_name | logger |
| thread_name | thread |
| level_value | levelValue |
今回は DEBUG レベル以上のログを標準出力する設定としましたが、property を活用すれば以下のような調整も可能です。
・環境変数など外部に定義された値
・デフォルト値
logback.xmlの配備問題
ここまでの設定で目的の JSON 形式のログ出力はできていました。
しかし、Java アプリケーションでモジュールを追加していくうちに、以下のログが出力されていることに気付いたので調査を開始。
1 2 3 4 5 6 7 8 9 10 11 12 13 | INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml] INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/hoge/fuga/build/resources/main/logback.xml] WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs multiple times on the classpath. WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [file:/hoge/fuga/build/resources/main/logback.xml] WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [jar:file:/hoge/fuga/build/libs/common-0.0.1.jar!/logback.xml] INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender] INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT] INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [net.logstash.logback.fieldnames.LogstashFieldNames] for [fieldNames] property INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT] INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration. INFO in ch.qos.logback.classic.joran.JoranConfigurator@7e5afaa6 - Registering current configuration as safe fallback point |
問題のログ
以下の WARN レベルの部分が気になりますね。
この WARN が出力されていなかった時は、前後の INFO のログも表示されていなかったのですよね。
Resource [logback.xml] occurs multiple times on the classpath.
Resource [logback.xml] occurs at [file:/hoge/fuga/build/resources/main/logback.xml]
Resource [logback.xml] occurs at [jar:file:/hoge/fuga/build/libs/common-0.0.1.jar!/logback.xml]
問題のログが出力されたパターン
今回、以下のように 2 つの Java モジュールを作成し、sample から common を参照させていました。
・sample
・common
両方のモジュールのクラスファイル内でログ出力していたため、それぞれのモジュールに logback.xml を配備していたのですが、どうやらそれが悪さをしているようです。
sample/src/main/resources/logback.xml
common/src/main/resources/logback.xml
common 配下のものを削除して無事解決となりました。
まとめ
slf4j と logback を使った JSON 形式のログ出力を試してみました。
今回の設定がベストプラクティスというわけではないですが、1 つの手段としては使えそうです。
ここ数年で、サーバ上のファイルにアプリケーションのログを出力するという時代は終わり。
Datadog や CloudWatch(AWS)、Prometheus などクラウド上の監視ツールに集約するのが一般的になりましたよね。
転送量や料金などコストのことも考えて、本当に必要な最小限のログ出力を行っていきたいところです。
