Spring BootでSpring MVC関連のログを制す

Spring BootでWebアプリケーションを作ろうとすると、「組み込みTomcat(サーブレットエンジン)」×「Spring MVC」の組み合わせでアプリケーションを作る事も多いと思います。その際に・・・自分が思っている通りに動かない時皆さんはどうしているでしょうか？
Spring BootやSpring MVCに詳しい方はフレームワークのクラスに適当にブレークポイントを指定して、どこまで処理が想定通りに動いているか確認する！！という強者も中にはいるかも！？しれませんが・・・Spring Boot(Spring MVC)初心者の方は、何が起きているのかわからず・・・エラー解析に多くの（無駄な）時間をかけてしまうことがあるのではないかと思います。

どうすればよい？

エラーの内容によって対処は変わりますが、ここでは・・・アプリケーション自体は起動したけど、自前で用意したControllerの呼び出し結果が想定と異なる場合に、まずはどうするのがよいのか？というところを紹介したいと思います。本エントリーでは「404 NOT FOUND」が発生した場合のエラー解析を例に話を進めさせてもらいます。

結論→詳細なログを出すべし！！

Spring Boot(Spring MVC)初心者の方は、思い通り動くアプリケーションが作れるようになるまでは・・・とりあえず詳細なログ（DEBUG/TRACEレベルのログ）を出しておくのがよいのかな〜と思います。

WARNING:

開発環境以外では、基本的にはINFO以上にしてください。

src/main/resources/application.properties

# Web関連のロガーのログレベルをDEBUG or TRACEへ
logging.level.web=trace

# Spring MVCへのリクエスト/レスポンスログの詳細情報出力を有効化
spring.mvc.log-request-details=true

TIPS: 「web」というロガー名は何者？

Spring Bootでは「Logger Groups」という仕組みがサポートされており、「web」は組み込みのLogger Groupで、Web関連のロガーのログレベルをまとめて指定することができるようになっています。

デフォルトの動作を知る

Spring Bootアプリケーションを Spring Initializrから作成した場合、ログの出力レベルは「INFO」になっています。この状態でアプリケーションを起動し、存在しないパスへリクエストを送った時に出力されるログを見てみましょう。

まずは、アプリケーション起動時には以下のようなログ（Tomcatが起動したことがわかるログ）が出力されます。

コンソール(起動時)

2021-05-04 14:17:03.094  INFO 76330 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2021-05-04 14:17:03.101  INFO 76330 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2021-05-04 14:17:03.102  INFO 76330 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.45]
2021-05-04 14:17:03.144  INFO 76330 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2021-05-04 14:17:03.144  INFO 76330 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 668 ms
2021-05-04 14:17:03.262  INFO 76330 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2021-05-04 14:17:03.394  INFO 76330 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''

起動後にクライアントから存在しないパスへアクセスしてみます。

コンソール(クライアント)

% curl -D - "http://localhost:8080/home?name=Kazuki" -H "X-Tracking-Id: $(uuidgen)"
HTTP/1.1 404 
Vary: Origin
Vary: Access-Control-Request-Method
Vary: Access-Control-Request-Headers
Content-Type: application/json
Transfer-Encoding: chunked
Date: Tue, 04 May 2021 05:17:19 GMT

{"timestamp":"2021-05-04T05:17:19.058+00:00","status":404,"error":"Not Found","message":"","path":"/home"}

curlコマンドの結果よりクライアントには「404: NOT FOUND」が返却されたことがわかりますが、サーバのログをみてみると・・・ DispatcherServlet が初期化されたことがわかるログは出ていますが、それ以外の情報はログに出ていません。

コンソール(初回アクセス時)

...(省略)...
2021-05-04 14:17:19.011  INFO 76330 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2021-05-04 14:17:19.012  INFO 76330 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2021-05-04 14:17:19.013  INFO 76330 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms

これは・・・エラー原因がクライアント側に存在するため（＝存在しないパスへアクセスしてきているため）、サーバ側の問題ではないのでログは出力していないという感じだと思います。
テストによりアプリケーションの品質が担保されているプロダクション環境などにおいては、クライアント側の問題で発生する事象をログを出力しないのは適切だと言えますが、絶賛開発中（しかもフレームワーク利用の初心者が開発中）であればログを出した方がよいことがあるはずです。

