Testing Varnish with varnishtest

Tags: testing (1) vtc (1)

The varnishtest program is a script-driven testing tool that uses Varnish Test Case (VTC) files to test specific scenarios. It is a functional testing tool, where the various elements of the delivery chain can be defined:

The Varnish server
The client
The origin server
Extra proxy servers
Varnishlog output
Other server processes that are called

The varnishtest program

The varnishtest program allows you to run isolated test cases that leverage the varnishd program without interfering with any live Varnish environment on the server.

varnishtest takes a couple of arguments, most of which are optional. There’s only one non-optional argument and that’s the VTC script.

Here’s how varnishtest can be used in its most basic form:

varnishtest test.vtc

This command loads the test.vtc file that contains the VTC logic. You can also run multiple VTC scripts in a single test run:

varnishtest test1.vtc test2.vtc test3.vtc

Arguments and options can be added to the command:

The -b option will set the internal buffer size, which defaults to 1 MB
The -D option can be used to define macros that can be used in the VTC scripts
The -i option overrides the PATH and vmod_path where binaries and VMODs can be found
The -j option defines how many tests can be run in parallel
The -k option will continue the test run when test failures occur
The -n option sets the number of test iterations
The -p option overrides varnishd runtime parameters within the VTC scope
The -q option enables quiet mode and only displays failures
The -t option defines the execution timeout of the test run, which defaults to 60 seconds
The -v option enables verbose mode and provides more verbose output

Here’s an example of a macro that is set using the -D option:

varnishtest -D name=Varnish test.vtc

Because of the -D name=Varnish option, the ${name} macro becomes available in the VTC files. Its value will be Varnish.

The following example will run each test five times and will run three tests in parallel:

varnishtest -j 3 -n 5 test.vtc

For more information about varnishtest and its configuration options, please have a look at the varnishtest documentation page.

varnishtest documentation →

Varnish Test Case language (VTC)

The Varnish Test Case (VTC) language defines the HTTP components and test scenarios to test the behavior of Varnish and your VCL code.

In VTC you can define the various elements of the delivery chain:

The Varnish server
The client
The origin server
Extra proxy servers
Varnishlog output
Other server processes that are called

The testing scenarios involve interactions between these elements and through the expect keyword assertions can be made. These assertions determine whether or not the test case was successful.

A typical Varnish Test Case contains three HTTP components:

The HTTP client, defined as client c1
The Varnish instance, defined as varnish v1
The web server, defined as server s1

VTC HTTP components

For more information about the Varnish Test Case syntax, please have a look at the VTC documentation page.

Varnish Test Case documentation →

Naming convention

The varnishtest program comes with dozens of pre-defined tests that are used in the Varnish development process for feature testing and bug fixing.

The filename of each of these VTC files adheres to the following naming convention:

[id]%05d.vtc

One example is v00032.vtc. It starts with v, which represents the [id], followed by five digits.

The list below describes the meaning of the [id] part:

	id ~ ^a		--> varnishtest(1) tests
	id ~ ^a02	--> HTTP2
	id ~ ^b		--> Basic functionality tests
	id ~ ^c		--> Complex functionality tests
	id ~ ^d		--> Director VMOD tests
	id ~ ^e		--> ESI tests
	id ~ ^f		--> Security-related tests
	id ~ ^g		--> GZIP tests
	id ~ ^h		--> HAproxy 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		--> Transport protocol tests
	id ~ ^t02	--> HTTP2
	id ~ ^u		--> Utilities and background processes
	id ~ ^v		--> VCL tests: execute VRT functions

This means that v00032.vtc is a VCL test and b00012 .vtc is a basic functionality test.

Although you are free to use any name you want for your tests, it does make sense to use the naming convention. It will help you avoid writing tests that already exist or that are similar.

Declaring a test case

A VTC file starts with a varnishtest declaration that describes the purpose of the test.

Here’s an example of such a declaration:

varnishtest "Language cookie cache variation test"

As you can see, the test case tests how language cookie cache variations behave in Varnish.

Declaring a server

In VTC a server declaration mimics the behavior of an actual origin web server. You define a sequence of expected input and the corresponding output.

A minimal VTC server declaration looks like this:

server s1 {
    rxreq
    txresp
} -start

s1 is the name of the server
rxreq will accept and receive an incoming HTTP request, and parse its headers and request body
txresp will transmit an HTTP response to the requesting server
-start will start a server thread in the background

Here’s an example of a server declaration that contains an expect assertion:

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

This server declaration expects incoming requests to match the /blog URL. When this is the case a response will be returned with blog as the response body.

Declaring a Varnish instance

To test the behavior of Varnish, you can use a Varnish VTC declaration. Here’s a minimal example that includes a -vcl+backend statement:

varnish v1 -vcl+backend { } -start

This -vcl+backend statement ensures that all defined servers in VTC are added as backends in the VCL file.

It is also possible to include your own VCL code, as you can see in the following example:

varnish v1 -vcl+backend { 
    vcl 4.1;

    sub vcl_recv {
        if(req.url ~ "^/admin") {
            return(pass);
        }
        unset req.http.Cookie;
        return(hash);
    }
} -start

This example also features the -vcl+backend option, which ensures backends are automatically defined. But there’s also some VCL logic that bypasses the cache for URLs that match the ^/admin regular expression pattern and that caches all other requests.

Declaring a client

In VTC a client declaration is used to send actual HTTP requests to Varnish. Keywords like txreq and rxresp are used to send a request and get the response. By adding an assertion through the expect keyword, you can test whether or not the logic is behaving as expected:

client c1 {
    txreq
    rxresp
    expect resp.body == "Hello world"
} -run

This example sends a client request to Varnish for the / URL. When the response is received the client expects the response body to be Hello world. The -run option is required to start the client.

It is also possible to add a lot more extra information to the request:

The URL can be overridden.
Custom headers can be added.
Multiple requests can be sent by a single client.

Here’s an example:

client c1 {
    txreq -hdr "Cookie: language=nl" -url "/greeting"
    rxresp
    expect resp.body == "Goede morgen"

    txreq -hdr "Cookie: language=en" -url "/greeting"
    rxresp
    expect resp.body == "Good morning" 

    txreq -url "/greeting"
    rxresp
    expect resp.body == "Good morning"        
} -run

This example will send three requests to the /greeting endpoint. Depending on the value of the language cookie, a specific response body is expected. If the three expectations are met, the test case will be successful.

Running a test

Imagine the following VTC file:

varnishtest "Language cookie cache variation"
server s1 {
    rxreq
    expect req.http.Cookie == "language=nl"
    txresp -body "Goede morgen"

    rxreq
    expect req.http.Cookie != "language=nl"
    txresp -body "Good morning"

    rxreq
    expect req.http.Cookie != "language=nl"
    txresp -body "Good morning" 

    rxreq
    expect req.http.Cookie != "language=nl"
    txresp -body "Good morning"            
} -start

varnish v1 -vcl+backend { 
    vcl 4.1;

    sub vcl_recv {
        if (req.http.Cookie) {
            set req.http.Cookie = ";" + req.http.Cookie;
            set req.http.Cookie = regsuball(req.http.Cookie, "; +", ";");
            set req.http.Cookie = regsuball(req.http.Cookie, ";(language)=", "; \1=");
            set req.http.Cookie = regsuball(req.http.Cookie, ";[^ ][^;]*", "");
            set req.http.Cookie = regsuball(req.http.Cookie, "^[; ]+|[; ]+$", "");

            if (req.http.cookie ~ "^\s*$") {
                unset req.http.cookie;
            }

            return(hash);
        }
    }

    sub vcl_hash {
        if(req.http.Cookie ~ "^.*language=(nl|en);*.*$") {
            hash_data(regsub( req.http.Cookie, "^.*language=(nl|en);*.*$", "\1" ));    
        } else {
            hash_data("en");
        }

    }
} -start

