Logging Hits and Misses Tutorial

One of the first thing you will to know about your Varnish setup is whether or not content is cached. In this tutorial we’ll provide a vcl snippet to achieve this as well as how to leverage it via varnishlog and varnishncsa.

VCL

Code

The code is fairly straightforward:

sub vcl_recv {
	unset req.http.x-cache;
}

sub vcl_hit {
	set req.http.x-cache = "hit";
}

sub vcl_miss {
	set req.http.x-cache = "miss";
}

sub vcl_pass {
	set req.http.x-cache = "pass";
}

sub vcl_pipe {
	set req.http.x-cache = "pipe uncacheable";
}

sub vcl_synth {
	set resp.http.x-cache = "synth synth";
}

sub vcl_deliver {
	if (obj.uncacheable) {
		set req.http.x-cache = req.http.x-cache + " uncacheable" ;
	} else {
		set req.http.x-cache = req.http.x-cache + " cached" ;
	}
	# uncomment the following line to show the information in the response
	# set resp.http.x-cache = req.http.x-cache;
}

The x-cache header is were we store the information, using two terms that cover slightly different aspect of the content,

The first word can be:

  • hit: we are delivering an object from the cache
  • miss: the object comes from the backend after failing to find it in the cache.
  • pass: the object comes from the backend because the request bypassed the cache.
  • synth: we created a synthetic object on-the-fly to satisfy the request.

The second word will be:

  • cached: the object will be reused.
  • uncacheable: the object comes from the backend but will not be reused.
  • synth: synthetic object.

Installation

You can either copy-paste the above snippet at the top of your vcl file (after the vcl 4.X; statement), or you can save it as /etc/varnish/hit-miss.vcl and include it:

vcl 4.0;

include "hit-miss.vcl";

import std;
...

Using this information

From the client

You’ll need to uncomment the lastine to see this information as a request header. This is not done by default as it outputs information that should possibly be hidden from regular users.

You can use the -i switch in a curl command to see the headers:

$ curl -i http://VARNISHSERVER/

HTTP/1.1 200 OK
Date: Tue, 24 Jul 2018 18:43:16 GMT
Server: Varnish
Content-Type: text/html; charset=utf-8
X-Varnish: 32773
Age: 0
Via: 1.1 varnish
connection: close
x-cache: miss cached
Content-Length: 282
...

Note: Piped responses can’t be modified, so you cann’t get the information for them that way.

In varnishncsa

varnishncsa grabs information about an HTTP transaction and formats it, usually as a line for easy logging. It can notably collect header values and split them. To do this we just have to specify the right variable in the -F argument (man varnishncsa):

# log the first term of x-chache
varnishncsa -F '%{VSL:ReqHeader:x-cache[1]}x %U %s'
# log the second term of x-chache
varnishncsa -F '%{VSL:ReqHeader:x-cache[2]}x %U %s'
# log the full header
varnishncsa -F '<%{VSL:ReqHeader:x-cache}x> %U %s'

In varnishlog

varnishlog (and varnishncsa) uses a powerful VSL query language (man vsl-query) that allows for versatile filters.

For example, you can:

# only show passes:
varnishlog -q 'ReqHeader:x-cache[1] eq pass'
# only show cached objects
varnishlog -q 'ReqHeader:x-cache[2] eq cached'

*Note: you can apply the same -q arguments to varnishncsa.