Improve logging for development (DEBUG vs TRACE) [SPR-16946]

[spring-projects-issues]

Rossen Stoyanchev opened SPR-16946 and commented

This started in Spring Boot #902, then #21437, and I'm opening this general ticket to revisit logging for development purposes more broadly, at the container level and any other module.

The general idea is that logging at DEBUG level should be user-friendly and carefully calibrated to be minimal, yet helpful by including the most relevant bits of information that are useful over and over again (vs debugging a specific issue). That means being relatively Spartan at DEBUG level, and showing more at TRACE as two tiers of debugging information.

Often it is difficult to know in isolation if a piece of information is useful, if it is duplicated, if it adds too much noise, or if it reads well. It's only possible to spot the issues and decide what looks best by viewing the overall logging.

I'll append some specific examples of core logging related to web startup, but a general review would probably be needed.

---

Affects: 5.0.7

Sub-tasks:

• Fine-tune logging for web requests [SPR-16898] #21437 Fine-tune logging for web requests
• Create wiki page on debug/trace logging [SPR-16954] #21492 Create wiki page on debug/trace logging
• Add correlation id to log messages in WebFlux [SPR-16966] #21504 Add correlation id to log messages in WebFlux
• Single category for all WebFlux logging [SPR-17012] #21550 Single category for all WebFlux logging
• Provide control over logging of potentially sensitive request details [SPR-17029] #21567 Provide control over logging of potentially sensitive request details
• Add sections on logging in WebFlux and Spring MVC docs [SPR-17032] #21570 Add sections on logging in WebFlux and Spring MVC docs

Issue Links:

• Change logging level to info in PropertiesLoaderSupport when logging message that resource is not found and ignoreResourceNotFound is true [SPR-7772] #12428 Change logging level to info in PropertiesLoaderSupport when logging message that resource is not found and ignoreResourceNotFound is true ("is duplicated by")
• Fine-tune logging for web requests [SPR-16898] #21437 Fine-tune logging for web requests
• Improve/unify debug logging at BeanDefinitionReader and BeanFactory level [SPR-17090] #21627 Improve/unify debug logging at BeanDefinitionReader and BeanFactory level

[spring-projects-issues]

Rossen Stoyanchev commented

1. The following appears twice on startup for the root and the DispatcherServlet context:

16:32:33.502 [main] INFO ContextLoader - Root WebApplicationContext: initialization started
16:32:33.519 [main] DEBUG StandardServletEnvironment - Adding PropertySource 'servletConfigInitParams' with lowest search precedence
16:32:33.519 [main] DEBUG StandardServletEnvironment - Adding PropertySource 'servletContextInitParams' with lowest search precedence
16:32:33.523 [main] DEBUG StandardServletEnvironment - Adding PropertySource 'jndiProperties' with lowest search precedence
16:32:33.523 [main] DEBUG StandardServletEnvironment - Adding PropertySource 'systemProperties' with lowest search precedence
16:32:33.524 [main] DEBUG StandardServletEnvironment - Adding PropertySource 'systemEnvironment' with lowest search precedence
16:32:33.524 [main] DEBUG StandardServletEnvironment - Initialized StandardServletEnvironment with PropertySources [StubPropertySource {name='servletConfigInitParams'}, StubPropertySource {name='servletContextInitParams'}, JndiPropertySource {name='jndiProperties'}, MapPropertySource {name='systemProperties'}, SystemEnvironmentPropertySource {name='systemEnvironment'}]
16:32:33.527 [main] DEBUG StandardServletEnvironment - Replacing PropertySource 'servletContextInitParams' with 'servletContextInitParams'

For starters it's too much noise to see all the time, even at TRACE level, with duplication and low value. The question is what should Environment present at DEBUG level? Active profiles perhaps, it's rather minimal too. The list of sources by itself seems less useful, for the extra noise it adds, unless it shows more about the properties in each source – count of props, names only, names and values, or perhaps each source decides how to present itself.

2. Root context related

