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?

Answer 1

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>

Answer 2

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.

Answer 3

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"/>

Answer 4

Use an interceptor:

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

It will run for every request.

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.
}

}

Answer 6

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!