同僚氏のPRレビューをするにあたって、ロギング、Exceptionハンドリングよくわかってないなって思って再入門してみた。 「@ExceptionHandlerのメソッドでハンドリングしたときのレスポンスをログ出力する」というのがPRの内容だった。
「1.どこでアクセス（リクエスト）ログを出力するのがよいのか」、「2.どうやってExceptionハンドリングが行われているのか」について調べたことをまとめる。
※本記事の環境はJava 11, Spring Boot 2.4.4
ロギング
Spring Bootは、Commons Loggingを使ってログ出力をしている。デフォルト設定としては、Java Util Logging、Log4j2、Logbackを提供している。
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>
ログレベルで出力するファイルを分ける
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>
- 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
サンプルの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ハンドラ
