~saiya/hatenablog

No Code, No Life.

Logger を Spring に DI させれば同じようなコードを毎回書かなくて済むしテスト記述性も改善できる

SLF4J などの Logger を使うときに、毎回以下のようなボイラープレートを書くのにうんざりしていませんか? 少なくとも私は大変うんざりしています:

class TestController {   // Kotlin Example
    companion object {
        private val log = LoggerFactory.getLogger(TestController::class.java)
    }   // 長くてつらい...
}
class TestController {   // Java Example
    private static final Logger LOG = LoggerFactory.getLogger(TestController.class);
    // これは 1 行だが、とはいえ長いし class 名を二度書くのが辛い & コピペ間違いも起こしやすい
}

夜中に寝苦しくて眠れない時などに趣味で Kotlin + spring-boot 2.0 + その他諸々 にチャレンジしているのですが、その際に上記の悩みを Spring の DI で解消してみました (その結果としてテスト記述性も良くなりました) という久々の記事です。

なお、この記事は上記の通りの趣味的な都合により Kotlin, Spring メインの記述となっていますが、Java, Scala や Spring 以外の DI ツールでも類似・同様のことはおそらく可能ではないでしょうか (未検証)。

調べた限り世の中でも知られている苦労らしい

KotlinでLoggerの生成を少し楽にした - Qiita, Best practices for loggers - Kotlin Discussions などにおいて記述を多少省略する試みは広く行われているようです (Kotlin)。

しかし、数行にわたる記述を毎回書くという点は変わらない様子です。

では、どうするか

Spring の DI の一般的手法として、constructor injection (DI してほしいものをコンストラクタ引数で宣言する)という手法があります。

それを使い、かつ Kotlin の primary constructor で property を宣言する構文を用いることで、こんな風にできました:

@Controller
class TestController (val log : Logger) {   // ここで Logger をもらってしまう
    fun example() {
        log.info("It works")   // ↑の記述だけで Logger を使える
    }
}

Java では出来るもののトレードオフがあります、詳しくは後述。

Logger を DI するための下準備

上記のように Logger を受け取るコードをいきなり書くと「 Loggerインスタンスなんて見つからんぞ!」と Spring に怒られるはずです。 そのため「DI 先の class に応じた Logger インスタンスを作って DI する」ための仕込みが必要であり、それは以下のようにして実現できます:

@Configuration
class LoggerInjectionConfig {     // この class を component-scan で見える場所に置いておくか @Import で明示的に読み込む

    @Bean
    @Scope("prototype")
    fun logger(ip : InjectionPoint): Logger {    // Logger を DI する都度に呼ばれる
        return LoggerFactory.getLogger(
                ip.methodParameter?.containingClass
                        ?: ip.field?.declaringClass
                        ?: throw BeanCreationException("Cannot find type for Logger")
        )
    }
}

// Java 版は(めんどいので)書いてないですが、上記のコードの雰囲気で伝わるのではないかなぁ...

上記のように InjectionPoint なるものに DI 先の情報が渡ってくるので、それを使って Logger を生成する実装をしておいてやれば、先のように Logger を DI することが可能になります。

何がうれしいか

Logger を使う記述が簡潔になる (※Javaでは微妙な点あり)

@Controller
class TestController {   // 本手法の導入前
    companion object {
        private val log = LoggerFactory.getLogger(TestController::class.java)
    }
}

@Controller
class TestController (val log : Logger) {    // 本手法
}

と、大変簡潔になります。

Logger を使う処理というのは少なからず書くことがあるので、これによる頭の負荷の軽減は、上記の InjectionPoint 云々の実装を入れるには十分見合うものではないでしょうか。

ただし、Java の場合、コンストラクタ引数で受け取った Logger をフィールド変数に格納して...という一連の記述が冗長になってしまいます。そのため、Java で記述の簡潔さを優先する場合、field injection (フィールドに @Autowired を付けてフィールドに直接 DI する)を用いることになりますが、field injection は後述するテスト上のメリットが得られないといった負の側面があり近年の Spring の潮流としてもあまり推奨されていない、というトレードオフがあります。いっそ Lombok を使ったほうが良いかもしれませんね...。

public class TestController {
     
     @Autowired    // field injection すればこの記述だけで良いが、後述するテスト上のメリットが得られない点が微妙
     private Logger log; 


     public TestController(Logger log){
          this.log = log;
     }
     // かといって constructor injection すると、Kotlin と違って簡潔に記述できない
     // ( 記述の短縮どころか、伝統的な Logger の初期化方法より長くなっている )
}

ログ出力に対するテストがしやすくなる

