Hands-on varnishtest

Tags: ops (30)

This tutorial will help you dive into varnishtest using self-contained and concrete examples that you can run on your own computer. Each test case adds more layers and is duly commented so you can explore on your own.

The supporting files can be found in this repository and are linked to at the beginning of each section.

1. The most basic test case

Let’s start with basic-001.vtc:

# lines starting with a # are comment, they are ignored by varnishtest,
# same as empty lines

# every vtc MUST start with a "varnishtest DESCRIPTION" line

varnishtest "This does nothing"

We can run this with varnishtest basic-001.vtc:

$ varnishtest basic-001.vtc
#    top  TEST basic-001.vtc passed (0.093)

It’s not very exciting, but it works, and it’s fast (93ms!).

If you do not have varnishtest installed (it’s part of the regular varnish/varnish-plus package), you can use docker instead:

# mount basic-001.vtc as /test.vtc and execute it inside the container
docker run --rm -v $(pwd)/basic-001.vtc:/test.vtc varnish varnishtest /test.vtc
#    top  TEST /test.vtc passed (0.054)

Future section will not repeat the docker instruction, but know that it’s always an option!

2. Multiline strings, curly braces and verbosity

In basic-002.vtc we add strings:

varnishtest {this looks
weird
right}

# run that test with "varnistest -v basic-002.vtc" to confirm the
# multi-line-ness of the title

