Varnishlog filter the records for debugging

Written by
Date: 2011-07-25 10:36:30 00:00


Varnish Logs

Varnish is a powerful reverse proxy that can balance the load of multiple web servers, and cache the required pages at the same time. You can read more about it at its home page

Now we all know that debugging is an important part of installing, configuring and fine tuning any piece of software, and that goes to varnish too, and varnishlog is a great utility to help you while debugging varnish.

varnishlog

As the name says, it display Varnish logs, but if you have a very busy site, and your run it with no parameters you will hardly follow the logs in the screen, so your first option to solve this, is to write the logs to a file and analyze them later.

varnishlog -w /home/user/varnishlogs.log

You can then use less to view the document. But you’ll have too much information to digest and it would be better to filter it by IP or some other field. We normally use grep to do that, but in the case of varnishlog the info is placed one field by line so grep is not useful.

Here an example, of the varnishlog output.

   17 SessionOpen  c 66.249.72.22 47013 :80
   17 ReqStart     c 66.249.72.22 47013 487860892
   17 RxRequest    c GET
   17 RxURL        c /find-Linux-command-to-find-files-on-your-disk
   17 RxProtocol   c HTTP/1.1
   17 RxHeader     c Host: www.go2linux.org
   17 RxHeader     c Connection: Keep-alive
   17 RxHeader     c Accept: */*
   17 RxHeader     c From: googlebot(at)googlebot.com
   17 RxHeader     c User-Agent: Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)
   17 RxHeader     c Accept-Encoding: gzip,deflate
   17 RxHeader     c If-Modified-Since: Sun, 24 Jul 2011 16:10:35 GMT
   17 VCL_call     c recv lookup
   17 VCL_call     c hash hash
   17 Hit          c 487859722
   17 VCL_call     c hit deliver
   17 VCL_call     c deliver deliver
   17 TxProtocol   c HTTP/1.1
   17 TxStatus     c 304
   17 TxResponse   c Not Modified
   17 TxHeader     c Date: Mon, 25 Jul 2011 16:28:26 GMT
   17 TxHeader     c Via: 1.1 varnish
   17 TxHeader     c X-Varnish: 487860892
   17 TxHeader     c Last-Modified: Sun, 24 Jul 2011 16:10:35 GMT
   17 TxHeader     c Cache-Control: public, max-age=300
   17 TxHeader     c Vary: Accept-Encoding, Accept-Encoding
   17 TxHeader     c Connection: keep-alive
   17 TxHeader     c X-Cache: HIT
   17 TxHeader     c X-Cache-Hits: 1
   17 Length       c 0
   17 ReqEnd       c 487860892 1311611306.344539404 1311611306.344666958 0.000112295 0.000054836 0.000072718

We can now filter for any of those fields, and only show the records that contain certain value for a specific field. Let’s see an example.

varnishlog -c -o RxRequest GET

Will show all records (like the one above) that have the field RxRequest with GET value. You can also list all records for an specific IP

varnishlog -c -o SessionOpen 11.22.33.44

You can also write everything to a file with

varnishlog -w /home/user/varnish.log

and then read from there filtering with:

varnishlog -r /home/user/varnish.log -c -o SessionOpen 11.22.33.44

As you can see varnishlog can be very useful, if you can filter the info you really need