そもそもの Spring などの DI を利用する一般的なメリットとして「DI するオブジェクトを差し替えることで、コードの再利用やテストがしやすくなる」というメリットがあるはずです。

しかし、一般的な Logger のイディオムは全くもって DI していないので、上記のメリットが得られなくなってしまっていないでしょうか?

例えば、以下のようなニーズを想定してみます:

  • 大事なログを出す処理なので「ログが期待通りに出ていること」をテストで assert したい
  • パラメタに渡した機密の情報(例えばクレジットカード番号とか)が「あらゆるログに一切出ていないこと」をテストで assert したい
  • ログに興味がないテストケースなので、ログは単に破棄したい
  • 上記のような制御を、設定ファイル決め打ちなどではなく、テストケースごとにプログラム記述で制御したい

一般的な Logger のイディオムを使っている場合、 Loggercompanion object / static final で決め打ちされてしまっているため、上記のようなニーズを満たすことが難しくなります。

リフレクションを用いて強引に Logger を差し替えるのは明らかに保守性も実装効率も悪いですし、かといって SLF4J や Log4j のバックエンドにまるまる自作の実装を差し込んで...といった手法では実装やメンテナンスに苦労が伴うことでしょう。

一方で、今回の手法を用いて Logger を DI するように実装していれば、spring-boot の @MockBean といった DI・モックツールの機能をフルに活用して何とでもできます。

上記の事例で示したようにログについてテストをしたい局面がいつ来るかは分からないことなので、当該手法を予め仕込んでおくことも個人的にはおすすめです。仕込みが無い状態で「クレジットカード番号があらゆるログに一切出ていないこと」というテストを後から実装するのは、概して苦労が伴うものと思われます。

重箱の隅な想定議論

ここから先は細かいことが気になる人向け。

パフォーマンスはどうなのか

例えば「リクエストのたびに Logger を使う側のクラスが秒間 100 回といったペースで new される」ようなケースにもし該当するならば、本手法の InjectionPoint の情報を元に Logger.getLogger するコストは無視できなくなりえます。

ただ、上記のオーバーヘッドよりも、そもそもの DI コンテナによるオブジェクト生成処理のオーバーヘッドの方が遥かに大でしょうから、そのようなケースでは DI コンテナの利用自体を諦めるほうが妥当と思われます。

加えて、ログの出力には一般的に I/O を伴うものであり I/O は CPU・メモリ処理よりも遥かに遅いものでもあるため、プログラム上の処理以前に I/O 性能がまずネックとなる可能性を考慮する必要があるでしょう。

また、個人的には、そのような頻繁・大量に new されるオブジェクトがログ出力を行うという設計には bad smell を感じます (DDD 風に言うと、ドメインオブジェクトを Controller・Service・DataSource層 から分離出来ていないのではないか、と)。

Logger を使う側のクラスが継承関係にある場合どうなるのか

Constructor injection を用いて Logger を DI する場合、本手法では派生クラスの型を元に Logger が生成されることになります。また、先述のテスト記述性のメリットを得るためにはその Logger を基底クラスにそのまま渡すことになるでしょう。その結果として、基底クラスの実装によって出力されるログも、 getLogger(派生クラス) によって得られた Logger に出力されることとなります。

それによるデメリットはロガーの使い方に依存しますが、例えば以下の点が想定されます:

  1. Logger のクラス名・パッケージ名でログを細かく振り分けており、かつ基底クラスで出しているログと派生クラスで出しているログすらも振り分けたい
  2. 派生クラスのログとして出力されてしまうと、そのログが基底クラスの実装で出ていることを認識や調査することができず混乱する

1 のように本当にそのような緻密な制御が必要であれば、そもそも DI などによって一律に Logger を生成してしまうのでなく、 Logger を使う場所それぞれできちんと明示的に class を指定して Logger を生成する(つまり従来的なボイラープレートコードを書く)方が妥当と思われます。ただし、ログのレベル(INFO, ERROR ...)や MDC などでなくパッケージ名・クラス名に依存した細かな振り分けが本当に必要なのか、現代的なログのベストプラクティスに沿うことはできないのか、という検討をされることを個人的にはおすすめします。

2 のケースは文脈や経験の要素も大きいと思われます。しかし個人的な考えとしては、2 が問題となるケースでは得てして「基底クラスが何をしているかが分かっていない and 基底クラスのソースを必要に応じて見るという行為が難しい」「クラスの継承関係が深くなっておりコードを追うのがつらい」といった負が背景にあることが多いように思われます。そのような負に該当するのであれば、本手法とは別次元の課題の解決が必要かもしれません。