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": "[email protected]", "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": "[email protected]", "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) <- [[email protected]]
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": "[email protected]",
"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":"[email protected]","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":"[email protected]","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) <- [[email protected]]
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:
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.
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;
}
}
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.
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):
@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...