Let’s start with a weird syntax quirk: while we use double quotes (") for single-line strings, we can also use {} for multi-line strings:

varnishtest {this looks
weird
right}

This will work:

$ varnishtest basic-002.vtc
#    top  TEST basic-002.vtc passed (0.023)

but that’s not very telling, let’s rerun that in verbose more, with the -v flag (we’ll snip the irrelevant log lines):

$ varnishtest basic-002.vtc -v
<snip>
**   top   === varnishtest {this looks
*    top   VTEST this looks
weird
right
<snip>

Here you can see two things:

  • the top === is varnishtest telling us where in the file it is, and what it’s about to execute

  • the top VTEST is the actual output of the actions, and we can verify it actually saw the 3-lines string

This multiline string trick will come in handy very, very soon!

3. The server

varnishtest is centered around agents that will perform tasks independently. Those tasks are defined in specification strings that look like code blocks thanks to the {} multi-line quirk.

Let’s start easy with a server that just receives a request and sends back a response. The name of the server must start with an “s” (in general, agent names start with the first letter of the agent type).

Once the server specification is defined, we will start s1 and wait for the scenario to finish. Here is basic-003.vtc:

varnishtest "our first agent and specification block"

server s1 {
	# receive request
	rxreq
	# transmit response
	txresp -status 200 -hdr "connection: close" -hdr "beep: boop" -body "Father\n"
}

# note that this above doesn't actually start the server, it mereley defines it
# we can start the server like this
server s1 -start

# then, we can ask s1 to wait, and the call will only return once the spec is
# executed
server s1 -wait

Ok, let us run this test case:

varnishtest basic-003.vtc

It will do… nothing? This is because right now varnishtest is waiting for the s1 specification to finish, and currently it is stuck on the rxreq statement, meaning it is waiting for a request. So we are now going to open a new terminal, and send that request!

First we need to find the ip:port that s1 is listening on:

ss -plt |grep varnishtest
LISTEN 0      10         127.0.0.1:42849      0.0.0.0:*    users:(("varnishtest",pid=203008,fd=5))

Once you have the ip:port information you can simply run curl -v against it:

# curl -I 127.0.0.1:42849
HTTP/1.1 200 OK
beep: boop                        <-- THIS IS US!!!!!!!!!!!!
Date: Thu, 28 Dec 2023 17:48:29 GMT
Content-Length: 0

Once this is done, your vtc will complete inside your first terminal with results similar to

#   top  TEST basic-003.vtc passed (11.468)

Note: We can combine the two commands above with a little awk to create the below single line command:

curl -v $(ss -plt | awk '/varnishtest/ {print $4; exit}')

4. Macros and shell

In the previous test, we had to pop up a second terminal, which worked, but wasn’t very practical. basic-004.vtc shows how we can do better with two new tools: shell and macros:

varnishtest "We need to talk about macro"

# let's get a server with an empty spec. We don't really care about what it
# does, only about its existence

server s1 -start

# we can use this macro, for example in a shell script:
shell {
	echo "we are running from ${pwd}, with s1 is listening on ${s1_sock}"
	echo "about to run the false command"
	false
}

# you can make the test pass by changing "false" to "true", or removing the
# line altogether

So, this appears to define a shell block that will actually run the shell command in it, as a regular script would, and we also see ${pwd} and ${s1_sock} which looks like variables (those are our macros).

Question is: who defines them and what do they resolve to? To answer that, werun the test:

varnishtest basic-004.vtc

Wait… what?…it failed?

Yes, but that’s on purpose! First, this shows that varnishtest automatically switches to verbose mode if a test fails, which is pretty nice. Second, it allows us to look at the logs, notably:

...
**** top   shell_out|about to run the false command
**** top   shell_status = 0x0001
---- top   shell_exit not as expected: got 0x0001 wanted 0x0000
...

There are a few cool things here:

  • shell_out shows us stdout, here that’s the output of the second echo command

  • shell_status, informs us that the shell returned 1…

  • …which apparently upset shell_exit, who was expecting a 0

It turns out it’s all normal as the shell command will fail if any of its command returns non-zero (like false, for example). To verify that, you can change the false command with true and the test will pass (but without logs).

Now that this detour is done, let’s focus on this log line:

**** top   shell_out|we are running from /home/guillaume/work/vtc-examples, with s1 is listening on 127.0.0.1:33523

So we can see the first echo output, and that both ${pwd} and ${s1_sock} have been replaced by other values. If you look a few lines above, you can actually see varnishtest logging their definitions:

**** top   extmacro def pwd=/home/guillaume/work/vtc-examples       <----- that's ${pwd}
**** top   extmacro def date(...)
**** top   extmacro def string(...)
**** top   extmacro def localhost=127.0.0.1
**** top   extmacro def bad_backend=127.0.0.1:41113
**** top   extmacro def listen_addr=127.0.0.1:0
**** top   extmacro def bad_ip=192.0.2.255
**** top   macro def testdir=/home/guillaume/work/vtc-examples
**** top   macro def tmpdir=/tmp/vtc.4005032.2f784281
**** top   macro def vtcid=vtc.4005032.2f784281
**   top   === varnishtest "We need to talk about macro"            <------ we're entering our test
*    top   VTEST We need to talk about macro
**   top   === server s1 -start
**   s1    Starting server                                          <------ s1 starts
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=33523
**** s1    macro def s1_sock=127.0.0.1:33523                        <----- and here's ${s1_sock}

What we’re seeing here is that there’s a handful of macros that get defined as soon as varnishtest starts, and others get automatically created when the new server is started (even though its specification was empty).

That’s pretty cool, that means that we could automate the previous test (basic-003.vtc) without the need for an external terminal with something like this:

varnishtest "our first agent and specification block"
server s1 {
	rxreq
	txresp
} -start
shell {
	curl -v $(ss -plunt | awk '/varnishtest/ {print $5; exit}')
}

However, as we’re going to see next, there’s an even better approach…

5. The Client

The client side of a varnishtest is used to connect to your test case server, it is also a real http client.

To set this up, we’re reusing our server friend from basic-003.vtc, but this time telling it to respond to two requests in a row.

Our client will look similar to the server one, with a couple of variations:

  • we use -connect ip:port so the client knows what to connect to

  • the rxreq/txresp pair is replaced with the txreq/rxresp one

  • we use -run which is the equivalent to -start -wait

Let’s call this basic-005.vtc:

varnishtest "Connecting a client to a server"

server s1 {
	rxreq
	txresp

	rxreq
	txresp
} -start

client c1 -connect ${s1_sock} {
	txreq -url "/foo" -hdr "something: anything"
	rxresp

	# interesting, we don't need to quote single words, but we usually
	# do it for consistency
	txreq -url /bar_and_maybe_baz
	rxresp
} -run

Without surprise, this passes:

$ varnishtest basic-005.vtc
top  TEST basic-005.vtc passed (0.075)

Now, the interesting is that, because clients are actual HTTP clients, we can connect them to real servers, for example:

varnishtest "Connecting a client to a server (a real one)"
client c2 -connect "example.com 80" {
	txreq
	rxresp
} -run

(and this is actually part of basic-005.vtc in the git repository)

6. Using Expect Statements

So far, our tests “passed”, in the sense that txreq/rxreq/txresp/rxresp are succeeding i.e., they send and receive valid http messages. Now we want to be stricter and make sure that the URLs, headers, and bodies have the values we expect, and for this, using the well-named expect keyword.

basic-006.vtc is, by far, the largest test we’ve seen so far, but don’t worry, it’s just one client and server exchanging two requests/responses and making sure the expectations are correct:

varnishtest "Hope for the best, expect the worst"

server s1 {
	rxreq
	expect req.url == "/foo"
	expect req.http.something == "anything"

	# be aware: if you try to set the body before the headers, s1 will fail
	txresp -status 123 -hdr "x: 17.4" -body "tadbbb"

	# by the way, I can also read `req.* later, as long as I haven't
	# received a new one
	expect req.body == "greek god"
} -start

client c1 -connect ${s1_sock} {
	# oh, look! Line continuations!
	txreq \
		-url "/foo" \
		-hdr "something: anything" \
		-body "greek god"
	rxresp

	# that status is nonsensical, but hey, if that's what I expect...
	expect resp.status == 123
	# strings that look like a number can be numerically tested
	expect resp.http.x > 17
	expect resp.http.x <= 17.5
	expect resp.body == "tadaaa"
	# we use <undef> for "without a value"
	expect resp.http.y == <undef>
} -run

Before we run it, let’s note a few things:

  • the expect syntax is expect THING1 COMPARATOR THING2

  • COMPARATOR can test equality (==), order (>, >=, <, <=), regex (~)

  • THING1 and THING2 will be resolved as variables and understood as numbers, if they can and need to

  • we can use <undef> to express the absence of value

But enough looking around, let’s run this test:

varnishtest basic-006.vtc

And, yes, it’s another one of those tests that fail on purpose. Once again, as you can imagine, there’s a good reason. A passing expect isn’t really interesting itself. The fun begins when things go wrong; and when they do, you want to be able to understand what happened.

Thankfully, varnishtest is pretty clear about the issue; we just have to look for line(s) starting with ---:

**   c1    === expect resp.http.x <= 17.5
**** c1    EXPECT resp.http.x (17.4) <= "17.5" match
**   c1    === expect resp.body == "tadaaa"
---- c1    EXPECT resp.body (tadbbb) == "tadaaa" failed

So, apparently, our expect resp.body == "tadaaa" test didn’t work. In passing, notice how the logs give us both info about the name of the variable (resp.body) and its resolved value ((tadbbb))?

If you fix either the offending expect line or the txresp one, so they match, the test should pass:

varnishtest basic-006.vtc
#    top  TEST basic-006.vtc passed (0.070)

7. Varnish and some logs

We’ve been patient, but now it’s really time to put the “varnish” back into varnishtest! The varnish agent will look like a server, but note the -vcl SPEC argument that allows us to define our VCL in basic-007.vtc:

varnishtest "it's time to introduce varnish"

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

server s2 {
	rxreq
	expect req.url == "/to_s2"
	txresp -hdr "server: s2"
} -start

# here's the star of the show, the varnish agent
varnish v1 -vcl {
	# pretty cool, we don't explicitly need the "vcl 4.1;" line
	backend s1 {
		.host = "${s1_addr}";
		.port = "${s1_port}";
	}

	# did you know you could specify .host as "HOST:PORT"?
	backend s2 { .host = "${s2_sock}"; }

	sub vcl_recv {
		if (req.url == "/to_s1") {
			set req.backend_hint = s1;
		} else {
			set req.backend_hint = s2;
		}
	}
} -start

client c1 -connect ${v1_sock} {
	txreq -url "/to_s1"
	rxresp
	expect resp.http.server == "s1"

	txreq -url "/to_s2"
	rxresp
	expect resp.http.server == "s2"
} -run

# if we have two servers, we need two request, obviously
# even though, there's no suspense, since the data is cached
client c1 -connect ${v1_sock} {
	txreq -url "/to_s1"
	rxresp
	expect resp.http.server == "s1"

	txreq -url "/to_s2"
	rxresp
	expect resp.http.server == "s2"
} -run

No trick here, the test passes, but there’s a bunch of things I want to show you, so we’re running the test verbosely this time:

varnishtest basic-007.vtc -v

First stop, we realize that we are running a full-blown Varnish server, and we can see the command line used to start it, as well as the work directory used and the pid:

**   top   === varnish v1 \
**** dT    0.001
**   s1    Started on 127.0.0.1:45467 (2 iterations)
**   s2    Started on 127.0.0.1:37511 (1 iterations)
**** dT    0.007
**   v1    Launch
***  v1    CMD: cd ${pwd} && exec varnishd  -d -n /tmp/vtc.4021796.2b5bb555/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 45405' -P /tmp/vtc.4021796.2b5bb555/v1/varnishd.pid  -p default_grace=0
***  v1    CMD: cd /home/guillaume/work/vtc-examples && exec varnishd  -d -n /tmp/vtc.4021796.2b5bb555/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 45405' -P /tmp/vtc.4021796.2b5bb555/v1/varnishd.pid  -p default_grace=0
***  v1    PID: 4021802
**** v1    macro def v1_pid=4021802                                                                              <- pid
**** v1    macro def v1_name=/tmp/vtc.4021796.2b5bb555/v1                                                        <- work directory
**** dT    0.032
***  v1    debug|Debug: Version: varnish-7.4.2 revision cd1d10ab53a6f6115b2b4f3b2a1da94c1f749f80
***  v1    debug|Debug: Platform: Linux,6.6.3-arch1-1,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
***  v1    debug|200 314
***  v1    debug|-----------------------------
***  v1    debug|Varnish Cache CLI 1.0
***  v1    debug|-----------------------------
***  v1    debug|Linux,6.6.3-arch1-1,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
***  v1    debug|varnish-7.4.2 revision cd1d10ab53a6f6115b2b4f3b2a1da94c1f749f80
***  v1    debug|
***  v1    debug|Type 'help' for command list.
***  v1    debug|Type 'quit' to close CLI session.
***  v1    debug|Type 'start' to launch worker process.
***  v1    debug|

If we go down a bit, we also find out that varnishtest actually straight up uses varnishadm to load the VCL!

***  v1    CLI RX  200
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Varnish Cache CLI 1.0
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Linux,6.6.3-arch1-1,x86_64,-jnone,-sdefault,-sdefault,-hcritbit
**** v1    CLI RX|varnish-7.4.2 revision cd1d10ab53a6f6115b2b4f3b2a1da94c1f749f80
**** v1    CLI RX|
**** v1    CLI RX|Type 'help' for command list.
**** v1    CLI RX|Type 'quit' to close CLI session.
**** v1    CLI RX|Type 'start' to launch worker process.
**** v1    CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P                        <---- note the heredoc
**** v1    CLI TX|vcl 4.1;
**** v1    CLI TX|backend s1 { .host = "127.0.0.1"; .port = "45467"; }
**** v1    CLI TX|backend s2 { .host = "127.0.0.1"; .port = "37511"; }
**** v1    CLI TX|
**** v1    CLI TX|
**** v1    CLI TX|\t\tsub vcl_recv {
**** v1    CLI TX|\t\t\tif (req.url == "/to_s1") {
**** v1    CLI TX|\t\t\t\tset req.backend_hint = s1;
**** v1    CLI TX|\t\t\t} else {
**** v1    CLI TX|\t\t\t\tset req.backend_hint = s2;
**** v1    CLI TX|\t\t\t}
**** v1    CLI TX|\t\t}
**** v1    CLI TX|\t
**** v1    CLI TX|%XJEIFLH|)Xspa8P                                           <---- this signals the end of the VCL

I find it pretty cool, we usually only see EOF as a delimiting identifier, %XJEIFLH|)Xspa8P is quite a sight! It makes sense though, you want a delimiter unlikely to appear in a VCL.

