Truncate large response bodies when logging in RequestResponseBodyMethodProcessor [SPR-17254] #21787
Description
Andy Wilkinson opened SPR-17254 and commented
The usability of the new debug request and response logging is hurt a little bit when a large response body is being returned. A concrete example is Spring Boot Actuator's Prometheus endpoint that is called by Prometheus to get all of an application's metrics. The logging for such a request looks like this:
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
1. 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
1. HELP jvm_buffer_total_capacity_bytes An estimate of the total capacity of the buffers in this pool
1. 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
1. HELP process_files_open The open file descriptor count
1. TYPE process_files_open gauge
process_files_open{application="initializr-stats-generator",} 128.0
1. HELP jvm_gc_live_data_size_bytes Size of old generation memory pool after a full GC
1. TYPE jvm_gc_live_data_size_bytes gauge
jvm_gc_live_data_size_bytes{application="initializr-stats-generator",} 2.4477432E7
1. HELP tomcat_threads_current
1. TYPE tomcat_threads_current gauge
tomcat_threads_current{application="initializr-stats-generator",name="http-nio-8081",} 10.0
1. HELP tomcat_cache_access_total
1. TYPE tomcat_cache_access_total counter
tomcat_cache_access_total{application="initializr-stats-generator",} 0.0
1. HELP tomcat_servlet_request_max_seconds
1. TYPE tomcat_servlet_request_max_seconds gauge
tomcat_servlet_request_max_seconds{application="initializr-stats-generator",name="default",} 0.0
1. HELP tomcat_threads_busy
1. TYPE tomcat_threads_busy gauge
tomcat_threads_busy{application="initializr-stats-generator",name="http-nio-8081",} 1.0
1. HELP jvm_threads_peak The peak live thread count since the Java virtual machine started or peak was reset
1. TYPE jvm_threads_peak gauge
jvm_threads_peak{application="initializr-stats-generator",} 36.0
1. HELP system_cpu_count The number of processors available to the Java virtual machine
1. TYPE system_cpu_count gauge
system_cpu_count{application="initializr-stats-generator",} 8.0
1. HELP tomcat_global_sent_bytes_total
1. TYPE tomcat_global_sent_bytes_total counter
tomcat_global_sent_bytes_total{application="initializr-stats-generator",name="http-nio-8081",} 0.0
1. HELP tomcat_global_error_total
1. TYPE tomcat_global_error_total counter
tomcat_global_error_total{application="initializr-stats-generator",name="http-nio-8081",} 0.0
1. HELP system_cpu_usage The "recent cpu usage" for the whole system
1. TYPE system_cpu_usage gauge
system_cpu_usage{application="initializr-stats-generator",} 0.0
1. HELP logback_events_total Number of error level events that made it to the logs
1. 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
1. HELP process_files_max The maximum file descriptor count
1. TYPE process_files_max gauge
process_files_max{application="initializr-stats-generator",} 10240.0
1. HELP tomcat_sessions_created_total
1. TYPE tomcat_sessions_created_total counter
tomcat_sessions_created_total{application="initializr-stats-generator",} 0.0
1. HELP jvm_memory_committed_bytes The amount of memory in bytes that is committed for the Java virtual machine to use
1. 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
1. HELP jvm_classes_loaded The number of classes that are currently loaded in the Java virtual machine
1. TYPE jvm_classes_loaded gauge
jvm_classes_loaded{application="initializr-stats-generator",} 8396.0
1. HELP tomcat_sessions_expired_total
1. TYPE tomcat_sessions_expired_total counter
tomcat_sessions_expired_total{application="initializr-stats-generator",} 0.0
1. HELP jvm_buffer_memory_used_bytes An estimate of the memory that the Java virtual machine is using for this buffer pool
1. 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
1. HELP jvm_gc_pause_seconds Time spent in GC pause
1. 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
1. HELP jvm_gc_pause_seconds_max Time spent in GC pause
1. 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
1. HELP jvm_threads_live The current number of live threads including both daemon and non-daemon threads
1. TYPE jvm_threads_live gauge
jvm_threads_live{application="initializr-stats-generator",} 34.0
1. HELP tomcat_servlet_request_seconds
1. 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
1. HELP tomcat_sessions_rejected_total
1. TYPE tomcat_sessions_rejected_total counter
tomcat_sessions_rejected_total{application="initializr-stats-generator",} 0.0
1. HELP process_uptime_seconds The uptime of the Java virtual machine
1. TYPE process_uptime_seconds gauge
process_uptime_seconds{application="initializr-stats-generator",} 5.233
1. HELP process_start_time_seconds Start time of the process since unix epoch.
1. TYPE process_start_time_seconds gauge
process_start_time_seconds{application="initializr-stats-generator",} 1.53621930324E9
1. HELP tomcat_global_request_seconds
1. 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
1. HELP jvm_gc_max_data_size_bytes Max size of old generation memory pool
1. TYPE jvm_gc_max_data_size_bytes gauge
jvm_gc_max_data_size_bytes{application="initializr-stats-generator",} 2.863661056E9
1. HELP process_cpu_usage The "recent cpu usage" for the Java Virtual Machine process
1. TYPE process_cpu_usage gauge
process_cpu_usage{application="initializr-stats-generator",} 0.0
1. HELP jvm_buffer_count An estimate of the number of buffers in the pool
1. 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
1. HELP tomcat_cache_hit_total
1. TYPE tomcat_cache_hit_total counter
tomcat_cache_hit_total{application="initializr-stats-generator",} 0.0
1. 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
1. TYPE jvm_gc_memory_allocated_bytes_total counter
jvm_gc_memory_allocated_bytes_total{application="initializr-stats-generator",} 1.762172E8
1. HELP tomcat_global_request_max_seconds
1. TYPE tomcat_global_request_max_seconds gauge
tomcat_global_request_max_seconds{application="initializr-stats-generator",name="http-nio-8081",} 0.0
1. HELP tomcat_sessions_active_max
1. TYPE tomcat_sessions_active_max gauge
tomcat_sessions_active_max{application="initializr-stats-generator",} 0.0
1. HELP tomcat_sessions_alive_max_seconds
1. TYPE tomcat_sessions_alive_max_seconds gauge
tomcat_sessions_alive_max_seconds{application="initializr-stats-generator",} 0.0
1. HELP tomcat_sessions_active_current
1. TYPE tomcat_sessions_active_current gauge
tomcat_sessions_active_current{application="initializr-stats-generator",} 0.0
1. 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
1. TYPE jvm_gc_memory_promoted_bytes_total counter
jvm_gc_memory_promoted_bytes_total{application="initializr-stats-generator",} 1.7393152E7
1. HELP jvm_memory_used_bytes The amount of used memory
1. 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
1. HELP tomcat_threads_config_max
1. TYPE tomcat_threads_config_max gauge
tomcat_threads_config_max{application="initializr-stats-generator",name="http-nio-8081",} 200.0
1. HELP jvm_threads_daemon The current number of live daemon threads
1. TYPE jvm_threads_daemon gauge
jvm_threads_daemon{application="initializr-stats-generator",} 32.0
1. HELP jvm_classes_unloaded_total The total number of classes unloaded since the Java virtual machine has started execution
1. TYPE jvm_classes_unloaded_total counter
jvm_classes_unloaded_total{application="initializr-stats-generator",} 0.0
1. HELP tomcat_global_received_bytes_total
1. TYPE tomcat_global_received_bytes_total counter
tomcat_global_received_bytes_total{application="initializr-stats-generator",name="http-nio-8081",} 0.0
1. HELP tomcat_servlet_error_total
1. TYPE tomcat_servlet_error_total counter
tomcat_servlet_error_total{application="initializr-stats-generator",name="default",} 0.0
1. 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
1. TYPE system_load_average_1m gauge
system_load_average_1m{application="initializr-stats-generator",} 2.48779296875
"]
I think it would be useful to truncate the response body at debug level and log the full body at trace level. While I haven't seen an example of it, if similar logging is performed for request bodies, I wonder if it may make sense to make a similar improvement on that side of the exchange as well.
Affects: 5.1 RC2
Reference URL: spring-projects/spring-boot#14292