{"id":781,"date":"2013-05-25T09:45:03","date_gmt":"2013-05-25T07:45:03","guid":{"rendered":"http:\/\/www.streppone.it\/cosimo\/blog\/?p=781"},"modified":"2013-05-25T10:10:47","modified_gmt":"2013-05-25T08:10:47","slug":"display-and-filter-traffic-at-the-varnish-level-vlogdump","status":"publish","type":"post","link":"https:\/\/www.streppone.it\/cosimo\/blog\/2013\/05\/display-and-filter-traffic-at-the-varnish-level-vlogdump\/","title":{"rendered":"Display and filter traffic at the varnish level: vlogdump"},"content":{"rendered":"

Haven’t written much in the last few months. The reason is that I’ve been at work building the Opera Discover<\/a> service backend, that we launched on Opera mobile for Android just a few days ago.<\/p>\n

A few weeks before, during the first stress test sessions of Discover, I wrote this little tool called vlogdump<\/code> that Opera allowed me to put up on github<\/a>. The main purpose, besides learning awk<\/a> :-) is to display and filter traffic coming into your varnish daemon.<\/b>.<\/p>\n

vlogdump<\/code> is not meant to replace varnishlog<\/code> but I know that sometimes varnishlog gives me too much output to deal with, especially if I want to pinpoint a single client or a single request. I know that the varnishlog that ships with varnish 3.0.x is way better in this regard, but we’re using 2.1.x, and that version of varnishlog is not as capable.<\/p>\n

vlogdump<\/code> is easier to look at than varnishlog, but at the same time it conveys much more information than varnishncsa<\/code> or the typical access.log<\/code> format.<\/p>\n

Here’s an example of output:<\/p>\n

$ varnishlog | vlogdump -v only_misses=1
\n 172.22.0.15 => GET \/assets\/e85ed0a7b1b87120a0a2bfa025531c6733a48802 HTTP\/1.0 MISS<\/span>
\n            <= 200 OK 28.432 ms\n 172.22.0.18 => GET \/assets\/5a9e9440c5c85e8dc5d65e03e15c95e390901fa7 HTTP\/1.0 MISS<\/span>
\n            <= 200 OK 36.905 ms\n 172.22.0.18 => GET \/icons\/categories\/te\/icon32x32-technology.png HTTP\/1.0 MISS<\/span>
\n            <= 304 Not Modified 0.589 ms\n 172.22.0.15 => GET \/api\/fetch\/article-preview\/?client=2&language=en-GB HTTP\/1.1 MISS<\/span>
\n            <= 301 MOVED PERMANENTLY 8.381 ms\n 172.22.0.18 => GET \/assets\/c3830e95b717761005e26ce49ebab253e0ccb40b HTTP\/1.0 MISS<\/span>
\n            <= 200 OK 291.354 ms\n 172.22.0.18 => GET \/api\/category?client=2&language=en-GB HTTP\/1.1 MISS<\/span>
\n            <= 200 OK 58.025 ms\n  ...\n<\/code>\n<\/div>\n

Another interesting example.<\/p>\n

Show request and response headers of transactions that resulted in cache hits and had request headers (any of them) matching \"Android\"<\/b>:<\/p>\n

$ varnishlog | vlogdump -v show_req_headers=1 -v show_resp_headers=1 -v req_headers_match=Android -v only_hits=1
\n 83.149.37.122 => GET \/api\/category\/?... HTTP\/1.1 HIT<\/span>
\n            <= 200 OK         0.088 ms<\/span>
\n   req.http.Accept = application\/json;version=1
\n   req.http.Accept-Encoding = gzip
\n   req.http.Host = ...opera.com
\n   req.http.Connection = Keep-Alive
\n   req.http.User-Agent = Mozilla\/5.0 (Linux; Android 4.1.2; GT-N7100 Build\/JZO54K) AppleWebKit\/537.31 (KHTML, like Gecko) Chrome\/26.0.1410.58 Mobile Safari\/537.31 OPR\/14.0.1074.57768
\n 
\n   beresp.http.Server = Apache
\n   beresp.http.Content-Encoding = gzip
\n   beresp.http.Content-Type = application\/json
\n   beresp.http.Vary = Accept-Encoding, Origin
\n   beresp.http.Content-Length = 4217
\n   beresp.http.Date = Sat, 25 May 2013 07:59:53 GMT
\n   beresp.http.X-Varnish = 1611090407 1611007435
\n   beresp.http.Age = 267
\n   beresp.http.Via = 1.1 varnish
\n   beresp.http.Connection = keep-alive
\n<\/code>\n<\/div>\n

Now that you're eager to try it :-), you can do so in a few commands, and assuming you have the right awk installed:<\/p>\n

wget -q -Ovlogdump https:\/\/raw.github.com\/cosimo\/vlogdump\/master\/vlogdump
\nvarnishlog | .\/vlogdump [options]
\n<\/code><\/p>\n

The documentation<\/a> lists all the available options.<\/p>\n

You can do more interesting things<\/b>:<\/p>\n