Varnish logs a lot. Sometimes it is a bit too much and verifying that your VCL works the way it is supposed to can be a bit of a bother, especially on a busy server. The new logging in Varnish 4 helps a lot, but a lot of the time its easier to just a add a header or two to indicate what is happening.
When I recently I did a post on Grace in Varnish 4.0 I did this to make debugging easier. As I was testing this with the excellent httpie tool it was a lot easier getting both the HTTP response headers and the builtin debug info in the same terminal, especially since I was writing VCL that was timing sensitive.
Storing arbitrary information in req
A handy place to store random bit of data is putting it in the Req object, as request headers. Request headers are typically not seen outside of your network so it is pretty safe to store data there, unless the backend might choke on it if you add a silly header which is then given to the backend. So, make sure not to give the headers name that collide with the HTTP spec.
In my case I wanted to add an indicator of what sort of grace would be used. Grace would basically be operating in three modes:
- none, no grace is involved
- limited, grace while revalidating the object
- full, grace while the server is down
So, I set a header in vcl_recv to the default value. Then, throughout the VCL I override it when I need to. When I engage limited grace (while revalidating the object) I do:
set req.http.grace = "normal(limited)";
or when the backend is down and we need all the grace we can muster:
set req.http.grace = "full";
Delivering it to the client
Since the req object is not delivered to the client we need to copy the data from the req object to resp. We do this when we deliver it. If you do it in vcl_backend_response the headers will be stored in the cache and this might not be what you want.
sub vcl_deliver { set resp.http.grace = req.http.grace; }
If you don't want everyone on the internet too see the information you deploy a ACL.
acl trusted { "192.168.0.0"/16; } sub vcl_deliver { if (client.ip ~ trusted) { set resp.http.grace = req.http.grace; } }
Now I get some nice information about the state grace in Varnish when I do requests.
vagrant@trusty-amd64:~$ http http://localhost/cgi-bin/test.cgi HTTP/1.1 200 OK Accept-Ranges: bytes .. Via: 1.1 varnish (v4) X-Varnish: 65550 32817 grace: full
And I dont need to dig around in Varnishlog to figure out just what happened.