javaspringspring-bootspring-mvc

How to log JSON request in spring application?


After many attempts, I'm here to ask if there is a way to log the input JSON request before it is deserialized into a Java Object.

My attempts:

1: I'm able to correctly log the request, before deserialization, but then is giving me "I/O error while reading input message"

Code: RequestInterceptor (getRequestBody from HttpServletRequest)

@Slf4j
@Order(3)
@Component
public class RequestInterceptor implements HandlerInterceptor {

    @Override
    public boolean preHandle(final HttpServletRequest request, 
                             final HttpServletResponse response,
                             final Object handler) throws Exception {
        logRequestDetails(request);
        return true;
    }

    @SuppressWarnings("unchecked")
    private void logRequestDetails(HttpServletRequest request) throws IOException {
        String httpMethod = request.getMethod();
        String url = request.getRequestURL().toString();
        String queryString = request.getQueryString();
        Map<String, String> pathVariables = (Map<String, String>) request.getAttribute(HandlerMapping.URI_TEMPLATE_VARIABLES_ATTRIBUTE);
        String requestBody = getRequestBody(request);
        
        log.info("REQUEST INFO: [ (Method: {}) (URL: {}) (Query String: {}) (Path Variables: {}) ]", httpMethod, url, queryString, pathVariables);
        log.info("REQUEST: {}", requestBody);
    
    }
    
    private String getRequestBody(HttpServletRequest request) {
        StringBuilder stringBuilder = new StringBuilder();
        try (BufferedReader bufferedReader = request.getReader()) {
            String line;
            while ((line = bufferedReader.readLine()) != null) {
                stringBuilder.append(line);
            }
        } catch (IOException e) {
            return "[Error Reading Body]";
        }
        return stringBuilder.toString();
    }
    
}

Logs: HttpMessageNotReadableException: I/O error while reading input message

2024-07-10 00:43:00.523 | http-nio-9001-exec-1 | INFO  | i.g.p.dav.adap.inbou.rest.interceptor.RequestInterceptor | 90963499-0c12-43e3-bd03-f92392090e26 | 16c64a15-6383-4ca2-87ae-34516435f64f | REQUEST INFO: [ (Method: POST) (URL: http://localhost:9001/api/account/passengers/associate-passengers) (Query String: null) (Path Variables: {}) ]
2024-07-10 00:43:00.523 | http-nio-9001-exec-1 | INFO  | i.g.p.dav.adap.inbou.rest.interceptor.RequestInterceptor | 90963499-0c12-43e3-bd03-f92392090e26 | 16c64a15-6383-4ca2-87ae-34516435f64f | REQUEST: [  {    "accountId": 100,    "firstName": "David",    "lastName": "Guetta",    "dateOfBirth": "1967-11-07",    "nationalityId": 63,    "email": "davidguetta@gmail.com",    "phoneNumber": "+33 3334448899"  }]
2024-07-10 00:43:00.654 | http-nio-9001-exec-1 | ERROR | i.g.p.coa.rese.adapt.inbound.controller.rest.ExceptionRestController | 90963499-0c12-43e3-bd03-f92392090e26 | 16c64a15-6383-4ca2-87ae-34516435f64f | Exception 238abf96-75f5-47c2-88dc-93c4ef83e935
org.springframework.http.converter.HttpMessageNotReadableException: I/O error while reading input message
    at org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodArgumentResolver.readWithMessageConverters(AbstractMessageConverterMethodArgumentResolver.java:200) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.readWithMessageConverters(RequestResponseBodyMethodProcessor.java:159) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.resolveArgument(RequestResponseBodyMethodProcessor.java:134) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.method.support.HandlerMethodArgumentResolverComposite.resolveArgument(HandlerMethodArgumentResolverComposite.java:122) ~[spring-web-6.1.4.jar:6.1.4]
    at org.springframework.web.method.support.InvocableHandlerMethod.getMethodArgumentValues(InvocableHandlerMethod.java:228) ~[spring-web-6.1.4.jar:6.1.4]
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:182) ~[spring-web-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:118) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:920) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:830) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1089) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:979) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1014) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:914) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:590) ~[tomcat-embed-core-10.1.19.jar:6.0]
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658) ~[tomcat-embed-core-10.1.19.jar:6.0]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:205) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51) ~[tomcat-embed-websocket-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-6.1.4.jar:6.1.4]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.1.4.jar:6.1.4]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-6.1.4.jar:6.1.4]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.1.4.jar:6.1.4]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-6.1.4.jar:6.1.4]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.1.4.jar:6.1.4]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:167) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90) ~[tomcat-embed-core-10.1.19.jar:10.1.19]