Of course, we also get our network macros, once v1 is fully started:

**** v1    macro def v1_addr=127.0.0.1
**** v1    macro def v1_port=44447
**** v1    macro def v1_sock=127.0.0.1:44447
**** v1    macro def v1_a0_addr=127.0.0.1
**** v1    macro def v1_a0_port=44447
**** v1    macro def v1_a0_sock=127.0.0.1:44447

And later on, varnishtest is kind enough to provide us with the varnishlog output:

<...>
**** v1    vsl|       1002 BereqMethod     b GET
**** v1    vsl|       1002 BereqURL        b /to_s1
**** v1    vsl|       1002 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1002 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1002 BereqHeader     b User-Agent: c1
**** v1    vsl|       1002 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1002 BereqHeader     b Via: 1.1 v1 (Varnish/7.4)
**** v1    vsl|       1002 BereqHeader     b Accept-Encoding: gzip
<...>

Logs are essential for debugging, and as you can see, varnishtest takes those very seriously. While you are exploring those logs, have a look at what the clients and servers have to say. You’ll notice that they will tell you all about the buffers they receive and how they interpret them:

**   c1    === rxresp
**** dT    0.713
**** c1    rxhdr|HTTP/1.1 200 OK\r
**** c1    rxhdr|server: s2\r
**** c1    rxhdr|Date: Sat, 30 Dec 2023 20:23:02 GMT\r
**** c1    rxhdr|Content-Length: 0\r
**** c1    rxhdr|X-Varnish: 1007 1004\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 v1 (Varnish/7.4)\r
**** c1    rxhdr|Accept-Ranges: bytes\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 190
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |200
**** c1    http[ 2] |OK
**** c1    http[ 3] |server: s2
**** c1    http[ 4] |Date: Sat, 30 Dec 2023 20:23:02 GMT
**** c1    http[ 5] |Content-Length: 0
**** c1    http[ 6] |X-Varnish: 1007 1004
**** c1    http[ 7] |Age: 0
**** c1    http[ 8] |Via: 1.1 v1 (Varnish/7.4)
**** c1    http[ 9] |Accept-Ranges: bytes
**** c1    http[10] |Connection: keep-alive
**** c1    bodylen = 0