出力レベルをDEBUGにしてみる

まずは、Logger Groupである「web」の出力レベルをDEBUGにするとどのような情報が出力されるか確認してみましょう。

src/main/resources/application.properties

# Web関連のロガーのログレベルをDEBUGへ
logging.level.web=debug

# Spring MVCへのリクエスト/レスポンスログの詳細情報出力はいったん無効化
spring.mvc.log-request-details=false

Tomcat起動時に初期化した「サーブレットフィルタ」「サーブレット」「リクエストハンドラ」などの情報が出力されるようになります。

コンソール(起動時)

...(省略)...
2021-05-04 14:18:09.048  INFO 76343 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 642 ms
[phone]:18:09.061 DEBUG 76343 --- [           main] o.s.b.w.s.ServletContextInitializerBeans : Mapping filters: characterEncodingFilter urls=[/*] order=-2147483648, formContentFilter urls=[/*] order=-9900, requestContextFilter urls=[/*] order=-105, customFilterWithDI urls=[/*] order=2147483647
[phone]:18:09.061 DEBUG 76343 --- [           main] o.s.b.w.s.ServletContextInitializerBeans : Mapping servlets: dispatcherServlet urls=[/]
2021-05-04 14:18:09.154  INFO 76343 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
[phone]:18:09.159 DEBUG 76343 --- [           main] s.w.s.m.m.a.RequestMappingHandlerAdapter : ControllerAdvice beans: 0 @ModelAttribute, 0 @InitBinder, 1 RequestBodyAdvice, 1 ResponseBodyAdvice
[phone]:18:09.190 DEBUG 76343 --- [           main] s.w.s.m.m.a.RequestMappingHandlerMapping : 3 mappings in 'requestMappingHandlerMapping'
[phone]:18:09.204 DEBUG 76343 --- [           main] o.s.w.s.handler.SimpleUrlHandlerMapping  : Patterns [/webjars/**, /**] in 'resourceHandlerMapping'
[phone]:18:09.209 DEBUG 76343 --- [           main] .m.m.a.ExceptionHandlerExceptionResolver : ControllerAdvice beans: 0 @ExceptionHandler, 1 ResponseBodyAdvice
2021-05-04 14:18:09.267  INFO 76343 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''

初回アクセス時にDispatcherServletが初期化され、初期化時に検出したSpring MVCのコンポーネントの情報などが出力されるようになります。

コンソール(初回アクセス時=サーブレット初期化時)

...(省略)...
2021-05-04 14:22:46.885  INFO 76343 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2021-05-04 14:22:46.886  INFO 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
[phone]:22:46.886 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected StandardServletMultipartResolver
[phone]:22:46.886 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected AcceptHeaderLocaleResolver
[phone]:22:46.886 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected FixedThemeResolver
[phone]:22:46.887 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected org.springframework.web.servlet.view.DefaultRequestToViewNameTranslator@56db55b7
[phone]:22:46.887 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected org.springframework.web.servlet.support.SessionFlashMapManager@1336fef8
[phone]:22:46.887 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : enableLoggingRequestDetails='false': request parameters and headers will be masked to prevent unsafe logging of potentially sensitive data
2021-05-04 14:22:46.888  INFO 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 2 ms

リクエスト時には、Spring(Spring Boot)がどのように処理して最終的に「404: NOT FOUND」にしたのかがわかるような情報が出力されます。

コンソール(リクエスト時)

[phone]:22:46.895 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/home?name=Kazuki", parameters={masked}
[phone]:22:46.906 DEBUG 76343 --- [nio-8080-exec-1] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped to ResourceHttpRequestHandler [Classpath [META-INF/resources/], Classpath [resources/], Classpath [static/], Classpath [public/], ServletContext [/]]
[phone]:22:46.908 DEBUG 76343 --- [nio-8080-exec-1] o.s.w.s.r.ResourceHttpRequestHandler     : Resource not found
[phone]:22:46.908 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 404 NOT_FOUND
[phone]:22:46.912 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : "ERROR" dispatch for GET "/error?name=Kazuki", parameters={masked}
[phone]:22:46.913 DEBUG 76343 --- [nio-8080-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController#error(HttpServletRequest)
[phone]:22:46.936 DEBUG 76343 --- [nio-8080-exec-1] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Using 'application/json', given [*/*] and supported [application/json, application/*+json, application/json, application/*+json]
[phone]:22:46.936 DEBUG 76343 --- [nio-8080-exec-1] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Writing [{timestamp=Tue May 04 14:22:46 JST 2021, status=404, error=Not Found, message=, path=/home}]
[phone]:22:46.960 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 404

ざっくり説明すると・・・・

2021-05-04 14:22:46.895 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/home?name=Kazuki", parameters={masked}

では、GET /home というパスにリクエストがあったことが確認できます。

2021-05-04 14:22:46.906 DEBUG 76343 --- [nio-8080-exec-1] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped to ResourceHttpRequestHandler [Classpath [META-INF/resources/], Classpath [resources/], Classpath [static/], Classpath [public/], ServletContext [/]]
2021-05-04 14:22:46.908 DEBUG 76343 --- [nio-8080-exec-1] o.s.w.s.r.ResourceHttpRequestHandler     : Resource not found
2021-05-04 14:22:46.908 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 404 NOT_FOUND

では、GET /home に対応する「リクエストハンドラ（Controllerなど）」が見つからなかったことが確認できます。

2021-05-04 14:22:46.912 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : "ERROR" dispatch for GET "/error?name=Kazuki", parameters={masked}
2021-05-04 14:22:46.913 DEBUG 76343 --- [nio-8080-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController#error(HttpServletRequest)
2021-05-04 14:22:46.936 DEBUG 76343 --- [nio-8080-exec-1] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Using 'application/json', given [*/*] and supported [application/json, application/*+json, application/json, application/*+json]
2021-05-04 14:22:46.936 DEBUG 76343 --- [nio-8080-exec-1] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Writing [{timestamp=Tue May 04 14:22:46 JST 2021, status=404, error=Not Found, message=, path=/home}]
2021-05-04 14:22:46.960 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 404

では、エラー応答を行う「リクエストハンドラ（Spring Bootデフォルトのハンドラ）」へリクエストを転送し、そのリクエストハンドラによってエラー応答(JSON)が行われていることが確認できます。が・・・しかし、ログレベルをDEBUGにすることで「404: NOT FOUND」が応答された直接的な原因や処理の流れは（何となく）わかりますが、このログだけでは本質的な原因を特定することはできていません。

出力レベルをTRACEにしてみる

つぎに、Logger Groupである「web」の出力レベルをTRACEにするとどのような情報が出力されるか確認してみましょう。

src/main/resources/application.properties

# Web関連のロガーのログレベルをTRACEへ
logging.level.web=trace

# Spring MVCへのリクエスト/レスポンスログの詳細情報出力はいったん無効化
spring.mvc.log-request-details=false

Tomcat起動時に初期化した「サーブレットフィルタ」「サーブレット」「リクエストハンドラ」などの詳細な情報が出力されるようになります。

コンソール(起動時)

...(省略)...
2021-05-04 14:48:57.491  INFO 76466 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 703 ms
[phone]:48:57.493 TRACE 76466 --- [           main] o.s.b.w.s.ServletContextInitializerBeans : Added existing Servlet initializer bean 'dispatcherServletRegistration'; order=2147483647, resource=class path resource [org/springframework/boot/autoconfigure/web/servlet/DispatcherServletAutoConfiguration$DispatcherServletRegistrationConfiguration.class]
[phone]:48:57.498 TRACE 76466 --- [           main] o.s.b.w.s.ServletContextInitializerBeans : Created Filter initializer for bean 'characterEncodingFilter'; order=-2147483648, resource=class path resource [org/springframework/boot/autoconfigure/web/servlet/HttpEncodingAutoConfiguration.class]
[phone]:48:57.498 TRACE 76466 --- [           main] o.s.b.w.s.ServletContextInitializerBeans : Created Filter initializer for bean 'formContentFilter'; order=-9900, resource=class path resource [org/springframework/boot/autoconfigure/web/servlet/WebMvcAutoConfiguration.class]
[phone]:48:57.498 TRACE 76466 --- [           main] o.s.b.w.s.ServletContextInitializerBeans : Created Filter initializer for bean 'requestContextFilter'; order=-105, resource=class path resource [org/springframework/boot/autoconfigure/web/servlet/WebMvcAutoConfiguration$WebMvcAutoConfigurationAdapter.class]
2021-05-04 14:48:57.501 DEBUG 76466 --- [           main] o.s.b.w.s.ServletContextInitializerBeans : Mapping filters: characterEncodingFilter urls=[/*] order=-2147483648, formContentFilter urls=[/*] order=-9900, requestContextFilter urls=[/*] order=-105
2021-05-04 14:48:57.501 DEBUG 76466 --- [           main] o.s.b.w.s.ServletContextInitializerBeans : Mapping servlets: dispatcherServlet urls=[/]
2021-05-04 14:48:57.594  INFO 76466 --- [           main] o.s.s.concurrent.ThreadPoolTaskExecutor  : Initializing ExecutorService 'applicationTaskExecutor'
2021-05-04 14:48:57.600 DEBUG 76466 --- [           main] s.w.s.m.m.a.RequestMappingHandlerAdapter : ControllerAdvice beans: 0 @ModelAttribute, 0 @InitBinder, 1 RequestBodyAdvice, 1 ResponseBodyAdvice
[phone]:48:57.630 TRACE 76466 --- [           main] s.w.s.m.m.a.RequestMappingHandlerMapping : 
+	c.e.c.c.DemoController:
+	{GET [/hello]}: hello(String,String)
[phone]:48:57.633 TRACE 76466 --- [           main] s.w.s.m.m.a.RequestMappingHandlerMapping : 
+	o.s.b.a.w.s.e.BasicErrorController:
+	{ [/error]}: error(HttpServletRequest)
+	{ [/error], produces [text/html]}: errorHtml(HttpServletRequest,HttpServletResponse)
2021-05-04 14:48:57.635 DEBUG 76466 --- [           main] s.w.s.m.m.a.RequestMappingHandlerMapping : 3 mappings in 'requestMappingHandlerMapping'
2021-05-04 14:48:57.643 DEBUG 76466 --- [           main] o.s.w.s.h.BeanNameUrlHandlerMapping      : Detected 0 mappings in 'beanNameHandlerMapping'
[phone]:48:57.645 TRACE 76466 --- [           main] o.s.w.s.f.support.RouterFunctionMapping  : 0 RouterFunction(s) in 'routerFunctionMapping'
[phone]:48:57.652 TRACE 76466 --- [           main] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped [/webjars/**] onto ResourceHttpRequestHandler [Classpath [META-INF/resources/webjars/]]
[phone]:48:57.653 TRACE 76466 --- [           main] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped [/**] onto ResourceHttpRequestHandler [Classpath [META-INF/resources/], Classpath [resources/], Classpath [static/], Classpath [public/], ServletContext [/]]
2021-05-04 14:48:57.653 DEBUG 76466 --- [           main] o.s.w.s.handler.SimpleUrlHandlerMapping  : Patterns [/webjars/**, /**] in 'resourceHandlerMapping'
...(省略)...

どのような情報が詳細かされたかというと・・・

2021-05-04 14:48:57.493 TRACE 76466 --- [           main] o.s.b.w.s.ServletContextInitializerBeans : Added existing Servlet initializer bean 'dispatcherServletRegistration'; order=2147483647, resource=class path resource [org/springframework/boot/autoconfigure/web/servlet/DispatcherServletAutoConfiguration$DispatcherServletRegistrationConfiguration.class]
2021-05-04 14:48:57.498 TRACE 76466 --- [           main] o.s.b.w.s.ServletContextInitializerBeans : Created Filter initializer for bean 'characterEncodingFilter'; order=-2147483648, resource=class path resource [org/springframework/boot/autoconfigure/web/servlet/HttpEncodingAutoConfiguration.class]
2021-05-04 14:48:57.498 TRACE 76466 --- [           main] o.s.b.w.s.ServletContextInitializerBeans : Created Filter initializer for bean 'formContentFilter'; order=-9900, resource=class path resource [org/springframework/boot/autoconfigure/web/servlet/WebMvcAutoConfiguration.class]
2021-05-04 14:48:57.498 TRACE 76466 --- [           main] o.s.b.w.s.ServletContextInitializerBeans : Created Filter initializer for bean 'requestContextFilter'; order=-105, resource=class path resource [org/springframework/boot/autoconfigure/web/servlet/WebMvcAutoConfiguration$WebMvcAutoConfigurationAdapter.class]

では、アプリケーションに適用されたサーブレットフィルタに関する詳細な情報を確認することができます。

2021-05-04 14:48:57.630 TRACE 76466 --- [           main] s.w.s.m.m.a.RequestMappingHandlerMapping : 
    c.e.c.c.DemoController:
    {GET [/hello]}: hello(String,String)
2021-05-04 14:48:57.633 TRACE 76466 --- [           main] s.w.s.m.m.a.RequestMappingHandlerMapping : 
    o.s.b.a.w.s.e.BasicErrorController:
    { [/error]}: error(HttpServletRequest)
    { [/error], produces [text/html]}: errorHtml(HttpServletRequest,HttpServletResponse)

では、アプリケーションに適用されたController（アノテーション駆動のハンドラ）に関する詳細な情報を確認することができます。今回のケースで言えば、GET /home に対応するControllerが適用されていないことがわかります。もし GET /home に対応するControllerを作っているのに「404: NOT FOUND」が出るのであれば、おそらくControllerの作り方に誤り（例えば・・・@Controllerアノテーションをつけ忘れた、GET /home ではなく GET /homa になってしまっていた 等）がある可能性を疑うことができるはずです。

NOTE:

本エントリーしてでは解説は扱いしますが、↓のログでは、Controller以外のハンドラに関する詳細な情報を確認することができます。

2021-05-04 14:48:57.645 TRACE 76466 --- [ main] o.s.w.s.f.support.RouterFunctionMapping : 0 RouterFunction(s) in 'routerFunctionMapping'
2021-05-04 14:48:57.652 TRACE 76466 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped [/webjars/] onto ResourceHttpRequestHandler [Classpath [META-INF/resources/webjars/]]
2021-05-04 14:48:57.653 TRACE 76466 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped [/] onto ResourceHttpRequestHandler [Classpath [META-INF/resources/], Classpath [resources/], Classpath [static/], Classpath [public/], ServletContext [/]]

初回アクセス時にDispatcherServletが初期化され、初期化時に検出したSpring MVCのコンポーネントの情報などが出力されるようになります（ここはDEBUG時と出力形式が異なりますが情報量自体に大きな違いはなさそうです）。

> ```diff:コンソール(初回アクセス時＝サブレット初期化時)
...(省略)...
2021-05-04 15:08:46.276  INFO 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
[phone]:08:46.276 TRACE 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected org.springframework.web.multipart.support.StandardServletMultipartResolver@7b11d29a
[phone]:08:46.276 TRACE 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected org.springframework.web.servlet.i18n.AcceptHeaderLocaleResolver@40c65638
[phone]:08:46.276 TRACE 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected org.springframework.web.servlet.theme.FixedThemeResolver@63250c7d
[phone]:08:46.277 TRACE 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected DefaultRequestToViewNameTranslator
[phone]:08:46.277 TRACE 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected SessionFlashMapManager
2021-05-04 15:08:46.277 DEBUG 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : enableLoggingRequestDetails='false': request parameters and headers will be masked to prevent unsafe logging of potentially sensitive data
...(省略)...

リクエスト時には、Spring(Spring Boot)がどのように処理して最終的に「404: NOT FOUND」にしたのかがわかるような情報がより詳細に出力されます。

コンソール(リクエスト時)

[phone]:08:46.284 TRACE 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/home?name=Kazuki", parameters={masked}, headers={masked} in DispatcherServlet 'dispatcherServlet'
[phone]:08:46.289 TRACE 76513 --- [nio-8080-exec-1] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped to HandlerExecutionChain with [ResourceHttpRequestHandler [Classpath [META-INF/resources/], Classpath [resources/], Classpath [static/], Classpath [public/], ServletContext [/]]] and 3 interceptors
2021-05-04 15:08:46.290 DEBUG 76513 --- [nio-8080-exec-1] o.s.w.s.r.ResourceHttpRequestHandler     : Resource not found
[phone]:08:46.291 TRACE 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : No view rendering, null ModelAndView returned.
2021-05-04 15:08:46.291 DEBUG 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 404 NOT_FOUND, headers={masked}
[phone]:08:46.303 TRACE 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : "ERROR" dispatch for GET "/error?name=Kazuki", parameters={masked}, headers={masked} in DispatcherServlet 'dispatcherServlet'
[phone]:08:46.304 TRACE 76513 --- [nio-8080-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : 2 matching mappings: [{ [/error]}, { [/error], produces [text/html]}]
[phone]:08:46.305 TRACE 76513 --- [nio-8080-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController#error(HttpServletRequest)
[phone]:08:46.315 TRACE 76513 --- [nio-8080-exec-1] o.s.web.method.HandlerMethod             : Arguments: [org.apache.catalina.core.ApplicationHttpRequest@c1b8e4a]
2021-05-04 15:08:46.330 DEBUG 76513 --- [nio-8080-exec-1] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Using 'application/json', given [*/*] and supported [application/json, application/*+json, application/json, application/*+json]
[phone]:08:46.331 TRACE 76513 --- [nio-8080-exec-1] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Writing [{timestamp=Tue May 04 15:08:46 JST 2021, status=404, error=Not Found, message=, path=/home}]
[phone]:08:46.359 TRACE 76513 --- [nio-8080-exec-1] s.w.s.m.m.a.RequestMappingHandlerAdapter : Applying default cacheSeconds=-1
[phone]:08:46.360 TRACE 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : No view rendering, null ModelAndView returned.
2021-05-04 15:08:46.360 DEBUG 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 404, headers={masked}

更に詳細な情報を出力してみる

リクエストに対応するControllerを指定する方法は、代表的な方法は「リクエストメソッド(GET, POSTなど)」と「リクエストパス（/home など）」の組み合わせで一致させることですが、更に「リクエストパラメータ(name=value)」や「リクエストヘッダ（name: value）」などを条件に指定することもあります（具体的には・・・画面を扱うアプリケーションにて、一つの入力フォーム内に複数のサブミットボタンが配置されているような場合は、押されたボタンの名前で呼び出すハンドラを切り替えるような設計にすることがあるため）。そのため、Logger Groupである「web」の出力レベルをTRACEにするだけではエラー解析に必要な情報が不足することがあります。そのような場合は・・・・「Spring MVCへのリクエスト/レスポンスログの詳細情報出力」を有効化してみてください。

src/main/resources/application.properties

# Web関連のロガーのログレベルをTRACEへ
logging.level.web=trace

# Spring MVCへのリクエスト/レスポンスログの詳細情報出力を有効化
spring.mvc.log-request-details=true

「詳細情報出力を有効化」すると、{masked}となっていた部分に実際の値（リクエストパラメータ値、リクエストヘッダ値、レスポンスヘッダ値）が出力されます。

-2021-05-04 15:08:46.284 TRACE 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/home?name=Kazuki", parameters={masked}, headers={masked} in DispatcherServlet 'dispatcherServlet'
[phone]:21:20.327 TRACE 76565 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/home?name=Kazuki", parameters={name:[Kazuki]}, headers={host:[localhost:8080], user-agent:[curl/7.64.1], accept:[*/*], x-tracking-id:[EA4CE16E-5D5E-4959-BA77-228F08F61B0D]} in DispatcherServlet 'dispatcherServlet'
...(省略)...
-2021-05-04 15:08:46.291 DEBUG 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 404 NOT_FOUND, headers={masked}
[phone]:21:20.349 DEBUG 76565 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 404 NOT_FOUND, headers={Vary:[Origin, Access-Control-Request-Method, Access-Control-Request-Headers], Vary:[Origin, Access-Control-Request-Method, Access-Control-Request-Headers], Vary:[Origin, Access-Control-Request-Method, Access-Control-Request-Headers]}
...(省略)...
-2021-05-04 15:08:46.360 DEBUG 76513 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 404, headers={masked}
[phone]:21:20.432 DEBUG 76565 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 404, headers={Vary:[Origin, Access-Control-Request-Method, Access-Control-Request-Headers], Vary:[Origin, Access-Control-Request-Method, Access-Control-Request-Headers], Vary:[Origin, Access-Control-Request-Method, Access-Control-Request-Headers], Content-Type:[application/json], Transfer-Encoding:[chunked], Date:[Tue, 04 May 2021 06:21:20 GMT]}