2: I'm able to correctly log the request, before deserialization, but then is giving me "request body is missing"

Code: RequestInterceptor (request wrapped into ContentCachingRequestWrapper)

@Slf4j
@Order(3)
@Component
public class RequestInterceptor implements HandlerInterceptor {

    @Override
    public boolean preHandle(final HttpServletRequest request, 
                             final HttpServletResponse response,
                             final Object handler) throws Exception {
        ContentCachingRequestWrapper requestWrapper;
        
        if (request instanceof ContentCachingRequestWrapper contentCachingRequestWrapper) {
            requestWrapper = contentCachingRequestWrapper;
        } else {
            requestWrapper = new ContentCachingRequestWrapper(request);
        }
        
        logRequestDetails(requestWrapper);
        return true;
    }

    @SuppressWarnings("unchecked")
    private void logRequestDetails(ContentCachingRequestWrapper request) throws IOException {
        String httpMethod = request.getMethod();
        String url = request.getRequestURL().toString();
        String queryString = request.getQueryString();
        Map<String, String> pathVariables = (Map<String, String>) request.getAttribute(HandlerMapping.URI_TEMPLATE_VARIABLES_ATTRIBUTE);
        String requestBody = getRequestBody(request);
        
        log.info("REQUEST INFO: [ (Method: {}) (URL: {}) (Query String: {}) (Path Variables: {}) ]", httpMethod, url, queryString, pathVariables);
        log.info("REQUEST: {}", requestBody);
    
    }
    
    private String getRequestBody(HttpServletRequest request) {
        StringBuilder stringBuilder = new StringBuilder();
        try (BufferedReader bufferedReader = request.getReader()) {
            String line;
            while ((line = bufferedReader.readLine()) != null) {
                stringBuilder.append(line);
            }
        } catch (IOException e) {
            return "[Error Reading Body]";
        }
        return stringBuilder.toString();
    }
    
}

Logs: HttpMessageNotReadableException: Required request body is missing

2024-07-10 00:35:34.738 | http-nio-9001-exec-2 | INFO  | i.g.p.dav.adap.inbou.rest.interceptor.RequestInterceptor | 176cc195-73ec-4921-8d84-5d50f5853cf6 | 5d3d84a5-5330-4608-bc6b-e90916543c94 | REQUEST INFO: [ (Method: POST) (URL: http://localhost:9001/api/account/passengers/associate-passengers) (Query String: null) (Path Variables: {}) ]
2024-07-10 00:35:34.738 | http-nio-9001-exec-2 | INFO  | i.g.p.dav.adap.inbou.rest.interceptor.RequestInterceptor | 176cc195-73ec-4921-8d84-5d50f5853cf6 | 5d3d84a5-5330-4608-bc6b-e90916543c94 | REQUEST: [  {    "accountId": 100,    "firstName": "David",    "lastName": "Guetta",    "dateOfBirth": "1967-11-07",    "nationalityId": 63,    "email": "davidguetta@gmail.com",    "phoneNumber": "+33 3334448899"  }]
2024-07-10 00:35:34.758 | http-nio-9001-exec-2 | ERROR | i.g.p.coa.rese.adapt.inbound.controller.rest.ExceptionRestController | 176cc195-73ec-4921-8d84-5d50f5853cf6 | 5d3d84a5-5330-4608-bc6b-e90916543c94 | Exception 6e9a77ed-24bf-438d-934c-4c7981c6bb70
org.springframework.http.converter.HttpMessageNotReadableException: Required request body is missing: public io.github.paulmarcelinbejan.davinci.adapters.api.DavinciApiResponse<java.util.List<io.github.paulmarcelinbejan.coandaairlines.reservationsystem.ports.domain.Passenger>> io.github.paulmarcelinbejan.coandaairlines.reservationsystem.adapters.inbound.controller.rest.PassengerRestController.associatePassengers(java.util.List<io.github.paulmarcelinbejan.coandaairlines.reservationsystem.adapters.inbound.dto.request.PassengerRequest>)
    at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.readWithMessageConverters(RequestResponseBodyMethodProcessor.java:162) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.resolveArgument(RequestResponseBodyMethodProcessor.java:134) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.method.support.HandlerMethodArgumentResolverComposite.resolveArgument(HandlerMethodArgumentResolverComposite.java:122) ~[spring-web-6.1.4.jar:6.1.4]
    at org.springframework.web.method.support.InvocableHandlerMethod.getMethodArgumentValues(InvocableHandlerMethod.java:228) ~[spring-web-6.1.4.jar:6.1.4]
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:182) ~[spring-web-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:118) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:920) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:830) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1089) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:979) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1014) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:914) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:590) ~[tomcat-embed-core-10.1.19.jar:6.0]
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885) ~[spring-webmvc-6.1.4.jar:6.1.4]
    at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:658) ~[tomcat-embed-core-10.1.19.jar:6.0]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:205) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51) ~[tomcat-embed-websocket-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-6.1.4.jar:6.1.4]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.1.4.jar:6.1.4]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-6.1.4.jar:6.1.4]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.1.4.jar:6.1.4]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-6.1.4.jar:6.1.4]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116) ~[spring-web-6.1.4.jar:6.1.4]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:174) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:149) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:167) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90) ~[tomcat-embed-core-10.1.19.jar:10.1.19]

