Varnish, What is causing hit-for-pass?

Question

This is the varnishlog (edited - expanded to give more info):

*   << Request  >> 172651    
-   Begin          req 172650 rxreq
-   Timestamp      Start: 1455791132.581465 0.000000 0.000000
-   Timestamp      Req: 1455791132.581465 0.000000 0.000000
-   ReqStart       127.0.0.1 47991
-   ReqMethod      GET
-   ReqURL         /
-   ReqProtocol    HTTP/1.1
-   ReqHeader      X-Real-IP: x.x.x.x
-   ReqHeader      X-Forwarded-For: x.x.x.1, x.x.x.2
-   ReqHeader      X-Forwarded-Proto: https
-   ReqHeader      X-Forwarded-Port: 443
-   ReqHeader      Host: mydomain.com
-   ReqHeader      User-Agent: Go-http-client/1.1  (//benchmark app, but regular browser client happens the same
-   ReqHeader      Cf-Connecting-Ip: x.x.x.x
-   ReqHeader      Cf-Ipcountry: AND
-   ReqHeader      Cf-Origin-Https: off
-   ReqHeader      Cf-Ray: 27690752ab232e21-NRT
-   ReqHeader      Cf-Visitor: {"scheme":"https"}
-   ReqUnset       X-Forwarded-For: x.x.x.1, x.x.x.2
-   ReqHeader      X-Forwarded-For: x.x.x.ext, x.x.x.1, x.x.x.2
-   VCL_call       RECV
-   VCL_return     hash
-   VCL_call       HASH
-   VCL_return     lookup
-   Debug          "XXXX HIT-FOR-PASS"
-   HitPass        393349
-   VCL_call       PASS
-   VCL_return     fetch
-   Link           bereq 172652 pass
-   Timestamp      Fetch: 1455791132.581733 0.000268 0.000268
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespHeader     Server: nginx
-   RespHeader     Date: Thu, 18 Feb 2016 10:25:32 GMT
-   RespHeader     Content-Type: text/html; charset=utf-8
-   RespHeader     Vary: Accept-Encoding, Accept-Encoding
-   RespHeader     Etag: "1455788472-0"
-   RespHeader     Content-Language: ja
-   RespHeader     Cache-Control: no-cache
-   RespHeader     Last-Modified: Thu, 18 Feb 2016 09:41:12 GMT
-   RespHeader     X-Content-Options: nosniff
-   RespHeader     X-Micro-Cache: HIT
-   RespHeader     X-Varnish: 172651
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   VCL_return     deliver
-   Timestamp      Process: 1455791132.581744 0.000279 0.000011
-   RespHeader     Accept-Ranges: bytes
-   RespHeader     Transfer-Encoding: chunked
-   Debug          "RES_MODE 8"
-   RespHeader     Connection: keep-alive
-   Timestamp      Resp: 1455791132.581794 0.000329 0.000049
-   ReqAcct        336 0 336 436 57069 57505
-   End            

I have read that this is created when a set-cookie header is set, or cache-control: max-age=0 is set.

Well, I have this in my sub vcl_backend_response trying to avoid hit for pass. It's quite rude, but I don't know what from the backend is causing this hit for pass:

sub vcl_backend_response {
  unset beresp.http.set-cookie;
  unset beresp.http.expires;
  set beresp.http.Cache-Control = "max-age=6000";
}

I am getting rid of the Expire because it was set to timestamp 0. So I though it might be that. Then I tried to play with Cache-control but the same. I am about to just unset all the headers at this rate...

It's after all a 304 response, so why is it not caching it?

More info: the backend is a Drupal app.

Edit 1: about vcl_recv

yes I do have stuff, I am returning pass for some paths (not the one I am checking), I am unsetting cookies for files, and I am unsetting all the cookies that are not drupal session for the rest. It's mroe or less a copy/paste drupal default sub vcl_recv. If you want I can copy it here.

Btw, I changed other stuff and now I get hit for pass also in response 200 (but when I am using benchmark tool,). Somebody deleted the answer that said it might be because of the response 304. I was checking that, but the answer is gone :(

Alright here is the vcl_recv:

sub vcl_recv {
 if (req.url ~ "^/status\.php$" ||
    req.url ~ "^/admin/.*$" ||
     [...]
     req.url ~ "^.*\.js.*$" ) 
    {
       return (pass);
    }

  if (req.url ~ "^/admin/content/backup_migrate/export") {
    return (pipe);
  }

  ## COOKIES ##
  if (req.url ~ "(?i)\.(css|js|jpg|jpeg|gif|png|ico|svg|map)(\?.*)?$") {
    unset req.http.Cookie;
  }
  if (req.http.Cookie) {
    set req.http.Cookie = ";" + req.http.Cookie;
    set req.http.Cookie = regsuball(req.http.Cookie, "; +", ";"); 
    set req.http.Cookie = regsuball(req.http.Cookie, ";(SESS[a-z0-9]+|SSESS[a-z0-9]+|NO_CACHE)=", "; \1=");
    set req.http.Cookie = regsuball(req.http.Cookie, ";[^ ][^;]*", "");
    set req.http.Cookie = regsuball(req.http.Cookie, "^[; ]+|[; ]+$", "");
   if (req.http.Cookie == "") {
        unset req.http.Cookie;
    }
    # if any of our cookies of interest are still there, we disable caching and pass the request
    else {
        return (pass);
    }
 }
}

It's getting hit-for-pass almost always in all http. 304 responses and 200 responses. I have edited the varnishlog above to show a full example to give more info.

EDIT: So this is the log for the request before it shows hit for pass. The one that is surely the guilty of setting the hit for pass:

-   ReqHeader      X-Forwarded-For: 127.0.0.1
-   VCL_return     hash
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       MISS
-   VCL_return     fetch
-   Link           bereq 3 fetch
-   Timestamp      Fetch: 1456731597.992472 0.099948 0.099948
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespHeader     Date: Mon, 29 Feb 2016 07:39:57 GMT
-   RespHeader     Content-Type: text/html; charset=utf-8
-   RespHeader     Content-Encoding: gzip
-   RespHeader     Vary: Accept-Encoding
-   RespHeader     Etag: "1456730796-0"
-   RespHeader     Content-Language: ja
-   RespHeader     Cache-Control: no-cache
-   RespHeader     Last-Modified: Mon, 29 Feb 2016 07:26:36 GMT
-   RespHeader     Expires: Thu, 01 Jan 1970 00:00:01 GMT
-   RespHeader     X-Content-Options: nosniff
-   RespHeader     X-Micro-Cache: EXPIRED
-   RespHeader     X-Varnish: 2
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish-v4
-   RespUnset      Etag: "1456730796-0"
-   RespHeader     ETag: W/"1456730796-0"
-   VCL_call       DELIVER
-   RespHeader     X-Cache: MISS
-   RespHeader     X-Cache-Hits: 0
-   RespUnset      X-Varnish: 2
-   RespUnset      Via: 1.1 varnish-v4
-   VCL_return     deliver
-   Timestamp      Process: 1456731597.992517 0.099993 0.000044
-   RespUnset      Content-Encoding: gzip
-   RespHeader     Accept-Ranges: bytes
-   RespHeader     Content-Length: 53980
-   Debug          "RES_MODE 42"
-   RespHeader     Connection: keep-alive
-   Gzip           U D - 12752 53980 80 101936 101946
-   Timestamp      Resp: 1456731597.992817 0.100293 0.000300
-   ReqAcct        746 0 746 437 53980 54417

Answer 1

This question is getting too long and I am afraid it might not be usefull to other people either.

Thanks to link given by the other answer I saw this (the default implementation of vcl_backend_response):

sub vcl_backend_response {
if (beresp.ttl <= 0s ||
    beresp.http.Set-Cookie ||
    beresp.http.Surrogate-control ~ "no-store" ||
    (!beresp.http.Surrogate-Control &&
    beresp.http.Cache-Control ~ "no-cache|no-store|private") ||
    beresp.http.Vary == "*") {
    /*
     * Mark as "Hit-For-Pass" for the next 2 minutes
     */
    set beresp.ttl = 120s;
    set beresp.uncacheable = true;
}
return (deliver);
}

This are all the conditions that cause hit for pass. Thanks to that I could see that what was causing hit for pass is exactly this beresp.ttl <=0.

So which value has beres.ttl? On the same link we read this: beresp.ttl is initialized with the first value it finds among:

The s-maxage variable in the Cache-Control response header field
The max-age variable in the Cache-Control response header field
The Expires response header field
The default_ttl parameter.

It doesn't matter that you modify the headers in vcl_backend_response because ttl has been already set!

So well, looking at my headers I can see that from the backend I have:

 -  RespHeader Expires: Thu, 01 Jan 1970 00:00:01 GMT

Which is what is causing the hit for pass. So that is the answer to my question. Now, why do I have this header I have no idea, that would be a different question. ( I modified nginx with expires 30d; to all the locations with no result)

Answer 2

It could be that your problem is exactly that it is a 304 response:

The Varnish 3 book says:

Only the following status codes will be cached by default:

200: OK
203: Non-Authoritative Information
300: Multiple Choices
301: Moved Permanently
302: Moved Temporarily
307: Temporary Redirect
410: Gone
404: Not Found

You can still cache other status codes, but you will have to set the beresp.ttl to a positive value in vcl_fetch yourself.

http://book.varnish-software.com/3.0/VCL_Basics.html

What surprises me is that the Varnish 4 book also mentions "304: Not modified" as cacheable. http://book.varnish-software.com/4.0/chapters/VCL_Basics.html

This does not make sense to me because if Varnish was caching the 304 response of a conditional request, than every non-conditional request for the same resource should also get the 304 response without a response body which seems quite useless.