Testing with varnishtest

You may not be aware of this, but VarnishTest is an awesome tool. varnishtest is a sandbox (testing environment) that is completely isolated from the production environment where one can TEST untested code changes and do all kinds of out-of-this-world experimentation.

varnishtest protects your “live” servers, reviewed VCL codes and other collections of data and/or content from severe changes that could be caused by experimental code. We all know that once in a mission-critical system phase it is quite difficult to revert back.

Varnish comes with varnishtest pre-installed and runs personalized tests for whatever case you define. There is also a whole set of pre-defined tests that you can use to help your understanding and testing.

Here is a list of contexts where you can use VarnishTest:

  • Testing your Varnish and backend installation
  • Configuring your Varnish Cache installation
  • When writing complex caching policies in VCL such as:
    • test a cache invalidation method
    • reproduce bugs when filing a report
  • When tuning Varnish Cache
  • To define and test modules for Varnish Cache extensions (VMOD)
  • Writing applications that integrate well with Varnish Cache and utilize all its characteristics.

The Varnish Testcase Language (VTC)

This is the language that varnishtest understands. The extension used by Varnish test case files is (.vtc).

Normally, a VTC file describes a scenario with different scripted HTTP-talking operations and generally one or more Varnish instances (clients) to test.

Naming convention

varnishtest has a whole set of pre-defined tests that you can use if you understand what it is doing. It follows a naming convention, which will help you to understand which set is what type of example.



Prefix:   [id]%05d.vtc

	id ~ [a] --> varnishtest(1) tests
	id ~ [b] --> Basic functionality tests
	id ~ [c] --> Complex functionality tests
	id ~ [d] --> Director VMOD tests
	id ~ [e] --> ESI tests
	id ~ [g] --> GZIP tests
	id ~ [j] --> JAIL tests
	id ~ [l] --> VSL tests
	id ~ [m] --> VMOD tests excluding director
	id ~ [o] --> prOxy protocol
	id ~ [p] --> Persistent tests
	id ~ [r] --> Regression tests, same number as ticket
	id ~ [s] --> Slow tests, expiry, grace etc.
	id ~ [t] --> sTreaming tests
	id ~ [u] --> Unusual background processes
	id ~ [v] --> VCL tests: execute VRT functions

Note: You can use any naming convention to write your test, but a defined naming convention could help you to avoid rewriting similar tests.

Name the test

varnishtest requires that you name the test. Here is an example:

varnishtest "This is a varnishtest for testing"

Defining the components

varnishtest requires three components to run the test:

  • A server (origin server)
  • A Varnish Cache instance
  • A client
Sphinx Neo-Hittite

Declaring the server

  • A server declaration must start with s
  • rxreq : accepts/receives requests
  • txresp : transmits/responds to requests
  • - start : boots server

What follows is an example of declaring a server:

server s1 {
  rxreq
  txresp
} -start

Declaring the Varnish Cache instance

  • A Varnish Cache instance declaration must start with v
  • Instance controlled by the manager process
  • - start : forks a child for this instance from the actual cache process

What follows is an example of declaring a Varnish Cache instance:

varnish v1 -arg "-b ${s1_addr}:${s1_port}" -start

Declaring a client

  • Stimulated client declaration must start with c
  • - run : starts the client

What follows is an example of declaring a Varnish Cache instance:

client c1 {
 txreq
 rxresp

 expect resp.http.via ~ "varnish"
} -run

In this example, c1 transmits one request and receives one response.

Since Varnish is a proxy instance, the response should be received from the backend via Varnish Cache (Varnish instance in this case).

  • we can see c1 expects Varnish in the via HTTP header field.
  • The tilde (~) is used as a match operator of regular expressions
  • the exact name of the variable here (e.g. resp.http.via) depends on the version of Varnish installed.

Running the test

  • To run the test, issue the command as shown below:
varnishtest example.vtc

Note: If you are writing your own test, make sure that you point to the directory where the test is stored.

This is the positive output to expect:

#     top  TEST example.vtc passed (1.709)

If you feel the need to inspect/understand the test better, you can always try the verbose mode with a -v as shown below:

varnishtest -v example.vtc

This is what a verbose output looks like for the example.vtc:

**** top   0.0 macro def varnishd=varnishd
**** top   0.0 macro def varnishadm=varnishadm
**** top   0.0 macro def varnishstat=varnishstat
**** top   0.0 macro def varnishhist=varnishhist
**** top   0.0 macro def varnishlog=varnishlog
**** top   0.0 macro def varnishncsa=varnishncsa
**** top   0.0 macro def vmod_std=std
**** top   0.0 macro def vmod_debug=debug
**** top   0.0 macro def vmod_directors=directors
**** top   0.0 macro def pwd=/home/syeda/vagrant/wiki_varnish/source/vtc
**** top   0.0 macro def bad_ip=192.0.2.255
**** top   0.0 macro def tmpdir=/tmp/vtc.28133.566a24ae
*    top   0.0 TEST example.vtc starting
**   top   0.0 === varnishtest "Varnish as Proxy"
*    top   0.0 TEST Varnish as Proxy
**   top   0.0 === server s1 {
**   s1    0.0 Starting server
**** s1    0.0 macro def s1_addr=127.0.0.1
**** s1    0.0 macro def s1_port=38019
**** s1    0.0 macro def s1_sock=127.0.0.1 38019
*    s1    0.0 Listen on 127.0.0.1 38019
**   top   0.0 === varnish v1 -arg "-b ${s1_addr}:${s1_port}" -start
**   s1    0.0 Started on 127.0.0.1 38019
**   v1    0.0 Launch
***  v1    0.0 CMD: cd ${pwd} && exec ${varnishd}  -d -n /tmp/vtc.28133.566a24ae/v1 -l 2m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -p sigsegv_handler=on -p thread_pool_min=10 -p debug=+vtc_mode -a '127.0.0.1:0' -M '127.0.0.1 35687' -P /tmp/vtc.28133.566a24ae/v1/varnishd.pid  -b 127.0.0.1:38019
***  v1    0.0 CMD: cd /home/syeda/vagrant/wiki_varnish/source/vtc && exec varnishd  -d -n /tmp/vtc.28133.566a24ae/v1 -l 2m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -p sigsegv_handler=on -p thread_pool_min=10 -p debug=+vtc_mode -a '127.0.0.1:0' -M '127.0.0.1 35687' -P /tmp/vtc.28133.566a24ae/v1/varnishd.pid  -b 127.0.0.1:38019
***  v1    0.0 PID: 28139
**** v1    0.0 macro def v1_pid=28139
**** v1    0.0 macro def v1_name=/tmp/vtc.28133.566a24ae/v1
***  v1    0.1 debug| Debug: Platform: Linux,4.4.0-31-generic,x86_64,-jnone,-smalloc,-smalloc,-hcritbit\n
***  v1    0.1 debug| \n
***  v1    0.1 debug| 200 282     \n
***  v1    0.1 debug| -----------------------------\n
***  v1    0.1 debug| Varnish Cache CLI 1.0\n
***  v1    0.1 debug| -----------------------------\n
***  v1    0.1 debug| Linux,4.4.0-31-generic,x86_64,-jnone,-smalloc,-smalloc,-hcritbit\n
***  v1    0.1 debug| varnish-4.1.3 revision 5e3b6d2\n
***  v1    0.1 debug| \n
***  v1    0.1 debug| Type 'help' for command list.\n
***  v1    0.1 debug| Type 'quit' to close CLI session.\n
***  v1    0.1 debug| Type 'start' to launch worker process.\n
***  v1    0.1 debug| \n
**** v1    0.2 CLIPOLL 1 0x1 0x0
***  v1    0.2 CLI connection fd = 10
***  v1    0.2 CLI RX  107
**** v1    0.2 CLI RX| rschtjfhvawvmhipbkcwawqnfpfnpzfj\n
**** v1    0.2 CLI RX| \n
**** v1    0.2 CLI RX| Authentication required.\n
**** v1    0.2 CLI TX| auth 0bfbf4b8810db883298f9986c13c96e53c6f5df332d2bf4202127028da5388ac\n
***  v1    0.2 CLI RX  200
**** v1    0.2 CLI RX| -----------------------------\n
**** v1    0.2 CLI RX| Varnish Cache CLI 1.0\n
**** v1    0.2 CLI RX| -----------------------------\n
**** v1    0.2 CLI RX| Linux,4.4.0-31-generic,x86_64,-jnone,-smalloc,-smalloc,-hcritbit\n
**** v1    0.2 CLI RX| varnish-4.1.3 revision 5e3b6d2\n
**** v1    0.2 CLI RX| \n
**** v1    0.2 CLI RX| Type 'help' for command list.\n
**** v1    0.2 CLI RX| Type 'quit' to close CLI session.\n
**** v1    0.2 CLI RX| Type 'start' to launch worker process.\n
**   v1    0.2 Start
**** v1    0.2 CLI TX| start
***  v1    0.3 debug| Debug: Child (28151) Started\n
***  v1    0.3 CLI RX  200
***  v1    0.3 wait-running
**** v1    0.3 CLI TX| status
***  v1    0.3 debug| Info: Child (28151) said Child starts\n
**** v1    0.3 vsl|          0 CLI             - Rd vcl.load "boot" vcl_boot.1470819134.142765999/vgc.so 1auto
**** v1    0.3 vsl|          0 CLI             - Wr 200 55 Loaded "vcl_boot.1470819134.142765999/vgc.so" as "boot"
**** v1    0.3 vsl|          0 CLI             - Rd vcl.use "boot"
**** v1    0.3 vsl|          0 CLI             - Wr 200 0
**** v1    0.3 vsl|          0 CLI             - Rd start
**** v1    0.3 vsl|          0 CLI             - Wr 200 0
***  v1    0.3 CLI RX  200
**** v1    0.3 CLI RX| Child in state running
**** v1    0.3 CLI TX| debug.xid 999
***  v1    0.4 CLI RX  200
**** v1    0.4 CLI RX| XID is 999
**** v1    0.4 CLI TX| debug.listen_address
**** v1    0.4 vsl|          0 CLI             - Rd debug.xid 999
**** v1    0.4 vsl|          0 CLI             - Wr 200 10 XID is 999
***  v1    0.4 CLI RX  200
**** v1    0.4 CLI RX| 127.0.0.1 42992\n
**   v1    0.4 Listen on 127.0.0.1 42992
**** v1    0.4 macro def v1_addr=127.0.0.1
**** v1    0.4 macro def v1_port=42992
**** v1    0.4 macro def v1_sock=127.0.0.1 42992
**   top   0.4 === client c1 {
**   c1    0.4 Starting client
**   c1    0.4 Waiting for client
***  c1    0.4 Connect to 127.0.0.1 42992
***  c1    0.4 connected fd 11 from 127.0.0.1 48370 to 127.0.0.1 42992
**   c1    0.4 === txreq
**** c1    0.4 txreq| GET / HTTP/1.1\r\n
**** c1    0.4 txreq| \r\n
**   c1    0.4 === rxresp
***  s1    0.4 accepted fd 5
**   s1    0.4 === rxreq
**** s1    0.4 rxhdr| GET / HTTP/1.1\r\n
**** s1    0.4 rxhdr| X-Forwarded-For: 127.0.0.1\r\n
**** s1    0.4 rxhdr| Accept-Encoding: gzip\r\n
**** s1    0.4 rxhdr| X-Varnish: 1002\r\n
**** s1    0.4 rxhdr| Host: 127.0.0.1:38019\r\n
**** s1    0.4 rxhdr| \r\n
**** s1    0.4 rxhdrlen = 109
**** s1    0.4 http[ 0] | GET
**** s1    0.4 http[ 1] | /
**** s1    0.4 http[ 2] | HTTP/1.1
**** s1    0.4 http[ 3] | X-Forwarded-For: 127.0.0.1
**** s1    0.4 http[ 4] | Accept-Encoding: gzip
**** s1    0.4 http[ 5] | X-Varnish: 1002
**** s1    0.4 http[ 6] | Host: 127.0.0.1:38019
**** s1    0.4 bodylen = 0
**   s1    0.4 === txresp
**** s1    0.4 txresp| HTTP/1.1 200 OK\r\n
**** s1    0.4 txresp| Content-Length: 0\r\n
**** s1    0.4 txresp| \r\n
***  s1    0.4 shutting fd 5
**   s1    0.4 Ending
**** c1    0.4 rxhdr| HTTP/1.1 200 OK\r\n
**** c1    0.4 rxhdr| Content-Length: 0\r\n
**** c1    0.4 rxhdr| Date: Wed, 10 Aug 2016 08:52:14 GMT\r\n
**** c1    0.4 rxhdr| X-Varnish: 1001\r\n
**** c1    0.4 rxhdr| Age: 0\r\n
**** c1    0.4 rxhdr| Via: 1.1 varnish-v4\r\n
**** c1    0.4 rxhdr| Accept-Ranges: bytes\r\n
**** c1    0.4 rxhdr| Connection: keep-alive\r\n
**** c1    0.4 rxhdr| \r\n
**** c1    0.4 rxhdrlen = 167
**** c1    0.4 http[ 0] | HTTP/1.1
**** c1    0.4 http[ 1] | 200
**** c1    0.4 http[ 2] | OK
**** c1    0.4 http[ 3] | Content-Length: 0
**** c1    0.4 http[ 4] | Date: Wed, 10 Aug 2016 08:52:14 GMT
**** c1    0.4 http[ 5] | X-Varnish: 1001
**** c1    0.4 http[ 6] | Age: 0
**** c1    0.4 http[ 7] | Via: 1.1 varnish-v4
**** c1    0.4 http[ 8] | Accept-Ranges: bytes
**** c1    0.4 http[ 9] | Connection: keep-alive
**** c1    0.4 bodylen = 0
**   c1    0.4 === expect resp.http.via ~ "varnish"
**** c1    0.4 EXPECT resp.http.via (1.1 varnish-v4) ~ "varnish" match
***  c1    0.4 closing fd 11
**   c1    0.4 Ending
*    top   0.4 RESETTING after example.vtc
**   s1    0.4 Waiting for server (4/-1)
**** s1    0.4 macro undef s1_addr
**** s1    0.4 macro undef s1_port
**** s1    0.4 macro undef s1_sock
**   v1    0.4 Wait
**** v1    0.4 CLI TX| backend.list
***  v1    0.5 CLI RX  200
**** v1    0.5 CLI RX| Backend name                   Admin      Probe\n
**** v1    0.5 CLI RX| boot.default                   probe      Healthy (no probe)
**   v1    0.5 Stop
**** v1    0.5 CLI TX| stop
**** v1    0.5 vsl|          0 CLI             - Rd debug.listen_address
**** v1    0.5 vsl|          0 CLI             - Wr 200 16 127.0.0.1 42992

**** v1    0.5 vsl|       1000 Begin           c sess 0 HTTP/1
**** v1    0.5 vsl|       1000 SessOpen        c 127.0.0.1 48370 127.0.0.1:42992 127.0.0.1 42992 1470819134.544697 19
**** v1    0.5 vsl|       1000 Link            c req 1001 rxreq
**** v1    0.5 vsl|          0 ExpKill         - EXP_Inbox p=0x7fcac24290c0 e=0.000000000 f=0x8
**** v1    0.5 vsl|          0 ExpKill         - EXP_When p=0x7fcac24290c0 e=1470819264.546130657 f=0x1c10
**** v1    0.5 vsl|       1002 Begin           b bereq 1001 fetch
**** v1    0.5 vsl|       1002 Timestamp       b Start: 1470819134.544893 0.000000 0.000000
**** v1    0.5 vsl|       1002 BereqMethod     b GET
**** v1    0.5 vsl|       1002 BereqURL        b /
**** v1    0.5 vsl|       1002 BereqProtocol   b HTTP/1.1
**** v1    0.5 vsl|       1002 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    0.5 vsl|       1002 BereqHeader     b Accept-Encoding: gzip
**** v1    0.5 vsl|       1002 BereqHeader     b X-Varnish: 1002
**** v1    0.5 vsl|       1002 VCL_call        b BACKEND_FETCH
**** v1    0.5 vsl|       1002 VCL_return      b fetch
**** v1    0.5 vsl|       1002 BereqHeader     b Host: 127.0.0.1:38019
**** v1    0.5 vsl|       1002 BackendOpen     b 22 boot.default 127.0.0.1 38019 127.0.0.1 36052
**** v1    0.5 vsl|       1002 BackendStart    b 127.0.0.1 38019
**** v1    0.5 vsl|       1002 Timestamp       b Bereq: 1470819134.545688 0.000795 0.000795
**** v1    0.5 vsl|       1002 Timestamp       b Beresp: 1470819134.546131 0.001238 0.000443
**** v1    0.5 vsl|       1002 BerespProtocol  b HTTP/1.1
**** v1    0.5 vsl|       1002 BerespStatus    b 200
**** v1    0.5 vsl|       1002 BerespReason    b OK
**** v1    0.5 vsl|       1002 BerespHeader    b Content-Length: 0
**** v1    0.5 vsl|       1002 BerespHeader    b Date: Wed, 10 Aug 2016 08:52:14 GMT
**** v1    0.5 vsl|       1002 TTL             b RFC 120 10 -1 1470819135 1470819135 1470819134 0 0
**** v1    0.5 vsl|       1002 VCL_call        b BACKEND_RESPONSE
**** v1    0.5 vsl|       1002 VCL_return      b deliver
**** v1    0.5 vsl|       1002 Storage         b malloc s0
**** v1    0.5 vsl|       1002 ObjProtocol     b HTTP/1.1
**** v1    0.5 vsl|       1002 ObjStatus       b 200
**** v1    0.5 vsl|       1002 ObjReason       b OK
**** v1    0.5 vsl|       1002 ObjHeader       b Content-Length: 0
**** v1    0.5 vsl|       1002 ObjHeader       b Date: Wed, 10 Aug 2016 08:52:14 GMT
**** v1    0.5 vsl|       1002 Fetch_Body      b 0 none -
**** v1    0.5 vsl|       1002 BackendReuse    b 22 boot.default
**** v1    0.5 vsl|       1002 Timestamp       b BerespBody: 1470819134.556594 0.011701 0.010463
**** v1    0.5 vsl|       1002 Length          b 0
**** v1    0.5 vsl|       1002 BereqAcct       b 109 0 109 38 0 38
**** v1    0.5 vsl|       1002 End             b
**** v1    0.5 vsl|       1001 Begin           c req 1000 rxreq
**** v1    0.5 vsl|       1001 Timestamp       c Start: 1470819134.544785 0.000000 0.000000
**** v1    0.5 vsl|       1001 Timestamp       c Req: 1470819134.544785 0.000000 0.000000
**** v1    0.5 vsl|       1001 ReqStart        c 127.0.0.1 48370
**** v1    0.5 vsl|       1001 ReqMethod       c GET
**** v1    0.5 vsl|       1001 ReqURL          c /
**** v1    0.5 vsl|       1001 ReqProtocol     c HTTP/1.1
**** v1    0.5 vsl|       1001 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    0.5 vsl|       1001 VCL_call        c RECV
**** v1    0.5 vsl|       1001 VCL_return      c hash
**** v1    0.5 vsl|       1001 VCL_call        c HASH
**** v1    0.5 vsl|       1001 VCL_return      c lookup
**** v1    0.5 vsl|       1001 VCL_call        c MISS
**** v1    0.5 vsl|       1001 VCL_return      c fetch
**** v1    0.5 vsl|       1001 Link            c bereq 1002 fetch
**** v1    0.5 vsl|       1001 Timestamp       c Fetch: 1470819134.556696 0.011911 0.011911
**** v1    0.5 vsl|       1001 RespProtocol    c HTTP/1.1
**** v1    0.5 vsl|       1001 RespStatus      c 200
**** v1    0.5 vsl|       1001 RespReason      c OK
**** v1    0.5 vsl|       1001 RespHeader      c Content-Length: 0
**** v1    0.5 vsl|       1001 RespHeader      c Date: Wed, 10 Aug 2016 08:52:14 GMT
**** v1    0.5 vsl|       1001 RespHeader      c X-Varnish: 1001
**** v1    0.5 vsl|       1001 RespHeader      c Age: 0
**** v1    0.5 vsl|       1001 RespHeader      c Via: 1.1 varnish-v4
**** v1    0.5 vsl|       1001 VCL_call        c DELIVER
**** v1    0.5 vsl|       1001 VCL_return      c deliver
**** v1    0.5 vsl|       1001 Timestamp       c Process: 1470819134.556794 0.012010 0.000098
**** v1    0.5 vsl|       1001 RespHeader      c Accept-Ranges: bytes
**** v1    0.5 vsl|       1001 Debug           c RES_MODE 2
**** v1    0.5 vsl|       1001 RespHeader      c Connection: keep-alive
**** v1    0.5 vsl|       1001 Timestamp       c Resp: 1470819134.556935 0.012150 0.000140
**** v1    0.5 vsl|       1001 ReqAcct         c 18 0 18 167 0 167
**** v1    0.5 vsl|       1001 End             c
**** v1    0.5 vsl|       1000 SessClose       c REM_CLOSE 0.014
**** v1    0.5 vsl|       1000 End             c
**** v1    0.5 vsl|          0 CLI             - Rd backend.list
**** v1    0.5 vsl|          0 CLI             - Wr 200 108 Backend name                   Admin      Probe
boot.default                   probe      Healthy (no probe)
***  v1    0.5 debug| Debug: Stopping Child\n
**** v1    0.6 vsl|          0 CLI             - EOF on CLI connection, worker stops
***  v1    1.5 debug| Info: Child (28151) ended\n
***  v1    1.5 debug| Info: Child (28151) said Child dies\n
***  v1    1.5 debug| Debug: Child cleanup complete\n
***  v1    1.5 CLI RX  200
**** v1    1.5 CLI TX| status
***  v1    1.5 CLI RX  200
**** v1    1.5 CLI RX| Child in state stopped
**** v1    1.5 STDOUT poll 0x10
**   v1    1.5 R 28139 Status: 0000 (u 0.112000 s 0.036000)
*    top   1.6 TEST example.vtc completed

#     top  TEST example.vtc passed (1.612)

Taking your varnishtest to the next level

Connecting a real backend

varnish v1 -vcl {

	# Server declaration here

	backend default {
		.host = "${s1_addr}";
		.port = "${s1_port}";
	}

	sub vcl_deliver {
		set resp.http.hello = example.hello("Varnish!");
	}
} -start

Server - Answering more than one request

# more then one backend

server s1 {
  rxreq
  txresp

  rxreq
  txresp
 } -start

Server - Expecting a request with URL

# expecting a request with a given url

server s1 {
  rxreq
  expect req.url == "/"
  txresp
} -start

Server - Expecting particular text in body

#Expecting an url with specified text in the body

server s1 {
    rxreq
    expect req.url == "info.varnish-software.com/blog/"
    txresp  -body "varnish"

    rxreq
    expect req.url == "info.varnish-software.com/blog/"
    txresp  -body "cache"

}

Client - Expecting response

# running one client multiple times to mock up a stream of client requests

client c1 {
	txreq
	rxresp
}

client c1 -run
client c1 -run
client c1 -run


# client sending multiple requests

clent c1 {
	txreq -url "/info.varnish-software.com/blog/"
	rxresp
  expect resp.status == 200

	txreq -url "/info.varnish-software.com/blog/"
	rxresp
  expect resp.status == 200
} -run

delay 0.5

#client expecting particular response

client c1 {
	txreq -url "/"
	rxresp
	expect resp.http.hello == "Hello Varnish!"
} -run

Setting Varnish to expect

# setting varnish to expect

varnish v1 -expect cache_miss == 0
varnish v1 -expect cache_hit == 0

client c1 -run

varnish v1 -expect cache_miss == 2
varnish v1 -expect cache_hit == 0

client c1 -run
client c1 -run
client c1 -run

varnish v1 -expect cache_miss == 2
varnish v1 -expect cache_hit == 6

You may have noticed varnishtest preparing, executing

Some resources to look at for VarnishTest

If you want to try out the test cases available with varnishtest, clone the varnish-cache repository from github and visit the folder:

cd varnish-cache/bin/varnishtest/tests

All the tests are here. Run them with VarnishTest

Naming Scheme for VarnishTest

Another great post at Smashing Magazine about VarnishTest written by our field engineer, Arianna Aondio

Understanding VTC

VarnishTest for Humans

Getting started with VarnishTest