使用Spring Boot掌握Spring MVC相关的日志

当使用Spring Boot来构建Web应用程序时,我认为通常会使用“内嵌Tomcat(servlet引擎)”和“Spring MVC”的组合来创建应用程序。在这种情况下……当应用程序不按照自己的预期运行时,大家会怎么做呢?
精通Spring Boot和Spring MVC的人可能会在框架类中随意设置断点,以检查处理是否按照预期进行!也许也有这样的强者存在!?但是对于Spring Boot(Spring MVC)初学者来说,可能不知道发生了什么……他们可能需要花费大量(无用)的时间来分析错误。

我该怎么办?

错误的处理方式取决于错误的内容,但在这里…当应用程序本身启动时,如果调用自定义控制器的结果与预期不符,首先应该做什么呢?我想介绍一下。在本文中,我们将以”404 NOT FOUND”错误为例进行错误分析。

结论→需要提供详细的日志!!

对于初学者来说,想要能够创建一个按照自己意愿运行的Spring Boot(Spring MVC)应用程序,可能需要先输出详细的日志(DEBUG/TRACE级别的日志)作为备选方案吧~

警告:

请在非开发环境下,基本上设置为INFO以上。

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

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

提示:「web」是一个什么样的记录器名称?

在Spring Boot中,支持一种名为「Logger Groups」的机制,「web」是一个内嵌的Logger Group,可以集中指定与Web相关的记录器的日志级别。

了解默认操作

如果使用Spring Initializr创建Spring Boot应用程序,日志输出级别将为“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,以确认会输出哪些信息。

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

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

当Tomcat启动时,会输出已初始化的”Servlet Filter”、”Servlet”、”请求处理程序”等信息。

