beresp.ttl set to -1.000?

[MAGNIEN, Thierry]

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