Spring Web filter for logging request and response

RequestAndResponseLoggingFilter.java

/*
Copyright 2017 Hidetake Iwata

Licensed under the Apache License, Version 2.0 (the "License");
you may not use this file except in compliance with the License.
You may obtain a copy of the License at

    http://www.apache.org/licenses/LICENSE-2.0

Unless required by applicable law or agreed to in writing, software
distributed under the License is distributed on an "AS IS" BASIS,
WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
See the License for the specific language governing permissions and
limitations under the License.
*/

import lombok.extern.slf4j.Slf4j;
import lombok.val;
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;

/**
 * Spring Web filter for logging request and response.
 *
 * @author Hidetake Iwata
 * @see org.springframework.web.filter.AbstractRequestLoggingFilter
 * @see ContentCachingRequestWrapper
 * @see ContentCachingResponseWrapper
 */
@Slf4j
public class RequestAndResponseLoggingFilter extends OncePerRequestFilter {
    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 request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
        if (isAsyncDispatch(request)) {
            filterChain.doFilter(request, response);
        } else {
            doFilterWrapped(wrapRequest(request), wrapResponse(response), filterChain);
        }
    }

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

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

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

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

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

    private static void logResponse(ContentCachingResponseWrapper response, String prefix) {
        val status = response.getStatus();
        log.info("{} {} {}", prefix, status, HttpStatus.valueOf(status).getReasonPhrase());
        response.getHeaderNames().forEach(headerName ->
            response.getHeaders(headerName).forEach(headerValue ->
                log.info("{} {}: {}", prefix, headerName, headerValue)));
        log.info("{}", prefix);
        val 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) {
        val mediaType = MediaType.valueOf(contentType);
        val visible = VISIBLE_TYPES.stream().anyMatch(visibleType -> visibleType.includes(mediaType));
        if (visible) {
            try {
                val contentString = new String(content, contentEncoding);
                Stream.of(contentString.split("\r\n|\r|\n")).forEach(line -> log.info("{} {}", prefix, line));
            } catch (UnsupportedEncodingException e) {
                log.info("{} [{} bytes content]", prefix, content.length);
            }
        } else {
            log.info("{} [{} bytes content]", prefix, content.length);
        }
    }

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

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

spring.log

2017-11-03 13:33:18.777  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|> POST /users?v=1
2017-11-03 13:33:18.778  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|> User-Agent: curl/7.54.0
2017-11-03 13:33:18.778  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|> Host: localhost:8080
2017-11-03 13:33:18.778  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|> Accept: */*
2017-11-03 13:33:18.778  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|> Content-Length: 24
2017-11-03 13:33:18.778  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|> Content-Type: application/json
2017-11-03 13:33:18.778  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|>
2017-11-03 13:33:18.784  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|> {"id": 1, "name": "Foo"}
2017-11-03 13:33:18.784  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|< 200 OK
2017-11-03 13:33:18.784  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|< Content-Length: 49
2017-11-03 13:33:18.784  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|< Date: Fri, 03 Nov 2017 04:33:18 GMT
2017-11-03 13:33:18.784  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|< Content-Type: application/json
2017-11-03 13:33:18.784  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|<
2017-11-03 13:33:18.784  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|< {
2017-11-03 13:33:18.784  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|<   "id": 1,
2017-11-03 13:33:18.785  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|<   "name": "Foo",
2017-11-03 13:33:18.785  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|<   "active": true
2017-11-03 13:33:18.785  INFO 17287 --- [tp1860754643-33] RequestAndResponseLoggingFilter  : 0:0:0:0:0:0:0:1|< }

@Ramesh1249

public class XXFilter implements Filter {

@Override
public void init(FilterConfig filterConfig) throws ServletException {

}

@Override
public void doFilter(ServletRequest request, ServletResponse response, FilterChain filterChain) throws IOException, ServletException {
    HttpServletResponse httpServletResponse = (HttpServletResponse) response;

    httpServletResponse.setHeader("RequestId", "1234455"); --> UUID random, you can use.
    filterChain.doFilter(request, response);
}

@Override
public void destroy() {

}

}

any idea why when I return org.springframework.http.ResponseEntity in controller

response invalid?

ref: https://stackoverflow.com/questions/39935190/contentcachingresponsewrapper-produces-empty-response

This filter will cause an issue if the original filter is already a ContentCachingResponseWrapper. It will clear the cached content by invoking copyToResponse, which makes the filter who wraps the response with ContentCachingResponseWrapper loses the cached content in it.

Two solutions to avoid this issue:

1. Always wrap the response with ContentCachingResponseWrapper even if it is already a ContentCachingResponseWrapper.
2. If the original response is ContentCachingResponseWrapper, don't copyToResponse`, read the cached response without clear it.

This filter will cause an issue if the original filter is already a ContentCachingResponseWrapper. It will clear the cached content by invoking copyToResponse, which makes the filter who wraps the response with ContentCachingResponseWrapper loses the cached content in it.

Two solutions to avoid this issue:

1. Always wrap the response with ContentCachingResponseWrapper even if it is already a ContentCachingResponseWrapper.
2. If the original response is ContentCachingResponseWrapper, don't copyToResponse`, read the cached response without clear it.

Could you please share a version of the code with the changes you are talking about?

Since it is using a ContentCachingRequestWrapper, doesn't this only work for POST and application/x-www-form-urlencoded requests?

This approach works fine for requests (with body) and success responses (with body). In case of error (400, 404 and Others), the response body comes blank. Any idea to solve using OncePerRequestFilter?

I followed the same code in my rest api project but I get the following error - "org.springframework.http.InvalidMediaTypeException: Invalid mime type "null": 'mimeType' must not be empty.
I am getting Http 500 error while testing in Postman. Please help me.

Since it is using a ContentCachingRequestWrapper, doesn't this only work for POST and application/x-www-form-urlencoded requests?

yes

I am not getting response headers any idea why

@lavanya2290 check whether u r sending headers; in case u r sending headers kindy shared the code snippet.

@tejas07
can u check in https://github.com/lavanya2290/request-response-log.git

How can I use this filter before the permission evaluator.. I do not find any way. trying since days. Handlers do execute before, bad is they have a limitation which this filter can do. Any ideas?

Fixed the garbled characters probrem on json format.
See this fork https://github.com/LinfinyJapan/RequestAndResponseLoggingFilter

Hi!

If I try to log the request body in beforeRequest method, then It does not do anything. Do you know why?

Thanks!

Becuase @component annotation is missing