11

The application should log the following information without impacting a client, asynchronously(in a separate thread).

  • Request HTTP Method and URI
  • Request Headers (Except the default)
  • Client's IP Address
  • Request Processing Time(In milliseconds)
  • Request Body
  • Response Body

If we consume inputstream in the filter, then it cant be consumed again by spring for json to object mapping. Somewhere during the input stream to object mapping, can we plug our logger?

Update:

We can write over logging code in a MessageConverter, but it doesnt seems to be a good idea.

public class MyMappingJackson2MessageConverter extends AbstractHttpMessageConverter<Object> {
    ...
    protected Object readInternal(Class<? extends Object> clazz, HttpInputMessage inputMessage)
            throws IOException, HttpMessageNotReadableException {
        InputStream inputStream = inputMessage.getBody();
        String requestBody = IOUtils.toString(inputStream, StandardCharsets.UTF_8);
        String method = request.getMethod();
        String uri = request.getRequestURI();
        LOGGER.debug("{} {}", method, uri);
        LOGGER.debug("{}", requestBody);
        return objectMapper.readValue(requestBody, clazz);
    }

    protected void writeInternal(Object o, HttpOutputMessage outputMessage)
            throws IOException, HttpMessageNotWritableException {
        String responseBody = objectMapper.writeValueAsString(o);
        LOGGER.debug("{}", responseBody);
        outputMessage.getBody().write(responseBody.getBytes(StandardCharsets.UTF_8));
    }
}
Nilesh
  • 1,977
  • 3
  • 24
  • 51

4 Answers4

6

An answer from baeldung.com :

Spring provides a built-in solution to log payloads. We can use ready-made filters by plugging into Spring application using configuration. AbstractRequestLoggingFilter is a filter which provides basic functions of logging. Subclasses should override the beforeRequest() and afterRequest() methods to perform the actual logging around the request. Spring framework provides following concrete implementation classes which can be used to log the incoming request. These are:

Spring Boot application can be configured by adding a bean definition to enable request logging:

@Configuration
public class RequestLoggingFilterConfig {

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

Also, this logging filter requires the log level be set to DEBUG. In application.properties put

logging.level.org.springframework.web.filter.CommonsRequestLoggingFilter=DEBUG

To make the logging asynchronous, we may use asynchronous appenders. Unfortunately it does not support logging response payloads. :(

Nilesh
  • 1,977
  • 3
  • 24
  • 51
  • 2
    This is perfect fit to log request. But how about if we want to log response status code (200, 404, 500...)? – The Tran May 10 '19 at 06:04
  • 2
    Yeah, this is only useful for logging requests. What about logging response payloads or response headers or response statuscodes etc? Did Spring forget to implement that? Should we implement that on our own is there a Spring class to do this? – theprogrammer Nov 13 '19 at 16:00
  • 1
    this answer does not provide response logging, which is questioned.. not an actual answer.. – aswzen Nov 20 '19 at 07:55
  • 1
    Voting down. Incomplete answer. Doesn't mention how to log responses. – Mudassir Shahzad Aug 17 '20 at 11:56
2

You can achieve this using spring aspect. It provides you some annotations like: @Before , @AfterReturning, @AfterThrowing etc. You may not don't need all endpoints log, so here have some filters based on package. Here are some examples:

For Request:

@Before("within(your.package.where.is.endpoint..*)")
    public void endpointBefore(JoinPoint p) {
        if (log.isTraceEnabled()) {
            log.trace(p.getTarget().getClass().getSimpleName() + " " + p.getSignature().getName() + " START");
            Object[] signatureArgs = p.getArgs();


            ObjectMapper mapper = new ObjectMapper();
            mapper.enable(SerializationFeature.INDENT_OUTPUT);
            try {

                if (signatureArgs[0] != null) {
                    log.trace("\nRequest object: \n" + mapper.writeValueAsString(signatureArgs[0]));
                }
            } catch (JsonProcessingException e) {
            }
        }
    }

here `@Before("within(your.package.where.is.endpoint..*)")` has the package path. All endpoints within this package will generate the log.

For Response:

@AfterReturning(value = ("within(your.package.where.is.endpoint..*)"),
            returning = "returnValue")
    public void endpointAfterReturning(JoinPoint p, Object returnValue) {
        if (log.isTraceEnabled()) {
            ObjectMapper mapper = new ObjectMapper();
            mapper.enable(SerializationFeature.INDENT_OUTPUT);
            try {
                log.trace("\nResponse object: \n" + mapper.writeValueAsString(returnValue));
            } catch (JsonProcessingException e) {
                System.out.println(e.getMessage());
            }
            log.trace(p.getTarget().getClass().getSimpleName() + " " + p.getSignature().getName() + " END");
        }
    }

here `@AfterReturning("within(your.package.where.is.endpoint..*)")` has the package path. All endpoints within this package will generate the log. Also Object returnValue has the response.

For Exception:

@AfterThrowing(pointcut = ("within(your.package.where.is.endpoint..*)"), throwing = "e")
public void endpointAfterThrowing(JoinPoint p, Exception e) throws DmoneyException {
    if (log.isTraceEnabled()) {
        System.out.println(e.getMessage());

        e.printStackTrace();


        log.error(p.getTarget().getClass().getSimpleName() + " " + p.getSignature().getName() + " " + e.getMessage());
    }
}
here `@AfterThrowing(pointcut = ("within(your.package.where.is.endpoint..*)"), throwing = "e")`  has the package path. All endpoints within this package will generate the log. Also Exception e has the error response.

Here is the full code:

import com.fasterxml.jackson.core.JsonProcessingException;
import com.fasterxml.jackson.databind.ObjectMapper;
import com.fasterxml.jackson.databind.SerializationFeature;
import org.apache.log4j.Logger;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;

@Aspect
@Order(1)
@Component
//@ConditionalOnExpression("${endpoint.aspect.enabled:true}")
public class EndpointAspect {
    static Logger log = Logger.getLogger(EndpointAspect.class);

    @Before("within(your.package.where.is.endpoint..*)")
    public void endpointBefore(JoinPoint p) {
        if (log.isTraceEnabled()) {
            log.trace(p.getTarget().getClass().getSimpleName() + " " + p.getSignature().getName() + " START");
            Object[] signatureArgs = p.getArgs();


            ObjectMapper mapper = new ObjectMapper();
            mapper.enable(SerializationFeature.INDENT_OUTPUT);
            try {

                if (signatureArgs[0] != null) {
                    log.trace("\nRequest object: \n" + mapper.writeValueAsString(signatureArgs[0]));
                }
            } catch (JsonProcessingException e) {
            }
        }
    }

    @AfterReturning(value = ("within(your.package.where.is.endpoint..*)"),
            returning = "returnValue")
    public void endpointAfterReturning(JoinPoint p, Object returnValue) {
        if (log.isTraceEnabled()) {
            ObjectMapper mapper = new ObjectMapper();
            mapper.enable(SerializationFeature.INDENT_OUTPUT);
            try {
                log.trace("\nResponse object: \n" + mapper.writeValueAsString(returnValue));
            } catch (JsonProcessingException e) {
                System.out.println(e.getMessage());
            }
            log.trace(p.getTarget().getClass().getSimpleName() + " " + p.getSignature().getName() + " END");
        }
    }


    @AfterThrowing(pointcut = ("within(your.package.where.is.endpoint..*)"), throwing = "e")
    public void endpointAfterThrowing(JoinPoint p, Exception e) throws Exception {
        if (log.isTraceEnabled()) {
            System.out.println(e.getMessage());

            e.printStackTrace();


            log.error(p.getTarget().getClass().getSimpleName() + " " + p.getSignature().getName() + " " + e.getMessage());
        }
    }
}

More info about AOP visit here:

Spring docks about AOP

Sample article about AOP

AbstractVoid
  • 3,108
  • 2
  • 39
  • 37
Md. Sajedul Karim
  • 7,031
  • 3
  • 56
  • 81
  • 1
    Can you explain how this code works? It looks like we are intercepting the method calls to `@RestController`s? – Nilesh Jun 06 '18 at 07:21
  • 1
    @Nilesh , thanks for your question. Here main part is @ Aspect. This is aspect oriented programming. For @ Aspect spring will automatically fire this class for defined package name. Here it will fire for Endpoints/Controllers where you define the rest method.. – Md. Sajedul Karim Jun 06 '18 at 16:22
  • 1
    With the help of AOP we are getting a object passed to RestControllers, and we are converting those objects back to json for logging. This is what I understood. Please correct me if I'm wrong. Since Controllers comes at the end of the request processing flow, not all requests will be logged. For example those which falls javax.validation, requests which are not valid json. Arent they? Is it possible to log them at the edge, I mean as soon as they are received by servlet container(Using AOP off course)? – Nilesh Jun 07 '18 at 09:07
0

I guess your best option is to do the logging in an Async Method.

@Async
public void asyncMethodWithVoidReturnType() {
  System.out.println("Execute method asynchronously. "
    + Thread.currentThread().getName());
}

Please refer to:

Async

How to Async

willermo
  • 485
  • 3
  • 13
0

I would use 2 elements: A LoggingFilter and the Async support from Spring. For the first one, I would use a CommonsRequestLoggingFilter that already knows how to intercept the HTTP requests, create the configuration for that and the Async. You can do something like:

First Enable Async Support

@Configuration
@EnableAsync
public class SpringAsyncConfig { ... }

Then Create the loggingFilter:

public class LoggingFilter extends CommonsRequestLoggingFilter {

@Override
protected void beforeRequest(final HttpServletRequest request, final String message) {
    // DO something
    myAsyncMethodRequest(request, message)
}

@Override
protected void afterRequest(final HttpServletRequest request, final String message) {
    // Do something
   myAsyncMethodResponse(request, message)
}

// -----------------------------------------
// Async Methods
// -----------------------------------------

   @Async
   protected void myAsyncMethodRequest(HttpServletRequest request, String message) {

    // Do your thing
    // You can use message that has a raw message from the properties
   // defined in the logFilter() method. 
   // Also you can extract it from the HttpServletRequest using: 
   // IOUtils.toString(request.getReader());

   }

   @Async
   protected void myAsyncMethodResponse(HttpServletRequest request, String message) {

    // Do your thing
   }

}

Then create a custom logging configuration for the filter that you created:

@Configuration
public class LoggingConfiguration {

    @Bean
    public LoggingConfiguration logFilter() {
        LoggingFilter filter
                = new LoggingFilter();
        filter.setIncludeQueryString(true);
        filter.setIncludePayload(true);
        filter.setIncludeHeaders(true);

        return filter;
    }
}

To extract the data from the request you can use the message parameter or process the HttpServletRequest. Take as an example:

Juan Urrego
  • 313
  • 2
  • 9
  • 1
    How to get response body in CommonsRequestLoggingFilter ? – Nilesh Jan 18 '18 at 06:57
  • Well you just need to read the HttpServletRequest or also you can use `message` that it has the fields that you define in the annotated method with @Bean – Juan Urrego Jan 18 '18 at 07:30
  • Try something like this if you want to extract from the servlet and not from the message: `IOUtils.toString(request.getReader());`. Don't forget to catch or throw the Exception. After that you can process the message as you want. Also if you know that the content is JSON you can use Jackson or GSON to process it – Juan Urrego Jan 18 '18 at 07:33
  • I think this is the right way to define our logging filter class: `public class LoggingFilter extends AbstractRequestLoggingFilter`. – NanoNova Apr 26 '22 at 07:57