beresp.ttl set to -1.000?

[Jason Price]

So, no one has seen anything like this?

I'm watching varnish override the backend's given TTL... and I can't fathom
what is going on here.


On Mon, Jan 20, 2014 at 9:00 PM, Jason Price <japrice at gmail.com> wrote:

> I'm very confused.
>
> Despite backend headers instructing caching for 15 minutes, beresp.ttl
> get's overridden to be -1.000 immediately before vcl_fetch starts running.
>
> For the test, I restarted varnish, ran the test with an empty cache, and
> validated at the end that only one connection/request had come in via
> varnishstat.
>
> Backend response headers (via tcpdump/wireshark):
>
> Expires: Tue, 21 Jan 2014 01:35:54 GMT
> Cache-Control: max-age=900, s-maxage=900, public
> Vary: Accept-Encoding
> Vary: Accept-Encoding
> Content-Type: application/json
>
> Varnishlog output showing the two TTL lines.
>
>    10 TTL          c 562972947 RFC 900 -1 -1 1390267254 0 1390267254
> 1390268154 900
>    10 VCL_call     c fetch
>    10 TTL          c 562972947 VCL 120 -1 -1 1390267254 -0
>    10 VCL_return   c hit_for_pass
>
> So, vcl_fetch changes the ttl?
>
> Here's my modified vcl_fetch (faintly adapted from default.vcl for
> debugging):
>
> sub vcl_fetch {
>   if (beresp.ttl <= 0s) {
>     std.syslog((3*8)+5, "ttl fail");
>   }
>   if (beresp.http.Set-Cookie) {
>     std.syslog((3*8)+5, "cookie fail");
>   }
>   if (beresp.http.Vary == "*") {
>     std.syslog((3*8)+5, "Very fail");
>   }
>   if (beresp.ttl <= 0s || beresp.http.Set-Cookie || beresp.http.Vary ==
> "*") {
>     if (beresp.status == 400) {
>       set beresp.ttl = 5 s;
>       return (deliver);
>     } else if (beresp.status == 500) {
>       set beresp.ttl = 5 s;
>       std.syslog((3*8)+5, "beresp status code 500 for url request " +
> req.url);
>       return (deliver);
>     } else {
>       /*
>       * Mark as "Hit-For-Pass" for the next 2 minutes
>       */
>       std.syslog((3 * 8) + 5, "what? beresp.ttl " + beresp.ttl +
>           " beresp.proto " + beresp.proto +
>           " beresp.status " + beresp.status +
>           " beresp.response " + beresp.response +
>           " beresp.backend.ip " + beresp.backend.ip +
>           " beresp.http.Set-Cookie is " + beresp.http.Set-Cookie +
>           " beresp.http.Vary is " + beresp.http.Vary +
>           " req.url is " + req.url);
>       set beresp.ttl = 120 s;
>       return (hit_for_pass);
>     }
>   }
>   return (deliver);
> }
>
> And indeed, the logs show:
>
> Jan 21 01:20:54 devvcache4x00 varnishd[4761]: *ttl fail*
> Jan 21 01:20:54 devvcache4x00 varnishd[4761]: what? *beresp.ttl -1.000*beresp.proto HTTP/1.1 beresp.status 200 beresp.response OK
> beresp.backend.ip 10.224.4.167 beresp.http.Set-Cookie is  beresp.http.Vary
> is Accept-Encoding, Accept-Encoding req.url is <elided>
>
> Why is beresp.ttl getting set to -1.000 ?   I can't find anything
> modifying beresp.ttl in my code (except what's above to set it to something
> positive).
>
> Varnish 3.0.4, with vmod_redis, vmod_digest
>
> Thank you for any help;
> Jason
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20140124/d7d6e20f/attachment.html>