3: Using LoggingFilterBean I'm able to log the request, but it is logged at the end of the api, and not when the api is invoked, and moreover, the 2 ids from MappedDiagnosticContext (| 99d30bc4-4102-482a-a78e-614f2c0f5876 | 31b3b078-737f-4c60-a429-0596a0736b7a |) written by the interceptors are not logged.

Code: LoggingFilterBean

@Slf4j
@Component
public class LoggingFilterBean extends GenericFilterBean {

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        ContentCachingRequestWrapper requestWrapper = requestWrapper(request);
        ContentCachingResponseWrapper responseWrapper = responseWrapper(response);
        
        chain.doFilter(requestWrapper, responseWrapper);
        
        logRequest(requestWrapper);
        logResponse(responseWrapper);
    }

    private void logRequest(ContentCachingRequestWrapper request) {
        StringBuilder builder = new StringBuilder();
        final String jsonRequest = new String(request.getContentAsByteArray());
        builder.append(jsonRequest);
        log.info("Request: {}", builder);
    }

    private void logResponse(ContentCachingResponseWrapper response) throws IOException {
        StringBuilder builder = new StringBuilder();
        builder.append(new String(response.getContentAsByteArray()));
        log.info("Response: {}", builder);
        response.copyBodyToResponse();
    }

    private ContentCachingRequestWrapper requestWrapper(ServletRequest request) {
        if (request instanceof ContentCachingRequestWrapper requestWrapper) {
            return requestWrapper;
        }
        return new ContentCachingRequestWrapper((HttpServletRequest) request);
    }

    private ContentCachingResponseWrapper responseWrapper(ServletResponse response) {
        if (response instanceof ContentCachingResponseWrapper responseWrapper) {
            return responseWrapper;
        }
        return new ContentCachingResponseWrapper((HttpServletResponse) response);
    }
    
}

Logs:

