4

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.

Improve this question

3 Answers 3

Reset to default
4

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.

Improve this answer
Sign up to request clarification or add additional context in comments.

Comments

2

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(); } }); }
Improve this answer

Comments

1

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

Improve this answer

2 Comments

Trying to use this but without luck. Overriding doFilterInternal() in CommonsRequestLoggingFilter, where replacing filter, adding this AbstractAnnotationConfigDispatcherServletInitializer, filter gets instantiated, but not invoking doFilterInternal
I finally got it working. I needed to implement more methods in ServletInputStream like David Ehrmann sugested. In response method close() does not get called, so I hooked to flush() which gets called 3 times, so I needed to make sure it will log only once.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.