おまけ：Spring Boot Actuatorで出力レベルを変更する

プロダクション環境でログレベルを変えることは基本的にはないと思いますが、ステージング環境や各種テスティング環境にて、一時的に出力レベルを変更してアプリケーション内部の動作を確認したい場合は、Spring Boot ActuatorのLoggersエンドポイントを利用してログの出力レベルを変更することもできます。

依存アーティファクトとして、spring-boot-starter-actuatorを追加します。

pom.xml

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-actuator</artifactId>
</dependency>

loggersのWebエンドポイントを有効化します。

src/main/resources/application.properties

# loggersのwebエンドポイントを有効化
management.endpoints.web.exposure.include=info,loggers

起動後に現在の出力レベルを確認しましょう。

% curl -D - -X GET http://localhost:8080/actuator/loggers/web
HTTP/1.1 200 
Content-Type: application/vnd.spring-boot.actuator.v3+json
Transfer-Encoding: chunked
Date: Tue, 04 May 2021 07:04:57 GMT

{"configuredLevel":null,"members":["org.springframework.core.codec","org.springframework.http","org.springframework.web","org.springframework.boot.actuate.endpoint.web","org.springframework.boot.web.servlet.ServletContextInitializerBeans"]}

出力レベルをTRACEにしてみます。

% curl -D - -X POST http://localhost:8080/actuator/loggers/web -d '{"configuredLevel": "TRACE"}' -H "Content-Type: application/json"
HTTP/1.1 204 
Date: Tue, 04 May 2021 07:05:37 GMT

