I was asked to develop a Tomcat valve that logs all HTTP requests including their body. As the stream containing the body can only be read once, I found out I needed to wrap the request. I found a JBOSS-based example here (download link "Maven project for a valve that dumps the full request with the body"):
https://bz.apache.org/bugzilla/show_bug.cgi?id=45014
I adapted it to work with vanilla Tomcat and with more current APIs (I'm using tomcat-catalina:8.5.20).
Here's what my valve looks like:
public class CaptureValve extends ValveBase {
// ...
@Override
public void invoke(Request request, Response response) throws IOException, ServletException {
// Wrap request so the body can be read multiple times
RequestWrapper wrappedRequest = new RequestWrapper(request);
// important - otherwise, requests aren't passed further down the chain...
getNext().invoke(wrappedRequest, response);
// Simplified for demo purposes - now I'm reading the body to log it
LogBody(wrappedRequest.getBody());
}
// ...
}
Now the RequestWrapper, as you would imagine, just proxies the calls to the wrapped object except for GetRequest: here are the relevant parts of that class:
public class RequestWrapper extends Request {
//...
public RequestWrapper(Request wrapped) throws IOException {
wrappedCatalinaRequest = wrapped;
loggingRequest = new LoggingRequest(wrapped);
}
//...
@Override
public HttpServletRequest getRequest() {
// here is where the actual request used to read from is retrieved
logger.info("getRequest()");
return loggingRequest;
}
//...
}
So the next part is LoggingRequest which wraps the inner RequestFacade:
private class LoggingRequest extends RequestFacade {
private LoggingInputStream is;
LoggingRequest(Request request) throws IOException {
super(request);
int len = 0;
try {
len = Integer.parseInt(request.getHeader("content-length"));
} catch (NumberFormatException e) {
// ignore and assume 0 length
}
String contentType = request.getHeader("content-type");
if (contentType != null) {
for (String ct : contentType.split(";")) {
String s = ct.trim();
if (s.startsWith("charset")) {
charset = s.substring(s.indexOf("=") + 1);
break;
}
}
}
// This line causes the issues I describe below
is = new LoggingInputStream(request.getRequest().getInputStream(), len, charset);
}
@Override
public ServletInputStream getInputStream() throws IOException {
logger.info("LoggingRequest.getInputStream()");
return is;
}
@Override
public BufferedReader getReader() throws IOException {
logger.info("LoggingRequest.getReader()");
return new BufferedReader(new InputStreamReader(is, charset));
}
public String getPayload() {
logger.info("Method: " + new Object() {}.getClass().getEnclosingMethod().getName());
return is.getPayload();
}
}
Be aware of the line where I assign the input stream to the is variable. This is where the issues I describe below start.
Finally, the wrapper for the ServletInputStream - as you can see, the idea is to, when the body is read from the actual Tomcat application, to write the read bytes also into a buffer which can then be read again over the getPayload() method. I stripped the obvious parts of the code, you can find it in the linked sample project where I got all this from if you want to see all the details:
public class LoggingInputStream extends ServletInputStream {
//...
public LoggingInputStream(ServletInputStream inputStream, int length, String charset) {
super();
is = inputStream;
bytes = new ByteArrayOutputStream(length);
charsetName = (charset == null ? "UTF-8" : charset);
}
/*
* Since we are not sure which method will be used just override all 4 of them:
*/
@Override
public int read() throws IOException {
logger.info("LoggingInputStream.read()");
int ch = is.read();
if (ch != -1) {
bytes.write(ch);
// logger.info("read:" + ch);
// logger.info("bytes.size()=" + bytes.size());
}
return ch;
}
@Override
public int read(byte[] b) throws IOException {
logger.info("LoggingInputStream.read(byte[] b)");
// logger.info("byte[].length=" + b.length);
// logger.info("byte[]=" + b);
int numBytesRead = is.read(b);
if (numBytesRead != -1) {
for (int i = 0; i < numBytesRead; i++) {
bytes.write(b[i]);
}
}
return numBytesRead;
}
@Override
public int read(byte[] b, int o, int l) throws IOException {
logger.info("LoggingInputStream.read(byte[] b, int o, int l)");
int numBytesRead = is.read(b, o, l);
if (numBytesRead != -1) {
for (int i = o; i < numBytesRead; i++) {
bytes.write(b[i]);
}
}
return numBytesRead;
}
@Override
public int readLine(byte[] b, int o, int l) throws IOException {
logger.info("LoggingInputStream.readLine(byte[] b, int o, int l)");
int numBytesRead = is.readLine(b, o, l);
if (numBytesRead != -1) {
for (int i = o; i < numBytesRead; i++) {
bytes.write(b[i]);
}
}
return numBytesRead;
}
@Override
public boolean isFinished() {
logger.info("isFinished");
try {
return is.available() == 0;
}
catch (IOException ioe) {
return false;
}
}
@Override
public boolean isReady() {
logger.info("isReady");
return true;
}
@Override
public void setReadListener(ReadListener listener) {
throw new RuntimeException("Not implemented");
}
public String getPayload() {
if (bytes.size() > 0) {
try {
sb.append(bytes.toString(charsetName));
} catch (UnsupportedEncodingException e) {
sb.append("Error occurred when attempting to read request body with charset '").append(charsetName).append("': ");
sb.append(e.getMessage());
}
}
return sb.toString();
}
}
So far so good, I got this actually working. I wrote a very simple Spring application with a basic POST request method that I call from Postman to test it. It's simple as:
public String testPost(String body) {
return body;
}
I send a body with my Postman test request, I get the body that I sent back from the call - and my valve is also able to read the body and log it.
But when I wanted to use it with the actual Tomcat app this should be used with, it just doesn't work. The app seems not to be able to read the body of the request anymore. I can see in my logs that the stream's read() methods are never called. So I tried another app - for that I simply used the Tomcat Manager app and set the session expiration for a web app to another value (which is also just a very simple POST request). It also does not work ... the body which contains the new timeout value never reaches the Tomcat app. But it works with my own Spring app.
Remember this line I mentioned above?
is = new LoggingInputStream(request.getRequest().getInputStream(), len, charset);
I tracked this line down as the cause - as soon as I comment in that line, no matter if I comment out anything of my code that comes after this line, the problem appears - the target application is now not able to read the stream anymore. But I only get the request object reference here and assign it to another variable. I don't actually read the stream here.
I'm a bit lost and would be glad for any ideas what could be wrong here.
Oh and the target tomcat version is 8.0.46 whereas I'm on 9.0 and 8.5 (tested on all three, same results).
Edit: Logged calls on my wrapper objects
RequestWrapper.<init> ctor RequestWrapper
RequestWrapper$LoggingRequest.<init> ctor LoggingRequest
LoggingInputStream.<init> LoggingInputStream length: 7
RequestWrapper.getContext Method: getContext
RequestWrapper.isAsyncSupported Method: isAsyncSupported
RequestWrapper.isAsync Method: isAsync
RequestWrapper.isAsyncDispatching Method: isAsyncDispatching
RequestWrapper.getRequest getRequest() - POST
RequestWrapper.getRequest getRequest() - POST
RequestWrapper.getUserPrincipal Method: getUserPrincipal
RequestWrapper.getSessionInternal Method: getSessionInternal
RequestWrapper.getWrapper Method: getWrapper
RequestWrapper.getRequestPathMB Method: getRequestPathMB
RequestWrapper.getMethod Method: getMethod
RequestWrapper.getMethod Method: getMethod
RequestWrapper.getUserPrincipal Method: getUserPrincipal
RequestWrapper.getNote Method: getNote
RequestWrapper.getCoyoteRequest Method: getCoyoteRequest
RequestWrapper.getCoyoteRequest Method: getCoyoteRequest
RequestWrapper.setAuthType Method: setAuthType
RequestWrapper.setUserPrincipal Method: setUserPrincipal
RequestWrapper.getSessionInternal Method: getSessionInternal
RequestWrapper.getContext Method: getContext
RequestWrapper.changeSessionId Method: changeSessionId
RequestWrapper.getPrincipal Method: getPrincipal
RequestWrapper.getRequestPathMB Method: getRequestPathMB
RequestWrapper.getWrapper Method: getWrapper
RequestWrapper.isAsyncSupported Method: isAsyncSupported
RequestWrapper.getRequestPathMB Method: getRequestPathMB
RequestWrapper.getDispatcherType Method: getDispatcherType
RequestWrapper.setAttribute Method: setAttribute
RequestWrapper.setAttribute Method: setAttribute
RequestWrapper.getFilterChain Method: getFilterChain
RequestWrapper.getAttribute Method: getAttribute
RequestWrapper.getAttribute Method: getAttribute
RequestWrapper.isAsyncDispatching Method: isAsyncDispatching
RequestWrapper.getRequest getRequest() - POST
RequestWrapper.getAttribute Method: getAttribute
RequestWrapper.isAsync Method: isAsync
RequestWrapper.getRequest getRequest() - POST
RequestWrapper.getBody Method: getBody
RequestWrapper$LoggingRequest.getPayload Method: getPayload
LoggingInputStream.getPayload getPayload size: 0
LoggingInputStream.getPayload getPayload result:
Edit: I added a sample project at https://github.com/codekoenig/RequestLoggerValve
