Logging all network traffic in Spring mvc
I have a spring mvc application using RequestBody and ResponseBody annotations. They are configured using MappingJackson2HttpMessageConverter. I also have slf4j. I would like to register all the json as it goes in and out of my controller. I expanded
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 lose the message. Also, labels () and reset () are not supported. It is implemented by PushbackInputStream, so I tried to read its content and push it like so:
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 am getting an exception
java.io.IOException: Push back buffer is full
I also tried to enable logging at the http level as described here: Spring RestTemplate - how to enable full debugging / logging of requests / responses? no luck,
source to share
After a whole day of experimenting, I got a working solution. It consists of a registration filter, two request and response wrappers, and a registration filter registration:
filter class:
/**
* 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 uses flow fairings as suggested by Master Rab and David Ehrmann.
The 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 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 the response wrapper differ only in the close / flush method (no closure is 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 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;
}
}
Finally, the LoggingFilter must be registered with the AbstractAnnotationConfigDispatcherServletInitializer as follows:
@Override
protected Filter[] getServletFilters() {
LoggingFilter requestLoggingFilter = new LoggingFilter();
return new Filter[]{requestLoggingFilter};
}
I know there is a maven lib for this, but I don't want to include the whole library because of the little logging utility. It was much more difficult than I thought. I was expecting this by just changing the log4j.properties. I still think this should be part of Spring.
source to share
It looks like you want to decorate HttpInputMessage
so that it returns a decorated InputStream
one that logs all reads to an internal buffer and then to close()
or finalize()
writes what was read.
Here's an InputStream that will record what has been 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();
}
});
}
source to share
Decoration HttpInputMessage
, as suggested by David Ehrmann, is one of the likely solutions.
The whole problem with this functionality is that it requires it to be InputStream
read more than once. However, this is not possible, once you read a part or stream, you "consume" it, and there is no way to go back and read it again.
A typical solution is to use a filter that wraps the query so that it can be reread InputStream
. One approach is to use a TeeInputStream , which copies all bytes read from InputStream
to the secondary OutputStream
.
There's a github project that only uses a filter like this, and is actually just for the same purpose spring-mvc-logger Class is RequestWrapper
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 also carries over the answer
source to share