client c1 {
    txreq -hdr "Cookie: a=1; b=2; language=nl; c=3"
    rxresp
    expect resp.body == "Goede morgen"

    txreq -hdr "Cookie: a=1; language=en"
    rxresp
    expect resp.body == "Good morning" 

    txreq -hdr "Cookie: a=1; language=fr"
    rxresp
    expect resp.body == "Good morning"  

    txreq
    rxresp
    expect resp.body == "Good morning"        
} -run

This Varnish Test Case sends HTTP requests to a Varnish instance that uses the value of the language cookie to create cache variations. The VCL ensures that only the values nl for Dutch and en for English are supported. Any other value will cause a fallback to English.

The test case checks whether or not the right cookie values are extracted by the VCL file and whether or not the right variations are cached.

Through varnishtest test.vtc the test.vtc file that includes this VTC will be executed.

Here’s the output:

$ varnishtest test.vtc
#    top  TEST test.vtc passed (0.649)

Test failures

When a VTC fails, verbose output will explain exactly what was going on when the failure occurred.

Let’s trigger a failure by taking the previous VTC and changing the last assertion from expect resp.body == "Good morning" to expect resp.body == "Bonjour".

Because the server has no support for French content and because Varnish doesn’t create a separate cache variation for the fr value, the test fails. Here’s the very verbose output:

