How to log properly http requests with Spring MVC

Question

Hello I've been trying to figure out generic way to log http requests in my application, so far no luck, here is how I handle the logging right now i.e:

@RequestMapping(value="register", method = RequestMethod.POST)
    @ResponseBody
    public String register(@RequestParam(value="param1",required=false) String param1, @RequestParam("param2") String param2, @RequestParam("param3") String param3, HttpServletRequest request){
        long start = System.currentTimeMillis();
        logger.info("!--REQUEST START--!");

        logger.info("Request URL: " + request.getRequestURL().toString());

        List<String> requestParameterNames = Collections.list((Enumeration<String>)request.getParameterNames());
        logger.info("Parameter number: " + requestParameterNames.size()); 

 for (String parameterName : requestParameterNames){
           logger.info("Parameter name: " + parameterName + " - Parameter value: " + request.getParameter(parameterName));
        }
                  //Some processing logic, call to the various services/methods with different parameters, response is always String(Json)
        String response = service.callSomeServiceMethods(param1,param2,param3);

logger.info("Response is: " + response);

        long end = System.currentTimeMillis();
        logger.info("Requested completed in: " + (end-start) + "ms");
        logger.info("!--REQUEST END--!");   

        return response;
    }

So what I do right now for different controllers/methods is copy everything from beginning of the inside of the method until the processing logic which differs from method to method and then copy everything from below of that as showed in above template.

