Logging all network traffic in Spring mvc

Question

I have spring mvc application using RequestBody and ResponseBody annotations. They are configured with MappingJackson2HttpMessageConverter. I also have slf4j set up. I would like to log all json as it comes in and out from my controller. I did extend

MappingJackson2HttpMessageConverter

@Override
public Object read(Type type, Class<?> contextClass, HttpInputMessage inputMessage)
        throws IOException, HttpMessageNotReadableException {
    logStream(inputMessage.getBody());
    return super.read(type, contextClass, inputMessage);
}

I can get the input stream, but if I read the content it becomes empty and I loose the message. Moreover mark() and reset() is not supported. It is implemented by PushbackInputStream, so I tried to read it's content and push it back like this:

public void logStream(InputStream is) {
    if (is instanceof PushbackInputStream)
    try {
        PushbackInputStream pushbackInputStream = (PushbackInputStream) is;
        byte[] bytes = new byte[20000];
        StringBuilder sb = new StringBuilder(is.available());
        int red = is.read();
        int pos =0;
        while (red > -1) {
            bytes[pos] = (byte) red;
            pos=1 + pos;
            red = is.read();
        }
        pushbackInputStream.unread(bytes,0, pos-1);
        log.info("Json payload " + sb.toString());
    } catch (Exception e) {
        log.error("ignoring exception in logger ", e);
    }
}

but I get exception

java.io.IOException: Push back buffer is full

I also tried to turn on logging on http level as described here:Spring RestTemplate - how to enable full debugging/logging of requests/responses? without luck.

Answer 1

After more than whole work day of experimenting I got working solution. It consists of Logging filter, two wrappers for request and response and registration of Logging filter:

the filter class is:

/**
 * Http logging filter, which wraps around request and response in
 * each http call and logs
 * whole request and response bodies. It is enabled by 
 * putting this instance into filter chain
 * by overriding getServletFilters() in  
 * AbstractAnnotationConfigDispatcherServletInitializer.
 */
public class LoggingFilter extends AbstractRequestLoggingFilter {

private static final Logger log = LoggerFactory.getLogger(LoggingFilter.class);

@Override
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
        throws ServletException, IOException {
    long id = System.currentTimeMillis();
    RequestLoggingWrapper requestLoggingWrapper = new RequestLoggingWrapper(id, request);
    ResponseLoggingWrapper responseLoggingWrapper = new ResponseLoggingWrapper(id, response);
    log.debug(id + ": http request " + request.getRequestURI());
    super.doFilterInternal(requestLoggingWrapper, responseLoggingWrapper, filterChain);
    log.debug(id + ": http response " + response.getStatus() + " finished in " + (System.currentTimeMillis() - id) + "ms");
}

@Override
protected void beforeRequest(HttpServletRequest request, String message) {

}

@Override
protected void afterRequest(HttpServletRequest request, String message) {

}
}

this class is using stream wrappers, which was suggested by Master Slave and David Ehrmann.

Request wrapper looks like this:

/**
 * Request logging wrapper using proxy split stream to extract request body
 */
public class RequestLoggingWrapper extends HttpServletRequestWrapper {
private static final Logger log =  LoggerFactory.getLogger(RequestLoggingWrapper.class);
private final ByteArrayOutputStream bos = new ByteArrayOutputStream();
private long id;

/**
 * @param requestId and id which gets logged to output file. It's used to bind request with
 *                  response
 * @param request   request from which we want to extract post data
 */
public RequestLoggingWrapper(Long requestId, HttpServletRequest request) {
    super(request);
    this.id = requestId;
}

@Override
public ServletInputStream getInputStream() throws IOException {
    final ServletInputStream servletInputStream = RequestLoggingWrapper.super.getInputStream();
    return new ServletInputStream() {
        private TeeInputStream tee = new TeeInputStream(servletInputStream, bos);

        @Override
        public int read() throws IOException {
            return tee.read();
        }

        @Override
        public int read(byte[] b, int off, int len) throws IOException {
            return tee.read(b, off, len);
        }

        @Override
        public int read(byte[] b) throws IOException {
            return tee.read(b);
        }

        @Override
        public boolean isFinished() {
            return servletInputStream.isFinished();
        }

        @Override
        public boolean isReady() {
            return servletInputStream.isReady();
        }

        @Override
        public void setReadListener(ReadListener readListener) {
            servletInputStream.setReadListener(readListener);
        }

        @Override
        public void close() throws IOException {
            super.close();
            // do the logging
            logRequest();
        }
    };
}

public void logRequest() {
    log.info(getId() + ": http request " + new String(toByteArray()));
}

public byte[] toByteArray() {
    return bos.toByteArray();
}

public long getId() {
    return id;
}

public void setId(long id) {
    this.id = id;
}
}