$ varnishtest test.vtc
**** dT    0.000
*    top   TEST test.vtc starting
**** top   extmacro def pwd=/etc/varnish
**** 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:40127
**** top   extmacro def listen_addr=127.0.0.1:0
**** top   extmacro def bad_ip=192.0.2.255
**** top   macro def testdir=/etc/varnish
**** top   macro def tmpdir=/tmp/vtc.1204.1da971c3
**   top   === varnishtest "Language cookie cache variation"
*    top   VTEST Language cookie cache variation
**   top   === server s1 {
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=32807
**** s1    macro def s1_sock=127.0.0.1:32807
*    s1    Listen on 127.0.0.1:32807
**   top   === varnish v1 -vcl+backend {
**** dT    0.001
**   s1    Started on 127.0.0.1:32807 (1 iterations)
**** dT    0.007
**   v1    Launch
***  v1    CMD: cd ${pwd} && exec varnishd  -d -n /tmp/vtc.1204.1da971c3/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 -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 33323' -P /tmp/vtc.1204.1da971c3/v1/varnishd.pid
***  v1    CMD: cd /etc/varnish && exec varnishd  -d -n /tmp/vtc.1204.1da971c3/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 -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 33323' -P /tmp/vtc.1204.1da971c3/v1/varnishd.pid
**** dT    0.008
***  v1    PID: 1210
**** v1    macro def v1_pid=1210
**** v1    macro def v1_name=/tmp/vtc.1204.1da971c3/v1
**** dT    0.019
***  v1    debug|Debug: Version: varnish-7.0.1 revision d454d0ed759ce8ed2b5c7bf244090a73487e8021
***  v1    debug|Debug: Platform: Linux,5.10.76-linuxkit,aarch64,-junix,-sdefault,-sdefault,-hcritbit
***  v1    debug|200 318
***  v1    debug|-----------------------------
***  v1    debug|Varnish Cache CLI 1.0
***  v1    debug|-----------------------------
***  v1    debug|Linux,5.10.76-linuxkit,aarch64,-junix,-sdefault,-sdefault,-hcritbit
***  v1    debug|varnish-7.0.1 revision d454d0ed759ce8ed2b5c7bf244090a73487e8021
***  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|
**** dT    0.121
**** v1    CLIPOLL 1 0x1 0x0 0x0
***  v1    CLI connection fd = 7
**** dT    0.122
***  v1    CLI RX  107
**** v1    CLI RX|vmflkeqmasqgjwqwcteihfqznqwmlney
**** v1    CLI RX|
**** v1    CLI RX|Authentication required.
**** v1    CLI TX|auth 03c9bf424fbaf18bd3bb931640ac9ee7fb242ea18ad0b525f8604aa33fda1952
**** dT    0.123
***  v1    CLI RX  200
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Varnish Cache CLI 1.0
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Linux,5.10.76-linuxkit,aarch64,-junix,-sdefault,-sdefault,-hcritbit
**** v1    CLI RX|varnish-7.0.1 revision d454d0ed759ce8ed2b5c7bf244090a73487e8021
**** 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.
**** dT    0.124
**** v1    CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P
**** v1    CLI TX|vcl 4.1;
**** v1    CLI TX|backend s1 { .host = "127.0.0.1"; .port = "32807"; }
**** v1    CLI TX|
**** v1    CLI TX|
**** v1    CLI TX|    vcl 4.1;
**** v1    CLI TX|
**** v1    CLI TX|    sub vcl_recv {
**** v1    CLI TX|        if (req.http.Cookie) {
**** v1    CLI TX|            set req.http.Cookie = ";" + req.http.Cookie;
**** v1    CLI TX|            set req.http.Cookie = regsuball(req.http.Cookie, "; +", ";");
**** v1    CLI TX|            set req.http.Cookie = regsuball(req.http.Cookie, ";(language)=", "; \1=");
**** v1    CLI TX|            set req.http.Cookie = regsuball(req.http.Cookie, ";[^ ][^;]*", "");
**** v1    CLI TX|            set req.http.Cookie = regsuball(req.http.Cookie, "^[; ]+|[; ]+$", "");
**** v1    CLI TX|
**** v1    CLI TX|            if (req.http.cookie ~ "^\s*$") {
**** v1    CLI TX|                unset req.http.cookie;
**** v1    CLI TX|            }
**** v1    CLI TX|
**** v1    CLI TX|            return(hash);
**** v1    CLI TX|        }
**** v1    CLI TX|    }
**** v1    CLI TX|
**** v1    CLI TX|    sub vcl_hash {
**** v1    CLI TX|        if(req.http.Cookie ~ "^.*language=(nl|en|fr);*.*$") {
**** v1    CLI TX|            hash_data(regsub( req.http.Cookie, "^.*language=(nl|en|fr);*.*$", "\1" ));
**** v1    CLI TX|        } else {
**** v1    CLI TX|            hash_data("en");
**** v1    CLI TX|        }
**** v1    CLI TX|
**** v1    CLI TX|    }
**** v1    CLI TX|
**** v1    CLI TX|%XJEIFLH|)Xspa8P
**** dT    0.229
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.329
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.333
***  v1    CLI RX  200
**** v1    CLI RX|VCL compiled.
**** v1    CLI TX|vcl.use vcl1
***  v1    CLI RX  200
**** v1    CLI RX|VCL 'vcl1' now active
**   v1    Start
**** v1    CLI TX|start
**** dT    0.334
***  v1    debug|Debug: Child (1226) Started
**** dT    0.357
***  v1    CLI RX  200
***  v1    wait-running
**** v1    CLI TX|status
***  v1    CLI RX  200
**** v1    CLI RX|Child in state running
**** v1    CLI TX|debug.listen_address
***  v1    debug|Info: Child (1226) said Child starts
**** dT    0.358
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 45471
**** v1    CLI TX|debug.xid 999
***  v1    CLI RX  200
**** v1    CLI RX|XID is 999
**** v1    CLI TX|debug.listen_address
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 45471
**   v1    Listen on 127.0.0.1 45471
**** v1    macro def v1_addr=127.0.0.1
**** v1    macro def v1_port=45471
**** v1    macro def v1_sock=127.0.0.1:45471
**** v1    macro def v1_a0_addr=127.0.0.1
**** v1    macro def v1_a0_port=45471
**** v1    macro def v1_a0_sock=127.0.0.1:45471
**** dT    0.434
**** v1    vsl|          0 CLI             - Rd vcl.load "vcl1" vcl_vcl1.1640785455.977380/vgc.so 1auto
**** v1    vsl|          0 CLI             - Wr 200 52 Loaded "vcl_vcl1.1640785455.977380/vgc.so" as "vcl1"
**** v1    vsl|          0 CLI             - Rd vcl.use "vcl1"
**** v1    vsl|          0 CLI             - Wr 200 0
**** v1    vsl|          0 CLI             - Rd start
**** v1    vsl|          0 Debug           - sockopt: Setting SO_LINGER for a0=127.0.0.1:45471
**** v1    vsl|          0 Debug           - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:45471
**** v1    vsl|          0 Debug           - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:45471
**** v1    vsl|          0 Debug           - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:45471
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:45471
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:45471
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:45471
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:45471
**** v1    vsl|          0 CLI             - Wr 200 0
**** v1    vsl|          0 CLI             - Rd debug.listen_address
**** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 45471

**** v1    vsl|          0 CLI             - Rd debug.xid 999
**** v1    vsl|          0 CLI             - Wr 200 10 XID is 999
**** v1    vsl|          0 CLI             - Rd debug.listen_address
**** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 45471

**** dT    0.459
**   top   === client c1 {
**   c1    Starting client
**   c1    Waiting for client
**   c1    Started on 127.0.0.1:45471 (1 iterations)
***  c1    Connect to 127.0.0.1:45471
***  c1    connected fd 17 from 127.0.0.1 45314 to 127.0.0.1:45471
**   c1    === txreq -hdr "Cookie: a=1; b=2; language=nl; c=3"
**** c1    txreq|GET / HTTP/1.1\r
**** c1    txreq|Cookie: a=1; b=2; language=nl; c=3\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === rxresp
***  s1    accepted fd 5 127.0.0.1 51844
**   s1    === rxreq
**** dT    0.460
**** s1    rxhdr|GET / HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Cookie: language=nl\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1002\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 124
**** s1    http[ 0] |GET
**** s1    http[ 1] |/
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 5] |Cookie: language=nl
**** s1    http[ 6] |Accept-Encoding: gzip
**** s1    http[ 7] |X-Varnish: 1002
**** s1    bodylen = 0
**   s1    === expect req.http.Cookie == "language=nl"
**** s1    EXPECT req.http.Cookie (language=nl) == "language=nl" match
**   s1    === txresp -body "Goede morgen"
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Content-Length: 12\r
**** s1    txresp|\r
**** s1    txresp|Goede morgen
**   s1    === rxreq
**** c1    rxhdr|HTTP/1.1 200 OK\r
**** c1    rxhdr|Content-Length: 12\r
**** c1    rxhdr|Date: Wed, 29 Dec 2021 13:44:16 GMT\r
**** c1    rxhdr|X-Varnish: 1001\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 varnish (Varnish/7.0)\r
**** c1    rxhdr|Accept-Ranges: bytes\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 179
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |200
**** c1    http[ 2] |OK
**** c1    http[ 3] |Content-Length: 12
**** c1    http[ 4] |Date: Wed, 29 Dec 2021 13:44:16 GMT
**** c1    http[ 5] |X-Varnish: 1001
**** c1    http[ 6] |Age: 0
**** c1    http[ 7] |Via: 1.1 varnish (Varnish/7.0)
**** c1    http[ 8] |Accept-Ranges: bytes
**** c1    http[ 9] |Connection: keep-alive
**** c1    c-l|Goede morgen
**** c1    bodylen = 12
**   c1    === expect resp.body == "Goede morgen"
**** c1    EXPECT resp.body (Goede morgen) == "Goede morgen" match
**   c1    === txreq -hdr "Cookie: a=1; language=en"
**** c1    txreq|GET / HTTP/1.1\r
**** c1    txreq|Cookie: a=1; language=en\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    0.470
**** s1    rxhdr|GET / HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Cookie: language=en\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1004\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 124
**** s1    http[ 0] |GET
**** s1    http[ 1] |/
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 5] |Cookie: language=en
**** s1    http[ 6] |Accept-Encoding: gzip
**** s1    http[ 7] |X-Varnish: 1004
**** s1    bodylen = 0
**   s1    === expect req.http.Cookie != "language=nl"
**** s1    EXPECT req.http.Cookie (language=en) != "language=nl" match
**   s1    === txresp -body "Good morning"
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Content-Length: 12\r
**** s1    txresp|\r
**** s1    txresp|Good morning
**   s1    === rxreq
**** dT    0.471
**** c1    rxhdr|HTTP/1.1 200 OK\r
**** c1    rxhdr|Content-Length: 12\r
**** c1    rxhdr|Date: Wed, 29 Dec 2021 13:44:16 GMT\r
**** c1    rxhdr|X-Varnish: 1003\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 varnish (Varnish/7.0)\r
**** c1    rxhdr|Accept-Ranges: bytes\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 179
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |200
**** c1    http[ 2] |OK
**** c1    http[ 3] |Content-Length: 12
**** c1    http[ 4] |Date: Wed, 29 Dec 2021 13:44:16 GMT
**** c1    http[ 5] |X-Varnish: 1003
**** c1    http[ 6] |Age: 0
**** c1    http[ 7] |Via: 1.1 varnish (Varnish/7.0)
**** c1    http[ 8] |Accept-Ranges: bytes
**** c1    http[ 9] |Connection: keep-alive
**** c1    c-l|Good morning
**** c1    bodylen = 12
**   c1    === expect resp.body == "Good morning"
**** c1    EXPECT resp.body (Good morning) == "Good morning" match
**   c1    === txreq -hdr "Cookie: a=1; language=fr"
**** c1    txreq|GET / HTTP/1.1\r
**** c1    txreq|Cookie: a=1; language=fr\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    0.483
**** s1    rxhdr|GET / HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Cookie: language=fr\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1006\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 124
**** s1    http[ 0] |GET
**** s1    http[ 1] |/
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 5] |Cookie: language=fr
**** s1    http[ 6] |Accept-Encoding: gzip
**** s1    http[ 7] |X-Varnish: 1006
**** s1    bodylen = 0
**   s1    === expect req.http.Cookie != "language=nl"
**** s1    EXPECT req.http.Cookie (language=fr) != "language=nl" match
**   s1    === txresp -body "Good morning"
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Content-Length: 12\r
**** s1    txresp|\r
**** s1    txresp|Good morning
**   s1    === rxreq
**** dT    0.484
**** c1    rxhdr|HTTP/1.1 200 OK\r
**** c1    rxhdr|Content-Length: 12\r
**** c1    rxhdr|Date: Wed, 29 Dec 2021 13:44:16 GMT\r
**** c1    rxhdr|X-Varnish: 1005\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 varnish (Varnish/7.0)\r
**** c1    rxhdr|Accept-Ranges: bytes\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 179
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |200
**** c1    http[ 2] |OK
**** c1    http[ 3] |Content-Length: 12
**** c1    http[ 4] |Date: Wed, 29 Dec 2021 13:44:16 GMT
**** c1    http[ 5] |X-Varnish: 1005
**** c1    http[ 6] |Age: 0
**** c1    http[ 7] |Via: 1.1 varnish (Varnish/7.0)
**** c1    http[ 8] |Accept-Ranges: bytes
**** c1    http[ 9] |Connection: keep-alive
**** c1    c-l|Good morning
**** c1    bodylen = 12
**   c1    === expect resp.body == "Good morning"
**** c1    EXPECT resp.body (Good morning) == "Good morning" match
**   c1    === txreq
**** c1    txreq|GET / HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    0.497
**** c1    rxhdr|HTTP/1.1 200 OK\r
**** c1    rxhdr|Content-Length: 12\r
**** c1    rxhdr|Date: Wed, 29 Dec 2021 13:44:16 GMT\r
**** c1    rxhdr|X-Varnish: 1007 1004\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 varnish (Varnish/7.0)\r
**** c1    rxhdr|Accept-Ranges: bytes\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 184
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |200
**** c1    http[ 2] |OK
**** c1    http[ 3] |Content-Length: 12
**** c1    http[ 4] |Date: Wed, 29 Dec 2021 13:44:16 GMT
**** c1    http[ 5] |X-Varnish: 1007 1004
**** c1    http[ 6] |Age: 0
**** c1    http[ 7] |Via: 1.1 varnish (Varnish/7.0)
**** c1    http[ 8] |Accept-Ranges: bytes
**** c1    http[ 9] |Connection: keep-alive
**** c1    c-l|Good morning
**** c1    bodylen = 12
**   c1    === expect resp.body == "Bonjour"
---- c1    EXPECT resp.body (Good morning) == "Bonjour" failed
*    top   RESETTING after test.vtc
**   s1    Waiting for server (4/-1)
**   v1    Wait
**** v1    CLI TX|panic.clear
***  v1    CLI RX  300
**** v1    CLI RX|No panic to clear
***  v1    debug|Info: manager stopping child
***  v1    debug|Debug: Stopping Child
**** dT    0.537
**** v1    vsl|       1000 Begin           c sess 0 HTTP/1
**** v1    vsl|       1000 SessOpen        c 127.0.0.1 45314 a0 127.0.0.1 45471 1640785456.312802 19
**** v1    vsl|       1000 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:45471
**** v1    vsl|       1000 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:45471
**** v1    vsl|       1000 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:45471
**** v1    vsl|       1000 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:45471
**** v1    vsl|       1000 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:45471
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:45471
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:45471
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:45471
**** v1    vsl|       1000 Link            c req 1001 rxreq
**** v1    vsl|       1002 Begin           b bereq 1001 fetch
**** v1    vsl|       1002 VCL_use         b vcl1
**** v1    vsl|       1002 Timestamp       b Start: 1640785456.312988 0.000000 0.000000
**** v1    vsl|       1002 BereqMethod     b GET
**** v1    vsl|       1002 BereqURL        b /
**** v1    vsl|       1002 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1002 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1002 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1002 BereqHeader     b Cookie: language=nl
**** v1    vsl|       1002 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1002 BereqHeader     b X-Varnish: 1002
**** v1    vsl|       1002 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1002 VCL_return      b fetch
**** v1    vsl|       1002 Timestamp       b Fetch: 1640785456.313013 0.000025 0.000025
**** v1    vsl|       1002 Timestamp       b Connected: 1640785456.313108 0.000119 0.000094
**** v1    vsl|       1002 BackendOpen     b 25 s1 127.0.0.1 32807 127.0.0.1 51844 connect
**** v1    vsl|       1002 Timestamp       b Bereq: 1640785456.313126 0.000137 0.000018
**** v1    vsl|       1002 Timestamp       b Beresp: 1640785456.313441 0.000453 0.000315
**** v1    vsl|       1002 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1002 BerespStatus    b 200
**** v1    vsl|       1002 BerespReason    b OK
**** v1    vsl|       1002 BerespHeader    b Content-Length: 12
**** v1    vsl|       1002 BerespHeader    b Date: Wed, 29 Dec 2021 13:44:16 GMT
**** v1    vsl|       1002 TTL             b RFC 120 10 0 1640785456 1640785456 1640785456 0 0 cacheable
**** v1    vsl|       1002 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1002 VCL_return      b deliver
**** v1    vsl|       1002 Timestamp       b Process: 1640785456.313543 0.000554 0.000101
**** v1    vsl|       1002 Filters         b
**** v1    vsl|       1002 Storage         b malloc s0
**** v1    vsl|       1002 Fetch_Body      b 3 length stream
**** v1    vsl|       1002 BackendClose    b 25 s1 recycle
**** v1    vsl|       1002 Timestamp       b BerespBody: 1640785456.323678 0.010689 0.010134
**** v1    vsl|       1002 Length          b 12
**** v1    vsl|       1002 BereqAcct       b 124 0 124 39 12 51
**** v1    vsl|       1002 End             b
**** v1    vsl|       1001 Begin           c req 1000 rxreq
**** v1    vsl|       1001 Timestamp       c Start: 1640785456.312860 0.000000 0.000000
**** v1    vsl|       1001 Timestamp       c Req: 1640785456.312860 0.000000 0.000000
**** v1    vsl|       1001 VCL_use         c vcl1
**** v1    vsl|       1001 ReqStart        c 127.0.0.1 45314 a0
**** v1    vsl|       1001 ReqMethod       c GET
**** v1    vsl|       1001 ReqURL          c /
**** v1    vsl|       1001 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1001 ReqHeader       c Cookie: a=1; b=2; language=nl; c=3
**** v1    vsl|       1001 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1001 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1001 VCL_call        c RECV
**** v1    vsl|       1001 ReqUnset        c Cookie: a=1; b=2; language=nl; c=3
**** v1    vsl|       1001 ReqHeader       c Cookie: ;a=1; b=2; language=nl; c=3
**** v1    vsl|       1001 ReqUnset        c Cookie: ;a=1; b=2; language=nl; c=3
**** v1    vsl|       1001 ReqHeader       c Cookie: ;a=1;b=2;language=nl;c=3
**** v1    vsl|       1001 ReqUnset        c Cookie: ;a=1;b=2;language=nl;c=3
**** v1    vsl|       1001 ReqHeader       c Cookie: ;a=1;b=2; language=nl;c=3
**** v1    vsl|       1001 ReqUnset        c Cookie: ;a=1;b=2; language=nl;c=3
**** v1    vsl|       1001 ReqHeader       c Cookie: ; language=nl
**** v1    vsl|       1001 ReqUnset        c Cookie: ; language=nl
**** v1    vsl|       1001 ReqHeader       c Cookie: language=nl
**** v1    vsl|       1001 VCL_return      c hash
**** v1    vsl|       1001 VCL_call        c HASH
**** v1    vsl|       1001 VCL_return      c lookup
**** v1    vsl|       1001 VCL_call        c MISS
**** v1    vsl|       1001 VCL_return      c fetch
**** v1    vsl|       1001 Link            c bereq 1002 fetch
**** v1    vsl|       1001 Timestamp       c Fetch: 1640785456.313619 0.000759 0.000759
**** v1    vsl|       1001 RespProtocol    c HTTP/1.1
**** v1    vsl|       1001 RespStatus      c 200
**** v1    vsl|       1001 RespReason      c OK
**** v1    vsl|       1001 RespHeader      c Content-Length: 12
**** v1    vsl|       1001 RespHeader      c Date: Wed, 29 Dec 2021 13:44:16 GMT
**** v1    vsl|       1001 RespHeader      c X-Varnish: 1001
**** v1    vsl|       1001 RespHeader      c Age: 0
**** v1    vsl|       1001 RespHeader      c Via: 1.1 varnish (Varnish/7.0)
**** v1    vsl|       1001 RespHeader      c Accept-Ranges: bytes
**** v1    vsl|       1001 VCL_call        c DELIVER
**** v1    vsl|       1001 VCL_return      c deliver
**** v1    vsl|       1001 Timestamp       c Process: 1640785456.313629 0.000768 0.000009
**** v1    vsl|       1001 Filters         c
**** v1    vsl|       1001 RespHeader      c Connection: keep-alive
**** v1    vsl|       1001 Timestamp       c Resp: 1640785456.323705 0.010844 0.010076
**** v1    vsl|       1001 ReqAcct         c 71 0 71 179 12 191
**** v1    vsl|       1001 End             c
**** v1    vsl|       1000 Link            c req 1003 rxreq
**** v1    vsl|       1004 Begin           b bereq 1003 fetch
**** v1    vsl|       1004 VCL_use         b vcl1
**** v1    vsl|       1004 Timestamp       b Start: 1640785456.323762 0.000000 0.000000
**** v1    vsl|       1004 BereqMethod     b GET
**** v1    vsl|       1004 BereqURL        b /
**** v1    vsl|       1004 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1004 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1004 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1004 BereqHeader     b Cookie: language=en
**** v1    vsl|       1004 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1004 BereqHeader     b X-Varnish: 1004
**** v1    vsl|       1004 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1004 VCL_return      b fetch
**** v1    vsl|       1004 Timestamp       b Fetch: 1640785456.323773 0.000010 0.000010
**** v1    vsl|       1004 Timestamp       b Connected: 1640785456.323774 0.000011 0.000000
**** v1    vsl|       1004 BackendOpen     b 25 s1 127.0.0.1 32807 127.0.0.1 51844 reuse
**** v1    vsl|       1004 Timestamp       b Bereq: 1640785456.323798 0.000036 0.000024
**** v1    vsl|       1004 Timestamp       b Beresp: 1640785456.324087 0.000325 0.000289
**** v1    vsl|       1004 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1004 BerespStatus    b 200
**** v1    vsl|       1004 BerespReason    b OK
**** v1    vsl|       1004 BerespHeader    b Content-Length: 12
**** v1    vsl|       1004 BerespHeader    b Date: Wed, 29 Dec 2021 13:44:16 GMT
**** v1    vsl|       1004 TTL             b RFC 120 10 0 1640785456 1640785456 1640785456 0 0 cacheable
**** v1    vsl|       1004 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1004 VCL_return      b deliver
**** v1    vsl|       1004 Timestamp       b Process: 1640785456.324100 0.000338 0.000012
**** v1    vsl|       1004 Filters         b
**** v1    vsl|       1004 Storage         b malloc s0
**** v1    vsl|       1004 Fetch_Body      b 3 length stream
**** v1    vsl|       1004 BackendClose    b 25 s1 recycle
**** v1    vsl|       1004 Timestamp       b BerespBody: 1640785456.336714 0.012952 0.012614
**** v1    vsl|       1004 Length          b 12
**** v1    vsl|       1004 BereqAcct       b 124 0 124 39 12 51
**** v1    vsl|       1004 End             b
**** v1    vsl|       1003 Begin           c req 1000 rxreq
**** v1    vsl|       1003 Timestamp       c Start: 1640785456.323723 0.000000 0.000000
**** v1    vsl|       1003 Timestamp       c Req: 1640785456.323723 0.000000 0.000000
**** v1    vsl|       1003 VCL_use         c vcl1
**** v1    vsl|       1003 ReqStart        c 127.0.0.1 45314 a0
**** v1    vsl|       1003 ReqMethod       c GET
**** v1    vsl|       1003 ReqURL          c /
**** v1    vsl|       1003 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1003 ReqHeader       c Cookie: a=1; language=en
**** v1    vsl|       1003 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1003 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1003 VCL_call        c RECV
**** v1    vsl|       1003 ReqUnset        c Cookie: a=1; language=en
**** v1    vsl|       1003 ReqHeader       c Cookie: ;a=1; language=en
**** v1    vsl|       1003 ReqUnset        c Cookie: ;a=1; language=en
**** v1    vsl|       1003 ReqHeader       c Cookie: ;a=1;language=en
**** v1    vsl|       1003 ReqUnset        c Cookie: ;a=1;language=en
**** v1    vsl|       1003 ReqHeader       c Cookie: ;a=1; language=en
**** v1    vsl|       1003 ReqUnset        c Cookie: ;a=1; language=en
**** v1    vsl|       1003 ReqHeader       c Cookie: ; language=en
**** v1    vsl|       1003 ReqUnset        c Cookie: ; language=en
**** v1    vsl|       1003 ReqHeader       c Cookie: language=en
**** v1    vsl|       1003 VCL_return      c hash
**** v1    vsl|       1003 VCL_call        c HASH
**** v1    vsl|       1003 VCL_return      c lookup
**** v1    vsl|       1003 VCL_call        c MISS
**** v1    vsl|       1003 VCL_return      c fetch
**** v1    vsl|       1003 Link            c bereq 1004 fetch
**** v1    vsl|       1003 Timestamp       c Fetch: 1640785456.324186 0.000463 0.000463
**** v1    vsl|       1003 RespProtocol    c HTTP/1.1
**** v1    vsl|       1003 RespStatus      c 200
**** v1    vsl|       1003 RespReason      c OK
**** v1    vsl|       1003 RespHeader      c Content-Length: 12
**** v1    vsl|       1003 RespHeader      c Date: Wed, 29 Dec 2021 13:44:16 GMT
**** v1    vsl|       1003 RespHeader      c X-Varnish: 1003
**** v1    vsl|       1003 RespHeader      c Age: 0
**** v1    vsl|       1003 RespHeader      c Via: 1.1 varnish (Varnish/7.0)
**** v1    vsl|       1003 RespHeader      c Accept-Ranges: bytes
**** v1    vsl|       1003 VCL_call        c DELIVER
**** v1    vsl|       1003 VCL_return      c deliver
**** v1    vsl|       1003 Timestamp       c Process: 1640785456.324192 0.000469 0.000005
**** v1    vsl|       1003 Filters         c
**** v1    vsl|       1003 RespHeader      c Connection: keep-alive
**** v1    vsl|       1003 Timestamp       c Resp: 1640785456.336744 0.013021 0.012552
**** v1    vsl|       1003 ReqAcct         c 61 0 61 179 12 191
**** v1    vsl|       1003 End             c
**** v1    vsl|       1000 Link            c req 1005 rxreq
**** v1    vsl|       1006 Begin           b bereq 1005 fetch
**** v1    vsl|       1006 VCL_use         b vcl1
**** v1    vsl|       1006 Timestamp       b Start: 1640785456.336788 0.000000 0.000000
**** v1    vsl|       1006 BereqMethod     b GET
**** v1    vsl|       1006 BereqURL        b /
**** v1    vsl|       1006 BereqProtocol   b HTTP/1.1
**** v1    vsl|       1006 BereqHeader     b Host: 127.0.0.1
**** v1    vsl|       1006 BereqHeader     b X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1006 BereqHeader     b Cookie: language=fr
**** v1    vsl|       1006 BereqHeader     b Accept-Encoding: gzip
**** v1    vsl|       1006 BereqHeader     b X-Varnish: 1006
**** v1    vsl|       1006 VCL_call        b BACKEND_FETCH
**** v1    vsl|       1006 VCL_return      b fetch
**** v1    vsl|       1006 Timestamp       b Fetch: 1640785456.336799 0.000010 0.000010
**** v1    vsl|       1006 Timestamp       b Connected: 1640785456.336800 0.000011 0.000001
**** v1    vsl|       1006 BackendOpen     b 25 s1 127.0.0.1 32807 127.0.0.1 51844 reuse
**** v1    vsl|       1006 Timestamp       b Bereq: 1640785456.336821 0.000032 0.000021
**** v1    vsl|       1006 Timestamp       b Beresp: 1640785456.337099 0.000311 0.000278
**** v1    vsl|       1006 BerespProtocol  b HTTP/1.1
**** v1    vsl|       1006 BerespStatus    b 200
**** v1    vsl|       1006 BerespReason    b OK
**** v1    vsl|       1006 BerespHeader    b Content-Length: 12
**** v1    vsl|       1006 BerespHeader    b Date: Wed, 29 Dec 2021 13:44:16 GMT
**** v1    vsl|       1006 TTL             b RFC 120 10 0 1640785456 1640785456 1640785456 0 0 cacheable
**** v1    vsl|       1006 VCL_call        b BACKEND_RESPONSE
**** v1    vsl|       1006 VCL_return      b deliver
**** v1    vsl|       1006 Timestamp       b Process: 1640785456.337108 0.000319 0.000008
**** v1    vsl|       1006 Filters         b
**** v1    vsl|       1006 Storage         b malloc s0
**** v1    vsl|       1006 Fetch_Body      b 3 length stream
**** v1    vsl|       1006 BackendClose    b 25 s1 recycle
**** v1    vsl|       1006 Timestamp       b BerespBody: 1640785456.349827 0.013039 0.012719
**** v1    vsl|       1006 Length          b 12
**** v1    vsl|       1006 BereqAcct       b 124 0 124 39 12 51
**** v1    vsl|       1006 End             b
**** v1    vsl|       1005 Begin           c req 1000 rxreq
**** v1    vsl|       1005 Timestamp       c Start: 1640785456.336751 0.000000 0.000000
**** v1    vsl|       1005 Timestamp       c Req: 1640785456.336751 0.000000 0.000000
**** v1    vsl|       1005 VCL_use         c vcl1
**** v1    vsl|       1005 ReqStart        c 127.0.0.1 45314 a0
**** v1    vsl|       1005 ReqMethod       c GET
**** v1    vsl|       1005 ReqURL          c /
**** v1    vsl|       1005 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1005 ReqHeader       c Cookie: a=1; language=fr
**** v1    vsl|       1005 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1005 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1005 VCL_call        c RECV
**** v1    vsl|       1005 ReqUnset        c Cookie: a=1; language=fr
**** v1    vsl|       1005 ReqHeader       c Cookie: ;a=1; language=fr
**** v1    vsl|       1005 ReqUnset        c Cookie: ;a=1; language=fr
**** v1    vsl|       1005 ReqHeader       c Cookie: ;a=1;language=fr
**** v1    vsl|       1005 ReqUnset        c Cookie: ;a=1;language=fr
**** v1    vsl|       1005 ReqHeader       c Cookie: ;a=1; language=fr
**** v1    vsl|       1005 ReqUnset        c Cookie: ;a=1; language=fr
**** v1    vsl|       1005 ReqHeader       c Cookie: ; language=fr
**** v1    vsl|       1005 ReqUnset        c Cookie: ; language=fr
**** v1    vsl|       1005 ReqHeader       c Cookie: language=fr
**** v1    vsl|       1005 VCL_return      c hash
**** v1    vsl|       1005 VCL_call        c HASH
**** v1    vsl|       1005 VCL_return      c lookup
**** v1    vsl|       1005 VCL_call        c MISS
**** v1    vsl|       1005 VCL_return      c fetch
**** v1    vsl|       1005 Link            c bereq 1006 fetch
**** v1    vsl|       1005 Timestamp       c Fetch: 1640785456.337150 0.000399 0.000399
**** v1    vsl|       1005 RespProtocol    c HTTP/1.1
**** v1    vsl|       1005 RespStatus      c 200
**** v1    vsl|       1005 RespReason      c OK
**** v1    vsl|       1005 RespHeader      c Content-Length: 12
**** v1    vsl|       1005 RespHeader      c Date: Wed, 29 Dec 2021 13:44:16 GMT
**** v1    vsl|       1005 RespHeader      c X-Varnish: 1005
**** v1    vsl|       1005 RespHeader      c Age: 0
**** v1    vsl|       1005 RespHeader      c Via: 1.1 varnish (Varnish/7.0)
**** v1    vsl|       1005 RespHeader      c Accept-Ranges: bytes
**** v1    vsl|       1005 VCL_call        c DELIVER
**** v1    vsl|       1005 VCL_return      c deliver
**** v1    vsl|       1005 Timestamp       c Process: 1640785456.337157 0.000405 0.000006
**** v1    vsl|       1005 Filters         c
**** v1    vsl|       1005 RespHeader      c Connection: keep-alive
**** v1    vsl|       1005 Timestamp       c Resp: 1640785456.349866 0.013114 0.012709
**** v1    vsl|       1005 ReqAcct         c 61 0 61 179 12 191
**** v1    vsl|       1005 End             c
**** v1    vsl|       1000 Link            c req 1007 rxreq
**** v1    vsl|       1007 Begin           c req 1000 rxreq
**** v1    vsl|       1007 Timestamp       c Start: 1640785456.349879 0.000000 0.000000
**** v1    vsl|       1007 Timestamp       c Req: 1640785456.349879 0.000000 0.000000
**** v1    vsl|       1007 VCL_use         c vcl1
**** v1    vsl|       1007 ReqStart        c 127.0.0.1 45314 a0
**** v1    vsl|       1007 ReqMethod       c GET
**** v1    vsl|       1007 ReqURL          c /
**** v1    vsl|       1007 ReqProtocol     c HTTP/1.1
**** v1    vsl|       1007 ReqHeader       c Host: 127.0.0.1
**** v1    vsl|       1007 ReqHeader       c X-Forwarded-For: 127.0.0.1
**** v1    vsl|       1007 VCL_call        c RECV
**** v1    vsl|       1007 VCL_return      c hash
**** v1    vsl|       1007 VCL_call        c HASH
**** v1    vsl|       1007 VCL_return      c lookup
**** v1    vsl|       1007 Hit             c 1004 119.974208 10.000000 0.000000
**** v1    vsl|       1007 VCL_call        c HIT
**** v1    vsl|       1007 VCL_return      c deliver
**** v1    vsl|       1007 RespProtocol    c HTTP/1.1
**** v1    vsl|       1007 RespStatus      c 200
**** v1    vsl|       1007 RespReason      c OK
**** v1    vsl|       1007 RespHeader      c Content-Length: 12
**** v1    vsl|       1007 RespHeader      c Date: Wed, 29 Dec 2021 13:44:16 GMT
**** v1    vsl|       1007 RespHeader      c X-Varnish: 1007 1004
**** v1    vsl|       1007 RespHeader      c Age: 0
**** v1    vsl|       1007 RespHeader      c Via: 1.1 varnish (Varnish/7.0)
**** v1    vsl|       1007 RespHeader      c Accept-Ranges: bytes
**** v1    vsl|       1007 VCL_call        c DELIVER
**** v1    vsl|       1007 VCL_return      c deliver
**** v1    vsl|       1007 Timestamp       c Process: 1640785456.349896 0.000016 0.000016
**** v1    vsl|       1007 Filters         c
**** v1    vsl|       1007 RespHeader      c Connection: keep-alive
**** v1    vsl|       1007 Timestamp       c Resp: 1640785456.349915 0.000035 0.000018
**** v1    vsl|       1007 ReqAcct         c 35 0 35 184 12 196
**** v1    vsl|       1007 End             c
**** v1    vsl|          0 CLI             - EOF on CLI connection, worker stops
**** dT    0.602
***  v1    debug|Info: Child (1226) ended
**** dT    0.603
***  v1    debug|Info: Child (1226) said Child dies
***  v1    debug|Debug: Child cleanup complete
***  v1    debug|Info: manager dies
**** v1    STDOUT EOF
**** dT    0.638
**   v1    WAIT4 pid=1210 status=0x0000 (user 0.195161 sys 0.040306)
*    top   TEST test.vtc FAILED
#    top  TEST test.vtc FAILED (0.641) exit=2

