[spring-projects/spring-boot]改进端点映射调试日志记录

输出来自AbstractHandlerMapping.鉴于最近对框架日志记录的更改，我有点惊讶的是它的级别是调试而不是跟踪。

我认为这是设计使然，因为 Spring MVC 控制器会得到这样的输出：

DEBUG 8126 --- [nio-8080-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.lang.String com.example.demo.MvcHomeController.greet(java.lang.String)
DEBUG 8126 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/?name=Boot", parameters={masked}
DEBUG 8126 --- [nio-8080-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to public java.lang.String com.example.demo.MvcHomeController.greet(java.lang.String)
DEBUG 8126 --- [nio-8080-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/html', given [text/html, application/xhtml+xml, image/webp, image/apng, application/xml;q=0.9, */*;q=0.8] and supported [text/plain, */*, text/plain, */*, application/json, application/*+json, application/json, application/*+json]
DEBUG 8126 --- [nio-8080-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Writing ["Hello, Boot"]
DEBUG 8126 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 200 OK

参见#13511

事实上，这是设计使然。 Brian 评论中的输出显示了每个 HTTP 请求的预期调试级别信息。也许第一条评论中的输出看起来很奇怪，因为它缺少其余的"o.s.web"日志记录？是否已关闭，我认为"o.s.web"现在默认使用 devtools 进行调试。我知道这意味着更多信息，但我们必须在每个请求的调试级别显示一些内容。

谢谢，两位。我没有意识到处理程序通常是用户的控制器。那么，这是由同一处理程序处理的所有端点操作的一个不幸的副作用，该处理程序然后执行一些进一步的路由以调用该操作的适当方法。

因此，执行器路由详细信息中缺少额外的日志消息。在完整的上下文中（即包括 osweb），您将看到 a）请求信息，b）Spring MVC 映射，以及 c）执行器路由，我认为这很好，即使 b）在这种情况下不是很有帮助。 AbstractHandlerMapping 可以选择从受保护的方法记录 b)，因此可以完全抑制它。

我们也许能够重写getHandlerExecutionChain并WebMvcEndpointHandlerMapping返回HandlerExecutionChain具有更好的toString().

我已将此标记为错误，因为我认为我们确实需要在正式发布之前以某种方式改进它

应该注意的是，上面的代码没有开发工具，因此现在应用了日志记录调整。如果我添加 devtools，这是当前日志：

2018-09-06 09:35:08.383 DEBUG 39735 --- [nio-8081-exec-1] s.b.a.e.w.s.WebMvcEndpointHandlerMapping : Mapped to public java.lang.Object org.springframework.boot.actuate.endpoint.web.servlet.AbstractWebMvcEndpointHandlerMapping$OperationHandler.handle(javax.servlet.http.HttpServletRequest,java.util.Map<java.lang.String, java.lang.String>)
2018-09-06 09:35:08.389 DEBUG 39735 --- [nio-8081-exec-1] o.s.web.servlet.DispatcherServlet        : GET "/actuator/prometheus", parameters={}
2018-09-06 09:35:08.390 DEBUG 39735 --- [nio-8081-exec-1] s.b.a.e.w.s.WebMvcEndpointHandlerMapping : Mapped to public java.lang.Object org.springframework.boot.actuate.endpoint.web.servlet.AbstractWebMvcEndpointHandlerMapping$OperationHandler.handle(javax.servlet.http.HttpServletRequest,java.util.Map<java.lang.String, java.lang.String>)
2018-09-06 09:35:08.428 DEBUG 39735 --- [nio-8081-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/plain;version=0.0.4;charset=utf-8;q=1', given [text/plain;version=0.0.4;q=1, */*;q=0.1] and supported [text/plain;version=0.0.4;charset=utf-8]
2018-09-06 09:35:08.428 DEBUG 39735 --- [nio-8081-exec-1] m.m.a.RequestResponseBodyMethodProcessor : Writing ["# HELP jvm_memory_max_bytes The maximum amount of memory in bytes that can be used for memory management
# TYPE jvm_memory_max_bytes gauge
jvm_memory_max_bytes{application="initializr-stats-generator",area="nonheap",id="Code Cache",} 2.5165824E8
jvm_memory_max_bytes{application="initializr-stats-generator",area="nonheap",id="Metaspace",} -1.0
jvm_memory_max_bytes{application="initializr-stats-generator",area="nonheap",id="Compressed Class Space",} 1.073741824E9
jvm_memory_max_bytes{application="initializr-stats-generator",area="heap",id="PS Eden Space",} 1.402994688E9
jvm_memory_max_bytes{application="initializr-stats-generator",area="heap",id="PS Survivor Space",} 1.1010048E7
jvm_memory_max_bytes{application="initializr-stats-generator",area="heap",id="PS Old Gen",} 2.863661056E9
# HELP jvm_buffer_total_capacity_bytes An estimate of the total capacity of the buffers in this pool
# TYPE jvm_buffer_total_capacity_bytes gauge
jvm_buffer_total_capacity_bytes{application="initializr-stats-generator",id="direct",} 16384.0
jvm_buffer_total_capacity_bytes{application="initializr-stats-generator",id="mapped",} 0.0
# HELP process_files_open The open file descriptor count
# TYPE process_files_open gauge
process_files_open{application="initializr-stats-generator",} 128.0
# HELP jvm_gc_live_data_size_bytes Size of old generation memory pool after a full GC
# TYPE jvm_gc_live_data_size_bytes gauge
jvm_gc_live_data_size_bytes{application="initializr-stats-generator",} 2.4477432E7
# HELP tomcat_threads_current  
# TYPE tomcat_threads_current gauge
tomcat_threads_current{application="initializr-stats-generator",name="http-nio-8081",} 10.0
# HELP tomcat_cache_access_total  
# TYPE tomcat_cache_access_total counter
tomcat_cache_access_total{application="initializr-stats-generator",} 0.0
# HELP tomcat_servlet_request_max_seconds  
# TYPE tomcat_servlet_request_max_seconds gauge
tomcat_servlet_request_max_seconds{application="initializr-stats-generator",name="default",} 0.0
# HELP tomcat_threads_busy  
# TYPE tomcat_threads_busy gauge
tomcat_threads_busy{application="initializr-stats-generator",name="http-nio-8081",} 1.0
# HELP jvm_threads_peak The peak live thread count since the Java virtual machine started or peak was reset
# TYPE jvm_threads_peak gauge
jvm_threads_peak{application="initializr-stats-generator",} 36.0
# HELP system_cpu_count The number of processors available to the Java virtual machine
# TYPE system_cpu_count gauge
system_cpu_count{application="initializr-stats-generator",} 8.0
# HELP tomcat_global_sent_bytes_total  
# TYPE tomcat_global_sent_bytes_total counter
tomcat_global_sent_bytes_total{application="initializr-stats-generator",name="http-nio-8081",} 0.0
# HELP tomcat_global_error_total  
# TYPE tomcat_global_error_total counter
tomcat_global_error_total{application="initializr-stats-generator",name="http-nio-8081",} 0.0
# HELP system_cpu_usage The "recent cpu usage" for the whole system
# TYPE system_cpu_usage gauge
system_cpu_usage{application="initializr-stats-generator",} 0.0
# HELP logback_events_total Number of error level events that made it to the logs
# TYPE logback_events_total counter
logback_events_total{application="initializr-stats-generator",level="error",} 0.0
logback_events_total{application="initializr-stats-generator",level="warn",} 0.0
logback_events_total{application="initializr-stats-generator",level="info",} 15.0
logback_events_total{application="initializr-stats-generator",level="debug",} 31.0
logback_events_total{application="initializr-stats-generator",level="trace",} 0.0
# HELP process_files_max The maximum file descriptor count
# TYPE process_files_max gauge
process_files_max{application="initializr-stats-generator",} 10240.0
# HELP tomcat_sessions_created_total  
# TYPE tomcat_sessions_created_total counter
tomcat_sessions_created_total{application="initializr-stats-generator",} 0.0
# HELP jvm_memory_committed_bytes The amount of memory in bytes that is committed for the Java virtual machine to use
# TYPE jvm_memory_committed_bytes gauge
jvm_memory_committed_bytes{application="initializr-stats-generator",area="nonheap",id="Code Cache",} 8847360.0
jvm_memory_committed_bytes{application="initializr-stats-generator",area="nonheap",id="Metaspace",} 4.3384832E7
jvm_memory_committed_bytes{application="initializr-stats-generator",area="nonheap",id="Compressed Class Space",} 6160384.0
jvm_memory_committed_bytes{application="initializr-stats-generator",area="heap",id="PS Eden Space",} 2.65814016E8
jvm_memory_committed_bytes{application="initializr-stats-generator",area="heap",id="PS Survivor Space",} 1.1010048E7
jvm_memory_committed_bytes{application="initializr-stats-generator",area="heap",id="PS Old Gen",} 1.69345024E8
# HELP jvm_classes_loaded The number of classes that are currently loaded in the Java virtual machine
# TYPE jvm_classes_loaded gauge
jvm_classes_loaded{application="initializr-stats-generator",} 8396.0
# HELP tomcat_sessions_expired_total  
# TYPE tomcat_sessions_expired_total counter
tomcat_sessions_expired_total{application="initializr-stats-generator",} 0.0
# HELP jvm_buffer_memory_used_bytes An estimate of the memory that the Java virtual machine is using for this buffer pool
# TYPE jvm_buffer_memory_used_bytes gauge
jvm_buffer_memory_used_bytes{application="initializr-stats-generator",id="direct",} 16384.0
jvm_buffer_memory_used_bytes{application="initializr-stats-generator",id="mapped",} 0.0
# HELP jvm_gc_pause_seconds Time spent in GC pause
# TYPE jvm_gc_pause_seconds summary
jvm_gc_pause_seconds_count{action="end of minor GC",application="initializr-stats-generator",cause="Metadata GC Threshold",} 1.0
jvm_gc_pause_seconds_sum{action="end of minor GC",application="initializr-stats-generator",cause="Metadata GC Threshold",} 0.025
jvm_gc_pause_seconds_count{action="end of major GC",application="initializr-stats-generator",cause="Metadata GC Threshold",} 1.0
jvm_gc_pause_seconds_sum{action="end of major GC",application="initializr-stats-generator",cause="Metadata GC Threshold",} 0.073
# HELP jvm_gc_pause_seconds_max Time spent in GC pause
# TYPE jvm_gc_pause_seconds_max gauge
jvm_gc_pause_seconds_max{action="end of minor GC",application="initializr-stats-generator",cause="Metadata GC Threshold",} 0.025
jvm_gc_pause_seconds_max{action="end of major GC",application="initializr-stats-generator",cause="Metadata GC Threshold",} 0.073
# HELP jvm_threads_live The current number of live threads including both daemon and non-daemon threads
# TYPE jvm_threads_live gauge
jvm_threads_live{application="initializr-stats-generator",} 34.0
# HELP tomcat_servlet_request_seconds  
# TYPE tomcat_servlet_request_seconds summary
tomcat_servlet_request_seconds_count{application="initializr-stats-generator",name="default",} 0.0
tomcat_servlet_request_seconds_sum{application="initializr-stats-generator",name="default",} 0.0
# HELP tomcat_sessions_rejected_total  
# TYPE tomcat_sessions_rejected_total counter
tomcat_sessions_rejected_total{application="initializr-stats-generator",} 0.0
# HELP process_uptime_seconds The uptime of the Java virtual machine
# TYPE process_uptime_seconds gauge
process_uptime_seconds{application="initializr-stats-generator",} 5.233
# HELP process_start_time_seconds Start time of the process since unix epoch.
# TYPE process_start_time_seconds gauge
process_start_time_seconds{application="initializr-stats-generator",} 1.53621930324E9
# HELP tomcat_global_request_seconds  
# TYPE tomcat_global_request_seconds summary
tomcat_global_request_seconds_count{application="initializr-stats-generator",name="http-nio-8081",} 0.0
tomcat_global_request_seconds_sum{application="initializr-stats-generator",name="http-nio-8081",} 0.0
# HELP jvm_gc_max_data_size_bytes Max size of old generation memory pool
# TYPE jvm_gc_max_data_size_bytes gauge
jvm_gc_max_data_size_bytes{application="initializr-stats-generator",} 2.863661056E9
# HELP process_cpu_usage The "recent cpu usage" for the Java Virtual Machine process
# TYPE process_cpu_usage gauge
process_cpu_usage{application="initializr-stats-generator",} 0.0
# HELP jvm_buffer_count An estimate of the number of buffers in the pool
# TYPE jvm_buffer_count gauge
jvm_buffer_count{application="initializr-stats-generator",id="direct",} 2.0
jvm_buffer_count{application="initializr-stats-generator",id="mapped",} 0.0
# HELP tomcat_cache_hit_total  
# TYPE tomcat_cache_hit_total counter
tomcat_cache_hit_total{application="initializr-stats-generator",} 0.0
# HELP jvm_gc_memory_allocated_bytes_total Incremented for an increase in the size of the young generation memory pool after one GC to before the next
# TYPE jvm_gc_memory_allocated_bytes_total counter
jvm_gc_memory_allocated_bytes_total{application="initializr-stats-generator",} 1.762172E8
# HELP tomcat_global_request_max_seconds  
# TYPE tomcat_global_request_max_seconds gauge
tomcat_global_request_max_seconds{application="initializr-stats-generator",name="http-nio-8081",} 0.0
# HELP tomcat_sessions_active_max  
# TYPE tomcat_sessions_active_max gauge
tomcat_sessions_active_max{application="initializr-stats-generator",} 0.0
# HELP tomcat_sessions_alive_max_seconds  
# TYPE tomcat_sessions_alive_max_seconds gauge
tomcat_sessions_alive_max_seconds{application="initializr-stats-generator",} 0.0
# HELP tomcat_sessions_active_current  
# TYPE tomcat_sessions_active_current gauge
tomcat_sessions_active_current{application="initializr-stats-generator",} 0.0
# HELP jvm_gc_memory_promoted_bytes_total Count of positive increases in the size of the old generation memory pool before GC to after GC
# TYPE jvm_gc_memory_promoted_bytes_total counter
jvm_gc_memory_promoted_bytes_total{application="initializr-stats-generator",} 1.7393152E7
# HELP jvm_memory_used_bytes The amount of used memory
# TYPE jvm_memory_used_bytes gauge
jvm_memory_used_bytes{application="initializr-stats-generator",area="nonheap",id="Code Cache",} 8839168.0
jvm_memory_used_bytes{application="initializr-stats-generator",area="nonheap",id="Metaspace",} 4.0413216E7
jvm_memory_used_bytes{application="initializr-stats-generator",area="nonheap",id="Compressed Class Space",} 5576504.0
jvm_memory_used_bytes{application="initializr-stats-generator",area="heap",id="PS Eden Space",} 1.43610296E8
jvm_memory_used_bytes{application="initializr-stats-generator",area="heap",id="PS Survivor Space",} 0.0
jvm_memory_used_bytes{application="initializr-stats-generator",area="heap",id="PS Old Gen",} 2.4477432E7
# HELP tomcat_threads_config_max  
# TYPE tomcat_threads_config_max gauge
tomcat_threads_config_max{application="initializr-stats-generator",name="http-nio-8081",} 200.0
# HELP jvm_threads_daemon The current number of live daemon threads
# TYPE jvm_threads_daemon gauge
jvm_threads_daemon{application="initializr-stats-generator",} 32.0
# HELP jvm_classes_unloaded_total The total number of classes unloaded since the Java virtual machine has started execution
# TYPE jvm_classes_unloaded_total counter
jvm_classes_unloaded_total{application="initializr-stats-generator",} 0.0
# HELP tomcat_global_received_bytes_total  
# TYPE tomcat_global_received_bytes_total counter
tomcat_global_received_bytes_total{application="initializr-stats-generator",name="http-nio-8081",} 0.0
# HELP tomcat_servlet_error_total  
# TYPE tomcat_servlet_error_total counter
tomcat_servlet_error_total{application="initializr-stats-generator",name="default",} 0.0
# HELP system_load_average_1m The sum of the number of runnable entities queued to available processors and the number of runnable entities running on the available processors averaged over a period of time
# TYPE system_load_average_1m gauge
system_load_average_1m{application="initializr-stats-generator",} 2.48779296875
"]
2018-09-06 09:35:08.435 DEBUG 39735 --- [nio-8081-exec-1] o.s.web.servlet.DispatcherServlet        : Completed 200 OK

奇怪的是这一行被记录了两次：

2018-09-06 09:35:08.383 DEBUG 39735 --- [nio-8081-exec-1] s.b.a.e.w.s.WebMvcEndpointHandlerMapping : Mapped to public java.lang.Object org.springframework.boot.actuate.endpoint.web.servlet.AbstractWebMvcEndpointHandlerMapping$OperationHandler.handle(javax.servlet.http.HttpServletRequest,java.util.Map<java.lang.String, java.lang.String>)

知道为什么会发生这种情况吗？

我也不确定记录整个响应正文有多大用处。在这种情况下，这有点令人难以承受，我想在其他身体不小的情况下也会如此。

对于主体，它依赖于toString()正在渲染的对象的方法。对于文本来说，限制它是有意义的。对于双重日志记录，我想知道它是否与使用有关HandlerMappingIntrospector，例如Spring Security？

谢谢，罗森。是否存在 SPR 问题，或者我们应该开一个？

是的，请创建一个。

我已经打开https://jira.spring.io/browse/SPR-17254。

现在SPR-17254已得到解决，我已尝试改善 Actuator Web 端点的日志记录体验；基本上将其变成更有用的东西，因为目前它正在为所有端点写入相同的信息：

2018-09-06 09:35:08.390 DEBUG 39735 --- [nio-8081-exec-1] s.b.a.e.w.s.WebMvcEndpointHandlerMapping : Mapped to public java.lang.Object org.springframework.boot.actuate.endpoint.web.servlet.AbstractWebMvcEndpointHandlerMapping$OperationHandler.handle(javax.servlet.http.HttpServletRequest,java.util.Map<java.lang.String, java.lang.String>)

我已经在本地修补AbstractWebMvcEndpointHandlerMapping并设法记录以下内容：

o.s.web.servlet.DispatcherServlet        : GET "/actuator/info", parameters={}
s.b.a.e.w.s.WebMvcEndpointHandlerMapping : Mapped to [DiscoveredWebOperation@59573e1c operationMethod = Operation read method public java.util.Map org.springframework.boot.actuate.info.InfoEndpoint.info(), invoker = [ReflectiveOperationInvoker@3442fa93 target = org.springframework.boot.actuate.info.InfoEndpoint@32a531f, method = Operation read method public java.util.Map org.springframework.boot.actuate.info.InfoEndpoint.info()], id = 'info', blocking = true, requestPredicate = GET to path 'info' produces: application/vnd.spring-boot.actuator.v2+json,application/json]
m.m.a.RequestResponseBodyMethodProcessor : Using 'application/vnd.spring-boot.actuator.v2+json;q=0.8', given [text/html, application/xhtml+xml, image/webp, image/apng, application/xml;q=0.9, */*;q=0.8] and supported [application/vnd.spring-boot.actuator.v2+json, application/json]
m.m.a.RequestResponseBodyMethodProcessor : Writing [{}]
o.s.web.servlet.DispatcherServlet        : Completed 200 OK

有趣的是Operation read method public java.util.Map org.springframework.boot.actuate.info.InfoEndpoint.info()，但实际信息深深地埋藏在层次结构中AbstractDiscoveredOperation，而不是通过其界面公开Operation。

这里有几个解决方案：

1. 我们为此创建一个适当的合约，并向世界公开操作描述，这可能不是特定于通过反射可用的操作
2. 我们承认这个用例不值得改变如此重要的合同，我们可以轻松地确定像这样的日志s.b.a.e.w.s.WebMvcEndpointHandlerMapping : Mapped to Actuator WebEndpoint "info"