8. Working smarter, not harder

Now it’s time to show off a couple of cheat codes. Believe me, there are so many more found inside the documentation and man pages for varnishtest and vtc (seriously, have a look!).

This page breaks down basic-008.vtc, the test is a bit big, we’ll show the whole thing and then dive into snippets.

Here is the vtc:

varnishtest "Can we be lazier? And also do more work?"

# we can repeat a full spec...
server s1 -repeat 2 {
	rxreq
	expect req.url == "/to_s1"
	txresp -hdr "server: s1"
} -start

# ...or a subsection of it
server s2 {
	loop 2 {
		rxreq
		expect req.url == "/to_s2"
		txresp -hdr "server: s2"
	}
} -start

# -vcl+backend will populate backends based on the started servers
# and also, we can pass arguments to the varnishd command line
varnish v1 \
	-arg "-p default_grace=0" \
	-vcl+backend {
		sub vcl_recv {
			if (req.url == "/to_s1") {
				set req.backend_hint = s1;
			} else {
				set req.backend_hint = s2;
			}
		}
	} -start

# we can also use varnishadm, here to reduce the default ttl
varnish v1 -cliok "param.set default_ttl 1"

# by default, clients connect to ${s1_sock}, so no need to specify -connect
client c1 {
	txreq -url "/to_s1"
	rxresp
	expect resp.http.server == "s1"

	txreq -url "/to_s2"
	rxresp
	expect resp.http.server == "s2"

	# let's wait a bit so the objects expire
	delay 1

	# and fetch them again
	txreq -url "/to_s1"
	rxresp
	expect resp.http.server == "s1"

	txreq -url "/to_s2"
	rxresp
	expect resp.http.server == "s2"
} -run

