varnish does not relay POST request bodies to BEs under certain circumstances

[jtru]

I'm trying to cache responses to a certain subset of POST requests that have no side effects, in order to save a HTTP-based search appliance some work on repeated queries. For that, I have the client hash the POST request body into an HTTP request header, and use the following VCL definitions to implement the cache key calculation and cache lookup in Varnish:

sub vcl_recv {
    set req.backend_hint = gh_search.backend();
    unset req.http.GH-Is-Search;

    # Keep out request methods that might destroy data in the BEs.
    if (    req.method != "PURGE" &&
        req.method != "GET" &&
        req.method != "POST" &&
        req.method != "HEAD" )
    {
        return (synth(405, "The requested HTTP method is not supported."));
    }

    if (req.method == "PURGE" && client.ip ~ client_acl)
    {
        if (!client.ip ~ purge_acl)
        {
            return (synth(405, "PURGE is not allowed from your source IP address."));
        }
        return(purge);
    }

    # XXX !ATTENTION! XXX
    # The client is responsible for properly calculating a strong hash over
    # its POST Request body that constitutes a well-formed ElasticSearch
    # query (e. g. by MD5'ing the JSON document it generated), and place
    # this value in a standard HTTP Request Header field named
    # 'GH-Search-Hash'. This is imperative for the cache for POST responses
    # to work reliably.
    if (req.method == "HEAD" || req.method == "GET" || req.method == "POST")
    {
        if (req.url ~ "^/gh/(category|artikel)/")
        {
            set req.http.GH-Is-Search = "1";
            set req.http.GH-Orig-Method = req.method;
            std.cache_req_body(128KB);
            std.log("Buffered req body successfully.");
            return (hash);
        }
    }

    # Pass requests that did not meet the requirements checked above
    # directly to the backend, without ever entering the cache. This
    # shouldn't actually happen, except maybe for sanity checks directed
    # towards the ES backends and other debug activity going on.
    return(pass);
}

sub vcl_hash {
    if (req.http.GH-Is-Search && req.method == "POST" && req.http.GH-Search-Hash)
    {
        std.log("=====> Hashed POST Request Body present -> doing lookup <=====");
        if(req.http.Host)
        {
            hash_data(req.http.Host);
        }
        hash_data(req.http.GH-Search-Hash);
        hash_data(req.url);
        return(lookup);
    }
    else if (req.method == "POST")
    {
        std.log("CRITICAL: Unhashed POST request ended up in a cache lookup!");
    }
}

sub vcl_backend_fetch {
    std.log("GH-Orig-Method: " + bereq.http.GH-Orig-Method + " | Method: " + bereq.method);
    set bereq.method = bereq.http.GH-Orig-Method;
}

sub vcl_backend_response
{
    # This is necessary for having that information available in vcl_deliver
    set beresp.http.GH-BE = beresp.backend.name;

    if (beresp.status >= 300) {
        if (beresp.status == 500) {
            return (retry);
        }
        set beresp.uncacheable = true;
        set beresp.ttl = 5s;
        return (deliver);
    }
    else
    {
        if (bereq.http.GH-Search-Hash)
        {
            # Cache responses for 2 minutes
            set beresp.http.Expires = "" + (now + 120s);
        }
        return(deliver);
    }
}

What I see both on the backend http service and via tcpdump is that varnish seems to throw away the original request body, which results in a query the backends still find well-formed and generates a response for. This response is, of course, semantically wrong, but does get cached by Varnish. Subsequent requests with the same GH-Search-Hash request header get served from the cache.

Expected Behavior

Varnish should pass the original request body to the backend during vcl_backend_fetch. Additionally, I don't think it's a good idea to automagically and silently rewrite the request method from POST (and possibly other methods?) to GET there.

Current Behavior

Varnish truncates the POST request body during relaying of the request to the backend in vcl_backend_fetch, so that it arrives empty. From what I gathered from both tcpdump and a chatty BE http server that I set up for debugging purposes, the Content-Length request header is also stripped out of the relayed request.

