GREE Engineering

<　戻る
Varnishでテストコードを書こう！

Varnishでテストコードを書こう！

xcir

はじめまして、サーバ基盤チームの田中祥平(@xcir)です。
最近入社しまして、チームではいわなちゃんと呼ばれています。よろしくお願いします。

入社してからGREEの配信システムをVarnish Cache（以下Varnish）に置き換える仕事をしていたのですが、少し前に問題なく山を超えました。
そこで今回利用したVarnishの特にテスト機能について紹介しようと思います。

なお、今回の説明に利用するVersionは3.0.3です。

Varnishとは

VCLというドメイン固有言語をもち、キャッシュもできる高速リバースプロキシです。
if文が書けるので柔軟に記述しやすいという特徴があります。

たとえば/admin/以下に許可したIP以外からのアクセスは弾くと言ったことは以下のように記述できます。

if(req.url ~ "^/admin/" && client.ip !~ local){
  error 403;
}

Varnishを全く知らない人でもなんとなくわかるのではないでしょうか？

varnishtestとは

Varnish本体のレグレッションテストを行うために作られたもので、同時にアクセスが来た時でも問題なくレスポンスできるかなど300個近いテストコードがあります。
別に本体専用というわけでもないため、VCLを記述した際にテストコードを書いておくと便利です。
このテストコードはVarnish Test Codeということで拡張子もvtc、内部でもvtcと呼ばれています。
しかしvarnishtestはコマンドの中でもあまりメジャーな存在ではありません。
理由はman varnishtestにあるので見てみましょう

SCRIPTS
       The script language used for Varnishtest is not a strictly defined language. The best reference for writing scripts is the  varnishtest  program
itself.  In  the  Varnish
       source code repository, under bin/varnishtest/tests/, all the regression tests for Varnish are kept.
意訳：
文法は厳密に定義されてないよ！特に使い方のマニュアルなんてないよ！！本体のテストコードを頑張って読もう！！！
  • 詳細なドキュメントが公式に存在しない。
  • 見てねと言ってる本体のテストコードでも使われていないコマンドがある。
  • （私の観測範囲では）海外のブログでも余り詳しく取り上げられていない。

そんな理由でそもそも存在が知られてない上級者向けコマンドです。

命令数もコマンド数も多いので全て紹介するのではなくVCLをデバッグする上で知っておくと便利なvarnishtestの使い方について解説します。

基本的なテストコード(vtc)の構造

以下が単純なvtcになります。

varnishtest "example"

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

varnish v1 -vcl+backend {
    sub vcl_recv {
        return(lookup);
    }
} -start

client c1 {
    txreq -url "/"
    rxresp
    expect resp.status        == 200
} -run

vtcは上から順に実行され、また構造として2階層となっています。
よく使うコマンドとして

コマンド名 説明
varnishtest テストのタイトルを記述する
server HTTPサーバの振る舞いを記述、基本的にオリジンとして使う
varnish Varnishサーバの振る舞いを記述、VCLなどを記述
client クライアントの振る舞いを記述

があります。
それぞれの関係は

となります。
serverはオリジンの役割をすると考えてもらえばわかりやすいとおもいます。

server

まずserverの箇所を見てみましょう。

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

{～}で囲まれた箇所でこのHTTPサーバで何をするかを定義しています。（後で解説）
次に「server s1 -start」とありますが、ここでHTTPサーバを起動しています。

varnish

次にvarnishの箇所を見てみましょう。

varnish v1 -vcl+backend {
    sub vcl_recv {
        return(lookup);
    }
} -start

-vcl+backend{～}とあります。
ここの-vcl+backendはVCLの記述を含むことと、先に指定した「server s1」をデフォルトのバックエンドとして自動的に補完する事を表しています。
そして-startのところでVarnishを起動します。
先ほどのserverの指定では-startを別で書きましたがこのように同時に指定も可能です。
なので先ほどのserverの設定も

server s1 {
...
} -start

と言った風に記述することもできます。

client

そして最後にclientです

client c1 {
    txreq -url "/"
    rxresp
    expect resp.status        == 200
} -run

