All Articles

SpringのロギングとExceptionハンドリング再入門

同僚氏のPRレビューをするにあたって、ロギング、Exceptionハンドリングよくわかってないなって思って再入門してみた。 「@ExceptionHandlerのメソッドでハンドリングしたときのレスポンスをログ出力する」というのがPRの内容だった。

「1.どこでアクセス(リクエスト)ログを出力するのがよいのか」、「2.どうやってExceptionハンドリングが行われているのか」について調べたことをまとめる。

※本記事の環境はJava 11, Spring Boot 2.4.4

ロギング

公式ドキュメント

Spring Bootは、Commons Loggingを使ってログ出力をしている。デフォルト設定としては、Java Util LoggingLog4j2Logbackを提供している。

spring-boot-starter-loggingを依存関係に追加している場合は、Logbackが使われる。 spring-boot-starter-loggingには、Logback、Log4j、Slf4jが依存関係に追加されている。

ログのファイル出力

Spring Bootは、デフォルトでコンソールのみにだけログを出力してファイルには出力しない。ファイルに出力したい場合は、application.properties(yml)にlogging.file.pathでパスを指定するだけでよい。デフォルトのファイル名はspring.logなので、変更したい場合はlogging.file.nameでファイル名を指定する。

Logbackを使ったログ出力

howto-logginをそのままマネするだけで、Logbackを使ってログ出力が可能。

このように書けば、ファイルとコンソールにログを出力できる。

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
<include resource="org/springframework/boot/logging/logback/console-appender.xml" />
<property name="LOG_FILE" value="${LOG_FILE:-${LOG_PATH/}spring.log}" />
<include resource="org/springframework/boot/logging/logback/file-appender.xml" />
<root level="INFO">
<appender-ref ref="CONSOLE" />
<appender-ref ref="FILE" />
</root>
</configuration>
view raw logback-spring.xml hosted with ❤ by GitHub
 

ログレベルで出力するファイルを分ける

logback-spring.xmlでfilter要素を指定すれば、出力ログのフィルタリングができる。

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<include resource="org/springframework/boot/logging/logback/defaults.xml"/>
<!-- 標準出力はデフォルト -->
<include resource="org/springframework/boot/logging/logback/console-appender.xml" />
<property name="APPLICATION_LOG_FILE" value="${LOG_PATH}/application.log" />
<appender name="FILE_INFO" class="ch.qos.logback.core.rolling.RollingFileAppender">
<encoder>
<pattern>${FILE_LOG_PATTERN}</pattern>
<charset>${FILE_LOG_CHARSET}</charset>
</encoder>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>INFO</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
<file>${APPLICATION_LOG_FILE}</file>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>${APPLICATION_LOG_FILE}.%d{yyyy-MM-dd}.%i.gz</fileNamePattern>
<maxFileSize>10MB</maxFileSize>
</rollingPolicy>
</appender>
<property name="ERROR_LOG_FILE" value="${LOG_PATH}/error.log" />
<appender name="FILE_ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
<encoder>
<pattern>${FILE_LOG_PATTERN}</pattern>
<charset>${FILE_LOG_CHARSET}</charset>
</encoder>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>ERROR</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
<file>${ERROR_LOG_FILE}</file>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>${ERROR_LOG_FILE}.%d{yyyy-MM-dd}.%i.gz</fileNamePattern>
<maxFileSize>10MB</maxFileSize>
</rollingPolicy>
</appender>
<root level="INFO">
<appender-ref ref="CONSOLE" />
<appender-ref ref="FILE_INFO" />
<appender-ref ref="FILE_ERROR" />
</root>
</configuration>
view raw logback-spring.xml hosted with ❤ by GitHub

  • appender name=“FILE_INFO”

    • ログレベルINFOのログを${LOG_PATH}/application.logに出力
  • appender name=“FILE_ERROR”

    • ログレベルERRORのログを${LOG_PATH}/error.logに出力