and response wrapper is different only in close/flush method (close doesn't get called)

public class ResponseLoggingWrapper extends HttpServletResponseWrapper {
private static final Logger log = LoggerFactory.getLogger(ResponseLoggingWrapper.class);
private final ByteArrayOutputStream bos = new ByteArrayOutputStream();
private long id;

/**
 * @param requestId and id which gets logged to output file. It's used to bind response with
 *                  response (they will have same id, currenttimemilis is used)
 * @param response  response from which we want to extract stream data
 */
public ResponseLoggingWrapper(Long requestId, HttpServletResponse response) {
    super(response);
    this.id = requestId;
}

@Override
public ServletOutputStream getOutputStream() throws IOException {
    final ServletOutputStream servletOutputStream = ResponseLoggingWrapper.super.getOutputStream();
    return new ServletOutputStream() {
        private TeeOutputStream tee = new TeeOutputStream(servletOutputStream, bos);

        @Override
        public void write(byte[] b) throws IOException {
            tee.write(b);
        }

        @Override
        public void write(byte[] b, int off, int len) throws IOException {
            tee.write(b, off, len);
        }

        @Override
        public void flush() throws IOException {
            tee.flush();
            logRequest();
        }

        @Override
        public void write(int b) throws IOException {
            tee.write(b);
        }

        @Override
        public boolean isReady() {
            return servletOutputStream.isReady();
        }

        @Override
        public void setWriteListener(WriteListener writeListener) {
            servletOutputStream.setWriteListener(writeListener);
        }


        @Override
        public void close() throws IOException {
            super.close();
            // do the logging
            logRequest();
        }
    };
}

public void logRequest() {
    byte[] toLog = toByteArray();
    if (toLog != null && toLog.length > 0)
        log.info(getId() + ": http response " + new String(toLog));
}

/**
 * this method will clear the buffer, so
 *
 * @return captured bytes from stream
 */
public byte[] toByteArray() {
    byte[] ret = bos.toByteArray();
    bos.reset();
    return ret;
}

public long getId() {
    return id;
}

public void setId(long id) {
    this.id = id;
}

}

at last LoggingFilter needs to be registered in AbstractAnnotationConfigDispatcherServletInitializer like this:

 @Override
protected Filter[] getServletFilters() {
    LoggingFilter requestLoggingFilter = new LoggingFilter();

    return new Filter[]{requestLoggingFilter};
}

I know, there is maven lib for this, but I don't want to include whole lib because of small logging utility. It was much harder than I originally thought. I expected to achieve this just by modifying log4j.properties. I still think this should be part of Spring.

Answer 2

Decorating HttpInputMessage as David Ehrmann suggested is one likely solution.

The whole trouble with this functionality is that it requires InputStream to be read more than once. However, this is not possible, once you read a portion or a stream, its "consumed" and there no way to go back and read it again.

A typical solution is to apply a filter that will create a wrapper for a request that will allow re-reads of the inputStream. One approach is by using the TeeInputStream which copies all the bytes read from InputStream to a secondary OutputStream.

There's a github project that uses just that kind of a filter and in fact just for the same purpose spring-mvc-logger The RequestWrapper class used

public class RequestWrapper extends HttpServletRequestWrapper {

    private final ByteArrayOutputStream bos = new ByteArrayOutputStream();
    private long id;


    public RequestWrapper(Long requestId, HttpServletRequest request) {
        super(request);
        this.id = requestId;
    }

    @Override
    public ServletInputStream getInputStream() throws IOException {
        return new ServletInputStream() {
            private TeeInputStream tee = new TeeInputStream(RequestWrapper.super.getInputStream(), bos);

            @Override
            public int read() throws IOException {
                return tee.read();
            }
        };
    }

    public byte[] toByteArray(){
        return bos.toByteArray();
    }

    public long getId() {
        return id;
    }

    public void setId(long id) {
        this.id = id;
    }
}

A similar implementation wraps the response as well

Answer 3

It sounds like you want to decorate HttpInputMessage so it returns a decorated InputStream that logs all reads in an internal buffer, then on close() or finalize() logs what was read.

Here's an InputStream that will capture what was read:

  public class LoggingInputStream extends FilterInputStream {

      private ByteArrayOutputStream out = new ByteArrayOutputStream();
      private boolean logged = false;

      protected LoggingInputStream(InputStream in) {
          super(in);
      }

      @Override
      protected void finalize() throws Throwable {
          try {
              this.log();
          } finally {
              super.finalize();
          }
      }

      @Override
      public void close() throws IOException {
          try {
              this.log();
          } finally {
              super.close();
          }
      }

      @Override
      public int read() throws IOException {
          int r = super.read();
          if (r >= 0) {
              out.write(r);
          }
          return r;
      }

      @Override
      public int read(byte[] b) throws IOException {
          int read = super.read(b);
          if (read > 0) {
              out.write(b, 0, read);
          }
          return read;
      }

      @Override
      public int read(byte[] b, int off, int len) throws IOException {
          int read = super.read(b, off, len);
          if (read > 0) {
              out.write(b, off, read);
          }
          return read;
      }

      @Override
      public long skip(long n) throws IOException {
          long skipped = 0;
          byte[] b = new byte[4096];
          int read;
          while ((read = this.read(b, 0, (int)Math.min(n, b.length))) >= 0) {
              skipped += read;
              n -= read;
          }
          return skipped;
      }

      private void log() {
          if (!logged) {
              logged = true;
              try {
                  log.info("Json payload " + new String(out.toByteArray(), "UTF-8");
              } catch (UnsupportedEncodingException e) { }
          }
      }
  }

And now

@Override
public Object read(Type type, Class<?> contextClass, final HttpInputMessage inputMessage)
        throws IOException, HttpMessageNotReadableException {
    return super.read(type, contextClass, new HttpInputMessage() {
        @Override
        public InputStream getBody() {
            return new LoggingInputStream(inputMessage.getBody());
        }
        @Override
        public HttpHeaders getHeaders() {
            return inputMessage.getHeaders();
        }
    });
}