logbook does not print request body when method=POST and header=x-www-form-urlencoded

[wyzssw]

The bug project i have upload https://github.com/wyzssw/logbookbug

CURL FORMAT:

2017-06-29 12:10:39.632 [http-nio-9091-exec-2] INFO  [org.zalando.logbook.Logbook:74] - curl -v -X POST 'http://localhost:9091/test' -H 'accept: */*' -H 'accept-encoding: gzip, deflate, br' -H 'accept-language: zh-CN,zh;q=0.8,en;q=0.6,ja;q=0.4' -H 'cache-control: no-cache' -H 'connection: keep-alive' -H 'content-length: 16' -H 'content-type: application/x-www-form-urlencoded' -H 'host: localhost:9091' -H 'origin: chrome-extension://fhbjgbiflinjbdggehcddcbncdddomop' -H 'postman-token: a86ba1d7-e3bc-7f07-e3a5-ed50f24dbe33' -H 'user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/59.0.3071.115 Safari/537.36'
2017-06-29 12:10:39.638 [http-nio-9091-exec-2] INFO  [org.zalando.logbook.Logbook:79] - Outgoing Response: 07a478d4-8aea-415f-a036-785c5d63e228
HTTP/1.1 200 OK
Transfer-Encoding: chunked
Date: Thu, 29 Jun 2017 04:10:39 GMT
Content-Type: application/json;charset=UTF-8

{"name":"heelo","id":10,"nick":null,"age":null}

HTTP FORMAT:

2017-06-29 12:16:23.731 [http-nio-9091-exec-1] INFO  [org.zalando.logbook.Logbook:74] - Incoming Request: aba71aa5-542f-4d9b-83b9-f8c0314f4d35
POST http://localhost:9091/test HTTP/1.1
content-length: 16
accept-language: zh-CN,zh;q=0.8,en;q=0.6,ja;q=0.4
postman-token: 72a94c89-1345-08df-d8de-2c0a6f80571f
origin: chrome-extension://fhbjgbiflinjbdggehcddcbncdddomop
host: localhost:9091
content-type: application/x-www-form-urlencoded
connection: keep-alive
cache-control: no-cache
accept-encoding: gzip, deflate, br
user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/59.0.3071.115 Safari/537.36
accept: */*
2017-06-29 12:16:23.802 [http-nio-9091-exec-1] INFO  [org.zalando.logbook.Logbook:79] - Outgoing Response: aba71aa5-542f-4d9b-83b9-f8c0314f4d35
HTTP/1.1 200 OK
Transfer-Encoding: chunked
Date: Thu, 29 Jun 2017 04:16:23 GMT
Content-Type: application/json;charset=UTF-8

{"name":"heelo","id":10,"nick":null,"age":null}

[whiskeysierra]

Can you be sure you're not hitting this issue? https://github.com/zalando/logbook#known-issues

[wyzssw]

Yes, exactly it is . I will read #94 carefully.

[whiskeysierra]

I'd assume that Spring is calling HttpServletRequest.getParameter(String) somewhere. I found a usage where Spring looks for a trace parameter.

[wyzssw]

When handle x-www-form-urlencoded ,spring will bind parameters from HttpServletRequest to controller method parameters.It will call getParameter at this time.
For example of My project,

the Call Stack is :

WebUtils.getParametersStartingWith(ServletRequest, String) line: 672	
ServletRequestParameterPropertyValues.<init>(ServletRequest, String, String) line: 77	
ServletRequestParameterPropertyValues.<init>(ServletRequest) line: 52	
ExtendedServletRequestDataBinder(ServletRequestDataBinder).bind(ServletRequest) line: 100	
ServletModelAttributeMethodProcessor.bindRequestParameters(WebDataBinder, NativeWebRequest) line: 152	
ServletModelAttributeMethodProcessor(ModelAttributeMethodProcessor).resolveArgument(MethodParameter, ModelAndViewContainer, NativeWebRequest, WebDataBinderFactory) line: 113	
HandlerMethodArgumentResolverComposite.resolveArgument(MethodParameter, ModelAndViewContainer, NativeWebRequest, WebDataBinderFactory) line: 121	
ServletInvocableHandlerMethod(InvocableHandlerMethod).getMethodArgumentValues(NativeWebRequest, ModelAndViewContainer, Object...) line: 158	
ServletInvocableHandlerMethod(InvocableHandlerMethod).invokeForRequest(NativeWebRequest, ModelAndViewContainer, Object...) line: 128	
ServletInvocableHandlerMethod.invokeAndHandle(ServletWebRequest, ModelAndViewContainer, Object...) line: 97	
RequestMappingHandlerAdapter.invokeHandlerMethod(HttpServletRequest, HttpServletResponse, HandlerMethod) line: 827	
RequestMappingHandlerAdapter.handleInternal(HttpServletRequest, HttpServletResponse, HandlerMethod) line: 738	
RequestMappingHandlerAdapter(AbstractHandlerMethodAdapter).handle(HttpServletRequest, HttpServletResponse, Object) line: 85	
DispatcherServlet.doDispatch(HttpServletRequest, HttpServletResponse) line: 967	

[whiskeysierra]

Ok, good find. As stated in #94 I don't see a way to solve this completely.

[wyzssw]

x-www-form-urlencoded may be the the most common request in http protocol,
Without logbook complete curl ,i must debug in remote mode or log some data to locate problems which is inefficient.
With logbook complete curl ,i just copy curl to my terminal ，and start test Locally and Easily all by myself without other colleague cooperation

After read #94，i find the key concern is logbook can not judge parameter from query string or body.

but i don't care, if HTTP method is POST logbookFilter can just getParameterMap and construct a body , i just want the equivalent curl request not care about parameter come from.

[wyzssw]

I have overwrite CurlHttpLogFormatter.java format method in an unclean way,but it resolve my problem.

CompleteCurlHttpLogFormatter.java format method Snippet:

boolean isFormReq = FormBodyConstructs.isRemoteFormRequest(request);
request.getHeaders().forEach((header, values) -> {
          values.forEach(value -> {
              if (isFormReq && header.equalsIgnoreCase("Content-Length")) {
                 return;
              }
              command.add("-H");
              command.add(quote(header + ": " + value));
          });
});
final String body = isFormReq ? FormBodyConstructs.getFormBody(request) : request.getBodyAsString();

So is DefaultHttpLogFormatter.java

FormBodyConstructs.java

public class FormBodyConstructs {
  
  public static boolean isRemoteFormRequest(Object message){
     if (!(message instanceof FilteredHttpRequest)) {
       return false;
     }
     FilteredHttpRequest request = (FilteredHttpRequest)message;
     HttpRequest httpRequest = request.delegate();
     String method = request.getMethod();
     Map<String, List<String>> headers = request.getHeaders();
     boolean containsHeader = headers.entrySet().stream().filter(entry -> {
       boolean hasHeader = entry.getKey().equalsIgnoreCase("Content-Type");
       boolean isFormHeader = entry.getValue().stream().filter(v -> v.contains("application/x-www-form-urlencoded")).findAny().isPresent();
       return hasHeader && isFormHeader;
     }).findAny().isPresent();
     if (httpRequest instanceof HttpServletRequest && method.equalsIgnoreCase("POST") && containsHeader) {
        return true;
     }
     return false;
  }

  
  public static String getFormBody(Object message){
    FilteredHttpRequest filteredHttpRequest = (FilteredHttpRequest)message;
    HttpServletRequestWrapper requestWrapper = (HttpServletRequestWrapper)(filteredHttpRequest.delegate());
    ServletRequest request = requestWrapper.getRequest();
    Map<String, String[]> map = request.getParameterMap();
    StringBuilder body = new StringBuilder();
    map.forEach((k,v) ->{
      Stream.of(v).forEach(item -> body.append(k + "=" + item + "&"));
    });
    String end = StringUtils.removeEnd(body.toString(), "&"); 
    return end;
  }
}

It is really unclean. 😄

[whiskeysierra]

Map<String, String[]> map = request.getParameterMap();

That is the problem. As stated in #94, we can't use that method.

As soon as any party uses either this method or the underlying inputstream, then the other method will not work anymore. Right now we always use the inputstream. If somebody used getParameter before we don't see any body (as shown in this issue). We either live with that (as stated in the known issues) or we make it configurable whether in case of POST + application/x-www-form-urlencoded we:

• use getInputStream()
• use getParameter*()
• do nothing

[wyzssw]

• The Reason why logbook not print http request body under POST + application/x-www-form-urlencoded is org.springframework.web.filter.HiddenHttpMethodFilter(which has a method contains getParameter) before LogbookFilter. In this case,LogbookFilter can also construct body by getParameter*(), the only not work method is the getInputStream which can only read once.

• The request paramters only parsed under application/x-www-form-urlencoded, getParameter*() do noting effect to application/json

• Servlet Specification does not define ServletFilter can not use getParameter*(),So any party can define ServletFilter to use getParameter*().

• So Logbook can handle the two case individually,under application/json use getInputStream() and cache the body doing good for following method, and getParamter*() in case of application/x-www-form-urlencoded.

[whiskeysierra]

Servlet Specification does not define ServletFilter can not use getParameter*(),So any party can define ServletFilter to use getParameter*().

That is true, but by doing so we make a decision and that might not be in the best interest of the application code running after us.

But checking whether the request was POST + Content-Type: application/x-www-form-urlencoded and in that case using getParameter*() to reconstruct the body sounds like a pretty safe bet.

We would break anybody who intends to read the body (via getInputStream()) directly, which shouldn't be too many people.

[wyzssw]

You can expose a config option about do getParameter*() whether default enable or not which is much better than do noting anyway

[AlexanderYastrebov]

But checking whether the request was POST + Content-Type: application/x-www-form-urlencoded and in that case using getParameter*() to reconstruct the body sounds like a pretty safe bet.

Logbook is an utility library which has to serve two requirements: be useful and be not invasive.
I think we have to try to leave request/response intact as much as possible.

[whiskeysierra]

I discussed this with @AlexanderYastrebov and I'll just leave a snapshot of our whiteboard for my future self.