2024-07-10 01:00:21.665 | http-nio-9001-exec-1 | INFO  | i.g.p.dav.adap.inbou.rest.interceptor.RequestInterceptor | 99d30bc4-4102-482a-a78e-614f2c0f5876 | 31b3b078-737f-4c60-a429-0596a0736b7a | REQUEST INFO: [ (Method: POST) (URL: http://localhost:9001/api/account/passengers/associate-passengers) (Query String: null) (Path Variables: {}) ]
2024-07-10 01:00:21.745 | http-nio-9001-exec-1 | DEBUG | o.h.SQL | 99d30bc4-4102-482a-a78e-614f2c0f5876 | 31b3b078-737f-4c60-a429-0596a0736b7a | select nextval('id_passenger_seq')
2024-07-10 01:00:21.768 | http-nio-9001-exec-1 | DEBUG | o.h.SQL | 99d30bc4-4102-482a-a78e-614f2c0f5876 | 31b3b078-737f-4c60-a429-0596a0736b7a | insert into passenger (fk_account,date_of_birth,email,first_name,is_primary,last_name,fk_nationality,phone_number,id_passenger) values (?,?,?,?,?,?,?,?,?)
2024-07-10 01:00:21.770 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 99d30bc4-4102-482a-a78e-614f2c0f5876 | 31b3b078-737f-4c60-a429-0596a0736b7a | binding parameter (1:BIGINT) <- [9]
2024-07-10 01:00:21.771 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 99d30bc4-4102-482a-a78e-614f2c0f5876 | 31b3b078-737f-4c60-a429-0596a0736b7a | binding parameter (2:VARCHAR) <- [1967-11-07]
2024-07-10 01:00:21.771 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 99d30bc4-4102-482a-a78e-614f2c0f5876 | 31b3b078-737f-4c60-a429-0596a0736b7a | binding parameter (3:VARCHAR) <- [davidguetta@gmail.com]
2024-07-10 01:00:21.771 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 99d30bc4-4102-482a-a78e-614f2c0f5876 | 31b3b078-737f-4c60-a429-0596a0736b7a | binding parameter (4:VARCHAR) <- [David]
2024-07-10 01:00:21.771 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 99d30bc4-4102-482a-a78e-614f2c0f5876 | 31b3b078-737f-4c60-a429-0596a0736b7a | binding parameter (5:BOOLEAN) <- [false]
2024-07-10 01:00:21.771 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 99d30bc4-4102-482a-a78e-614f2c0f5876 | 31b3b078-737f-4c60-a429-0596a0736b7a | binding parameter (6:VARCHAR) <- [Guetta]
2024-07-10 01:00:21.771 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 99d30bc4-4102-482a-a78e-614f2c0f5876 | 31b3b078-737f-4c60-a429-0596a0736b7a | binding parameter (7:INTEGER) <- [63]
2024-07-10 01:00:21.771 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 99d30bc4-4102-482a-a78e-614f2c0f5876 | 31b3b078-737f-4c60-a429-0596a0736b7a | binding parameter (8:VARCHAR) <- [+33 3334448899]
2024-07-10 01:00:21.771 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 99d30bc4-4102-482a-a78e-614f2c0f5876 | 31b3b078-737f-4c60-a429-0596a0736b7a | binding parameter (9:BIGINT) <- [23]
2024-07-10 01:00:21.797 | http-nio-9001-exec-1 | INFO  | i.g.p.dav.adap.inbou.rest.filter.LoggingFilterBean |  |  | Request: [
  {
    "accountId": 9,
    "firstName": "David",
    "lastName": "Guetta",
    "dateOfBirth": "1967-11-07",
    "nationalityId": 63,
    "email": "davidguetta@gmail.com",
    "phoneNumber": "+33 3334448899"
  }
]
2024-07-10 01:00:21.797 | http-nio-9001-exec-1 | INFO  | i.g.p.dav.adap.inbou.rest.filter.LoggingFilterBean |  |  | Response: {"status":"OK","response":[{"id":23,"accountId":9,"isPrimary":false,"firstName":"David","lastName":"Guetta","dateOfBirth":"1967-11-07","nationalityId":63,"email":"davidguetta@gmail.com","phoneNumber":"+33 3334448899"}]}

One solution in order to be able to log before the API is invoked and without having exceptions is by using a ControllerAdvice:

4: The request is already deserialized, so in order to log the json as string I have to serialize the request.

Code: RequestBodyControllerAdvice

@Slf4j
@ControllerAdvice
@RequiredArgsConstructor
public class RequestBodyControllerAdvice extends RequestBodyAdviceAdapter {
    
    private final HttpServletRequest httpServletRequest;
    
    @Override
    public boolean supports(MethodParameter methodParameter, Type type, 
                            Class<? extends HttpMessageConverter<?>> aClass) {
        return true;
    }
    
    @Override
    public Object afterBodyRead(Object body, HttpInputMessage inputMessage,
                                MethodParameter parameter, Type targetType,
            Class<? extends HttpMessageConverter<?>> converterType) {
        
        String json;

        if (body instanceof JsonSerializer object) {
            json = object.toJSON();
        } else {
            try {
                json = OBJECT_MAPPER.writeValueAsString(body);
            } catch (JsonProcessingException e) {
                throw new RuntimeException(e);
            }
        }
        
        log.info("REQUEST: {}", json);
        
        return super.afterBodyRead(body, inputMessage, parameter, targetType, converterType);
    }
    
    private static final ObjectMapper OBJECT_MAPPER = new ObjectMapper();
    
}

Logs:

2024-07-10 01:31:55.879 | http-nio-9001-exec-1 | INFO  | i.g.p.dav.adap.inbou.rest.interceptor.RequestInterceptor | 0137fbd6-a64c-4b7c-9930-4225a6651051 | 7ed2fa14-ffcf-468e-82ff-a7f5a5bfddae | REQUEST INFO: [ (Method: POST) (URL: http://localhost:9001/api/account/passengers/associate-passengers) (Query String: null) (Path Variables: {}) ]
2024-07-10 01:31:55.902 | http-nio-9001-exec-1 | INFO  | i.g.p.dav.adap.inbou.rest.filter.RequestBodyControllerAdvice | 0137fbd6-a64c-4b7c-9930-4225a6651051 | 7ed2fa14-ffcf-468e-82ff-a7f5a5bfddae | REQUEST: [{"accountId":9,"firstName":"David","lastName":"Guetta","dateOfBirth":"1967-11-07","nationalityId":63,"email":"davidguetta@gmail.com","phoneNumber":"+33 3334448899"}]
2024-07-10 01:31:55.966 | http-nio-9001-exec-1 | DEBUG | o.h.SQL | 0137fbd6-a64c-4b7c-9930-4225a6651051 | 7ed2fa14-ffcf-468e-82ff-a7f5a5bfddae | select nextval('id_passenger_seq')
2024-07-10 01:31:55.988 | http-nio-9001-exec-1 | DEBUG | o.h.SQL | 0137fbd6-a64c-4b7c-9930-4225a6651051 | 7ed2fa14-ffcf-468e-82ff-a7f5a5bfddae | insert into passenger (fk_account,date_of_birth,email,first_name,is_primary,last_name,fk_nationality,phone_number,id_passenger) values (?,?,?,?,?,?,?,?,?)
2024-07-10 01:31:55.989 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 0137fbd6-a64c-4b7c-9930-4225a6651051 | 7ed2fa14-ffcf-468e-82ff-a7f5a5bfddae | binding parameter (1:BIGINT) <- [9]
2024-07-10 01:31:55.990 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 0137fbd6-a64c-4b7c-9930-4225a6651051 | 7ed2fa14-ffcf-468e-82ff-a7f5a5bfddae | binding parameter (2:VARCHAR) <- [1967-11-07]
2024-07-10 01:31:55.990 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 0137fbd6-a64c-4b7c-9930-4225a6651051 | 7ed2fa14-ffcf-468e-82ff-a7f5a5bfddae | binding parameter (3:VARCHAR) <- [davidguetta@gmail.com]
2024-07-10 01:31:55.990 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 0137fbd6-a64c-4b7c-9930-4225a6651051 | 7ed2fa14-ffcf-468e-82ff-a7f5a5bfddae | binding parameter (4:VARCHAR) <- [David]
2024-07-10 01:31:55.990 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 0137fbd6-a64c-4b7c-9930-4225a6651051 | 7ed2fa14-ffcf-468e-82ff-a7f5a5bfddae | binding parameter (5:BOOLEAN) <- [false]
2024-07-10 01:31:55.990 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 0137fbd6-a64c-4b7c-9930-4225a6651051 | 7ed2fa14-ffcf-468e-82ff-a7f5a5bfddae | binding parameter (6:VARCHAR) <- [Guetta]
2024-07-10 01:31:55.990 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 0137fbd6-a64c-4b7c-9930-4225a6651051 | 7ed2fa14-ffcf-468e-82ff-a7f5a5bfddae | binding parameter (7:INTEGER) <- [63]
2024-07-10 01:31:55.990 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 0137fbd6-a64c-4b7c-9930-4225a6651051 | 7ed2fa14-ffcf-468e-82ff-a7f5a5bfddae | binding parameter (8:VARCHAR) <- [+33 3334448899]
2024-07-10 01:31:55.990 | http-nio-9001-exec-1 | TRACE | o.h.o.jdb.bind | 0137fbd6-a64c-4b7c-9930-4225a6651051 | 7ed2fa14-ffcf-468e-82ff-a7f5a5bfddae | binding parameter (9:BIGINT) <- [25]

I'm looking for a solution to:

  1. Log at the beginning before entering into rest controller method
  2. Log the json request without having to serialize the request object which it has just beeing deserialized by spring.

Solution

  • I remember I had the same issue. Basically, the problem is if you consume the input stream you are going to get: Required request body is missing after reading request since the input stream can only be consumed once.

    Solution 1 Creating a logging filter that caches / saves request so that it can be read multiple times

    1. Create a logging filter

    This filter saves into our own CachedBodyHttpServletRequest to be able to use it for both logging and further processing

    @Slf4j
    @Component
    public class LoggingFilter extends OncePerRequestFilter {
    
        @Override
        protected void doFilterInternal(HttpServletRequest request,
                                        HttpServletResponse response,
                                        FilterChain filterChain) throws ServletException, IOException {
            var cachedRequest = new CachedBodyHttpServletRequest(request);
            log.info("PROCESSING REQUEST: " + request.getMethod() + " " + request.getRequestURI()
                    + getParameters(request));
            filterChain.doFilter(cachedRequest, response);
        }
    
        @SneakyThrows
        private String getParameters(HttpServletRequest request) {
            String body = new String(request.getInputStream().readAllBytes(), StandardCharsets.UTF_8);
            return body.isEmpty() ? "" : ", with following body: " + body;
        }
    }
    

    2. Create cacheable implementation of HttpServletRequestWrapper

    public class CachedBodyHttpServletRequest extends HttpServletRequestWrapper {
    
        private final byte[] cachedBody;
    
        public CachedBodyHttpServletRequest(HttpServletRequest request) throws IOException {
            super(request);
            this.cachedBody = StreamUtils.copyToByteArray(request.getInputStream());
        }
    
        @Override
        public ServletInputStream getInputStream() throws IOException {
            return new CachedBodyServletInputStream(this.cachedBody);
        }
    
        @Override
        public BufferedReader getReader() throws IOException {
            ByteArrayInputStream byteArrayInputStream = new ByteArrayInputStream(this.cachedBody);
            return new BufferedReader(new InputStreamReader(byteArrayInputStream));
        }
    }
    

    Relatively straight forward class that saves the inputStream into the byte array and lets you getInputStream multiple times by returning a ServletInputStream implementation of our CachedBodyServletInputStream.

    3. Create ServletInputStream implementation

    public class CachedBodyServletInputStream extends ServletInputStream {
        private final InputStream cachedBodyInputStream;
    
        public CachedBodyServletInputStream(byte[] cachedBody) {
            this.cachedBodyInputStream = new ByteArrayInputStream(cachedBody);
        }
    
        @Override
        public int read() throws IOException {
            return cachedBodyInputStream.read();
        }
    
        @SneakyThrows
        @Override
        public boolean isFinished() {
            return cachedBodyInputStream.available() == 0;
        }
    
        @Override
        public boolean isReady() {
            return true;
        }
    
        @Override
        public void setReadListener(ReadListener readListener) {
            throw new RuntimeException("Breaks Liskov`s substitution principle :(");
        }
    }
    

    This class is also relatively easy to follow. It overrides all the necessary methods but also has to override setReadListener for which we have no use in our simple example. While I followed the shortcut of throwing a runtime exception I should warn you that this is a bad style as it breaks the Liskov's Substitution principle... (in such a simple use case as logging negligible, but still)


    My solution was based on this article from Baeldung. I posted this solution first because that is what I ended up using in my project, an alternative, and perhaps simpler, solution from this article is to use CommonsRequestLoggingFilter (doesn't work reliably for spring boot < 2.0):

    Solution 2 CommonsRequestLoggingFilter bean

      @Bean
      CommonsRequestLoggingFilter logFilter() {
          CommonsRequestLoggingFilter filter = new CommonsRequestLoggingFilter();
            
          filter.setIncludeQueryString(true);
          filter.setIncludePayload(true);
          filter.setMaxPayloadLength(10000);
          filter.setIncludeHeaders(false);
          filter.setAfterMessagePrefix("REQUEST DATA : ");
            
          return filter;
      }
    

    Remember also to configure logging level to DEBUG:

    logging:
      level:
        org.springframework.web.filter: DEBUG
    

    Notice that the request is logged at the end of the api process.


    My last suggesion would have also been the @ControllerAdvice but like you correctly said at that point the request has already been processed and deserialized...