アクセスログの出力

Spring MVCで用意されているCommonsRequestLoggingFilter.javaを使ってアクセスログを出力してみる。

まず、CommonsRequestLoggingFilter.javaをBean登録する。

@Configuration(proxyBeanMethods = false)
public class RequestLoggingFilterConfig {
@Bean
public CommonsRequestLoggingFilter logFilter() {
CommonsRequestLoggingFilter filter = new CommonsRequestLoggingFilter();
filter.setIncludeQueryString(true);
filter.setIncludePayload(true);
filter.setMaxPayloadLength(10000);
filter.setIncludeHeaders(false);
filter.setAfterMessagePrefix("Request data : ");
return filter;
}
}

次に、application.ymlでログレベルDEBUGのログを出力するように設定する。

logging:
level:
org.springframework.web.filter.CommonsRequestLoggingFilter: debug
view raw application.yml hosted with ❤ by GitHub

サンプルのREST APIに対してリクエストを送ると、このような感じでログ出力される。

2021-03-21 21:17:10.364 DEBUG 24133 --- [nio-8080-exec-2] o.s.w.f.CommonsRequestLoggingFilter      : Before request [GET /users]
2021-03-21 21:17:10.396 DEBUG 24133 --- [nio-8080-exec-2] o.s.w.f.CommonsRequestLoggingFilter      : Request data : GET /users]
2021-03-21 21:17:14.724 DEBUG 24133 --- [nio-8080-exec-3] o.s.w.f.CommonsRequestLoggingFilter      : Before request [GET /users/1]
2021-03-21 21:17:14.735 DEBUG 24133 --- [nio-8080-exec-3] o.s.w.f.CommonsRequestLoggingFilter      : Request data : GET /users/1]
2021-03-21 21:17:17.829 DEBUG 24133 --- [nio-8080-exec-4] o.s.w.f.CommonsRequestLoggingFilter      : Before request [GET /users/5]
2021-03-21 21:17:17.837 DEBUG 24133 --- [nio-8080-exec-4] o.s.w.f.CommonsRequestLoggingFilter      : Request data : GET /users/5]
2021-03-21 21:17:31.881 DEBUG 24133 --- [nio-8080-exec-5] o.s.w.f.CommonsRequestLoggingFilter      : Before request [POST /users]
2021-03-21 21:17:31.904 DEBUG 24133 --- [nio-8080-exec-5] o.s.w.f.CommonsRequestLoggingFilter      : Request data : POST /users, payload={
    "name": "test"
}]

単にリクエスト情報を知りたい場合は、用意されているクラスを使えば簡単にできる。


ここで、冒頭の「どこでアクセス(リクエスト)ログを出力するのがよいのか」について考えてみる。 先ほど利用した、CommonsRequestLoggingFilter.javaは、AbstractRequestLoggingFilter.javaを継承しておりこのクラスは、OncePerRequestFilter.javaを継承している。

これを踏まえると、OncePerRequestFilter.javaを継承してアクセスログを出力するのが正しいそう。

Exceptionハンドリング

Spring MVCで、Controller以降の処理で発生した例外をハンドリングするコンポーネントとして、org.springframework.web.servlet.HandlerExceptionResolverインターフェースといくつかの実装クラスを提供している。

デフォルトで適用されるHandlerExceptionResolverの実装クラスと呼び出される順序は、「1.ExceptionHandlerExceptionResolver.java」、「2.ResponseStatusExceptionResolver.java」、「3.DefaultHandlerExceptionResolver.java」である。

  • ExceptionHandlerExceptionResolver.java

    • @ExceptionHandlerを指定したメソッドのためのExceptionハンドラ
  • ResponseStatusExceptionResolver.java

    • @ResponseStatusを付与した例外クラスのためのExceptionハンドラ
  • DefaultHandlerExceptionResolver.java

    • Spring MVCのコントローラの処理で発生する例外をハンドリングするためのExceptionハンドラ

Links