これもクライアントの振る舞いを記述しています。
クライアントはサーバではないので-start(起動)ではなく-run(実行)となります。

server(2階層目)

さて次に2階層目です。serverを見てみましょう。

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

これらを言葉に直してみると

server s1 {
    リクエストを受け付ける（＝リクエストが来るまでブロックする）
    リクエストされたURLが「/」と一致しているか評価する
    レスポンスを行う
}

といった感じです。

client(2階層目)

次にclientです。

client c1 {
    txreq -url "/"
    rxresp
    expect resp.status        == 200
} -run

これも言葉に直してみると

client c1 {
    Varnishに「/」をリクエストする
    レスポンスを待つ
    レスポンスのステータスコードが200かどうかを評価する
} -run

となります。

まとめ

一連の流れを書いてみると

となります。(クリックすると大きくなります)
以上がvtcの基本的な動きとなります。

ログの読み方

取り敢えず先ほどのvtcをvarnishtestで実行してみましょう

$ sudo varnishtest example.vtc
#     top  TEST example.vtc passed (0.525)

これが成功した時のログです。

逆に失敗した時は

$ sudo varnishtest example_ng.vtc
**** top   0.0 macro def varnishd=varnishd
**** top   0.0 macro def pwd=/******
**** top   0.0 macro def topbuild=/******/../..
**** top   0.0 macro def bad_ip=10.255.255.255
**** top   0.0 macro def tmpdir=/tmp/vtc.15733.0ad434d9
*    top   0.0 TEST example_ng.vtc starting
***  top   0.0 varnishtest
*    top   0.0 TEST example ng
***  top   0.0 server
***  top   0.0 server
**   s1    0.0 Starting server
**** s1    0.0 macro def s1_addr=127.0.0.1
**** s1    0.0 macro def s1_port=34773
**** s1    0.0 macro def s1_sock=127.0.0.1 34773
*    s1    0.0 Listen on 127.0.0.1 34773
***  top   0.0 varnish
**   s1    0.0 Started on 127.0.0.1 34773
**   v1    0.0 Launch
***  v1    0.0 CMD: cd ${pwd} && ${varnishd} -d -d -n /tmp/vtc.15733.0ad434d9/v1 -l 10m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -a '127.0.0.1:0' -S /tmp/vtc.15733.0ad434d9/v1/_S -M '127.0.0.1 33434' -P /tmp/vtc.15733.0ad434d9/v1/varnishd.pid -sfile,/tmp/vtc.15733.0ad434d9/v1,10M
***  v1    0.0 CMD: cd /****** && varnishd -d -d -n /tmp/vtc.15733.0ad434d9/v1 -l 10m,1m,- -p auto_restart=off -p syslog_cli_traffic=off -a '127.0.0.1:0' -S /tmp/vtc.15733.0ad434d9/v1/_S -M '127.0.0.1 33434' -P /tmp/vtc.15733.0ad434d9/v1/varnishd.pid -sfile,/tmp/vtc.15733.0ad434d9/v1,10M
***  v1    0.0 PID: 15739
***  v1    0.0 debug| Platform: Linux,*****,x86_64,-sfile,-smalloc,-hcritbit\n
***  v1    0.0 debug| 200 240     \n
***  v1    0.0 debug| -----------------------------\n
***  v1    0.0 debug| Varnish Cache CLI 1.0\n
***  v1    0.0 debug| -----------------------------\n
***  v1    0.0 debug| Linux,*****,x86_64,-sfile,-smalloc,-hcritbit\n
***  v1    0.0 debug| \n
***  v1    0.0 debug| Type 'help' for command list.\n
***  v1    0.0 debug| Type 'quit' to close CLI session.\n
***  v1    0.0 debug| Type 'start' to launch worker process.\n
***  v1    0.0 debug| \n
**** v1    0.1 CLIPOLL 1 0x1 0x0
***  v1    0.1 CLI connection fd = 9
***  v1    0.1 CLI RX  107
**** v1    0.1 CLI RX| zzdqyzamxgvyjajjyblnszxiqekgyfvx\n
**** v1    0.1 CLI RX| \n
**** v1    0.1 CLI RX| Authentication required.\n
**** v1    0.1 CLI TX| auth 2ce6468bdf71a0af7fde8538d0f06ea17d6771bbfa5b72254df73aec6cfc7b5c\n
***  v1    0.1 CLI RX  200
**** v1    0.1 CLI RX| -----------------------------\n
**** v1    0.1 CLI RX| Varnish Cache CLI 1.0\n
**** v1    0.1 CLI RX| -----------------------------\n
**** v1    0.1 CLI RX| Linux,*****,x86_64,-sfile,-smalloc,-hcritbit\n
**** v1    0.1 CLI RX| \n
**** v1    0.1 CLI RX| Type 'help' for command list.\n
**** v1    0.1 CLI RX| Type 'quit' to close CLI session.\n
**** v1    0.1 CLI RX| Type 'start' to launch worker process.\n
**** v1    0.1 CLI TX| vcl.inline vcl1 << %XJEIFLH|)Xspa8P\n
**** v1    0.1 CLI TX| backend s1 { .host = "127.0.0.1"; .port = "34773"; }\n
**** v1    0.1 CLI TX| \n
**** v1    0.1 CLI TX| \n
**** v1    0.1 CLI TX|     sub vcl_recv {\n
**** v1    0.1 CLI TX|         return(lookup);\n
**** v1    0.1 CLI TX|     }\n
**** v1    0.1 CLI TX| \n
**** v1    0.1 CLI TX| %XJEIFLH|)Xspa8P\n
***  v1    0.3 CLI RX  200
**** v1    0.3 CLI RX| VCL compiled.
**** v1    0.3 CLI TX| vcl.use vcl1
***  v1    0.3 CLI RX  200
**   v1    0.3 Start
**** v1    0.3 CLI TX| start
***  v1    0.3 debug| child (15752) Started\n
**** v1    0.3 vsl|     0 CLI          - Rd vcl.load "vcl1" ./vcl.1Nua0t2R.so
**** v1    0.3 vsl|     0 CLI          - Wr 200 36 Loaded "./vcl.1Nua0t2R.so" as "vcl1"
**** v1    0.3 vsl|     0 CLI          - Rd vcl.use "vcl1"
**** v1    0.3 vsl|     0 CLI          - Wr 200 0
**** v1    0.3 vsl|     0 CLI          - Rd start
**** v1    0.3 vsl|     0 Debug        - Acceptor is epoll
**** v1    0.3 vsl|     0 CLI          - Wr 200 0
***  v1    0.3 CLI RX  200
***  v1    0.3 wait-running
**** v1    0.3 CLI TX| status
***  v1    0.3 debug| Child (15752) said Child starts\n
***  v1    0.3 debug| Child (15752) said SMF.s0 mmap'ed 10485760 bytes of 10485760\n
**** v1    0.3 vsl|     0 WorkThread   - 0x7f4f9b3f4ac0 start
**** v1    0.3 vsl|     0 WorkThread   - 0x7f4f9abf3ac0 start
**** v1    0.3 vsl|     0 WorkThread   - 0x7f4f9a3f2ac0 start
**** v1    0.3 vsl|     0 WorkThread   - 0x7f4f99bf1ac0 start
**** v1    0.3 vsl|     0 WorkThread   - 0x7f4f993f0ac0 start
**** v1    0.3 vsl|     0 WorkThread   - 0x7f4f98befac0 start
**** v1    0.3 vsl|     0 WorkThread   - 0x7f4f983eeac0 start
**** v1    0.3 vsl|     0 WorkThread   - 0x7f4f97bedac0 start
**** v1    0.3 vsl|     0 WorkThread   - 0x7f4f973ecac0 start
**** v1    0.3 vsl|     0 WorkThread   - 0x7f4f96bebac0 start
***  v1    0.3 CLI RX  200
**** v1    0.3 CLI RX| Child in state running
**** v1    0.3 CLI TX| debug.xid 1000
***  v1    0.4 CLI RX  200
**** v1    0.4 CLI RX| XID is 1000
**** v1    0.4 CLI TX| debug.listen_address
***  v1    0.4 CLI RX  200
**** v1    0.4 CLI RX| 127.0.0.1 52004\n
**   v1    0.4 Listen on 127.0.0.1 52004
**** v1    0.4 macro def v1_addr=127.0.0.1
**** v1    0.4 macro def v1_port=52004
**** v1    0.4 macro def v1_sock=127.0.0.1 52004
***  top   0.4 client
**   c1    0.4 Starting client
**   c1    0.4 Waiting for client
***  c1    0.4 Connect to 127.0.0.1 52004
***  c1    0.4 connected fd 10 from 127.0.0.1 55785 to 127.0.0.1 52004
***  c1    0.4 txreq
**** c1    0.4 txreq| GET / HTTP/1.1\r\n
**** c1    0.4 txreq| \r\n
***  s1    0.4 accepted fd 4
***  s1    0.4 rxreq
**** s1    0.4 rxhdr| GET / HTTP/1.1\r\n
**** s1    0.4 rxhdr| X-Varnish: 1001\r\n
**** s1    0.4 rxhdr| Accept-Encoding: gzip\r\n
**** s1    0.4 rxhdr| Host: 127.0.0.1\r\n
**** s1    0.4 rxhdr| \r\n
**** 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-Varnish: 1001
**** s1    0.4 http[ 4] | Accept-Encoding: gzip
**** s1    0.4 http[ 5] | Host: 127.0.0.1
**** s1    0.4 bodylen = 0
***  s1    0.4 expect
**** s1    0.4 EXPECT req.url (/) == / (/) match
***  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 4
**   s1    0.4 Ending
***  c1    0.4 rxresp
**** c1    0.4 rxhdr| HTTP/1.1 200 Ok\r\n
**** c1    0.4 rxhdr| Content-Length: 0\r\n
**** c1    0.4 rxhdr| Accept-Ranges: bytes\r\n
**** c1    0.4 rxhdr| Date: Mon, 15 Apr 2013 00:20:30 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\r\n
**** c1    0.4 rxhdr| Connection: keep-alive\r\n
**** c1    0.4 rxhdr| \r\n
**** 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] | Accept-Ranges: bytes
**** c1    0.4 http[ 5] | Date: Mon, 15 Apr 2013 00:20:30 GMT
**** c1    0.4 http[ 6] | X-Varnish: 1001
**** c1    0.4 http[ 7] | Age: 0
**** c1    0.4 http[ 8] | Via: 1.1 varnish
**** c1    0.4 http[ 9] | Connection: keep-alive
**** c1    0.4 bodylen = 0
***  c1    0.4 expect
---- c1    0.4 EXPECT resp.status (200) == 404 (404) failed
*    top   0.4 RESETTING after example_ng.vtc
**   s1    0.4 Waiting for server
**** s1    0.4 macro undef s1_addr
**** s1    0.4 macro undef s1_port
**** s1    0.4 macro undef s1_sock
**** v1    0.4 vsl|     0 CLI          - Rd debug.xid 1000
**** v1    0.4 vsl|     0 CLI          - Wr 200 11 XID is 1000
**** v1    0.4 vsl|     0 CLI          - Rd debug.listen_address
**** v1    0.4 vsl|     0 CLI          - Wr 200 16 127.0.0.1 52004

**** v1    0.4 vsl|    11 SessionOpen  c 127.0.0.1 55785 127.0.0.1:0
**** v1    0.4 vsl|    11 ReqStart     c 127.0.0.1 55785 1001
**** v1    0.4 vsl|    11 RxRequest    c GET
**** v1    0.4 vsl|    11 RxURL        c /
**** v1    0.4 vsl|    11 RxProtocol   c HTTP/1.1
**** v1    0.4 vsl|    11 VCL_call     c recv
**** v1    0.4 vsl|    11 VCL_return   c lookup
**** v1    0.4 vsl|    11 VCL_call     c hash
**** v1    0.4 vsl|    11 Hash         c /
**** v1    0.4 vsl|    11 Hash         c 127.0.0.1
**** v1    0.4 vsl|    11 VCL_return   c hash
**** v1    0.4 vsl|    11 VCL_call     c miss
**** v1    0.4 vsl|    11 VCL_return   c fetch
**** v1    0.4 vsl|    13 BackendOpen  b s1 127.0.0.1 57395 127.0.0.1 34773
**** v1    0.4 vsl|    11 Backend      c 13 s1 s1
**** v1    0.4 vsl|    13 TxRequest    b GET
**** v1    0.4 vsl|    13 TxURL        b /
**** v1    0.4 vsl|    13 TxProtocol   b HTTP/1.1
**** v1    0.4 vsl|    13 TxHeader     b X-Varnish: 1001
**** v1    0.4 vsl|    13 TxHeader     b Accept-Encoding: gzip
**** v1    0.4 vsl|    13 TxHeader     b Host: 127.0.0.1
**** v1    0.4 vsl|    13 RxProtocol   b HTTP/1.1
**** v1    0.4 vsl|    13 RxStatus     b 200
**** v1    0.4 vsl|    13 RxResponse   b Ok
**** v1    0.4 vsl|    13 RxHeader     b Content-Length: 0
**** v1    0.4 vsl|    11 TTL          c 1001 RFC 120 -1 -1 1365985231 0 0 0 0
**** v1    0.4 vsl|    11 VCL_call     c fetch
**** v1    0.4 vsl|    11 VCL_return   c deliver
**** v1    0.4 vsl|    11 ObjProtocol  c HTTP/1.1
**** v1    0.4 vsl|    11 ObjResponse  c Ok
**** v1    0.4 vsl|    13 Fetch_Body   b 4(length) cls 0 mklen 1
**** v1    0.4 vsl|    13 Length       b 0
**** v1    0.4 vsl|    13 BackendReuse b s1
**** v1    0.4 vsl|    11 VCL_call     c deliver
**** v1    0.4 vsl|    11 VCL_return   c deliver
**** v1    0.4 vsl|    11 TxProtocol   c HTTP/1.1
**** v1    0.4 vsl|    11 TxStatus     c 200
**** v1    0.4 vsl|    11 TxResponse   c Ok
**** v1    0.4 vsl|    11 TxHeader     c Content-Length: 0
**** v1    0.4 vsl|    11 TxHeader     c Accept-Ranges: bytes
**** v1    0.4 vsl|    11 TxHeader     c Date: Mon, 15 Apr 2013 00:20:30 GMT
**** v1    0.4 vsl|    11 TxHeader     c X-Varnish: 1001
**** v1    0.4 vsl|    11 TxHeader     c Age: 0
**** v1    0.4 vsl|    11 TxHeader     c Via: 1.1 varnish
**** v1    0.4 vsl|    11 TxHeader     c Connection: keep-alive
**** v1    0.4 vsl|    11 Length       c 0
**** v1    0.4 vsl|    11 ReqEnd       c 1001 1365985230.747681856 1365985230.748583317 0.000089407 0.000833035 0.000068426
**** v1    0.5 vsl|    11 Debug        c herding
**   v1    1.4 Wait
**   v1    1.4 R 15739 Status: 0000
*    top   1.4 TEST example_ng.vtc FAILED

#     top  TEST example_ng.vtc FAILED (1.428) exit=1

失敗するためにレスポンスのステータスが404でなければエラーとしています。

client c1 {
    txreq -url "/"
    rxresp
    expect resp.status        == 404　★ここを変えた
} -run

非常に長くて何が何だかわかりませんが、大体見るべきポイントは同じなので解説します。

ログフォーマット

manに記載されている通り、varnishtestには厳密な定義はありません。そのため若干揺れがあり、必ずしも当てはまるものではありません。

logのレベル(0～4) 出力したコンポーネントの名前 経過時間 メッセージ
* top 1.4 TEST example_ng.vtc FAILED
レベルについて

logのレベルが上がるほど詳細になります。

レベル 表記 内容 例
0 # テストが成功した # top TEST example.vtc passed (0.498)
0 ---- テストが失敗した原因などの重要なログ ---- c1 0.4 EXPECT resp.status (200) == 404 (404) failed
1 * 各種コマンドのログ * top 1.4 TEST example_ng.vtc FAILED
2 ** 各種コマンドのログ ** s1 0.0 Starting server
3 *** 各種コマンドのログ *** s1 0.4 rxreq
4 **** 各種コマンドのログ **** s1 0.4 http[ 0] ｜ GET

VCLのテストの場合では、レベル0と4のログを見れば基本的に解決すると思います。

抜粋例
**** c1    0.4 rxhdr| HTTP/1.1 200 Ok\r\n
**** c1    0.4 rxhdr| Content-Length: 0\r\n
**** c1    0.4 rxhdr| Accept-Ranges: bytes\r\n
**** c1    0.4 rxhdr| Date: Mon, 15 Apr 2013 00:20:30 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\r\n
**** c1    0.4 rxhdr| Connection: keep-alive\r\n
**** c1    0.4 rxhdr| \r\n
**** c1    0.4 http[ 0] | HTTP/1.1
**** c1    0.4 http[ 1] | 200　★失敗した原因（ステータスが200）
**** c1    0.4 http[ 2] | Ok
**** c1    0.4 http[ 3] | Content-Length: 0
**** c1    0.4 http[ 4] | Accept-Ranges: bytes
**** c1    0.4 http[ 5] | Date: Mon, 15 Apr 2013 00:20:30 GMT
**** c1    0.4 http[ 6] | X-Varnish: 1001
**** c1    0.4 http[ 7] | Age: 0
**** c1    0.4 http[ 8] | Via: 1.1 varnish
**** c1    0.4 http[ 9] | Connection: keep-alive
**** c1    0.4 bodylen = 0
---- c1    0.4 EXPECT resp.status (200) == 404 (404) failed　★expect失敗
コンポーネントの名前について
コンポーネント名 説明
top varnishtestが発行するログ
s～ serverが発行するログ
v～ varnishが発行するログ
c～ clientが発行するログ

server,varnish,clientの名前は

server s1 {

のs1部分になります。
またこの名前はそれぞれs,v,cから始まる必要があります。
例えばserverの定義で

server origin1 {

とした場合はvtcのエラーとなります。

コマンド応用編

いままで、基本的な使い方とログの読み方について解説しました。
しかし、vclをデバッグするのに便利なコマンドが他にもあるので解説します。

serverコマンド

コマンド名 説明 使い方例
-repeat {～}で囲まれた部分を指定回数実行する -repeat 2
-listen アドレスとポートを指定する -listen "localhost:9821"
-start サーバを開始する -start

ここで重要なのが-repeatです。

server s1 {
    rxreq
    txresp
} -start

と指定した場合、serverは何回でもレスポンスするわけではなく1回のみレスポンスします。
そのため、2回以上serverがリクエストを受け付ける場合は

server s1 {
    rxreq
    txresp
    rxreq
    txresp
} -start

か

server s1 -repeat 2 {
    rxreq
    txresp
} -start

といった様に書く必要があります。
回数は実際のリクエストの回数より多めに指定しても問題ありません。

varnishコマンド

コマンド名 説明 使い方例
-storage ストレージを指定する -storage "-smalloc,1m"
-arg 起動パラメータを指定 -arg "-p thread_pool_stack=262144"
-cli CLIコマンド発行 -cli "vcl.list"
-vcl VCLを定義する -vcl {...}
-vcl+backend VCLを定義する(defaultのバックエンドを自動生成) -vcl+backend {...}
-start varnishを開始する -start
-stop varnishを停止する -stop

clientコマンド

コマンド名 説明 使い方例
-repeat {～}で囲まれた部分を指定回数実行する -repeat 2
-connect 接続先を指定 -connect "localhost:9821"
-run 開始する -run

clientとserverの{...}で使うコマンド

コマンド名 コマンドのオプション server client 説明 使い方例
timeout ✔ ✔ タイムアウト秒数を指定 timeout 10
txreq ✔ リクエストを送信 txreq -url "/"
-url ✔ リクエストを送信(url指定) txreq -url "/"
-req ✔ リクエストを送信(メソッド指定) txreq -req "POST" -url "/"
-proto ✔ リクエストを送信(プロトコル指定) txreq -proto HTTP/1.0 -url "/"
-hdr ✔ リクエストを送信(ヘッダ指定) txreq -hdr "hoge: hoge" -hdr "mage: mage" -url "/"
-body ✔ リクエストを送信(ボディ指定) txreq -req "POST" -url "/" -body {hello}
rxreq ✔ リクエストを受信 rxreq
txresp ✔ レスポンスを送信 txresp
-proto ✔ レスポンスを送信(プロトコル指定) txresp -proto HTTP/1.0
-hdr ✔ レスポンスを送信(ヘッダ指定) txresp -hdr "hoge: hoge" -hdr "mage: mage"
-body ✔ レスポンスを送信(ボディ指定) txresp -body {hello}
-status ✔ レスポンスを送信(ステータス指定) txresp -status 404
rxresp ✔ レスポンスを受信 rxresp
expect ✔ ✔ 式を評価する expect req.url == "/"
send ✔ ✔ そのまま送信 send "HTTP/1.1 200 Ok\r\nConnection: close\r\n\r\n"
sendhex ✔ ✔ そのまま送信(16進表記) sendhex "2e 51 30 36 54 30 b0 b4"
delay ✔ ✔ スリープする delay 1
loop ✔ ✔ {...}で囲んだ箇所を指定回数ループする loop 2 {...}

expectで使える演算子は以下のとおりです

演算子
==
!=
>
<
>=
<=

delayでは以下の表記方法があります。

表記 説明
delay 1 1秒スリープ
delay 1.5 1.5秒スリープ
delay .5 0.5秒スリープ

shellコマンド

shellコマンドを実行できます。

shell "echo hello"

といった風に使用可能です。

起動オプション

varnishテスト自体の起動オプションです

オプション名 説明 使い方
-D マクロ指定（後述） -Dkey=val
-n テストを指定回数繰り返す -n 2
-j テストを並列で動かす -j 2

varnishtestは結構時間がかかるので並列で動かしたくなりますが、重いので2,3ぐらいで留めておくのが良いかと思います。

マクロについて

vtc中に

include "${vclpath}/default.vcl";

といった風に記述しておいて

varnishtest -Dvclpath=/etc/varnish example.vtc

と実行すると、置換されて

include "/etc/varnish/default.vcl";

上記のようになります。
非常に便利ですが例えばvclのincludeを使った先については置換されないので注意が必要です。

またデフォルトで定義されるものとして

マクロ名 説明
pwd 現在のディレクトリ
date 現在時刻
tmpdir このテストで使ってるテンポラリディレクトリ
[server名]_sock 指定serverのアドレス・ポート
[varnish名]_sock 指定varnishのアドレス・ポート

などがあります。

その他記述する際の留意点など

server,varnish,clientについて

必ず3つが定義されている必要はありません。serverがなくてもいいですし、varnishがなくてもOKです。

コメントについて

vtc中にコメントを入れたい場合は先頭行に#を入れてください。

複数行のテキストの使い方

テキストは通常"..."で囲まれた範囲ですが、複数行を指定したい場合は{...}で囲むことで可能です。

単一行
"hoge"
複数行
{
hoge
fuga
}

謎のエラーへの対処(Syntax)

---- top   0.0 Unknown command: "rxreq"

rxreqはあるのにエラーになる場合があります。大抵の場合は前の行に問題があるケースが多いです。

NGパタン
server s1{
    rxreq
    txresp
}-start
OKパタン
server s1 {
    rxreq
    txresp
}-start

違いはs1と{の間にスペースがあることなのですが、こういうところが弱いのでよくわからないエラーが出た場合はスペース省略していないかをチェックしてみてください

異常終了時

ctrl+cで終了させたときや何らかの原因で異常終了した場合は、/tmpにvtc.～で始まるディレクトリが残っているケースがあります。
案外サイズが大きいので削除すると良いと思います。

まとめ

以上がvarnishtestの使い方でした。
実は、他にもsema（セマフォを使った同期）などのコマンドもあるのですが、VCLをテストする場合はこれぐらい知っておけば十分だと思います。
varnishはプログラムのように複雑な条件も書くことができるため、言ってしまうとバグが混入しやすいとも言えます。
そのためうまくvarnishtestを使うと良いのではないかと思います。

参考ページ

Varnish Cache公式ページ

xcir