Possible Solution

I had a peek in cache_http1_fetch.c:V1F_SendReq, and it does mention relaying request bodies to backends there, but I'm not familiar enough with the Varnish codebase to spot anything obvious that would explain the behaviour I described above. That said, I unfortunately don't have any conrete suggestions on how to address this.

Steps to Reproduce (for bugs)

1. Set up varnish with VCL from above with a generic HTTP backend (I am targeting ElasticSearch)
2. Have an HTTP client do a POST request against a varnishd instance with a non-empty request body
3. See backends not receiving any POST request body data

Your Environment

• Version used: 4.1.2 (from Debian packages provided for the Jessie release by varnish-cache.org)
• Operating System and version: Debian Jessie 8.4 for amd64

varnishlog excerpt produced by varnishd with the VCL from above for two requests (one triggering a backend fetch, the second delivering a response from cache):

====================================== varnishlog -g request
     1  *   << Request  >> 2         
     2  -   Begin          req 1 rxreq
     3  -   Timestamp      Start: 1461755371.705507 0.000000 0.000000
     4  -   Timestamp      Req: 1461755371.705507 0.000000 0.000000
     5  -   ReqStart       10.0.0.177 55820
     6  -   ReqMethod      POST
     7  -   ReqURL         /gh/artikel/_search?pretty
     8  -   ReqProtocol    HTTP/1.0
     9  -   ReqHeader      User-Agent: curl/7.38.0
    10  -   ReqHeader      Host: 10.10.10.59
    11  -   ReqHeader      Accept: */*
    12  -   ReqHeader      GH-Search-Hash: blah
    13  -   ReqHeader      Content-Length: 1718
    14  -   ReqHeader      Content-Type: application/x-www-form-urlencoded
    15  -   ReqHeader      X-Forwarded-For: 10.0.0.177
    16  -   VCL_call       RECV
    17  -   ReqHeader      GH-Is-Search: 1
    18  -   ReqHeader      GH-Orig-Method: POST
    19  -   Storage        malloc Transient
    20  -   Timestamp      ReqBody: 1461755371.705614 0.000107 0.000107
    21  -   Debug          "VRT_CacheReqBody(131072): 1718"
    22  -   VCL_Log        Buffered req body successfully.
    23  -   VCL_return     hash
    24  -   VCL_call       HASH
    25  -   VCL_Log        =====> Hashed POST Request Body present -> doing lookup <=====
    26  -   VCL_return     lookup
    27  -   VCL_call       MISS
    28  -   VCL_return     fetch
    29  -   Link           bereq 3 fetch
    30  -   Timestamp      Fetch: 1461755372.111639 0.406132 0.406025
    31  -   RespProtocol   HTTP/1.1
    32  -   RespStatus     200
    33  -   RespReason     OK
    34  -   RespHeader     Content-Type: application/json; charset=UTF-8
    35  -   RespHeader     Content-Length: 12066
    36  -   RespHeader     Date: Wed, 27 Apr 2016 11:09:32 GMT
    37  -   RespHeader     GH-BE: es_2
    38  -   RespHeader     Expires: Wed, 27 Apr 2016 11:11:32 GMT
    39  -   RespHeader     X-Varnish: 2
    40  -   RespHeader     Age: 0
    41  -   RespHeader     Via: 1.1 varnish-v4
    42  -   VCL_call       DELIVER
    43  -   VCL_Log        backend:es_2
    44  -   RespUnset      GH-BE: es_2
    45  -   VCL_return     deliver
    46  -   Timestamp      Process: 1461755372.111671 0.406164 0.000033
    47  -   RespHeader     Accept-Ranges: bytes
    48  -   Debug          "RES_MODE 2"
    49  -   RespHeader     Connection: close
    50  -   Timestamp      Resp: 1461755372.111717 0.406210 0.000046
    51  -   ReqAcct        194 1718 1912 250 12066 12316
    52  -   End            
    53  **  << BeReq    >> 3         
    54  --  Begin          bereq 2 fetch
    55  --  Timestamp      Start: 1461755371.705709 0.000000 0.000000
    56  --  BereqMethod    POST
    57  --  BereqURL       /gh/artikel/_search?pretty
    58  --  BereqProtocol  HTTP/1.0
    59  --  BereqHeader    User-Agent: curl/7.38.0
    60  --  BereqHeader    Host: 10.10.10.59
    61  --  BereqHeader    Accept: */*
    62  --  BereqHeader    GH-Search-Hash: blah
    63  --  BereqHeader    Content-Type: application/x-www-form-urlencoded
    64  --  BereqHeader    X-Forwarded-For: 10.0.0.177
    65  --  BereqHeader    GH-Is-Search: 1
    66  --  BereqHeader    GH-Orig-Method: POST
    67  --  BereqMethod    GET
    68  --  BereqProtocol  HTTP/1.1
    69  --  BereqHeader    Accept-Encoding: gzip
    70  --  BereqHeader    X-Varnish: 3
    71  --  VCL_call       BACKEND_FETCH
    72  --  VCL_Log        GH-Orig-Method: POST | Method: GET
    73  --  BereqMethod    POST
    74  --  VCL_return     fetch
    75  --  BackendOpen    54 boot.es_2 10.10.10.59 9200 10.10.10.59 57744
    76  --  Timestamp      Bereq: 1461755371.705961 0.000252 0.000252
    77  --  Timestamp      Beresp: 1461755372.111567 0.405858 0.405606
    78  --  BerespProtocol HTTP/1.1
    79  --  BerespStatus   200
    80  --  BerespReason   OK
    81  --  BerespHeader   Content-Type: application/json; charset=UTF-8
    82  --  BerespHeader   Content-Length: 12066
    83  --  BerespHeader   Date: Wed, 27 Apr 2016 11:09:32 GMT
    84  --  TTL            RFC 120 10 -1 1461755372 1461755372 1461755372 0 0
    85  --  VCL_call       BACKEND_RESPONSE
    86  --  BerespHeader   GH-BE: es_2
    87  --  BerespHeader   Expires: Wed, 27 Apr 2016 11:11:32 GMT
    88  --  VCL_return     deliver
    89  --  Storage        malloc s0
    90  --  ObjProtocol    HTTP/1.1
    91  --  ObjStatus      200
    92  --  ObjReason      OK
    93  --  ObjHeader      Content-Type: application/json; charset=UTF-8
    94  --  ObjHeader      Content-Length: 12066
    95  --  ObjHeader      Date: Wed, 27 Apr 2016 11:09:32 GMT
    96  --  ObjHeader      GH-BE: es_2
    97  --  ObjHeader      Expires: Wed, 27 Apr 2016 11:11:32 GMT
    98  --  Fetch_Body     3 length stream
    99  --  BackendReuse   54 boot.es_2
   100  --  Timestamp      BerespBody: 1461755372.111658 0.405950 0.000092
   101  --  Length         12066
   102  --  BereqAcct      277 0 277 89 12066 12155
   103  --  End            



   104  *   << Request  >> 32770     
   105  -   Begin          req 32769 rxreq
   106  -   Timestamp      Start: 1461755378.385775 0.000000 0.000000
   107  -   Timestamp      Req: 1461755378.385775 0.000000 0.000000
   108  -   ReqStart       10.0.0.177 55822
   109  -   ReqMethod      POST
   110  -   ReqURL         /gh/artikel/_search?pretty
   111  -   ReqProtocol    HTTP/1.0
   112  -   ReqHeader      User-Agent: curl/7.38.0
   113  -   ReqHeader      Host: 10.10.10.59
   114  -   ReqHeader      Accept: */*
   115  -   ReqHeader      GH-Search-Hash: blah
   116  -   ReqHeader      Content-Length: 1718
   117  -   ReqHeader      Content-Type: application/x-www-form-urlencoded
   118  -   ReqHeader      X-Forwarded-For: 10.0.0.177
   119  -   VCL_call       RECV
   120  -   ReqHeader      GH-Is-Search: 1
   121  -   ReqHeader      GH-Orig-Method: POST
   122  -   Storage        malloc Transient
   123  -   Timestamp      ReqBody: 1461755378.385852 0.000077 0.000077
   124  -   Debug          "VRT_CacheReqBody(131072): 1718"
   125  -   VCL_Log        Buffered req body successfully.
   126  -   VCL_return     hash
   127  -   VCL_call       HASH
   128  -   VCL_Log        =====> Hashed POST Request Body present -> doing lookup <=====
   129  -   VCL_return     lookup
   130  -   Hit            3
   131  -   VCL_call       HIT
   132  -   VCL_return     deliver
   133  -   RespProtocol   HTTP/1.1
   134  -   RespStatus     200
   135  -   RespReason     OK
   136  -   RespHeader     Content-Type: application/json; charset=UTF-8
   137  -   RespHeader     Content-Length: 12066
   138  -   RespHeader     Date: Wed, 27 Apr 2016 11:09:32 GMT
   139  -   RespHeader     GH-BE: es_2
   140  -   RespHeader     Expires: Wed, 27 Apr 2016 11:11:32 GMT
   141  -   RespHeader     X-Varnish: 32770 3
   142  -   RespHeader     Age: 6
   143  -   RespHeader     Via: 1.1 varnish-v4
   144  -   VCL_call       DELIVER
   145  -   VCL_Log        backend:es_2
   146  -   RespUnset      GH-BE: es_2
   147  -   VCL_return     deliver
   148  -   Timestamp      Process: 1461755378.385900 0.000125 0.000048
   149  -   RespHeader     Accept-Ranges: bytes
   150  -   Debug          "RES_MODE 2"
   151  -   RespHeader     Connection: close
   152  -   Timestamp      Resp: 1461755378.385934 0.000159 0.000034
   153  -   ReqAcct        194 1718 1912 256 12066 12322
   154  -   End   

[JordyMoos]

What is the status of this?

[fgsch]

Still being discussed and not before 5.0.

[lkarsten]

Backport review: not for 4.0/4.1.

[frko]

From which version on has this patch been included exactly?
I've been trying to figure it out so I can upgrade to the nearest version from 4.0.4 on as I would love to start caching the responses from POST requests we send to our ES cluster.

[onelharrison]

@frko, This problem has been fixed in 4.1 & 5.0.

[fgsch]

@onelharrison @frko This is available from 5.0 upwards.

[onelharrison]

Oh, thanks @fgsch. It seems @rezan was just pointing to a commit that would be of help if users were still on v4.x.

[frko]

Great news @fgsch, appreciate the fast feedback a lot! We will be ugrading to varnish 5 shortly. Any breaking vcl changes to be aware of? I remember some difficulties when we moved from 3.x to 4.0.

Regards, Frank.

[fgsch]

@frko not as many as between 3 and 4. You can see the changes and how to upgrade here:

https://varnish-cache.org/docs/5.1/whats-new/index.html

[frko]

Is there anything special I need todo on varnish 5 to have varnish send the request body to the backends? I have some vcl in place hashing on a http header with a content hash but I see empty bodies arriving when using tcpdump at the backends.

[hermunn]

Shameless plug:

Did you read https://docs.varnish-software.com/tutorials/caching-post-requests/ ?

[frko]

@hermunn Yes, I did, I am a bit confused I think about the bodyaccess vmod, is this strictly required indeed? As the example shows its use primarily for hashing the body ( which we already do at the client and pass the hash in a http header ). I presumed therefore I would not need it - which very well might be wrong.

[hermunn]

If you trust the client to hash correctly and never return(restart), then using the vmod should not be necessary. However, a malicious client can create two bodies (one and two) and send the hash of two with one as the body, poisoning the cache in a potentially very harmful way.