How to log POST parameters?

[xingfinal]

I'm using org.zalando:logbook-spring-boot-starter:1.0.0-RC1.
When content-type is application/x-www-form-urlencoded, logbook can't print post parameters.
So is there any configuration show the parameters?

[whiskeysierra]

Thanks for bringing this up!

First, just to verify: You are missing post parameters on incoming requests going towards your service, right? Because I think (haven't verified) that it should actually work for outgoing requests to other services.

I'll try to run some tests, so for now the following is just what I remember and what I think how it works:

The Servlet spec handles application/x-www-form-urlencoded somewhat differently, compared to other content types. The parameters that are part of the body are read and parsed by the Servlet container, prior to our filter running in the chain. At the point where we are in control we see a request without a body, because it was already consumed. But of course the parameters are not just missing, they are available. The HttpServletRequest offers getParameterMap and it states:

/**
 * Returns a java.util.Map of the parameters of this request.
 * 
 * <p>Request parameters are extra information sent with the request.
 * For HTTP servlets, parameters are contained in the query string or
 * posted form data.
 *
 * @return an immutable java.util.Map containing parameter names as 
 * keys and parameter values as map values. The keys in the parameter
 * map are of type String. The values in the parameter map are of type
 * String array.
 */
public Map<String, String[]> getParameterMap();

TL;DR: For HTTP servlets, parameters are contained in the query string or posted form data

That means what we get is a big pile of parameters without knowing where they came from. We have several options now:

• Keep everything as is (not very appealing, as it just discards those parameters and you never see them)
• Try to reconstruct the request body for application/x-www-form-urlencoded and be aware that this may result in query parameters accidentially be put in the body (if somebody combines query string and post parameters)
• Try to parse the query string and use that as a source to filter those parameters before reconstructing the body (very fragile and something we were trying to avoid already, multiple times)

[AlexanderYastrebov]

Other option would be to add explicit parameters field.
This field can be only added for POST and application/x-www-form-urlencoded

[whiskeysierra]

I did take another look at this and found this part of the javadoc of HttpServletRequest.getParameter(String):

If the parameter data was sent in the request body, such as occurs with an HTTP POST request, then reading the body directly via getInputStream() or getReader() can interfere with the execution of this method.

See also http://stackoverflow.com/a/10212328/232539

The request body can be read only once. Whenever you invoke request.getInputStream() or request.getReader() before request.getParameterXxx(), then the latter won't return anything, because the request body has already been read. The other way round also applies.

Basically I don't see any way to make this work in a clean way. Right now we are consuming the whole input stream. I'd assume that breaks everyone who uses application/x-www-form-urlencoded already.

[AlexanderYastrebov]

Can we skip reading body in this case and substitute its value with getParametersMap?
Body will be consumed, but it will not break underlying form processing servlet

[AlexanderYastrebov]

So for POST application/x-www-form-urlencoded body can be set to getParametersMap
For POST multipart/form-data body should not be touched at all, can be just marked <multipart> Also it makes no sense to log file uploads in general.

The main goal is not to break underlying servlets.

[whiskeysierra]

Body will be consumed, but it will not break underlying form processing servlet

It depends. That decision is usually left for the servlet to make. If the servlet correctly assumes it's in charge and wants to read the input stream directly (without using getParameter*) then we broke it.

[whiskeysierra]

My idea would be to allow the following behaviours to be configurable:

1. Don't touch POST application/x-www-form-urlencoded (default)
2. Read body and log it
3. Read parameters, reconstruct body and log it

Users of the library could then choose to use the strategy that fits them best.

I agree with the multipart suggestion.

[jhorstmann]

I would prefer to log the original request instead of reconstructing it, even if it would mean having to do the parameter parsing ourselves. So the configurable behaviour could be:

1. Don't touch and log application/x-www-form-urlencoded data
2. Read and log body, parse parameters from saved body

[jhorstmann]

Thinking about this some more, logic in the application depends on the parsed parameter map, not the original body, so maybe it is ok to log these parameters instead. I still would prefer not try to reconstruct the original body. This is not possible anyway in case parameters come from both query string and post body. Maybe a better solution would be to

• Don't touch either application/x-www-form-urlencoded or multipart/form-data
• (optionally) Log the whole getParameterMap (as json), without trying to reconstruct the original encoding. This could actually be logged independent of the request method.

And I just saw that Alexander already proposed something similar before.

[whiskeysierra]

I still would prefer not try to reconstruct the original body.

To be fair, conceptually and by design Logbook is doing exactly that. Everything we log, request line, headers and body, all of that is only reconstructed from what the underlying implementation is giving us. There could be defaults kicking in that we receive that we're never actually send by the client. Furthermore, since we are running in a filter (at least in the servlet part) we are already running behind something else (e.g. Tracer which adds a header to the request that we also log!). The same applies to the HTTP client integration where we're running as an interceptor after potentially many different others.

Coming from that point of view I'd say it's still ok to reconstruct the body for POST parameters. It has the nice benefit that we don't need any special handling or additional fields in our internal API. It's just a body (as it would be on the wire).

[whiskeysierra]

I added a test to verify that we do in fact consume the body right now and log the parameters as such:

{
  "origin": "remote",
  "type": "request",
  "correlation": "2d66e4bc-9a0d-11e5-a84c-1f39510f0d6b",
  "protocol": "HTTP/1.1",
  "sender": "127.0.0.1",
  "method": "POST",
  "path": "http://example.org/test",
  "headers": {
    "Content-Type": ["application/x-www-form-urlencoded"]
  },
  "body": "name=Alice&age=7.5"
}

I'll close the issue for now, as this is good enough for us. Users are encouraged to re-open this or create a new issue if needed.

An idea to solve this would be to delay the logging of the request until the servlet behind the filter actually either consumes the input stream or uses one of the getParameter* methods. Including the possible downside that it may delay the logging for a while. It's also unclear how to handle the case of neither of those methods are used.