Trouble with caching POSTs (using 4.1 & libvmod-bodyaccess)

[Lee Trout]

Hey everyone,

I've been stumped tonight trying to cache POST requests based on body
content. I first tried 4.0.3 with libvmod-bodyaccess and I was getting
400's from my upstream server from what appeared to be a missing content
length header (or maybe even missing body). I saw another email on this
list from last year where PHK thought there was a bug that had been fixed.

So I moved on to 4.1 and rebuilt libvmod-bodyaccess but unfortunately now
I'm just seeing a crash so I'm sure I've done something silly.

Any help would be greatly appreciated - VCL and varnish log below...

Thanks!

VCL

# cat /etc/varnish/default.vcl
vcl 4.0;
import bodyaccess;
import std;
# Requires libvmod-bodyaccess
# See
http://info.varnish-software.com/blog/introducing-libvmod-bodyaccess-reqbody-access-functions
# Check this file once installed with
# sudo /usr/sbin/varnishd -C -f /etc/varnish/default.vcl

backend default {
    .host = "10.1.1.109";
    .port = "80";
}


# Hash requests based on the request body (model input)
sub vcl_hash {
  if (req.method == "POST") {
    bodyaccess.hash_req_body();
  }
    return(lookup);
}

# On cache things that look like model api calls
sub vcl_recv {
    if (req.url ~ "/([-0-9a-zA-Z]+)/models/([-0-9a-zA-Z]+)/" && req.method
== "POST") {
        # Set the method as a header so we can reuse it for the fetch
        set req.http.x-meth = req.method;
        # Buffer the request body
        std.cache_req_body(10KB);
        return (hash);
    }
    return (pass);
}

sub vcl_backend_fetch {
  # Reuse our method we kept as a header in recv
  set bereq.method = bereq.http.x-meth;
  return(fetch);
}

sub vcl_backend_response {
  # Cache everything for 5 minutes
  set beresp.ttl = 5m;
}

sub vcl_deliver {
    if (obj.hits > 0) {
        set resp.http.X-Cache = "HIT";
    } else {
        set resp.http.X-Cache = "MISS";
    }
}


and varnish log


*              << Session  >>   1
-            1 Begin          c sess 0 HTTP/1
-            1 SessOpen       c 50.142.106.39 46903 :80 10.1.1.145 80
1453875715.569886 9
-            1 Link           c req 2 rxreq
-            1 VSL            - flush
-            1 End            - synth

*              << Request  >>   2
-            2 Begin          c req 1 rxreq
-            2 Timestamp      c Start: 1453875715.569958 0.000000 0.000000
-            2 Timestamp      c Req: 1453875715.569958 0.000000 0.000000
-            2 ReqStart       c 50.142.106.39 46903
-            2 ReqMethod      c POST
-            2 ReqURL         c /lee/models/HelloWorld/
-            2 ReqProtocol    c HTTP/1.1
-            2 ReqHeader      c Authorization: Basic
bGVlOmU0YjFjMTAyZTI1YmYyNjk2Njk1NzRkMjE2MDlhMGZm
-            2 ReqHeader      c Host: 54.213.164.12
-            2 ReqHeader      c Connection: close
-            2 ReqHeader      c User-Agent: Paw/2.2.9 (Macintosh; OS
X/10.11.3) GCDHTTPRequest
-            2 ReqHeader      c Content-Length: 21
-            2 ReqHeader      c X-Forwarded-For: 50.142.106.39
-            2 VCL_call       c RECV
-            2 ReqHeader      c x-meth: POST
-            2 Storage        c malloc Transient
-            2 Timestamp      c ReqBody: 1453875715.570038 0.000079 0.000079
-            2 Debug          c "VRT_CacheReqBody(10240): 21"
-            2 VCL_return     c hash
-            2 VCL_call       c HASH
-            2 VSL            c flush
-            2 End            c synth

Log abandoned
Log reacquired
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20160127/c1dfc5f1/attachment-0001.html>