When providing support we often spend some time crafting varnishlog statements that will catch what we're looking for. Sometimes we need to deploy AWK and Perl to find what we're looking for. It's a bit cumbersome.
The proposed solution to this is quite elegant. We're building a new Varnish API that has a query language built into it. We've been discussing it back and forth for a couple of years and it looks like we're finally going to see this become a reality.
So, without any further explanation I thought I´d start by throwing out some examples:
varnishlog -c 'req.url eq "/foo"'
That one was intuitive.
varnishlog -c 'req.http.cookie ~ "logged_in" and ReqEnd[5] > 0.5'
This one filters out requests delivered to logged in users that take more than 0.5 seconds to deliver. Quite powerful, eh? The query language has all the usual comparators you'd expect.
Ordered mode
varnishlog -o 'beresp.status == 503'
This one has more than meets the eye. The -o switch changes behaviour somewhat and becomes extremely powerful. When in ordered mode, all backend transactions and ESI sub-requests are reported as part of the client transaction that initiated them. The level increases by one by a 'initiated by' relation, so for example a backend transaction will have one higher level than the client transaction that initiated it on a cache miss.
- Lvl 0: Client request (cache miss)
- Lvl 1: Backend request
- Lvl 1: ESI subrequest (cache miss)
- Lvl 2: Backend request
- Lvl 2: Backend request (VCL restart)
- Lvl 2: ESI subrequest (cache miss)
- Lvl 3: Backend request
- Lvl 1: ESI subrequest (cache hit)
Query operators will, unless limited, see an ordered mode transaction tree as a single transaction, and matching will be done on any log line from the complete tree.
So, you can write a query that matches some ESI included transaction somewhere and you can get varnishlog to dump every request that went into building that page. Quite powerful.
Image (c) 2007 Stephen Donaghy used under Creative Commons license.