# check that "varnishtest basic-008.vtc" passes

If you need to do the same thing over and over, there are a couple of nifty solutions to help avoid duplicating a block of code. First, there is -repeat, which will repeat your server specification with the value you provide. Second, we have loop, which you can utilize to repeat just a subsection of your server specification:

server s1 -repeat 2 {
    rxreq
    expect req.url == "/to_s1"
    txresp -hdr "server: s1"
} -start
server s2 {
    loop 2 {
        rxreq
        expect req.url == "/to_s2"
        txresp -hdr "server: s2"
    }
} -start

Next is varnish management; you’re going to see I’ve been holding back a bit:

varnish v1 \
    -arg "-p default_grace=0" \
    -vcl+backend {
        sub vcl_recv {
            if (req.url == "/to_s1") {
                set req.backend_hint = s1;
            } else {
                set req.backend_hint = s2;
            }
        }
    } -start

We can pass command-line arguments to varnish, which is cool, but the big piece here is -vcl+backend. Its job is simple; generate backend VCL definitions for all the started servers and prepend them to your VCL. This simplifies test cases a lot!

Going above and beyond, we can also use varnishadm with -cliok (there’s also -clierr and -clijson)

varnish v1 -cliok "param.set default_ttl 1"

On the client side, we can now omit the -connect, because by default, a client will connect to ${s1_sock}:

client c1 {
    txreq -url "/to_s1"
    rxresp
    expect resp.http.server == "s1"

    txreq -url "/to_s2"
    rxresp
    expect resp.http.server == "s2"

    # let's wait a bit so the objects expire
    delay 1

    # and fetch them again
    txreq -url "/to_s1"
    rxresp
    expect resp.http.server == "s1"

    txreq -url "/to_s2"
    rxresp
    expect resp.http.server == "s2"
} -run

Even though we are all fancy, the test still passes, which is reassuring:

varnishtest basic-008.vtc
# top  TEST basic-008.vtc passed (1.932)

9. Varnish Counters

The last stop (for now) is counters. Varnish keeps tracks of hundreds of metrics that you can notably access though varnishstat, and all of them are listed in the varnish-counters page, if you need to see what they’re about.

In basic-009.vtc expect on some counter values and dump some of them:

varnishtest "Checking counters"

server s1 {
	rxreq
	txresp
} -start

# the builtin.vcl will do here, we just need s1 populated
varnish v1 -vcl+backend {} -start

# and finally a simple client
client c1 -repeat 1 {
	txreq
	rxresp
} -run

# we can then ensure some counters have the right value
varnish v1 -expect MAIN.client_req == 1
varnish v1 -expect MAIN.n_object == 1
varnish v1 -expect MAIN.cache_miss == 1
varnish v1 -expect MAIN.cache_hit == 0
varnish v1 -vsc "VBE.*.s1.*"

Lets run it (verbosely) and view our results:

varnishtest basic-009.vtc

which produces this on my machine:

**   top   === varnish v1 -expect MAIN.client_req == 1
**** dT    0.695
**   v1    as expected: MAIN.client_req (1) == 1 (1)
**   top   === varnish v1 -expect MAIN.n_object == 1
**   v1    as expected: MAIN.n_object (1) == 1 (1)
**   top   === varnish v1 -expect MAIN.cache_miss == 1
**   v1    as expected: MAIN.cache_miss (1) == 1 (1)
**   top   === varnish v1 -expect MAIN.cache_hit == 0
**   v1    as expected: MAIN.cache_hit (0) == 0 (0)
**   top   === varnish v1 -vsc "VBE.*.s1.*"
**** v1    VSC VBE.vcl1.s1.happy 0
**** v1    VSC VBE.vcl1.s1.bereq_hdrbytes 146
**** v1    VSC VBE.vcl1.s1.bereq_bodybytes 0
**** v1    VSC VBE.vcl1.s1.beresp_hdrbytes 87
**** v1    VSC VBE.vcl1.s1.beresp_bodybytes 0
**** v1    VSC VBE.vcl1.s1.pipe_hdrbytes 0
**** v1    VSC VBE.vcl1.s1.pipe_out 0
**** v1    VSC VBE.vcl1.s1.pipe_in 0
**** v1    VSC VBE.vcl1.s1.conn 0
**** v1    VSC VBE.vcl1.s1.req 1
**** v1    VSC VBE.vcl1.s1.unhealthy 0
**** v1    VSC VBE.vcl1.s1.busy 0
**** v1    VSC VBE.vcl1.s1.fail 0
**** v1    VSC VBE.vcl1.s1.fail_eacces 0
**** v1    VSC VBE.vcl1.s1.fail_eaddrnotavail 0
**** v1    VSC VBE.vcl1.s1.fail_econnrefused 0
**** v1    VSC VBE.vcl1.s1.fail_enetunreach 0
**** v1    VSC VBE.vcl1.s1.fail_etimedout 0
**** v1    VSC VBE.vcl1.s1.fail_other 0
**** v1    VSC VBE.vcl1.s1.helddown 0