16:32:33.531 [main] INFO AnnotationConfigWebApplicationContext - Refreshing Root WebApplicationContext: startup date [Fri Jun 15 16:32:33 EDT 2018]; root of context hierarchy
16:32:33.609 [main] INFO AnnotationConfigWebApplicationContext - Registering annotated classes: [class org.springframework.samples.mvc.config.RootConfig]
16:32:33.652 [main] DEBUG AnnotationConfigWebApplicationContext - Bean factory for Root WebApplicationContext: org.springframework.beans.factory.support.DefaultListableBeanFactory@1084ac45: defining beans [org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.context.event.internalEventListenerProcessor,org.springframework.context.event.internalEventListenerFactory,rootConfig]; root of factory hierarchy
16:32:33.909 [main] INFO AutowiredAnnotationBeanPostProcessor - JSR-330 'javax.inject.Inject' annotation found and supported for autowiring
16:32:33.967 [main] DEBUG AnnotationConfigWebApplicationContext - Unable to locate MessageSource with name 'messageSource': using default [org.springframework.context.support.DelegatingMessageSource@61191222]
16:32:33.969 [main] DEBUG AnnotationConfigWebApplicationContext - Unable to locate ApplicationEventMulticaster with name 'applicationEventMulticaster': using default [org.springframework.context.event.SimpleApplicationEventMulticaster@77724cbe]
16:32:34.105 [main] DEBUG AnnotationConfigWebApplicationContext - Unable to locate LifecycleProcessor with name 'lifecycleProcessor': using default [org.springframework.context.support.DefaultLifecycleProcessor@481b2f10]
16:32:34.120 [main] DEBUG ContextLoader - Published root WebApplicationContext as ServletContext attribute with name [org.springframework.web.context.WebApplicationContext.ROOT]
16:32:34.121 [main] INFO ContextLoader - Root WebApplicationContext: initialization completed in 612 ms

What should appear at DEBUG on every startup? I'd hand pick the Root context being based on which config classes, and maybe how long initialization took. The "Unable to locate..." or even the "JSR-330" don't make the cut IMO. They stop being useful once issues related to that are resolved, and become noise to be ignored. The setting of the request attribute is more useful for discovery but seen repeatedly, it becomes something to tune out.

3. DispatcherServlet context (similar points):

16:32:34.184 [main] INFO  AnnotationConfigWebApplicationContext - Refreshing WebApplicationContext for namespace 'dispatcher-servlet': startup date [Fri Jun 15 16:32:34 EDT 2018]; parent: Root WebApplicationContext
16:32:34.185 [main] INFO  AnnotationConfigWebApplicationContext - Registering annotated classes: [class org.springframework.samples.mvc.config.WebMvcConfig]
16:32:34.209 [main] DEBUG AnnotationConfigWebApplicationContext - Bean factory for WebApplicationContext for namespace 'dispatcher-servlet': org.springframework.beans.factory.support.DefaultListableBeanFactory@76437e9b: defining beans [org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,org.springframework.context.event.internalEventListenerProcessor,org.springframework.context.event.internalEventListenerFactory,webMvcConfig]; parent: org.springframework.beans.factory.support.DefaultListableBeanFactory@1084ac45
16:32:34.584 [main] INFO  AutowiredAnnotationBeanPostProcessor - JSR-330 'javax.inject.Inject' annotation found and supported for autowiring
16:32:34.626 [main] DEBUG AnnotationConfigWebApplicationContext - Unable to locate MessageSource with name 'messageSource': using default [org.springframework.context.support.DelegatingMessageSource@361cd35c]
16:32:34.626 [main] DEBUG AnnotationConfigWebApplicationContext - Unable to locate ApplicationEventMulticaster with name 'applicationEventMulticaster': using default [org.springframework.context.event.SimpleApplicationEventMulticaster@58a765ce]
16:32:35.282 [main] DEBUG RequestMappingHandlerMapping - Looking for request mappings in application context: WebApplicationContext for namespace 'dispatcher-servlet': startup date [Fri Jun 15 16:32:34 EDT 2018]; parent: Root WebApplicationContext

