Write Spring MVC Logger for log request and response

Hello! In this article, I will explain how to write a logger for logging requests and responses. It would seem that there is nothing complicated about this, but if you look at the documentation, you can see the following

Which tells us that we can read data only once and by calling either the getReader method or the getInputStream method. In order to get around this limitation, two special classes were invented ContentCachingRequetWrapper.java and ContentCachingResponseWrapper.java, which are just needed so that we can log the request data. In order to polish the data about requests and responses, we will implement a filter that will extend the OncePerRequestFilter.java class Let's call this our movie LoggingFilter and start writing it. First, let's declare an instance of our logger

private static final Logger logger = LoggerFactory.getLogger(LoggingFilter.class);

Next, we declare all the MIME types that we want to log

private static final List<MediaType> VISIBLE_TYPES = Arrays.asList(
      MediaType.valueOf("text/*"),
      MediaType.APPLICATION_FORM_URLENCODED,
      MediaType.APPLICATION_JSON,
      MediaType.APPLICATION_XML,
      MediaType.valueOf("application/*+json"),
      MediaType.valueOf("application/*+xml"),
      MediaType.MULTIPART_FORM_DATA
);

Then we override the methods from the parent class

@Override
protected void doFilterInternal(HttpServletRequest httpServletRequest,
                                HttpServletResponse httpServletResponse,
                                FilterChain filterChain) 
                                throws ServletException, IOException {
  if (isAsyncDispatch(httpServletRequest)) {
      filterChain.doFilter(httpServletRequest, httpServletResponse);
  } else {
     doFilterWrapped(wrapRequest(httpServletRequest),
                     wrapResponse(httpServletResponse,
                     filterChain);
 }

In this case, we check whether the call is asynchronous, and in this case we do not try to polish it, if the call is synchronous, then we try to wrap the logging Implementing the doFilterWrapped method

protected void doFilterWrapped(ContentCachingRequestWrapper contentCachingRequestWrapper, ContentCachingResponseWrapper contentCachingResponseWrapper, FilterChain filterChain) throws IOException, ServletException {
        try {
            beforeRequest(contentCachingRequestWrapper);
            filterChain.doFilter(contentCachingRequestWrapper, contentCachingResponseWrapper);
        } finally {
            afterRequest(contentCachingRequestWrapper, contentCachingResponseWrapper);
            contentCachingResponseWrapper.copyBodyToResponse();
        }
    }

In this method, we already receive a cached request and response and perform processing and post-processing of the request, and also copy the response data Let's write the request processing code

protected void beforeRequest(ContentCachingRequestWrapper request) {
    if (logger.isInfoEnabled()) {
        logRequestHeader(request, request.getRemoteAddr() + "|>");
    }
}

We check the logging level and if it is equal to the INFO level, then we also log the request headers

Let's write a post-processing method

protected void afterRequest(ContentCachingRequestWrapper request, ContentCachingResponseWrapper response) {
        if (logger.isInfoEnabled()) {
            logRequestBody(request, request.getRemoteAddr() + "|>");
            logResponse(response, request.getRemoteAddr() + "|>");
        }
    }

In this case, we also check that the logging level is set to INFO before polishing the request and response. And finally, the most interesting thing, we write logging of headers, as well as requests and responses

private static void logRequestHeader(ContentCachingRequestWrapper request, String prefix) {
        String queryString = request.getQueryString();
        if (queryString == null) {
            logger.info("{} {} {}", prefix, request.getMethod(), request.getRequestURI());
        } else {
            logger.info("{} {} {}?{}", prefix, request.getMethod(), request.getRequestURI(), queryString);
        }
        Collections.list(request.getHeaderNames()).forEach(headerName ->
                Collections.list(request.getHeaders(headerName)).forEach(headerValue -> logger.info("{} {} {}", prefix, headerName, headerValue)));
        logger.info("{}", prefix);
    }

In the logRequestHeader method, the following happens - from the request we get a string, check whether it is null and if null, then we code the HTTP method and the URL to which such a request came, otherwise the HTTP method is also logged, the URL to which the request came, and also all request headers Next, we need to write the code to log the request body

private static void logRequestBody(ContentCachingRequestWrapper request, String prefix) {
    byte[] content = request.getContentAsByteArray();
    if (content.length > 0) {
        logContent(content, request.getContentType(), request.getCharacterEncoding(), prefix);
    }
}

We receive data from the request as an array of bytes, and in the event that the size of the array is greater than zero, we pass the data to the logContent method, which we will write a little later.

Now is the time to write the code for logging responses from the application.

private static void logResponse(ContentCachingResponseWrapper response, String prefix) {
    int status = response.getStatus();
    logger.info("{} {} {}", prefix, status, HttpStatus.valueOf(status).getReasonPhrase());
    response.getHeaderNames().forEach(header -> response.getHeaders(header).forEach(headerValue -> logger.info("{} {} {}", prefix, header, headerValue)));
    logger.info("{}", prefix);
    byte[] content = response.getContentAsByteArray();
    if (content.length > 0) {
        logContent(content, response.getContentType(), response.getCharacterEncoding(), prefix);
    }
}

Let's figure out what exactly is happening here - with the first line we get the HTTP response code of our application and then log data about it. Next, we go through the response headers and log them in the same way. Further, the logic is quite similar to what we have seen before - we receive data from the response as an array of bytes and then pass it to the logContent method, which will look like this:

private static void logContent(byte[] content, String contentType, String contentEncoding, String prefix) {
        MediaType mediaType = MediaType.valueOf(contentType);
        boolean visible = VISIBLE_TYPES.stream().anyMatch(visibleType -> visibleType.includes(mediaType));
        if (visible) {
            try {
                String contentString = new String(content, contentEncoding);
                Stream.of(contentString.split("\r\n|\r\n")).forEach(line -> logger.info("{} {}", prefix, line));
            } catch (UnsupportedEncodingException e) {
                logger.info("{}, [{} bytes content]", prefix, content.length);
            }
        } else {
            logger.info("{}, [{} bytes content]", prefix, content.length);
        }
    }

What's going on here? First, we check if the type of the transmitted data is supported for doping, if not, then we simply display the size of the data array. If yes, then we get create a line from the data with the specified encoding in the request, and separate each line using carriage return and newline characters. If the encoding is not supported, then, as in the case of an unsupported data type, we simply log the size of the data that we received in the request or response

And the final touch in our code is the two methods that are actually needed to wrap our HttpServletRequest and HttpServletResponse in ContentCachingRequestWrapper and ContentCachingResponseWrapper

private static ContentCachingRequestWrapper wrapRequest(HttpServletRequest httpServletRequest) {
        if (httpServletRequest instanceof ContentCachingRequestWrapper) {
            return (ContentCachingRequestWrapper) httpServletRequest;
        } else {
            return new ContentCachingRequestWrapper(httpServletRequest);
        }
    }

    private static ContentCachingResponseWrapper wrapResponse(HttpServletResponse httpServletResponse) {
        if (httpServletResponse instanceof ContentCachingResponseWrapper) {
            return (ContentCachingResponseWrapper) httpServletResponse;
        } else {
            return new ContentCachingResponseWrapper(httpServletResponse);
        }
    }

Next, you need to register our filter in the deployment descriptor

<filter>
    <filter-name>Filter</filter-name>
    <filter-class>ru.skillfactory.filter.LoggingFilter</filter-class>
</filter>

<filter-mapping>
    <filter-name>Filter</filter-name>
    <url-pattern>*</url-pattern>
</filter-mapping>

Finally, make sure our filter is working properly

2021-01-18 12:25:24 DEBUG RequestResponseBodyMethodProcessor:91 - Read "application/json;charset=ISO-8859-1" to [StudentData(firstName=John, lastName=Doe, grade=5)]
2021-01-18 12:25:24 DEBUG RequestResponseBodyMethodProcessor:265 - Using 'text/plain', given [*/*] and supported [text/plain, */*, application/json, application/*+json]
2021-01-18 12:25:24 DEBUG RequestResponseBodyMethodProcessor:91 - Writing ["You are great with your grade 5"]
2021-01-18 12:25:24 DEBUG DispatcherServlet:1131 - Completed 200 OK
2021-01-18 12:25:24 INFO  LoggingFilter:104 - 0:0:0:0:0:0:0:1|> {
    "firstName": "John",
    "lastName": "Doe",
    "grade": 5
}
2021-01-18 12:25:24 INFO  LoggingFilter:89 - 0:0:0:0:0:0:0:1|> 200 OK
2021-01-18 12:25:24 INFO  LoggingFilter:91 - 0:0:0:0:0:0:0:1|>
2021-01-18 12:25:24 INFO  LoggingFilter:104 - 0:0:0:0:0:0:0:1|> You are great with your grade 5

Full code of LoggingFilter.java

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.http.HttpStatus;
import org.springframework.http.MediaType;
import org.springframework.web.filter.OncePerRequestFilter;
import org.springframework.web.util.ContentCachingRequestWrapper;
import org.springframework.web.util.ContentCachingResponseWrapper;

import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.io.UnsupportedEncodingException;
import java.util.Arrays;
import java.util.Collections;
import java.util.List;
import java.util.stream.Stream;

public class LoggingFilter extends OncePerRequestFilter {

    private static final Logger logger = LoggerFactory.getLogger(LoggingFilter.class);
    private static final List<MediaType> VISIBLE_TYPES = Arrays.asList(
            MediaType.valueOf("text/*"),
            MediaType.APPLICATION_FORM_URLENCODED,
            MediaType.APPLICATION_JSON,
            MediaType.APPLICATION_XML,
            MediaType.valueOf("application/*+json"),
            MediaType.valueOf("application/*+xml"),
            MediaType.MULTIPART_FORM_DATA
    );

    @Override
    protected void doFilterInternal(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse, FilterChain filterChain) throws ServletException, IOException {
        if (isAsyncDispatch(httpServletRequest)) {
            filterChain.doFilter(httpServletRequest, httpServletResponse);
        } else {
            doFilterWrapped(wrapRequest(httpServletRequest), wrapResponse(httpServletResponse), filterChain);
        }
    }

    protected void doFilterWrapped(ContentCachingRequestWrapper contentCachingRequestWrapper, ContentCachingResponseWrapper contentCachingResponseWrapper, FilterChain filterChain) throws IOException, ServletException {
        try {
            beforeRequest(contentCachingRequestWrapper);
            filterChain.doFilter(contentCachingRequestWrapper, contentCachingResponseWrapper);
        } finally {
            afterRequest(contentCachingRequestWrapper, contentCachingResponseWrapper);
            contentCachingResponseWrapper.copyBodyToResponse();
        }
    }

    protected void beforeRequest(ContentCachingRequestWrapper request) {
        if (logger.isInfoEnabled()) {
            logRequestHeader(request, request.getRemoteAddr() + "|>");
        }
    }

    protected void afterRequest(ContentCachingRequestWrapper request, ContentCachingResponseWrapper response) {
        if (logger.isInfoEnabled()) {
            logRequestBody(request, request.getRemoteAddr() + "|>");
            logResponse(response, request.getRemoteAddr() + "|>");
        }
    }

    private static void logRequestHeader(ContentCachingRequestWrapper request, String prefix) {
        String queryString = request.getQueryString();
        if (queryString == null) {
            logger.info("{} {} {}", prefix, request.getMethod(), request.getRequestURI());
        } else {
            logger.info("{} {} {}?{}", prefix, request.getMethod(), request.getRequestURI(), queryString);
        }
        Collections.list(request.getHeaderNames()).forEach(headerName ->
                Collections.list(request.getHeaders(headerName)).forEach(headerValue -> logger.info("{} {} {}", prefix, headerName, headerValue)));
        logger.info("{}", prefix);
    }

    private static void logRequestBody(ContentCachingRequestWrapper request, String prefix) {
        byte[] content = request.getContentAsByteArray();
        if (content.length > 0) {
            logContent(content, request.getContentType(), request.getCharacterEncoding(), prefix);
        }
    }

    private static void logResponse(ContentCachingResponseWrapper response, String prefix) {
        int status = response.getStatus();
        logger.info("{} {} {}", prefix, status, HttpStatus.valueOf(status).getReasonPhrase());
        response.getHeaderNames().forEach(header -> response.getHeaders(header).forEach(headerValue -> logger.info("{} {} {}", prefix, header, headerValue)));
        logger.info("{}", prefix);
        byte[] content = response.getContentAsByteArray();
        if (content.length > 0) {
            logContent(content, response.getContentType(), response.getCharacterEncoding(), prefix);
        }
    }

    private static void logContent(byte[] content, String contentType, String contentEncoding, String prefix) {
        MediaType mediaType = MediaType.valueOf(contentType);
        boolean visible = VISIBLE_TYPES.stream().anyMatch(visibleType -> visibleType.includes(mediaType));
        if (visible) {
            try {
                String contentString = new String(content, contentEncoding);
                Stream.of(contentString.split("\r\n|\r\n")).forEach(line -> logger.info("{} {}", prefix, line));
            } catch (UnsupportedEncodingException e) {
                logger.info("{}, [{} bytes content]", prefix, content.length);
            }
        } else {
            logger.info("{}, [{} bytes content]", prefix, content.length);
        }
    }

    private static ContentCachingRequestWrapper wrapRequest(HttpServletRequest httpServletRequest) {
        if (httpServletRequest instanceof ContentCachingRequestWrapper) {
            return (ContentCachingRequestWrapper) httpServletRequest;
        } else {
            return new ContentCachingRequestWrapper(httpServletRequest);
        }
    }

    private static ContentCachingResponseWrapper wrapResponse(HttpServletResponse httpServletResponse) {
        if (httpServletResponse instanceof ContentCachingResponseWrapper) {
            return (ContentCachingResponseWrapper) httpServletResponse;
        } else {
            return new ContentCachingResponseWrapper(httpServletResponse);
        }
    }
}

If you liked the article, then subscribe and share with your friends!
Thanks for attention