Debugging Varnish VCL configuration files

If you're a Drupal or PHP developer used to debugging or troubleshooting some code by adding a print $variable; or dpm($object); to your PHP, and then refreshing the page to see the debug message (or using XDebug, or using watchdog logging...), debugging Varnish's VCL language can be intimidating.

VCL uses C-like syntax, and is compiled when varnish starts, so you can't just modify a .vcl file and refresh to see changes or debug something. And there are only a few places where you can simply stick a debug statement. So, I'll explain four different ways I use to debug VCLs in this post (note: don't do this on a production server!):

Simple Error statements (like print in PHP)

Sometimes, all you need to do is see the output of a variable, like req.http.Cookie, inside vcl_recv(). In these cases, you can just add an error statement to throw an error in Varnish and output the contents of a string, like the Cookie:

error 503 req.http.Cookie;

Save the VCL and restart Varnish, and when you try accessing a page, you'll get Varnish's error page, and below the error message, the contents of the cookie, like so:

This debugging process works within vcl_recv() and vcl_fetch(), but causes problems (or crashes Varnish) in any other functions.

Debugging with syslog

You can also log debug messages to the system log (/var/log/messages on RedHat/CentOS, or /var/log/syslog on Debian/Ubuntu) using the syslog() function provided by vmod_std.

In your VCL (at the top), add in import std; to import the std library. Then, anywhere in the vcl, you can log messages to the system log using something like:

std.syslog(0, req.http.Cookie);

Restart varnish, and then tail -f /var/log/messages to watch a steady stream of varnish log messages!

Actively monitoring Varnish with varnishlog

varnishlog is another simple command-line utility that dumps out every bit of information varnish processes and returns during the course of it's processing, including backend pings, request headers, response headers, cache information, hash information, etc.

If you just enter varnishlog and watch (or dump the info into a file), be prepared to scroll for eons or grep like crazy to find the information you're looking for. Luckily, varnishlog also lets you filter the information it prints to screen with a few options, like -m to define a regular expression filter. For example:

# Display all Hashes.
varnishlog -c -i Hash

# Display User-Agent strings.
varnishlog -c -i RxHeader -I User-Agent

There are more examples available on the Varnish cache Wiki.

Monitoring Varnish with varnishtop

varnishtop is a simple command-line utility that displays varnish log entries with a rolling count (ranking logged entries by frequency within the past minute). What this means in laymans terms is that you can easily display things like how many times a particular URL is hit, different bits of information about requests (like Hashes, or headers, etc.).

I like to think of varnishtop as a simple way to display the incredibly deep stats from varnishlog in realtime, with better filtering.

Some example commands I've used when debugging scripts:

# Display request cookies.
varnishtop -i RxHeader -I Cookie

# Display varnish hash data ('searchtext' is text to filter within hash).
varnishtop -i "Hash" -I searchtext

# Display 404s.
varnishlog -b -m "RxStatus:404"

You can change the length of time being monitored from the default of 60 seconds by specifying -p period (note that this setting only works for Varnish > 3.0).

There are a few other common monitoring commands in this StackOverflow answer.

Dry-run Compiling a VCL

Sometimes you may simply have a syntax error in your .vcl file. In these cases, you can see exactly what's wrong by using the command varnishd -Cf /path/to/default.vcl, where default.vcl is the base VCL file you've configured for use with Varnish (on CentOS/RHEL systems, this file is usually /etc/varnish/default.vcl).

The output of this command will either be a successfully-compiled VCL, or an error message telling you on exactly what line the error occurs.

Other debugging techniques

Are there any other simple debugging techniques you use that I didn't cover here? Please let me know in the comments. I wanted to compile these techniques, and a few examples, because I've never really seen a good/concise primer on debugging Varnish configuration anywhere—just bits and pieces.