In some scenarios, we need to log every client request and response log (including detailed body information).

As you know, streams can only be read once. If we read the request body first in order to log it, then spring’s HttpMessageConverter will throw an exception when it reads the request body again: org.springframework.http.converter. HttpMessageNotReadableException: Required request body is missing: ....

The following example demonstrates this situation.

The case of HttpMessageNotReadableException

Filter for logging

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35

package io.springcloud.demo.filter;

import java.io.IOException;
import java.nio.charset.StandardCharsets;

import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.annotation.WebFilter;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;
import org.springframework.util.StreamUtils;
import org.springframework.web.filter.OncePerRequestFilter;

import lombok.extern.slf4j.Slf4j;

@Component
@WebFilter(urlPatterns = "/*")
@Order(-999)
@Slf4j
public class AccessLogFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
            throws ServletException, IOException {

        byte[] requestBody = StreamUtils.copyToByteArray(request.getInputStream());

        log.info("request body = {}", new String(requestBody, StandardCharsets.UTF_8));

        filterChain.doFilter(request, response);
    }
}

Controller that handles the request

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23

package io.springcloud.demo.controller;

import java.util.Map;

import org.springframework.http.MediaType;
import org.springframework.web.bind.annotation.PostMapping;
import org.springframework.web.bind.annotation.RequestBody;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

import lombok.extern.slf4j.Slf4j;

@RestController
@RequestMapping("/api/demo")
@Slf4j
public class DemoController {

    @PostMapping(consumes = MediaType.TEXT_PLAIN_VALUE, produces = MediaType.APPLICATION_JSON_VALUE)
    public Map<String, String> handle(@RequestBody String body) {
        log.info(body);
        return Map.of("requestBody", body, "timestamp", System.currentTimeMillis() + "", "success", "true");
    }
}

Request and response logs

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19

