Spring Boot – How to log all requests and responses with exceptions in single place? – Dev

The best answers to the question “Spring Boot – How to log all requests and responses with exceptions in single place?” in the category Dev.

QUESTION:

I’m working on rest api with spring boot. I need to log all requests with input params (with methods, eg. GET, POST, etc), request path, query string, corresponding class method of this request, also response of this action, both success and errors. For example:

successful request:

http://example.com/api/users/1

Log should look something like this:

{
   HttpStatus: 200,
   path: "api/users/1",
   method: "GET",
   clientIp: "0.0.0.0",
   accessToken: "XHGu6as5dajshdgau6i6asdjhgjhg",
   method: "UsersController.getUser",
   arguments: {
     id: 1 
   },
   response: {
      user: {
        id: 1,
        username: "user123",
        email: "[email protected]"   
      }
   },
   exceptions: []       
}

Or request with error:

http://example.com/api/users/9999

Log should be something like this:

{
   HttpStatus: 404,
   errorCode: 101,                 
   path: "api/users/9999",
   method: "GET",
   clientIp: "0.0.0.0",
   accessToken: "XHGu6as5dajshdgau6i6asdjhgjhg",
   method: "UsersController.getUser",
   arguments: {
     id: 9999 
   },
   returns: {            
   },
   exceptions: [
     {
       exception: "UserNotFoundException",
       message: "User with id 9999 not found",
       exceptionId: "adhaskldjaso98d7324kjh989",
       stacktrace: ...................    
   ]       
}

I want Request/Response to be a single entity, with custom information related to this entity, both in successful and error cases.

What is best practice in spring to achieve this, may be with filters? if yes, can you provide concrete example?

I’ve played with @ControllerAdvice and @ExceptionHandler, but as I mentioned, I need to handle all success and error requests in single place (and single log).

ANSWER:

Spring already provides a filter that does this job. Add following bean to your config

@Bean
public CommonsRequestLoggingFilter requestLoggingFilter() {
    CommonsRequestLoggingFilter loggingFilter = new CommonsRequestLoggingFilter();
    loggingFilter.setIncludeClientInfo(true);
    loggingFilter.setIncludeQueryString(true);
    loggingFilter.setIncludePayload(true);
    loggingFilter.setMaxPayloadLength(64000);
    return loggingFilter;
}

Don’t forget to change log level of org.springframework.web.filter.CommonsRequestLoggingFilter to DEBUG.

ANSWER:

Don’t write any Interceptors, Filters, Components, Aspects, etc., this is a very common problem and has been solved many times over.

Spring Boot has a modules called Actuator, which provides HTTP request logging out of the box. There’s an endpoint mapped to /trace (SB1.x) or /actuator/httptrace (SB2.0+) which will show you last 100 HTTP requests. You can customize it to log each request, or write to a DB.

To get the endpoints you want, you’ll need the spring-boot-starter-actuator dependency, and also to “whitelist” the endpoints you’re looking for, and possibly setup or disable security for it.

Also, where will this application run? Will you be using a PaaS? Hosting providers, Heroku for example, provide request logging as part of their service and you don’t need to do any coding whatsoever then.

ANSWER:

The Logbook library is specifically made for logging HTTP requests and responses. It supports Spring Boot using a special starter library.

To enable logging in Spring Boot all you need to do is adding the library to your project’s dependencies. For example assuming you are using Maven:

<dependency>
    <groupId>org.zalando</groupId>
    <artifactId>logbook-spring-boot-starter</artifactId>
    <version>1.5.0</version>
</dependency>

By default the logging output looks like this:

{
  "origin" : "local",
  "correlation" : "52e19498-890c-4f75-a06c-06ddcf20836e",
  "status" : 200,
  "headers" : {
    "X-Application-Context" : [
      "application:8088"
    ],
    "Content-Type" : [
      "application/json;charset=UTF-8"
    ],
    "Transfer-Encoding" : [
      "chunked"
    ],
    "Date" : [
      "Sun, 24 Dec 2017 13:10:45 GMT"
    ]
  },
  "body" : {
    "thekey" : "some_example"
  },
  "duration" : 105,
  "protocol" : "HTTP/1.1",
  "type" : "response"
}

It does however not output the class name that is handling the request. The library does have some interfaces for writing custom loggers.

Notes

In the meantime the library has significantly evolved, current version is 2.4.1, see https://github.com/zalando/logbook/releases. E.g. the default ouput format has changed, and can be configured, filtered, etc.

Do NOT forget to set the log level to TRACE, else you won’t see anything:

logging:
  level:
    org.zalando.logbook: TRACE

ANSWER:

You could use javax.servlet.Filter if there wasn’t a requirement to log java method that been executed.

But with this requirement you have to access information stored in handlerMapping of DispatcherServlet. That said, you can override DispatcherServlet to accomplish logging of request/response pair.

Below is an example of idea that can be further enhanced and adopted to your needs.

public class LoggableDispatcherServlet extends DispatcherServlet {

    private final Log logger = LogFactory.getLog(getClass());

    @Override
    protected void doDispatch(HttpServletRequest request, HttpServletResponse response) throws Exception {
        if (!(request instanceof ContentCachingRequestWrapper)) {
            request = new ContentCachingRequestWrapper(request);
        }
        if (!(response instanceof ContentCachingResponseWrapper)) {
            response = new ContentCachingResponseWrapper(response);
        }
        HandlerExecutionChain handler = getHandler(request);

        try {
            super.doDispatch(request, response);
        } finally {
            log(request, response, handler);
            updateResponse(response);
        }
    }

    private void log(HttpServletRequest requestToCache, HttpServletResponse responseToCache, HandlerExecutionChain handler) {
        LogMessage log = new LogMessage();
        log.setHttpStatus(responseToCache.getStatus());
        log.setHttpMethod(requestToCache.getMethod());
        log.setPath(requestToCache.getRequestURI());
        log.setClientIp(requestToCache.getRemoteAddr());
        log.setJavaMethod(handler.toString());
        log.setResponse(getResponsePayload(responseToCache));
        logger.info(log);
    }

    private String getResponsePayload(HttpServletResponse response) {
        ContentCachingResponseWrapper wrapper = WebUtils.getNativeResponse(response, ContentCachingResponseWrapper.class);
        if (wrapper != null) {

            byte[] buf = wrapper.getContentAsByteArray();
            if (buf.length > 0) {
                int length = Math.min(buf.length, 5120);
                try {
                    return new String(buf, 0, length, wrapper.getCharacterEncoding());
                }
                catch (UnsupportedEncodingException ex) {
                    // NOOP
                }
            }
        }
        return "[unknown]";
    }

    private void updateResponse(HttpServletResponse response) throws IOException {
        ContentCachingResponseWrapper responseWrapper =
            WebUtils.getNativeResponse(response, ContentCachingResponseWrapper.class);
        responseWrapper.copyBodyToResponse();
    }

}

HandlerExecutionChain – contains the information about request handler.

You then can register this dispatcher as following:

    @Bean
    public ServletRegistrationBean dispatcherRegistration() {
        return new ServletRegistrationBean(dispatcherServlet());
    }

    @Bean(name = DispatcherServletAutoConfiguration.DEFAULT_DISPATCHER_SERVLET_BEAN_NAME)
    public DispatcherServlet dispatcherServlet() {
        return new LoggableDispatcherServlet();
    }

And here’s the sample of logs:

http http://localhost:8090/settings/test
i.g.m.s.s.LoggableDispatcherServlet      : LogMessage{httpStatus=500, path="/error", httpMethod='GET', clientIp='127.0.0.1', javaMethod='HandlerExecutionChain with handler [public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.BasicErrorController.error(javax.servlet.http.HttpServletRequest)] and 3 interceptors', arguments=null, response="{"timestamp":1472475814077,"status":500,"error":"Internal Server Error","exception":"java.lang.RuntimeException","message":"org.springframework.web.util.NestedServletException: Request processing failed; nested exception is java.lang.RuntimeException","path":"/settings/test"}"}

http http://localhost:8090/settings/params
i.g.m.s.s.LoggableDispatcherServlet      : LogMessage{httpStatus=200, path="/settings/httpParams", httpMethod='GET', clientIp='127.0.0.1', javaMethod='HandlerExecutionChain with handler [public x.y.z.DTO x.y.z.Controller.params()] and 3 interceptors', arguments=null, response="{}"}

http http://localhost:8090/123
i.g.m.s.s.LoggableDispatcherServlet      : LogMessage{httpStatus=404, path="/error", httpMethod='GET', clientIp='127.0.0.1', javaMethod='HandlerExecutionChain with handler [public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.BasicErrorController.error(javax.servlet.http.HttpServletRequest)] and 3 interceptors', arguments=null, response="{"timestamp":1472475840592,"status":404,"error":"Not Found","message":"Not Found","path":"/123"}"}

UPDATE

In case of errors Spring does automatic error handling. Therefore, BasicErrorController#error is shown as request handler. If you want to preserve original request handler, then you can override this behavior at spring-webmvc-4.2.5.RELEASE-sources.jar!/org/springframework/web/servlet/DispatcherServlet.java:971 before #processDispatchResult is called, to cache original handler.