VSL cheatsheet
This page explains a few options common to VSL tools and provides ready-to-use VSL queries to simplify the first steps around the Varnish Shared Log.
Concepts
For performance reasons, Varnish doesn’t write log files. Instead, it outputs them in an in-memory circular buffer. Other processes can then read this buffer and decide what to do with the information.
This translates into a few points:
- logging is extremely fast and doesn’t slow down the main process
- this allows you to log a great deal of data for each transaction
- another tool is needed to collect/process the logs
varnishlog
varnishlog is not the tool you want to collect logs to store. However, it is the
perfect choice to obtain debugging data thanks to the vast amount of data
it produces.
For example, here is a what a request and its' backend request looks like:
* << Request >> 2
- Begin req 1 rxreq
- Timestamp Start: 1556292791.607415 0.000000 0.000000
- Timestamp Req: 1556292791.607415 0.000000 0.000000
- ReqStart 127.0.0.1 45212
- ReqMethod GET
- ReqURL /
- ReqProtocol HTTP/1.1
- ReqHeader Host: 0:8080
- ReqHeader User-Agent: curl/7.64.1
- ReqHeader Accept: */*
- ReqHeader X-Forwarded-For: 127.0.0.1
- VCL_call RECV
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- VCL_call MISS
- VCL_return fetch
- Link bereq 3 fetch
- Timestamp Fetch: 1556292791.612406 0.004991 0.004991
- RespProtocol HTTP/1.0
- RespStatus 200
- RespReason OK
- RespHeader Server: SimpleHTTP/0.6 Python/3.7.3
- RespHeader Date: Fri, 26 Apr 2019 15:33:11 GMT
- RespHeader Content-type: text/html; charset=utf-8
- RespHeader Content-Length: 12771
- RespProtocol HTTP/1.1
- RespHeader X-Varnish: 2
- RespHeader Age: 0
- RespHeader Via: 1.1 varnish (Varnish/5.2)
- VCL_call DELIVER
- VCL_return deliver
- Timestamp Process: 1556292791.612452 0.005036 0.000046
- RespHeader Accept-Ranges: bytes
- RespHeader Connection: keep-alive
- Timestamp Resp: 1556292791.612531 0.005116 0.000079
- ReqAcct 70 0 70 256 12771 13027
- End
** << BeReq >> 3
-- Begin bereq 2 fetch
-- Timestamp Start: 1556292791.607599 0.000000 0.000000
-- BereqMethod GET
-- BereqURL /
-- BereqProtocol HTTP/1.1
-- BereqHeader Host: 0:8080
-- BereqHeader User-Agent: curl/7.64.1
-- BereqHeader Accept: */*
-- BereqHeader X-Forwarded-For: 127.0.0.1
-- BereqHeader Accept-Encoding: gzip
-- BereqHeader X-Varnish: 3
-- VCL_call BACKEND_FETCH
-- VCL_return fetch
-- BackendOpen 33 boot.default 127.0.0.1 9999 127.0.0.1 33424
-- BackendStart 127.0.0.1 9999
-- Timestamp Bereq: 1556292791.607716 0.000118 0.000118
-- Timestamp Beresp: 1556292791.611821 0.004223 0.004105
-- BerespProtocol HTTP/1.0
-- BerespStatus 200
-- BerespReason OK
-- BerespHeader Server: SimpleHTTP/0.6 Python/3.7.3
-- BerespHeader Date: Fri, 26 Apr 2019 15:33:11 GMT
-- BerespHeader Content-type: text/html; charset=utf-8
-- BerespHeader Content-Length: 12771
-- TTL RFC 120 10 0 1556292792 1556292792 1556292791 0 0
-- VCL_call BACKEND_RESPONSE
-- TTL HFP 5 0 0 1556292792
-- VCL_return pass
-- Storage malloc Transient
-- ObjProtocol HTTP/1.0
-- ObjStatus 200
-- ObjReason OK
-- ObjHeader Server: SimpleHTTP/0.6 Python/3.7.3
-- ObjHeader Date: Fri, 26 Apr 2019 15:33:11 GMT
-- ObjHeader Content-type: text/html; charset=utf-8
-- ObjHeader Content-Length: 12771
-- Fetch_Body 3 length stream
-- BackendClose 33 boot.default
-- Timestamp BerespBody: 1556292791.612237 0.004639 0.000416
-- Length 12771
-- BereqAcct 135 0 135 156 12771 12927
-- End
varnishncsa
varnishncsa, on the other hand, is completely suitable for storage-ready logs;
producing this kind of output:
127.0.0.1 - - [26/Apr/2019:08:33:11 -0700] "GET http://0:8080/ HTTP/1.1" 200 12771 "-" "curl/7.64.1"
By default, it mimics the default ncsa output, meaning that there is quite a
loss of information when compared to varnishlog, but you can use the -F and
-f arguments to specify your own format string. More information is available in
man varnishncsa.
Note that by default, varnishncsa only shows client-side requests. You can
use -b to show only backend-side requests, or -bc to show all of them.
Basics
Reading in real-time
In the default mode, varnishlog and varnishncsa will only produce
output as the traffic flows through Varnish.
varnishlog
Reading the backlog
Both varnishncsa and varnishlog accept the -d switch that will read the
backlog instead of reading new entries in real-time. This is especially useful
if you want to check recent history.
varnishlog -d
Reading/writing a file
varnishlog can be used to write a (binary) file after filtering the requests:
varnishlog -w /var/logs/varnish/log.bin
This file can then be read by varnishncsa or varnishlog using -r and
possibly filtered again:
varnishncsa -r /var/logs/varnish/log.bin
Grouping requests
varnishlog, by default, will show individual transactions, but it is often
useful to group them to know which one causes what (ex. request to backend request,
ESI page to subfragment, etc.). This is done using -g requests:
varnishlog -g request
Check man varnishlog for more -g options.
VSL queries
The VSL query language is extensively documented in man vsl-query and
man vsl should be used as a reference to explain each record structure.
All queries are to be given as a parameter to the -q argument of a series of
Varnish tools:
- varnishlog
- varnishncsa
- varnishtop
- varnishhist
So, given the query ReqURL eq "/foo", all of these are valid:
varnishlog -q 'ReqURL eq "/foo"' -g request
varnishncsa -q 'ReqURL eq "/foo"' -d
varnishtop -q 'ReqURL eq "/foo"' -r /var/logs/varnish/log.bin
varnishhist -q 'ReqURL eq "/foo"'
Each will do its' own thing after having filtered the requests matching the query.
Integer warning
When comparing floats (like timestamps), be sure to represent your numbers as
floats (add a . at the end) to avoid the parser mistaking them as string.
In short:
# yes
varnishlog -q 'Timestamp:Process[2] > 8.'
# no
varnishlog -q 'Timestamp:Process[2] > 8'
Error requests
RespStatus >= 500
You can also be a bit more selective:
RespStatus != 200 and RespStatus != 304
Slow requests
Slow client:
Timestamp:Resp[2] > 5.
Slow backend:
Timestamp:BerespBody[2] > 5.
Exact URL
ReqURL eq "/foo"
Header value
Request host:
ReqHeader:Host eq api.example.com
Response server:
RespHeader:Server ~ apache
Find a vxid
Each Varnish request has a unique identifier called a vxid. This identifier
is placed in the x-varnish response header. It can also be logged as the XID
in a Guru Meditation response. You can use the vxid keyword to find the
request as follows:
vxid == 47822
Requests tagged with std.log()
It is possible to log information about a request from the VCL:
import std;
sub vcl_recv {
if (req.url == "/foo") {
std.log("tagA: valueA");
}
}
Once in place, it is simple to filter by:
Tag presence
VCL_Log:tagA
Tag absence
! VCL_Log:tagA
Tag value
VCL_Log:tagA eq valueA
Non-cached requests
Passes
Badly configured caches can pass (bypass the cache) cacheable content with a
return(pass) in vcl_recv. You can find the passed request with this:
Link[3] eq pass
Hit-for-miss
Content that is deemed uncacheable on the backend-side (max-age=0,
private content, etc.) is marked as uncacheable and becomes hit-for-miss,
instructing Varnish to avoid request coalescing for these.
To find hit-for-miss (HfM) requests:
HitMiss
To find the backend responses as they are marked as HfM, there is a convenient one-liner.
This will also show hit-for-pass (HfP) insertions; you can save the result, then
exclude the HfP transactions:
TTL[6] eq uncacheable
This will work as long as you don’t use -g. The deliver from the requests
will get a match and give the same result as the previous query:
TTL[6] eq uncacheable and VCL_return eq deliver
Hit-for-pass
HfP is the same as HfM except that if the content becomes cacheable, it still isn’t cached until the HfP window is over. To find the HfP requests:
Link[3] eq pass and VCL_return eq lookup
To find the insertions:
TTL[1] eq HFP