Log each web request: DEBUG = too much, INFO = too little

[berlin-ab]

Logging for web-mvc controller requests or static files should appears with the HTTP method and path. This will make debugging easier in production and development environments.

<logger name="org.springframework.web" level="INFO"/>

INFO = 3 log lines with no useful information
DEBUG = 30 log lines, with little useful information

Expectation:

[time] GET /foobar?some=params
[time] Handled by FoobarController => someMethod(...)

[dsyer]

Unfortunately all the logging is happening at a level below Spring Boot. Maybe we could collect some useful settings and curate them for you into a single Boot config flag. You could help by identifying the subset of real DEBUG log statements that you do find useful (ass opposed to the fantasy of what you might ideally like).

Or there's this really useful thing called "grep".

[berlin-ab]

First off, only the 1st request has ~20 lines. The 2nd request to an endpoint only has 8 lines.

current debug output

2014-05-20 09:28:27.058 DEBUG 10695 --- [nio-8080-exec-7] o.s.web.servlet.DispatcherServlet        : DispatcherServlet with name 'dispatcherServlet' processing GET request for [/example]
2014-05-20 09:28:27.058 DEBUG 10695 --- [nio-8080-exec-7] s.w.s.m.m.a.RequestMappingHandlerMapping : Looking up handler method for path /example
2014-05-20 09:28:27.059 DEBUG 10695 --- [nio-8080-exec-7] s.w.s.m.m.a.RequestMappingHandlerMapping : Returning handler method [public java.lang.Object project.app.ApplicationController.example()]
2014-05-20 09:28:27.059 DEBUG 10695 --- [nio-8080-exec-7] o.s.web.servlet.DispatcherServlet        : Last-Modified value for [/example] is: -1
2014-05-20 09:28:27.059 DEBUG 10695 --- [nio-8080-exec-7] o.s.w.s.v.ContentNegotiatingViewResolver : Requested media types are [text/html, application/xhtml+xml, image/webp, application/xml;q=0.9, */*;q=0.8] based on Accept header types and producible media types [*/*])
2014-05-20 09:28:27.060 DEBUG 10695 --- [nio-8080-exec-7] o.s.w.s.v.ContentNegotiatingViewResolver : Returning [org.springframework.boot.autoconfigure.groovy.template.web.GroovyTemplateView: unnamed; URL [null]] based on requested media type 'text/html'
2014-05-20 09:28:27.060 DEBUG 10695 --- [nio-8080-exec-7] o.s.web.servlet.DispatcherServlet        : Rendering view [org.springframework.boot.autoconfigure.groovy.template.web.GroovyTemplateView: unnamed; URL [null]] in DispatcherServlet with name 'dispatcherServlet'
2014-05-20 09:28:27.084 DEBUG 10695 --- [nio-8080-exec-7] o.s.web.servlet.DispatcherServlet        : Successfully completed request

There are useful bits on these lines, but there is also a lot of noise. It is hard to find the interesting bits.

As for grep, I'd rather the output be curated to show me the information that I'm interested in seeing. The debug output should be tailored to the experience of a developer working on an application, and not for internal framework debugging. For example: DispatcherServlet with name 'dispatcherServlet' processing GET request is not all that useful to a developer , but Returning handler method [public java.lang.Object project.app.ApplicationController.example()] is.

Contrast the above debug output with the output below. I think the Rails team has done a nice job of fitting a lot of data on as few of lines as possible in a very readable format.

Started GET "/?foo=bar&baz=bat" for 127.0.0.1 at 2014-05-20 09:44:50 -0400
Processing by StaticController#index as HTML
  Parameters: {"foo"=>"bar", "baz"=>"bat"}
  Rendered static/index.html.erb within layouts/application (0.2ms)
  Rendered shared/_messages.html.erb (0.1ms)
Completed 200 OK in 8ms (Views: 7.7ms | ActiveRecord: 0.0ms)

Also, I really miss the Parameters: {"foo"=>"bar", "baz"=>"bat"} when I'm reading through the org.springframework.web logs.

[dsyer]

So if you just switch off the DEBUG logging for the DispatcherServlet you have pretty much what you want? I'm not 100% convinced the Rails logger is telling me anything I really need to know for every request, though, and there are crucial other things missing (like security access decisions). This is beginning to feel like yet another issue that we need to solve in the code-generation/project setup phase, not at runtime or in the framework.

[berlin-ab]

@dsyer My example is a basic out-of-the-box experience. As for security access decisions and other important log items, I'll follow up with useful examples.

It might be worth removing DispatcherServlet lines. Like you said, maybe this is a code-generation, project template issue.

[snicoll]

If you want to improve the logging of DispatcherServlet, you should move this discussion over the Spring project.

[berlin-ab]

@philwebb I think this is a good candidate for spring-boot-devtools. I've found myself implementing a hack of AbstractRequestLoggingFilter for development debugging of requests/responses for each SB project I've been on. I don't really like the solution I come up with each time, and wish there were something better out of the box.

My use case is starting up the SB app, opening my front-end app (web or mobile), and seeing the request parameters/body in the log, and the response body with its status code. This helps me quickly debug that I'm sending the right params, and that Spring is parsing them correctly. The response output helps me to understand the actual output my client should expect. The response status code is important, but the response body is also very important.

Dev tools should be able to enable this by default, but remove it in production. Although, there is a case to be made that this would be valuable in an acceptance (pre-production) environment to help with debugging.

[snicoll]

How about sharing what you've done so far and we can see what we can do to integrate it? I am more in the camp of implementing a feature that can be controlled via properties and have Devtools switch that on for you. That's how we implemented the H2 console support and this proved to be quite effective.

Looking for your PR then!

[haydonryan]

we had a request from a customer who is passing GPS data into applications via the URL - if we could have a way to redact parts of those logs. Could be worth investigating a regex redactor?

[dsyer]

That sounds crazy to me (and not at all related to this issue, which is about dev time).

[wilkinsona]

Logback already has support for regex-based filtering of log events. Alternatively, if you really wanted to implement redaction you could use a custom layout. Neither belongs in Spring Boot, though.

[wilkinsona]

This doesn't seem to have really gone anywhere and we still believe that this would be better tackled outside of Spring Boot where it could benefit all Spring users.

[rstoyanchev]

This can only be addressed properly in the Spring Framework, so I've created SPR-16898.