[spring-projects-issues]

Rossen Stoyanchev commented

Link to Boot ticket #13511 to follow up on the changes at the Spring Framework level here. In the very least, for example, DEBUG level for org.springframework.web with devtools.

[spring-projects-issues]

Rossen Stoyanchev commented

4. Data binding and validation org.springfamework.validation.

07:41:22.915 [qtp2022012779-19] DEBUG DefaultHandlerExceptionResolver - Resolved org.springframework.web.bind.MethodArgumentNotValidException: Validation failed for argument [0] in public java.lang.String org.springframework.samples.mvc.messageconverters.MessageConvertersController.readJson(org.springframework.samples.mvc.messageconverters.JavaBean): [Field error in object 'javaBean' on field 'fruit': rejected value [null]; codes [NotNull.javaBean.fruit,NotNull.fruit,NotNull.java.lang.String,NotNull]; arguments [org.springframework.context.support.DefaultMessageSourceResolvable: codes [javaBean.fruit,fruit]; arguments []; default message [fruit]]; default message [must not be null]

The above is on a @Valid @RequestBody method arg. Some of it comes from FieldError#toString and some from DefaultMessageSourceCode#resolvableToString. The output could be presented more compactly (e.g. "Error on field 'fruit' in object 'javaBean': ..."). The information from DefaultMessageSourceCode is too detail for DEBUG to see all the time, and perhaps not even relevant in this case. However currently there is no way to obtain a different level of detail.

[spring-projects-issues]

Rossen Stoyanchev commented

5. Publication of events at end of a request.

18:20:03.129 [qtp1577353545-19] TRACE AnnotationConfigWebApplicationContext - Publishing event in WebApplicationContext for namespace 'dispatcher-servlet': ServletRequestHandledEvent: url=[/spring-mvc-showcase/]; client=[0:0:0:0:0:0:0:1]; method=[GET]; servlet=[dispatcher]; session=[node0y67yl52ha562r33s2qely7th0]; user=[null]; time=[2549ms]; status=[OK]
18:20:03.130 [qtp1577353545-19] TRACE AnnotationConfigWebApplicationContext - Publishing event in Root WebApplicationContext: ServletRequestHandledEvent: url=[/spring-mvc-showcase/]; client=[0:0:0:0:0:0:0:1]; method=[GET]; servlet=[dispatcher]; session=[node0y67yl52ha562r33s2qely7th0]; user=[null]; time=[2549ms]; status=[OK]

Anyone interested in those events can subscribe to receive them and log them if necessary. Even at TRACE this does not log anything useful, and it literally overtakes per request logging now after the changes.

[spring-projects-issues]

Adam Berlin commented

I love the idea of using devtools to trigger this behavior. It seems like many Spring libraries could take advantage of this idea. For example, Spring Data JPA could enable query logging by default in development with timing information. Rest Template could log requests and timing.

[spring-projects-issues]

Rossen Stoyanchev commented

I love the idea of using devtools to trigger this behavior

I've added a comment about that under the Boot follow-up ticket since that's where the change will have to be made. I've also created a wiki page, see #21492, to capture what we're doing. Once we're done here, we'll with other Spring projects for consideration to make similar changes.

[spring-projects-issues]

Juergen Hoeller commented

I'm done with a full first pass, revising our core use of log levels towards less WARN and INFO as as well as fine-tuning DEBUG vs TRACE. For an indicator, we got roughly the same number of error, warn and info log statements in the codebase now (~150 each), next to a huge number of debug statements (~1000) and some trace (~400). I suppose that means moving further debug statements to trace, as well as fine-tuning the wording of some of the debug statements.

As per your points, Rossen, I've covered everything but no.4 (i.e. the MethodArgumentNotValidException message is still as extensive). Feel free to have a crack at that in the exception's getMessage() implementation.