POST /api/demo HTTP/1.1
Content-Type: text/plain
User-Agent: PostmanRuntime/7.28.4
Accept: */*
Postman-Token: 7fcba173-f468-4ee7-bf73-09123117856b
Host: localhost
Accept-Encoding: gzip, deflate, br
Connection: keep-alive
Content-Length: 12
 
Hello Spring
 
HTTP/1.1 400 Bad Request
Connection: keep-alive
Transfer-Encoding: chunked
Content-Type: application/json
Date: Mon, 14 Mar 2022 07:19:05 GMT
 
{"timestamp":"2022-03-14T07:19:05.195+00:00","status":400,"error":"Bad Request","path":"/api/demo"}

Console output log

1
2

2022-03-14 15:19:05.152  INFO 2936 --- [  XNIO-1 task-1] i.s.demo.filter.AccessLogFilter          : request body = Hello Spring
2022-03-14 15:19:05.189  WARN 2936 --- [  XNIO-1 task-1] .w.s.m.s.DefaultHandlerExceptionResolver : Resolved [org.springframework.http.converter.HttpMessageNotReadableException: Required request body is missing: public java.util.Map<java.lang.String, java.lang.String> io.springcloud.demo.controller.DemoController.handle(java.lang.String)]

As you can see, the request body is indeed read accurately in the AccessLogFilter. But HttpMessageConverter throws an HttpMessageNotReadableException when reading the body.

Re-readable streams

The stream itself cannot be read repeatedly. But you can make a copy of it when you read it, and then you can read it multiple times. Luckily, spring provides this tool class.

  • ContentCachingRequestWrapper
  • ContentCachingResponseWrapper

As the name suggests, the purpose of these 2 classes is to cache the request body, and the response body.

ContentCachingRequestWrapper

This class is used to cache the request body. It inherits from the HttpServletRequestWrapper abstract class and of course implements the HttpServletRequest interface.

How it works is simple. When reading the request body will copy a copy to the cache, the cache can be read multiple times.

Construct methods.

  • public ContentCachingRequestWrapper(HttpServletRequest request)

  • public ContentCachingRequestWrapper(HttpServletRequest request, int contentCacheLimit)

    The length of the cache request body can be limited by the contentCacheLimit parameter, or not if not specified.

Special Methods.

  • public byte[] getContentAsByteArray()

    Get the contents of the cache with this method. This method can be read multiple times.

  • protected void handleContentOverflow(int contentCacheLimit)

    If the length of the cache request body is limited. Then this method will be called after the cache size exceeds the limit. It defaults to an empty implementation.

ContentCachingResponseWrapper

This class is used to cache response bodies. It inherits from the javax.servlet.http.HttpServletResponseWrapper abstract class. It also implements the HttpServletResponse interface.

It also works in a very simple way. The data that the server responds to the client is first cached by it. This cache can be read multiple times. Then at some point in time the cached data is responded to the client.

Construct methods.

  • public ContentCachingResponseWrapper(HttpServletResponse response)

Special Methods：

  • public void copyBodyToResponse() throws IOException

  • protected void copyBodyToResponse(boolean complete) throws IOException

    Send the cached data response to the client. If this method is not executed, then the client will never receive the data from the service response.

  • public int getContentSize()

    Get the length of the cached content.

  • public byte[] getContentAsByteArray()

  • public InputStream getContentInputStream()

    Gets the contents of the cache. Can be called multiple times.

Practicing

AccessLogFilter

Modify the AccessLogFilter.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47

package io.springcloud.demo.filter;

import java.io.IOException;
import java.nio.charset.StandardCharsets;

import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.annotation.WebFilter;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;
import org.springframework.web.filter.OncePerRequestFilter;
import org.springframework.web.util.ContentCachingRequestWrapper;
import org.springframework.web.util.ContentCachingResponseWrapper;

import lombok.extern.slf4j.Slf4j;

@Component
@WebFilter(urlPatterns = "/*")
@Order(-999)
@Slf4j
public class AccessLogFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
            throws ServletException, IOException {

        ContentCachingRequestWrapper req = new ContentCachingRequestWrapper(request);
        ContentCachingResponseWrapper resp = new ContentCachingResponseWrapper(response);

        // Execution request chain
        filterChain.doFilter(req, resp);
        
        // Get Cache
        byte[] requestBody = req.getContentAsByteArray();
        byte[] responseBody = resp.getContentAsByteArray();
        
        log.info("request body = {}", new String(requestBody, StandardCharsets.UTF_8));
        
        log.info("response body = {}", new String(responseBody, StandardCharsets.UTF_8));
        
        // Finally remember to respond to the client with the cached data.
        resp.copyBodyToResponse();
    }
}

Testing

Client Request Log

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19

POST /api/demo HTTP/1.1
Content-Type: text/plain
User-Agent: PostmanRuntime/7.28.4
Accept: */*
Postman-Token: f3bed095-c9fd-46fb-81e0-f5dd9d9ff21a
Host: localhost
Accept-Encoding: gzip, deflate, br
Connection: keep-alive
Content-Length: 12
 
Hello Spring
 
HTTP/1.1 200 OK
Connection: keep-alive
Content-Type: application/json
Content-Length: 75
Date: Mon, 14 Mar 2022 08:12:59 GMT
 
{"success":"true","requestBody":"Hello Spring","timestamp":"1647245579826"}

Console output log

1
2
3

2022-03-14 16:12:59.826  INFO 9036 --- [  XNIO-1 task-1] i.s.demo.controller.DemoController       : Hello Spring
2022-03-14 16:12:59.851  INFO 9036 --- [  XNIO-1 task-1] i.s.demo.filter.AccessLogFilter          : request body = Hello Spring
2022-03-14 16:12:59.852  INFO 9036 --- [  XNIO-1 task-1] i.s.demo.filter.AccessLogFilter          : response body = {"success":"true","requestBody":"Hello Spring","timestamp":"1647245579826"}

Everything is OK.

Finally

There is a problem to be noted. If the body is very large, such as a file upload request (multipart/form-data), or a file download response. It may lead to memory overflow. So it needs to be filtered in Filter for this type of requests.