デフォルトプロファイルでログレベルを debug に設定しないほうがよい話

3 年間勤務した L is B を退職しました。

L is B で最後に組み立てていたプログラムが SpringBoot のアプリケーションでした。そのアプリは WebFlux にしていたため、データの動きが非常にわかりづらく、開発中はデータの流れを追えるように debug ログを出力する設定をしていました。

f:id:mike_neck:20180802004547p:plain

`application.properties`

logging.level.com.example=debug

それが一通り完成したので、実際のデータのある環境で動かしてみました。その際に余計なログが出力されないように、production プロファイルでは、root ログレベルを info に設定しました。

`application-production.properties`

logging.level.root=info

さて、その production プロファイルで動かしたアプリのログには何が出力されるでしょう？

ログには debug ログも出力されていました。

その時と同じコードを用意できないので、同じようなコードを用意します

package com.example

@SpringBootApplication
class SpringProfilesOrderApplication: CommandLineRunner {
  private val latch = CountDownLatch(1)

  override fun run(vararg args: String?) =
      Flux.just(10, 20, 30)
          .delayElements(Duration.ofMillis(200L))
          .doOnNext { logger.debug("debug log: {}", it) }
          .doOnNext { logger.info("info log: {}", it) }
          .doOnTerminate { latch.countDown() }
          .subscribe()
          .asCloseable
          .use { latch.await() }

  companion object {
    private val logger: Logger = logger<SpringProfilesOrderApplication>()
    val Disposable.asCloseable: AutoCloseable get() = AutoCloseable { this.dispose() }
  }
}
fun main(args: Array<String>) {
  runApplication<SpringProfilesOrderApplication>(*args)
}

これを次のプロパティを持つ default プロファイルで実行すると、debug ログと info ログが出力されます。

`application.properties`

logging.level.com.example=debug

2019-12-28 20:43:12.742  INFO 19798 --- [           main] c.e.SpringProfilesOrderApplicationKt     : Starting SpringProfilesOrderApplicationKt on mike-neck.local with PID 19798 (/Users/user/spring-profiles-order/build/classes/kotlin/main started by user in /Users/user/spring-profiles-order)
2019-12-28 20:43:12.743 DEBUG 19798 --- [           main] c.e.SpringProfilesOrderApplicationKt     : Running with Spring Boot v2.2.2.RELEASE, Spring v5.2.2.RELEASE
2019-12-28 20:43:12.744  INFO 19798 --- [           main] c.e.SpringProfilesOrderApplicationKt     : No active profile set, falling back to default profiles: default
2019-12-28 20:43:13.138  INFO 19798 --- [           main] c.e.SpringProfilesOrderApplicationKt     : Started SpringProfilesOrderApplicationKt in 0.562 seconds (JVM running for 0.939)
2019-12-28 20:43:13.374 DEBUG 19798 --- [     parallel-1] c.e.SpringProfilesOrderApplication       : debug log: 10
2019-12-28 20:43:13.375  INFO 19798 --- [     parallel-1] c.e.SpringProfilesOrderApplication       : info log: 10
2019-12-28 20:43:13.578 DEBUG 19798 --- [     parallel-2] c.e.SpringProfilesOrderApplication       : debug log: 20
2019-12-28 20:43:13.578  INFO 19798 --- [     parallel-2] c.e.SpringProfilesOrderApplication       : info log: 20
2019-12-28 20:43:13.780 DEBUG 19798 --- [     parallel-3] c.e.SpringProfilesOrderApplication       : debug log: 30
2019-12-28 20:43:13.780  INFO 19798 --- [     parallel-3] c.e.SpringProfilesOrderApplication       : info log: 30

次に次のプロパティファイルを追加して、 production プロファイルで実行します。

`application-production.properties`

logging.level.root=info

しかし、出力内容は何も変わりません

2019-12-28 21:33:01.996  INFO 19906 --- [           main] c.e.SpringProfilesOrderApplicationKt     : Starting SpringProfilesOrderApplicationKt on mike-neck.local with PID 19906 (/Users/user/spring-profiles-order/build/classes/kotlin/main started by user in /Users/user/spring-profiles-order)
2019-12-28 21:33:01.997 DEBUG 19906 --- [           main] c.e.SpringProfilesOrderApplicationKt     : Running with Spring Boot v2.2.2.RELEASE, Spring v5.2.2.RELEASE
2019-12-28 21:33:01.997  INFO 19906 --- [           main] c.e.SpringProfilesOrderApplicationKt     : The following profiles are active: production
2019-12-28 21:33:02.419  INFO 19906 --- [           main] c.e.SpringProfilesOrderApplicationKt     : Started SpringProfilesOrderApplicationKt in 0.626 seconds (JVM running for 1.167)
2019-12-28 21:33:02.644 DEBUG 19906 --- [     parallel-1] c.e.SpringProfilesOrderApplication       : debug log: 10
2019-12-28 21:33:02.646  INFO 19906 --- [     parallel-1] c.e.SpringProfilesOrderApplication       : info log: 10
2019-12-28 21:33:02.850 DEBUG 19906 --- [     parallel-2] c.e.SpringProfilesOrderApplication       : debug log: 20
2019-12-28 21:33:02.850  INFO 19906 --- [     parallel-2] c.e.SpringProfilesOrderApplication       : info log: 20
2019-12-28 21:33:03.052 DEBUG 19906 --- [     parallel-3] c.e.SpringProfilesOrderApplication       : debug log: 30
2019-12-28 21:33:03.052  INFO 19906 --- [     parallel-3] c.e.SpringProfilesOrderApplication       : info log: 30

おそらく default プロファイルはどのプロファイルでも適用されていると考えられるので実験してみます。

`application.properties`

logging.level.com.example=info

このように default プロファイル用のプロパティファイルを修正した上で production プロファイルで実行してみると、 debug ログが出力されないのではないかと想定されます。で、その実行結果がこちら。

2019-12-28 23:14:38.261  INFO 20155 --- [           main] c.e.SpringProfilesOrderApplicationKt     : Starting SpringProfilesOrderApplicationKt on mike-neck.local with PID 20155 (/Users/mike/IdeaProjects/sandbox/spring-profiles-order/build/classes/kotlin/main started by mike in /Users/mike/IdeaProjects/sandbox/spring-profiles-order)
2019-12-28 23:14:38.262  INFO 20155 --- [           main] c.e.SpringProfilesOrderApplicationKt     : The following profiles are active: production
2019-12-28 23:14:38.683  INFO 20155 --- [           main] c.e.SpringProfilesOrderApplicationKt     : Started SpringProfilesOrderApplicationKt in 0.591 seconds (JVM running for 1.074)
2019-12-28 23:14:38.912  INFO 20155 --- [     parallel-1] c.e.SpringProfilesOrderApplication       : info log: 10
2019-12-28 23:14:39.115  INFO 20155 --- [     parallel-2] c.e.SpringProfilesOrderApplication       : info log: 20
2019-12-28 23:14:39.316  INFO 20155 --- [     parallel-3] c.e.SpringProfilesOrderApplication       : info log: 30

したがって、 default プロファイルは他のプロファイルが指定されている場合でも有効であると想定されます。

以上から、 default プロファイルにログレベルを debug にしない、するなら他のプロファイルで上書きするのがよいのではないかと思われます。

または、ロギングレベルについては、logback-spring.xml で設定するなど別のプロファイルも把握できる仕組みを利用したほうが良いかもしれません。

(追記 2019/12/29 0:32)

ちなみに、これはロギングだけの話ではないので、注意が必要です