From these hundreds of lines of output, the following lines explain what assertion triggered the failure:

**   c1    === expect resp.body == "Bonjour"
---- c1    EXPECT resp.body (Good morning) == "Bonjour" failed

Good morning was expected by the c1 client and Bonjour was received.

Quiet mode

By adding the -q option to the varnishtest command, quiet mode is enabled and the level of verbosity decreases significantly:

$ varnishtest -q test.vtc
#    top  TEST test.vtc FAILED (0.632) exit=2

Macros

Remember the following example from earlier in this tutorial?

varnishtest -D name=Varnish test.vtc

The -D option can be used to inject macros into the VTC file. Let’s use the ${name} macro in the following test case:

varnishtest "Macro test"
server s1 {
    rxreq
    txresp -body "Hello ${name}"
} -start

varnish v1 -vcl+backend {} -start

client c1 {
    txreq
    rxresp
    expect resp.body == "Hello Varnish"
} -run

And as expected the following varnishtest call results in a successful VTC:

$ varnishtest -D name=Varnish test.vtc
#    top  TEST test.vtc passed (0.640)

But when we change the value of the name macro to Foo, the test will fail:

$ varnishtest -D name=Foo test.vtc
**** dT    0.000
*    top   TEST test.vtc starting
**** top   extmacro def pwd=/etc/varnish
**** top   extmacro def date(...)
**** top   extmacro def string(...)
**** top   extmacro def name=Foo
**** top   extmacro def localhost=127.0.0.1
**** top   extmacro def bad_backend=127.0.0.1:42519
**** top   extmacro def listen_addr=127.0.0.1:0
**** top   extmacro def bad_ip=192.0.2.255
**** dT    0.001
**** top   macro def testdir=/etc/varnish
**** top   macro def tmpdir=/tmp/vtc.1396.3792baa1
**   top   === varnishtest "Macro test"
*    top   VTEST Macro test
**   top   === server s1 {
**   s1    Starting server
**** s1    macro def s1_addr=127.0.0.1
**** s1    macro def s1_port=46433
**** s1    macro def s1_sock=127.0.0.1:46433
*    s1    Listen on 127.0.0.1:46433
**   top   === varnish v1 -vcl+backend {} -start
**** dT    0.002
**   s1    Started on 127.0.0.1:46433 (1 iterations)
**** dT    0.009
**   v1    Launch
***  v1    CMD: cd ${pwd} && exec varnishd  -d -n /tmp/vtc.1396.3792baa1/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 -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 38303' -P /tmp/vtc.1396.3792baa1/v1/varnishd.pid
***  v1    CMD: cd /etc/varnish && exec varnishd  -d -n /tmp/vtc.1396.3792baa1/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 -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0' -M '127.0.0.1 38303' -P /tmp/vtc.1396.3792baa1/v1/varnishd.pid
**** dT    0.010
***  v1    PID: 1402
**** v1    macro def v1_pid=1402
**** v1    macro def v1_name=/tmp/vtc.1396.3792baa1/v1
**** dT    0.019
***  v1    debug|Debug: Version: varnish-7.0.1 revision d454d0ed759ce8ed2b5c7bf244090a73487e8021
***  v1    debug|Debug: Platform: Linux,5.10.76-linuxkit,aarch64,-junix,-sdefault,-sdefault,-hcritbit
***  v1    debug|200 318
***  v1    debug|-----------------------------
***  v1    debug|Varnish Cache CLI 1.0
***  v1    debug|-----------------------------
***  v1    debug|Linux,5.10.76-linuxkit,aarch64,-junix,-sdefault,-sdefault,-hcritbit
***  v1    debug|varnish-7.0.1 revision d454d0ed759ce8ed2b5c7bf244090a73487e8021
***  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|
**** dT    0.118
**** v1    CLIPOLL 1 0x1 0x0 0x0
***  v1    CLI connection fd = 7
**** dT    0.119
***  v1    CLI RX  107
**** v1    CLI RX|umyauwdfixomjikewpiansjzpqgulmps
**** v1    CLI RX|
**** v1    CLI RX|Authentication required.
**** v1    CLI TX|auth c3d6d87da028b06d20cb431e7f485c6407926ba23f6db29bab18668b62355bf5
**** dT    0.120
***  v1    CLI RX  200
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Varnish Cache CLI 1.0
**** v1    CLI RX|-----------------------------
**** v1    CLI RX|Linux,5.10.76-linuxkit,aarch64,-junix,-sdefault,-sdefault,-hcritbit
**** v1    CLI RX|varnish-7.0.1 revision d454d0ed759ce8ed2b5c7bf244090a73487e8021
**** 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
**** v1    CLI TX|vcl 4.1;
**** v1    CLI TX|backend s1 { .host = "127.0.0.1"; .port = "46433"; }
**** v1    CLI TX|
**** v1    CLI TX|
**** v1    CLI TX|%XJEIFLH|)Xspa8P
**** dT    0.224
***  v1    vsl|No VSL chunk found (child not started ?)
**** dT    0.300
***  v1    CLI RX  200
**** v1    CLI RX|VCL compiled.
**** v1    CLI TX|vcl.use vcl1
***  v1    CLI RX  200
**** v1    CLI RX|VCL 'vcl1' now active
**   v1    Start
**** v1    CLI TX|start
**** dT    0.301
***  v1    debug|Debug: Child (1418) Started
**** dT    0.325
***  v1    CLI RX  200
***  v1    wait-running
**** v1    CLI TX|status
***  v1    debug|Info: Child (1418) said Child starts
**** dT    0.326
***  v1    CLI RX  200
**** v1    CLI RX|Child in state running
**** v1    CLI TX|debug.listen_address
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 38963
**** v1    CLI TX|debug.xid 999
***  v1    CLI RX  200
**** v1    CLI RX|XID is 999
**** v1    CLI TX|debug.listen_address
***  v1    CLI RX  200
**** v1    CLI RX|a0 127.0.0.1 38963
**   v1    Listen on 127.0.0.1 38963
**** v1    macro def v1_addr=127.0.0.1
**** v1    macro def v1_port=38963
**** v1    macro def v1_sock=127.0.0.1:38963
**** v1    macro def v1_a0_addr=127.0.0.1
**** v1    macro def v1_a0_port=38963
**** v1    macro def v1_a0_sock=127.0.0.1:38963
**** dT    0.429
**** v1    vsl|          0 CLI             - Rd vcl.load "vcl1" vcl_vcl1.1640786884.525923/vgc.so 1auto
**** v1    vsl|          0 CLI             - Wr 200 52 Loaded "vcl_vcl1.1640786884.525923/vgc.so" as "vcl1"
**** v1    vsl|          0 CLI             - Rd vcl.use "vcl1"
**** v1    vsl|          0 CLI             - Wr 200 0
**** v1    vsl|          0 CLI             - Rd start
**** v1    vsl|          0 Debug           - sockopt: Setting SO_LINGER for a0=127.0.0.1:38963
**** v1    vsl|          0 Debug           - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:38963
**** v1    vsl|          0 Debug           - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:38963
**** v1    vsl|          0 Debug           - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:38963
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:38963
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:38963
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:38963
**** v1    vsl|          0 Debug           - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:38963
**** v1    vsl|          0 CLI             - Wr 200 0
**** v1    vsl|          0 CLI             - Rd debug.listen_address
**** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 38963

