beresp.ttl set to -1.000?

[Jason Price]

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/20140120/e64ab106/attachment.html>