Varnish vcl_backend_response not called

Question

I came across inconsistencies with Varnish 4.x documentation. According to the documentation vcl_backend_response will be called each time an object is fetched from the backend and the backend doesn't return an error (and is alive and healthy).

However, I noticed many of the 'fetch' requests (resulting from misses) are not going through this function at all. Here is an example output:

-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       MISS
-   VCL_return     fetch
-   Link           bereq 294915 fetch
-   Timestamp      Fetch: 1504198046.101306 0.003644 0.003644
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespHeader     Server: nginx/1.10.3 (Ubuntu)
-   RespHeader     Date: Thu, 31 Aug 2017 16:47:26 GMT
-   RespHeader     Vary: Accept-Encoding
-   RespHeader     Last-Modified: Thu, 31 Aug 2017 16:42:58 GMT
-   RespHeader     Expires: Thu, 31 Aug 2017 16:47:26 GMT
-   RespHeader     Cache-Control: public, max-age=90, s-maxage=332
-   RespHeader     Pragma: cache
-   RespHeader     X-Lift-Version: 2.6.3
-   RespHeader     X-Frame-Options: SAMEORIGIN
-   RespHeader     Content-Encoding: gzip
-   RespHeader     Content-Type: application/json; charset=utf-8
-   RespHeader     X-Varnish: 294914
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish-v4
-   VCL_call       DELIVER
-   RespHeader     grace: none
-   VCL_return     deliver

as opposed to a flow that adheres the documentation:

-   VCL_call       BACKEND_FETCH
-   VCL_return     fetch
-   BackendOpen    22 boot.default 127.0.0.1 9919 127.0.0.1 22536
-   Timestamp      Bereq: 1504198040.603601 0.000222 0.000222
-   Timestamp      Beresp: 1504198040.659723 0.056345 0.056123
-   BerespProtocol HTTP/1.1
-   BerespStatus   200
-   BerespReason   OK
-   BerespHeader   Server: nginx/1.10.3 (Ubuntu)
-   BerespHeader   Date: Thu, 31 Aug 2017 16:47:20 GMT
-   BerespHeader   Content-Type: text/html;charset=utf-8
-   BerespHeader   Transfer-Encoding: chunked
-   BerespHeader   Connection: keep-alive
-   BerespHeader   Vary: Accept-Encoding
-   BerespHeader   Last-Modified: Thu, 31 Aug 2017 16:42:58 GMT
-   BerespHeader   Expires: Thu, 31 Aug 2017 16:47:20 GMT
-   BerespHeader   Cache-Control: public, max-age=21600, s-maxage=21600
-   BerespHeader   Pragma: cache
-   BerespHeader   X-Lift-Version: 2.6.3
-   BerespHeader   X-Frame-Options: SAMEORIGIN
-   BerespHeader   Content-Encoding: gzip
-   TTL            RFC 21600 10 -1 1504198041 1504198041 1504198040 1504198040 21600
-   VCL_call       BACKEND_RESPONSE

So - according to Varnish log - when there is a miss and the object is fetched from the backed vcl_backend_response is not invoked. Unless I'm missing something - this contradicts the documentation.

Answer 1

There are no inconsistencies in the documentation. What you see is the normal behaviour since Varnish 4.0. During a cache miss, you'll see (at least) two transactions in varnishlog: (1) the one handling the client request (usual flow is vcl_recv → vcl_hash → vcl_miss → vcl_deliver; i.e. the first log excerpt in your question); and (2) the one handling the request to the backend side (usual flow is vcl_backend_fetch → vcl_backend_response; i.e. the second log excerpt in your question). That's why you don't see references to vcl_backend_response in the client transaction.

Obviously both transactions are connected. At some point the client transaction creates and waits for completion of the backend transaction. That's shown in the log of the client transaction:

-   ...
-   Link           bereq 294915 fetch
-   ...

That means a backend transaction was created (VXID 294915) in order to fetch an object from the origin.