**** v1    vsl|          0 CLI             - Rd debug.xid 999
**** v1    vsl|          0 CLI             - Wr 200 10 XID is 999
**** v1    vsl|          0 CLI             - Rd debug.listen_address
**** v1    vsl|          0 CLI             - Wr 200 19 a0 127.0.0.1 38963

**** dT    0.533
**   top   === client c1 {
**   c1    Starting client
**** dT    0.534
**   c1    Waiting for client
**   c1    Started on 127.0.0.1:38963 (1 iterations)
***  c1    Connect to 127.0.0.1:38963
**** dT    0.535
***  c1    connected fd 17 from 127.0.0.1 37660 to 127.0.0.1:38963
**   c1    === txreq
**** c1    txreq|GET / HTTP/1.1\r
**** c1    txreq|Host: 127.0.0.1\r
**** c1    txreq|\r
**   c1    === rxresp
**** dT    0.537
***  s1    accepted fd 5 127.0.0.1 55132
**   s1    === rxreq
**** s1    rxhdr|GET / HTTP/1.1\r
**** s1    rxhdr|Host: 127.0.0.1\r
**** s1    rxhdr|X-Forwarded-For: 127.0.0.1\r
**** s1    rxhdr|Accept-Encoding: gzip\r
**** s1    rxhdr|X-Varnish: 1002\r
**** s1    rxhdr|\r
**** s1    rxhdrlen = 103
**** s1    http[ 0] |GET
**** s1    http[ 1] |/
**** s1    http[ 2] |HTTP/1.1
**** s1    http[ 3] |Host: 127.0.0.1
**** s1    http[ 4] |X-Forwarded-For: 127.0.0.1
**** s1    http[ 5] |Accept-Encoding: gzip
**** s1    http[ 6] |X-Varnish: 1002
**** s1    bodylen = 0
**   s1    === txresp -body "Hello Foo"
**** s1    txresp|HTTP/1.1 200 OK\r
**** s1    txresp|Content-Length: 9\r
**** s1    txresp|\r
**** s1    txresp|Hello Foo
***  s1    shutting fd 5
**   s1    Ending
**** dT    0.539
**** c1    rxhdr|HTTP/1.1 200 OK\r
**** c1    rxhdr|Content-Length: 9\r
**** c1    rxhdr|Date: Wed, 29 Dec 2021 14:08:04 GMT\r
**** c1    rxhdr|X-Varnish: 1001\r
**** c1    rxhdr|Age: 0\r
**** c1    rxhdr|Via: 1.1 varnish (Varnish/7.0)\r
**** c1    rxhdr|Accept-Ranges: bytes\r
**** c1    rxhdr|Connection: keep-alive\r
**** c1    rxhdr|\r
**** c1    rxhdrlen = 178
**** c1    http[ 0] |HTTP/1.1
**** c1    http[ 1] |200
**** c1    http[ 2] |OK
**** c1    http[ 3] |Content-Length: 9
**** c1    http[ 4] |Date: Wed, 29 Dec 2021 14:08:04 GMT
**** c1    http[ 5] |X-Varnish: 1001
**** c1    http[ 6] |Age: 0
**** c1    http[ 7] |Via: 1.1 varnish (Varnish/7.0)
**** c1    http[ 8] |Accept-Ranges: bytes
**** c1    http[ 9] |Connection: keep-alive
**** c1    c-l|Hello Foo
**** c1    bodylen = 9
**   c1    === expect resp.body == "Hello Varnish"
---- c1    EXPECT resp.body (Hello Foo) == "Hello Varnish" failed
**** dT    0.540
*    top   RESETTING after test.vtc
**   s1    Waiting for server (4/-1)
**   v1    Wait
**** v1    CLI TX|panic.clear
***  v1    CLI RX  300
**** v1    CLI RX|No panic to clear
***  v1    debug|Info: manager stopping child
***  v1    debug|Debug: Stopping Child
**** dT    0.635
**** v1    vsl|       1000 Begin           c sess 0 HTTP/1
**** v1    vsl|       1000 SessOpen        c 127.0.0.1 37660 a0 127.0.0.1 38963 1640786884.941181 22
**** v1    vsl|       1000 Debug           c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:38963
**** v1    vsl|       1000 Debug           c sockopt: SO_KEEPALIVE may be inherited for a0=127.0.0.1:38963
**** v1    vsl|       1000 Debug           c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:38963
**** v1    vsl|       1000 Debug           c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:38963
**** v1    vsl|       1000 Debug           c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:38963
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:38963
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:38963
**** v1    vsl|       1000 Debug           c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:38963
**** v1    vsl|       1000 Link            c req 1001 rxreq
**** v1    vsl|          0 CLI             - EOF on CLI connection, worker stops
**** dT    0.646
***  v1    debug|Info: Child (1418) ended
***  v1    debug|Info: Child (1418) said Child dies
***  v1    debug|Debug: Child cleanup complete
***  v1    debug|Info: manager dies
**** dT    0.647
**** v1    STDOUT EOF
**** dT    0.741
**   v1    WAIT4 pid=1402 status=0x0000 (user 0.173099 sys 0.063989)
*    top   TEST test.vtc FAILED
#    top  TEST test.vtc FAILED (0.744) exit=2

The output of the c1 client is very clear about the reason for the failure:


**   c1    === expect resp.body == "Hello Varnish"
---- c1    EXPECT resp.body (Hello Foo) == "Hello Varnish" failed

Testing Varnish with varnishtest

The varnishtest program#

Varnish Test Case language (VTC)#

Naming convention#

Declaring a test case#

Declaring a server#

Declaring a Varnish instance#

Declaring a client#

Running a test#

Test failures#

Quiet mode#

Macros#