beresp.ttl set to -1.000?

[Jason Price]

Thank you for your help... In preparing the varnishlog output, I found my
mistake.

The default.vcl code was checking for an Authorization header, and was
instructing all code to return(pass); due to that.

--Jason




On Mon, Jan 27, 2014 at 8:54 AM, MAGNIEN, Thierry
<thierry.magnien at sfr.com>wrote:

> Hi Jason,
>
> Can you provide a full varnishlog output ? (not only -c nor -b)
>
> Thierry
>
> -----------------
> De : varnish-misc-bounces+thierry.magnien=sfr.com at varnish-cache.org[mailto:
> varnish-misc-bounces+thierry.magnien=sfr.com at varnish-cache.org] De la
> part de Jason Price
> Envoyé : vendredi 24 janvier 2014 22:29
> À : varnish-misc at varnish-cache.org
> Objet : Re: beresp.ttl set to -1.000?
>
> 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/20140127/6bc7d8a3/attachment.html>