duplicate beresp / code not hit in backend_response?

[Angelo Höngens]

Hey guys and girls,

I'm trying to debug an issue with varnish here. Running 
varnish-4.1.2-1.el7.x86_64.

I think I have two problems. The first one, is that for debugging 
purposes, I want to force a hit-for-pass on objects with a beresp.status 
of > 300, and my vcl_backend_response looks like this:

sub vcl_backend_response {
   if (beresp.status > 300) {
     set beresp.ttl = 0s;
     set beresp.uncacheable = true;
     set beresp.http.X-Debug-GT300Resp = "YES";
   }
   if (beresp.uncacheable) {
     set beresp.http.X-Cacheable = "NO:Not Cacheable";
   } else {
     set beresp.http.X-Cacheable = "YES";
     if (beresp.http.Set-Cookie) {
       unset beresp.http.Set-Cookie;
     }
   }
   return (deliver);
}

However, varnish does not seem to hit that code, as the 
X-Debug-GT300Resp header never seems to be added. See the below output 
of varnishlog -b -g request -q 'BerespStatus > 200'.

What's even more confusing, is that I first see a 'BerespStatus 304', 
and a bit down, I see 'BerespStatus 200'. Huh? Is varnish doing two 
requests to my backend?


**  << BeReq    >> 192316528
--  Begin          bereq 192316527 bgfetch
--  Timestamp      Start: 1460629439.397252 0.000000 0.000000
--  BereqMethod    GET
--  BereqURL       /L1E3873A88W480H320.jpg
--  BereqProtocol  HTTP/1.1
--  BereqHeader    Host: images.domain.nl
--  BereqHeader    Accept: image/webp,image/*,*/*;q=0.8
--  BereqHeader    User-Agent: Mozilla/5.0 (Windows NT 6.2; WOW64) 
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.112 Safari/537.36
--  BereqHeader    Referer: http://www.domain.nl/bla
--  BereqHeader    Accept-Language: en-US,en;q=0.8,sr;q=0.6
--  BereqHeader    Cookie: _svtri=1b7d5544-84cf-40f1-9228-7be06a208e99; 
_gat=1;
--  BereqHeader    X-Schema: http
--  BereqHeader    X-Forwarded-For: 46.217.107.164
--  BereqHeader    Accept-Encoding: gzip
--  BereqHeader    If-Modified-Since: Fri, 01 Apr 2016 02:58:55 GMT
--  BereqHeader    X-Varnish: 192316528
--  VCL_call       BACKEND_FETCH
--  VCL_return     fetch
--  BackendOpen    156 reload1460629152.default 127.0.0.1 8000 127.0.0.1 
45666
--  Timestamp      Bereq: 1460629439.397307 0.000056 0.000056
--  Timestamp      Beresp: 1460629439.399414 0.002162 0.002106
--  BerespProtocol HTTP/1.1
--  BerespStatus   304
--  BerespReason   Not Modified
--  BerespHeader   Cache-Control: public, stale-while-revalidate=300, 
max-age=300
--  BerespHeader   Last-Modified: Fri, 01 Apr 2016 02:58:55 GMT
--  BerespHeader   Server: Microsoft-IIS/8.5
--  BerespHeader   X-Server-Duration: 0
--  BerespHeader   X-Server-Name: CR1-WEB-111
--  BerespHeader   X-Server-Timestamp: 14-04-2016 12:23:59
--  BerespHeader   X-Server-ReponseStatus: 304
--  BerespHeader   X-Server-RouteType: CmsImageRouteHandler2
--  BerespHeader   X-AspNet-Version: 4.0.30319
--  BerespHeader   X-Powered-By: ASP.NET
--  BerespHeader   Date: Thu, 14 Apr 2016 10:23:58 GMT
--  TTL            RFC 300 300 -1 1460629439 1460629439 1460629438 0 300
--  BerespProtocol HTTP/1.1
--  BerespStatus   200
--  BerespReason   OK
--  BerespHeader   Content-Type: image/jpeg
--  BerespHeader   Content-Length: 92123
--  BerespHeader   X-Cacheable: YES
--  VCL_call       BACKEND_RESPONSE
--  BerespUnset    X-Cacheable: YES
--  BerespHeader   X-Cacheable: YES
--  VCL_return     deliver
--  Storage        malloc s0
--  ObjProtocol    HTTP/1.1
--  ObjStatus      200
--  ObjReason      OK
--  ObjHeader      Cache-Control: public, stale-while-revalidate=300, 
max-age=300
--  ObjHeader      Last-Modified: Fri, 01 Apr 2016 02:58:55 GMT
--  ObjHeader      Server: Microsoft-IIS/8.5
--  ObjHeader      X-Server-Duration: 0
--  ObjHeader      X-Server-Name: CR1-WEB-111
--  ObjHeader      X-Server-Timestamp: 14-04-2016 12:23:59
--  ObjHeader      X-Server-ReponseStatus: 304
--  ObjHeader      X-Server-RouteType: CmsImageRouteHandler2
--  ObjHeader      X-AspNet-Version: 4.0.30319
--  ObjHeader      X-Powered-By: ASP.NET
--  ObjHeader      Date: Thu, 14 Apr 2016 10:23:58 GMT
--  ObjHeader      Content-Type: image/jpeg
--  ObjHeader      Content-Length: 92123
--  ObjHeader      X-Cacheable: YES
--  BackendReuse   156 reload1460629152.default
--  Timestamp      BerespBody: 1460629439.399485 0.002233 0.000071
--  Length         92123
--  BereqAcct      900 0 900 418 0 418
--  End



-- 

With kind regards,


Angelo Höngens