「TRACE」に変更されたことを確認しましょう。

% curl -D - -X GET http://localhost:8080/actuator/loggers/web                                                                       
HTTP/1.1 200 
Content-Type: application/vnd.spring-boot.actuator.v3+json
Transfer-Encoding: chunked
Date: Tue, 04 May 2021 07:05:39 GMT

{"configuredLevel":"TRACE","members":["org.springframework.core.codec","org.springframework.http","org.springframework.web","org.springframework.boot.actuate.endpoint.web","org.springframework.boot.web.servlet.ServletContextInitializerBeans"]}

おまけ：Developer Toolsでローカルの出力レベルを変更する

アプリケーション開発をチームで行う場合、ソースコードはGitなどのバージョン管理システムを使うことになると思いますが、ローカルで試しにログレベルを変えて(例えばTRACEレベルに変更して)、そのまままリモートへpushしてしまった！！という経験（事故！？）はないですか？
ログは開発者の知識レベルによって出したい箇所や出したいレベルが変わってくるので、そのような場合は、Spring Bootが提供しているDeveloper Toolsを利用して、ローカル環境でのみ読み込まれる設定ファイルに個人が望むログ定義を指定するという方法があります。

依存アーティファクトとして、spring-boot-devtoolsを追加します。

pom.xml

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-devtools</artifactId>
  <optional>true</optional>
</dependency>

個人専用のプロパティファイルを作成し、そのファイルに出力レベル（ここではTRACE）を指定します。

% mkdir -p $HOME/.config/spring-boot && echo "logging.level.web=trace" > $HOME/.config/spring-boot/spring-boot-devtools.properties

% view $HOME/.config/spring-boot/spring-boot-devtools.properties

logging.level.web=trace

この状態でIDE上でアプリケーションを起動すると、「Logger Group」のwebの出力レベルがTRACEになります。

動作検証バージョン

• Spring Boot 2.4.5

まとめ

今回はSpring MVCに関わるログ出力に関して記載しましたが、ログ（特にエラーログ）はアプリケーション開発および保守していく上で非常に大事な要素になります。Spring Framework(Spring Frameworkベースの各種ライブラリ)も開発を手助けする各種ログを出力してくれているので、エラー解析やフレームワーク内部の動作検証をする際には、出力レベルを下げて実行してみると、これまで見えていなかったことが見えてくると思います。また「Logger Group」という仕組みでロガーをグループ化することで、関連するロガーを集約して管理できるのも地味にありがたいかも〜と思いました。

参考サイト

• https://docs.spring.io/spring-boot/docs/2.4.5/reference/htmlsingle