VSL cheatsheet Tutorial

This page aims to explains a few options common to some VSL tools, and also provides some 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 a 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 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’s the perfect choice to obtain debugging data thanks to the indecent amount of data it produces.

As an example, here’s 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 totally 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’s 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 show client-side requests, you can use -b to show only backend-side ones, or -bc to show them all.

Basics

Reading in real-time

This is 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 realtime. This is specially 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 te 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 cause one (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 parameter to the -q argument of a series of varnish tools:

  • varnishlog
  • varnishncsa
  • varnishtop
  • varnishhist

So, given a query ReqURL eq "/foo", all 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 of course do its own thing, but 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.0'
# no
varnishlog -q 'Timestamp:Process[2] > 8.'

Error requests

ReqStatus >= 500

You can also be a bit more selective:

ReqStatus != 200 and ReqStatus != 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’s 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’s 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 decided on the backend-side to be uncacheable (max-age=0, private content, etc.) is marked as uncacheable and become hit-for-miss, instructing Varnish to avoid request coalescing for them.

To find the HfM requests:

HitMiss

To find the backend responses as they are marked as HfM, there’s convenient one-liner.

This will also show hit-for-pass 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