...(省略)...
2021-05-04 14:18:09.048  INFO 76343 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 642 ms
+2021-05-04 14: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
+2021-05-04 14: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'
+2021-05-04 14:18:09.159 DEBUG 76343 --- [           main] s.w.s.m.m.a.RequestMappingHandlerAdapter : ControllerAdvice beans: 0 @ModelAttribute, 0 @InitBinder, 1 RequestBodyAdvice, 1 ResponseBodyAdvice
+2021-05-04 14:18:09.190 DEBUG 76343 --- [           main] s.w.s.m.m.a.RequestMappingHandlerMapping : 3 mappings in 'requestMappingHandlerMapping'
+2021-05-04 14:18:09.204 DEBUG 76343 --- [           main] o.s.w.s.handler.SimpleUrlHandlerMapping  : Patterns [/webjars/**, /**] in 'resourceHandlerMapping'
+2021-05-04 14: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'
+2021-05-04 14:22:46.886 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected StandardServletMultipartResolver
+2021-05-04 14:22:46.886 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected AcceptHeaderLocaleResolver
+2021-05-04 14:22:46.886 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected FixedThemeResolver
+2021-05-04 14:22:46.887 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected org.springframework.web.servlet.view.DefaultRequestToViewNameTranslator@56db55b7
+2021-05-04 14:22:46.887 DEBUG 76343 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Detected org.springframework.web.servlet.support.SessionFlashMapManager@1336fef8
+2021-05-04 14: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:未找到”错误的信息。

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

大略地说的话……

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对应的“请求处理程序(控制器等)”。

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:未找到”的响应,可以大致了解直接的原因和处理流程,但仅凭这些日志无法确定根本原因。

尝试将输出级别设置为TRACE

我们接下来来确认一下Logger Group中名为”web”的日志输出级别设置为TRACE时,会输出哪些信息。

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

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

当Tomcat启动时,会输出详细的信息,如初始化的”Servlet过滤器”、”Servlet”和”请求处理程序”等。

...(省略)...
2021-05-04 14:48:57.491  INFO 76466 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 703 ms
+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.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
+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)
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'
+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 [/]]
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]

你可以查看有关应用程序中应用的Servlet过滤器的详细信息。

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)

在应用程序中,您可以查看有关应用程序控制器(基于注释的处理程序)的详细信息。在这种情况下,您可以看到没有应用于GET /home的控制器。如果您创建了对应GET /home的控制器,但是出现了“404:未找到”错误,则可能是控制器的创建方式有误(例如没有添加@Controller注解,或者GET /home变成了GET /homa等),您应该怀疑错误的可能性。

请注意:

在本条目中,我们将讨论控制器以外的处理程序的详细信息,可以在下面的日志中查看。

2021-05-04 14:48:57.645 TRACE 76466 — [main] o.s.w.s.f.support.RouterFunctionMapping :’路由函数’中有0个路由函数
2021-05-04 14:48:57.652 TRACE 76466 — [main] o.s.w.s.handler.SimpleUrlHandlerMapping :将[/webjars/**]映射到资源HTTP请求处理程序[类路径[META-INF/resources/webjars/]]
2021-05-04 14:48:57.653 TRACE 76466 — [main] o.s.w.s.handler.SimpleUrlHandlerMapping :将[/**]映射到资源HTTP请求处理程序[类路径[META-INF/resources/], 类路径[resources/], 类路径[static/], 类路径[public/], Servlet上下文[/]]

当DispatcherServlet在初始访问时被初始化时,它会输出Spring MVC组件的信息,这些信息是在初始化过程中检测到的(尽管输出形式在DEBUG模式下可能会有所不同,但信息量本身并没有太大的差异)。

控制台(初始访问时=子授权初始化时)
…(省略)…
2021-05-04 15:08:46.276 INFO 76513 — [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : 正在初始化Servlet ‘dispatcherServlet’
+2021-05-04 15:08:46.276 TRACE 76513 — [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : 检测到org.springframework.web.multipart.support.StandardServletMultipartResolver@7b11d29a
+2021-05-04 15:08:46.276 TRACE 76513 — [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : 检测到org.springframework.web.servlet.i18n.AcceptHeaderLocaleResolver@40c65638
+2021-05-04 15:08:46.276 TRACE 76513 — [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : 检测到org.springframework.web.servlet.theme.FixedThemeResolver@63250c7d
+2021-05-04 15:08:46.277 TRACE 76513 — [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : 检测到DefaultRequestToViewNameTranslator
+2021-05-04 15:08:46.277 TRACE 76513 — [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : 检测到SessionFlashMapManager
2021-05-04 15:08:46.277 DEBUG 76513 — [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : enableLoggingRequestDetails=’false’:请求参数和标头将被屏蔽,以防止记录潜在的敏感数据
…(省略)…

当进行请求时,Spring(Spring Boot)将以更详细的方式输出信息,以便了解它是如何处理并最终导致“404: NOT FOUND”。

+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'
+2021-05-04 15: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
+2021-05-04 15: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}
+2021-05-04 15: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'
+2021-05-04 15:08:46.304 TRACE 76513 --- [nio-8080-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : 2 matching mappings: [{ [/error]}, { [/error], produces [text/html]}]
+2021-05-04 15: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)
+2021-05-04 15: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]
+2021-05-04 15: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}]
+2021-05-04 15:08:46.359 TRACE 76513 --- [nio-8080-exec-1] s.w.s.m.m.a.RequestMappingHandlerAdapter : Applying default cacheSeconds=-1
+2021-05-04 15: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}

尝试输出更详细的信息

指定响应请求的控制器的方法有多种,其中一种常见的方法是通过匹配请求方法(例如GET、POST等)和请求路径(例如/home),还可以根据请求参数(name=value)和请求头(name: value)等条件进行指定(具体情况如下…在处理界面的应用程序中,如果在一个输入表单中放置了多个提交按钮,可能会设计成根据点击的按钮名称切换调用的处理程序)。因此,仅将Logger Group设置为“web”的TRACE级别可能会导致缺少用于错误分析的必要信息。在这种情况下…尝试启用“Spring MVC请求/响应日志的详细信息输出”。

# 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'
+2021-05-04 15: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}
+2021-05-04 15: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}
+2021-05-04 15: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作为依赖组件。

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

启用 loggers 的 Web 端点。

# 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"]}

附加内容:可以通过开发者工具来更改本地的输出级别。

如果在团队中进行应用程序开发的情况下,我认为通常会使用像Git这样的版本控制系统来管理源代码。但是,您是否有过试图在本地更改日志级别(例如改为TRACE级别),然后不小心将其推送到远程的经历(意外!?)?

由于日志根据开发者的知识水平而改变,他们可能希望在特定位置和特定级别记录日志。在这种情况下,您可以使用Spring Boot提供的开发者工具,通过在本地环境中仅加载的配置文件中指定个人期望的日志定义的方法来实现。

作为依赖工具,将spring-boot-devtools添加进来。

<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框架(基于Spring框架的各种库)也提供了各种日志输出来帮助开发,所以当进行错误分析和框架内部操作验证时,可以尝试将输出级别降低,这样可能会看到之前看不到的东西。此外,通过“Logger Group”的机制将日志器分组,也可以方便地集中管理相关的日志,这也是值得欣赏的地方。

引用网站。

    https://docs.spring.io/spring-boot/docs/2.4.5/reference/htmlsingle
广告
将在 10 秒后关闭
bannerAds