It is kind of messy, and there is a lot of code repetition(which I don't like). But I need to log everything.

Does anyone have more experience with this kinds of logging, can anyone shed some light on this?

Realize

Use an aspect. See my answer @ #6682588 – Stryker

Answer 1

Use an interceptor:

• extend HandlerInterceptorAdapter and override preHandle
• define it with <mvc:interceptors> in dispatcher-servlet.xml

It will run for every request.

Earnest

See also #5656624 – Fajardo

Answer 2

EDIT: Also, see @membersound's comment on this answer, which improves this answer.

Spring supports this. See CommonsRequestLoggingFilter. If using Spring Boot, just register a bean of that type and Boot will apply it to the filter chain. Like:

@Bean
public Filter logFilter() {
    CommonsRequestLoggingFilter filter = new CommonsRequestLoggingFilter();
    filter.setIncludeQueryString(true);
    filter.setIncludePayload(true);
    filter.setMaxPayloadLength(5120);
    return filter;
}

Also, this logging filter requires the log level be set to DEBUG. E.g. do this in a logback.xml with:

<logger name="org.springframework.web.filter.CommonsRequestLoggingFilter" level="DEBUG"/>

Mono

As well you could just override: 'CommonsRequestLoggingFilter filter = new CommonsRequestLoggingFilter() { protected boolean shouldLog(javax.servlet.http.HttpServletRequest request) {return true;}; }; – Tax

@Tax it is not enough to overwrite the shouldLog() method to always return true, because CommonsRequestLoggingFilter uses logger.debug to display messages. In case the log level is not set to debug messages won't appear. – Entozoon

@PeterSzanto Yes of course. It was just a suggestion/alternative to setting the maxPayload to an explicit value. – Tax

What if I am using java logging and not logback? How can I direct this output to my logger? – Mendoza

Answer 3

The main issue with reading request is that as soon as the input stream is consumed its gone whoof... and cannot be read again. So the input stream has to be cached. Instead of writing your own classes for caching (which can be found at several places on web), Spring provides a couple of useful classes i.e. ContentCachingRequestWrapper and ContentCachingResponseWrapper. These classes can be utilized very effectively, for example, in filters for logging purposes.

Define a filter in web.xml:

<filter>
    <filter-name>loggingFilter</filter-name>
    <filter-class>org.springframework.web.filter.DelegatingFilterProxy</filter-class>
</filter>
<filter-mapping>
    <filter-name>loggingFilter</filter-name>
    <url-pattern>/*</url-pattern>
</filter-mapping>

Since the filter is declared as DelegatingFilterProxy, it can be declared as a bean using @Component or @Bean annotations. In the loggingFilter's doFilter method, wrap the request and response with spring provided classes before passing it to the filter chain:

HttpServletRequest requestToCache = new ContentCachingRequestWrapper(request);
HttpServletResponse responseToCache = new ContentCachingResponseWrapper(response);
chain.doFilter(requestToCache, responseToCache);
String requestData = getRequestData(requestToCache);
String responseData = getResponseData(responseToCache);

The input stream will be cached in the wrapped request as soon as the input stream is consumed after chain.doFilter(). Then it can be accessed as below:

public static String getRequestData(final HttpServletRequest request) throws UnsupportedEncodingException {
    String payload = null;
    ContentCachingRequestWrapper wrapper = WebUtils.getNativeRequest(request, ContentCachingRequestWrapper.class);
    if (wrapper != null) {
        byte[] buf = wrapper.getContentAsByteArray();
        if (buf.length > 0) {
            payload = new String(buf, 0, buf.length, wrapper.getCharacterEncoding());
        }
    }
    return payload;
}

However, things are a bit different for response. Since the response was also wrapped before passing it to the filter chain, it will also be cached to the output stream as soon as it is written on its way back. But since the output stream will also be consumed so you have to copy the response back to the output stream using wrapper.copyBodyToResponse(). See below:

public static String getResponseData(final HttpServletResponse response) throws IOException {
    String payload = null;
    ContentCachingResponseWrapper wrapper =
        WebUtils.getNativeResponse(response, ContentCachingResponseWrapper.class);
    if (wrapper != null) {
        byte[] buf = wrapper.getContentAsByteArray();
        if (buf.length > 0) {
            payload = new String(buf, 0, buf.length, wrapper.getCharacterEncoding());
            wrapper.copyBodyToResponse();
        }
    }
    return payload;
}

Hope it helps!

Saltsman

It's really helpful - but in this way, printing of the request will happen after the dofilter is done - is it a way to print the request data first, and then dofilter, and then print the response data? – Selfrespect

Yes, it is possible to read the request data before doFilter but then the consumed input stream cannot be read again in any of the subsequent filters or controller (Unless read from the cached input stream) – Saltsman

I am trying to use ContentCachingRequestWrapper but when trying to read a string from its getInputStream() I always get an empty string. I don't understand the implementation of its inner class ContentCachingInputStream? – Revenant

Looks like the input stream is already consumed before you are reading it. If it is consumed then it will be cached in cachedContent field of ContentCachingRequestWrapper. You can check this by calling getContentAsByteArray(). You can also check the source at grepcode.com/file/repo1.maven.org/maven2/org.springframework/… – Saltsman

B.Ali - Thank you for the answer. Can you please tell me how do you hook the custom filter to spring. I mean which configuration file should have it ? – Lighterage

just create a bean of loggingFilter in any of your application's configuration files loaded by spring. Be it xml or a java class annotated with @Configuration – Saltsman

Answer 4

Here's a small library I wrote you can use: spring-mvc-logger

I made it available via maven central:

<dependency>
    <groupId>com.github.isrsal</groupId>
    <artifactId>spring-mvc-logger</artifactId>
    <version>0.2</version>
</dependency>

Morganstein

I'm using it now, nice little utility, thanks Israel! – Valdovinos

What about async responses (servlet 3)? It seems it won't work. – Fritzie

Answer 5

Adding to what @B.Ali has answered. If you are using this in a spring asynchronous request (serlvet 3.0 or greater) handling scenario, then the following code is what worked for me.

public class OncePerRequestLoggingFilter extends OncePerRequestFilter {

@Override
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
    boolean isFirstRequest = !isAsyncDispatch(request);
    HttpServletRequest requestToUse = request;
    HttpServletResponse responseToUse = response;

    // The below check is critical and if not there, then the request/response gets corrupted.
    // Probably because in async case the filter is invoked multiple times.
    if (isFirstRequest && !(request instanceof ContentCachingRequestWrapper)) {
        requestToUse = new ContentCachingRequestWrapper(request);
    }

    if (isFirstRequest && !(response instanceof ContentCachingResponseWrapper)) {
        responseToUse = new ContentCachingResponseWrapper(response);
    }

    filterChain.doFilter(requestToUse, responseToUse);

    if (!isAsyncStarted(request)) {
        ContentCachingResponseWrapper responseWrapper =
                WebUtils.getNativeResponse(response, ContentCachingResponseWrapper.class);
        responseWrapper.copyBodyToResponse(); // IMPORTANT to copy it back to response
    }
}

@Override
protected boolean shouldNotFilterAsyncDispatch() {
    return false; // IMPORTANT this is true by default and wont work in async scenario.
}

}

Augustineaugustinian

Answer 6

As any tech answer ... it depends .. on the tech stack you are using and what your requirements are.

for example the more generic you want to make your logging, the further upfront you would want to do it. in your case, you are logging only requests which are logging enabled and being handled in the spring context. So you could be "missing" other requests.

I would look at the container or the web server you are using to run your app. That will remove this dependency on Spring. Plus containers provide you the flexibility of plugging in a logging provider and then configuring the format of the log outside code. For example, if you are using Apache Web server, use Apache web server logging to log all HTTP requests in the access logging layer. But be careful, some of the logging options have performance penalties. Log only what you seriously need for an access pattern monitoring perspective.

If you are using tomcat, then tomcat also will allow you to log stuff. Search for Access Valve in the tomcat documentation for the tomcat you are using. That will open up a world of possibilities.

More extensive logging should be the domain of the exception strategy ie the kind of detail you want to see when a problem occurs in the system.

Mclemore