Improve endpoint mapping debug logging

[snicoll]

I have an app that exports metrics to Prometheus with --debug. Prometheus calls /actuator/prometheus every 5 sec which leads to the following

2018-09-03 17:47:49.995 DEBUG 8241 --- [nio-8081-exec-2] 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-03 17:47:49.996 DEBUG 8241 --- [nio-8081-exec-2] 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-03 17:47:54.995 DEBUG 8241 --- [nio-8081-exec-3] 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-03 17:47:54.996 DEBUG 8241 --- [nio-8081-exec-3] 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-03 17:47:59.996 DEBUG 8241 --- [nio-8081-exec-5] 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-03 17:47:59.997 DEBUG 8241 --- [nio-8081-exec-5] 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-03 17:48:04.995 DEBUG 8241 --- [nio-8081-exec-4] 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-03 17:48:04.996 DEBUG 8241 --- [nio-8081-exec-4] 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-03 17:48:09.996 DEBUG 8241 --- [nio-8081-exec-6] 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-03 17:48:09.997 DEBUG 8241 --- [nio-8081-exec-6] 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-03 17:48:14.995 DEBUG 8241 --- [nio-8081-exec-7] 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-03 17:48:14.996 DEBUG 8241 --- [nio-8081-exec-7] 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-03 17:48:19.995 DEBUG 8241 --- [nio-8081-exec-8] 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-03 17:48:19.996 DEBUG 8241 --- [nio-8081-exec-8] 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-03 17:48:24.996 DEBUG 8241 --- [nio-8081-exec-9] 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-03 17:48:24.996 DEBUG 8241 --- [nio-8081-exec-9] 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-03 17:48:29.995 DEBUG 8241 --- [io-8081-exec-10] 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-03 17:48:29.996 DEBUG 8241 --- [io-8081-exec-10] 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-03 17:48:34.995 DEBUG 8241 --- [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>)

To complement with recent improvements in logging, I think we should attempt to improve this log if we can.

[wilkinsona]

The output comes from AbstractHandlerMapping. Given the recent changes to Framework's logging, I'm a little surprised that its level is debug rather than trace.

[bclozel]

I think it's by design, as you get that sort of output for Spring MVC Controllers:

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

See #13511

[rstoyanchev]

Indeed this is by design. The output in Brian's comment shows the intended DEBUG level information per HTTP request. Perhaps the output in the first comment looks odd because it lacks the rest of the "o.s.web" logging? Is that turned off, I thought "o.s.web" is now at DEBUG by default with devtools. I know that means even more information, but we have to show something at DEBUG level per request.

[wilkinsona]

Thanks, both. I hadn't appreciated that the handler would typically be the user's controller. This, then, is an unfortunate side-effect of all the endpoint operations being handled by the same handler that then does some further routing to call the appropriate method for the operation.

[rstoyanchev]

So there is an extra log message missing with the actuator routing details. In full context (i.e. including o.s.web), you would see a) the request info, b) the Spring MVC mapping, and c) the actuator routing, which I think is fine even if b) in this case isn't very helpful. Optionally AbstractHandlerMapping could log b) from a protected method, so it can be suppress it altogether.

[philwebb]

We might be able to override getHandlerExecutionChain in WebMvcEndpointHandlerMapping and return a HandlerExecutionChain subclass that has a better toString().

[philwebb]

I've marked this as a bug because I think we really need to improve it in some way before GA

[snicoll]

It should be noted that the code above is without devtools and therefore the logging tuning that are applied now. If I add devtools, this is the current log:

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

[wilkinsona]

It's curious that this line is logged twice:

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>)

Any idea why that happens?

I'm also not sure how useful it is that the entire response body is logged. It's a bit overwhelming in this case and I imagine that it will be in others where the body isn't small.

[rstoyanchev]

For the body it's relying on the toString() method of the Object being rendered. For text it would make sense to cap it. For the double logging, I wonder if it is related to the use of HandlerMappingIntrospector, for example by Spring Security?

[wilkinsona]

For the body it's relying on the toString() method of the Object being rendered. For text it would make sense to cap it

Thanks, Rossen. Is there an SPR issue for that, or should we open one?

[rstoyanchev]

Yes please, create one.

[wilkinsona]

I've opened https://jira.spring.io/browse/SPR-17254.

[bclozel]

Now that SPR-17254 is resolved, I've tried to improve the logging experience for Actuator web endpoints; basically turning this into something more useful, because currently it's writing the same information for all endpoints:

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>)

I've locally patched AbstractWebMvcEndpointHandlerMapping and managed to log the following instead:

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

The interesting bit is Operation read method public java.util.Map org.springframework.boot.actuate.info.InfoEndpoint.info(), but the actual information is buried deep down the hierarchy in AbstractDiscoveredOperation, and not exposed through its interface Operation.

A couple of solutions here:

1. We create a proper contract for that and expose an operation description to the world, something that might not be specific to operations available through reflection
2. We acknowledge that this use case is not worth changing such an important contract, and we could easily settle on a log like s.b.a.e.w.s.WebMvcEndpointHandlerMapping : Mapped to Actuator WebEndpoint "info"