Varnishのログにアクセスしてみよう！

2013/12/17

xcir

こんにちは、Service Reliabilityチームのいわなちゃん(@xcir)です。チーム名が読みづらいのでSRやSレアと呼ばれたりもしています。レアリティが上がるように頑張って行きたいと考えています。

前回は「Varnishでテストコードを書こう！」という記事を書いたので、今回はGREE Advent calendar 2013の17日目も兼ねてVarnish Cache(以下Varnish)のログを読んだり加工してみたりしようと思います。

また、使用したVersionは3.0.3です。

Varnishのログのしくみ

Proxyでアクセスログを取得したいというのはよくあると思います。通常のミドルウェアでは設定ファイルで出力ファイル名を決めたりします。しかし、Varnish本体(varnishd)の設定ではそのような項目はありません。

では、Varnishはログを出していないのか？というとそうではなく、共有メモリ(Varnish Shared memory Log 以下VSL)上にログを出力しています。そしてvarnishncsaなどのコマンドでVSLを読み込んでファイルに書き込んだり標準出力したりします。

ではなぜこのような仕組みになっているのでしょうか？一番の理由はパフォーマンスです。
例えばApacheのアクセスログはリクエストのたびにファイルに書き込みを行うため、高リクエストかつi/oに余裕がない場合は、そこがボトルネックになったりします。(BufferedLogsを有効にするとパフォーマンスが上がったりしますよね）
Varnishの場合はそのような操作をしないためログ出力がボトルネックになりません。そしてVarnishがVSLに吐き出すログは非常に多くの情報が含まれています。リクエスト・レスポンスヘッダなどはもちろんの事、どのようなAction(vcl_missなど)を通過したかなどもわかります。
また、オプション(vcl_trace)を有効にした場合、どの分岐(if文)を通過したかなども保存されます。そして膨大なログをパフォーマンスを損なわずにアクセスログの形(varnishncsa)やレスポンスタイムとヒット率のヒストグラム(varnishhist)で整形しているわけです。もちろんフィルタリングもできるので、たとえば404だけを抜き出すことも非常に簡単に行えます。

生ログを読んでみよう(varnishlog)

VSLで出力されている全情報を見る際に便利なのがvarnishlogです。
以下はwgetで叩いてみた時のログです

   13 BackendOpen  b default 127.0.0.1 44138 127.0.0.1 81
   13 TxRequest    b GET
   13 TxURL        b /
   13 TxProtocol   b HTTP/1.1
   13 TxHeader     b User-Agent: Wget/1.12 (linux-gnu)
   13 TxHeader     b Accept: */*
   13 TxHeader     b Host: 127.0.0.1
   13 TxHeader     b X-Varnish: 411435415
   13 RxProtocol   b HTTP/1.1
   13 RxStatus     b 200
   13 RxResponse   b OK
   13 RxHeader     b Date: Thu, 28 Nov 2013 10:06:07 GMT
   13 RxHeader     b Server: Apache/2.2.16 (Debian)
   13 RxHeader     b Vary: Accept-Encoding
   13 RxHeader     b Content-Length: 1673
   13 RxHeader     b Content-Type: text/html;charset=UTF-8
   13 Fetch_Body   b 4(length) cls 0 mklen 1
   13 Length       b 510
   13 BackendReuse b default
   11 SessionOpen  c 127.0.0.1 38026 :80
   11 ReqStart     c 127.0.0.1 38026 411435415
   11 RxRequest    c GET
   11 RxURL        c /
   11 RxProtocol   c HTTP/1.0
   11 RxHeader     c User-Agent: Wget/1.12 (linux-gnu)
   11 RxHeader     c Accept: */*
   11 RxHeader     c Host: 127.0.0.1
   11 RxHeader     c Connection: Keep-Alive
   11 VCL_call     c recv lookup
   11 VCL_call     c hash
   11 Hash         c /
   11 Hash         c 127.0.0.1
   11 VCL_return   c hash
   11 VCL_call     c miss fetch
   11 Backend      c 13 default default
   11 TTL          c 411435415 RFC 120 -1 -1 1385633167 0 1385633167 0 0
   11 VCL_call     c fetch deliver
   11 ObjProtocol  c HTTP/1.1
   11 ObjResponse  c OK
   11 ObjHeader    c Date: Thu, 28 Nov 2013 10:06:07 GMT
   11 ObjHeader    c Server: Apache/2.2.16 (Debian)
   11 ObjHeader    c Vary: Accept-Encoding
   11 ObjHeader    c Content-Type: text/html;charset=UTF-8
   11 ObjHeader    c Content-Encoding: gzip
   11 Gzip         c G F - 1673 510 80 80 4016
   11 VCL_call     c deliver deliver
   11 TxProtocol   c HTTP/1.1
   11 TxStatus     c 200
   11 TxResponse   c OK
   11 TxHeader     c Server: Apache/2.2.16 (Debian)
   11 TxHeader     c Vary: Accept-Encoding
   11 TxHeader     c Content-Type: text/html;charset=UTF-8
   11 TxHeader     c Date: Thu, 28 Nov 2013 10:06:07 GMT
   11 TxHeader     c X-Varnish: 411435415
   11 TxHeader     c Age: 0
   11 TxHeader     c Via: 1.1 varnish
   11 TxHeader     c Connection: close
   11 Gzip         c U D - 510 1673 80 80 4016
   11 Length       c 1673
   11 ReqEnd       c 411435415 1385633167.362369776 1385633167.364767551 0.000104427 0.002285004 0.000112772
   11 SessionClose c EOF mode

13 BackendOpen b default 127.0.0.1 44138 127.0.0.1 81

13 TxRequest b GET

13 TxURL b /

13 TxProtocol b HTTP/1.1

13 TxHeader b User-Agent: Wget/1.12 (linux-gnu)

13 TxHeader b Accept: */*

13 TxHeader b Host: 127.0.0.1

13 TxHeader b X-Varnish: 411435415

13 RxProtocol b HTTP/1.1

13 RxStatus b 200

13 RxResponse b OK

13 RxHeader b Date: Thu, 28 Nov 2013 10:06:07 GMT

13 RxHeader b Server: Apache/2.2.16 (Debian)

13 RxHeader b Vary: Accept-Encoding

13 RxHeader b Content-Length: 1673

13 RxHeader b Content-Type: text/html;charset=UTF-8

13 Fetch_Body b 4(length) cls 0 mklen 1

13 Length b 510

13 BackendReuse b default

11 SessionOpen c 127.0.0.1 38026 :80

11 ReqStart c 127.0.0.1 38026 411435415

11 RxRequest c GET

11 RxURL c /

11 RxProtocol c HTTP/1.0

11 RxHeader c User-Agent: Wget/1.12 (linux-gnu)

11 RxHeader c Accept: */*

11 RxHeader c Host: 127.0.0.1

11 RxHeader c Connection: Keep-Alive

11 VCL_call c recv lookup

11 VCL_call c hash

11 Hash c /

11 Hash c 127.0.0.1

11 VCL_return c hash

11 VCL_call c miss fetch

11 Backend c 13 default default

11 TTL c 411435415 RFC 120 -1 -1 1385633167 0 1385633167 0 0

11 VCL_call c fetch deliver

11 ObjProtocol c HTTP/1.1

11 ObjResponse c OK

11 ObjHeader c Date: Thu, 28 Nov 2013 10:06:07 GMT

11 ObjHeader c Server: Apache/2.2.16 (Debian)

11 ObjHeader c Vary: Accept-Encoding

11 ObjHeader c Content-Type: text/html;charset=UTF-8

11 ObjHeader c Content-Encoding: gzip

11 Gzip c G F - 1673 510 80 80 4016

11 VCL_call c deliver deliver

11 TxProtocol c HTTP/1.1

11 TxStatus c 200

11 TxResponse c OK

11 TxHeader c Server: Apache/2.2.16 (Debian)

11 TxHeader c Vary: Accept-Encoding

11 TxHeader c Content-Type: text/html;charset=UTF-8

11 TxHeader c Date: Thu, 28 Nov 2013 10:06:07 GMT

11 TxHeader c X-Varnish: 411435415

11 TxHeader c Age: 0

11 TxHeader c Via: 1.1 varnish

11 TxHeader c Connection: close

11 Gzip c U D - 510 1673 80 80 4016

11 Length c 1673

11 ReqEnd c 411435415 1385633167.362369776 1385633167.364767551 0.000104427 0.002285004 0.000112772

11 SessionClose c EOF mode

リクエストのヘッダやレスポンスのヘッダなどが見えたりしますがどのように読めばいいのか解説します。

   11 TxStatus     c 200

1	11 TxStatus c 200

トランザクション番号	タグ	データの流れ	データ
11	TxStatus	c	200

ログは4つの部分に分かれています。
それぞれ解説します。

トランザクション番号
番号が同一の場合は同一のHTTPのトランザクションであることを示します。あくまでリクエストのグループではなくトランザクションのグループなのでClient<->VarnishとVarnish<->Backendでは同じリクエストでもトランザクションが違います。

タグ
このデータがどのようなアクティビティなのかを示しています。例えばReqStartはリクエストの開始を意味します。
またPrefixにRx・Txが付くものにはそれぞれ意味があります。

Rx	Varnishが受け取ったデータ
Tx	Varnishが送信したデータ

データの流れ
Varnishがどことデータのやりとりをしているかを示しています。

c	clientに関するデータ
b	backendに関するデータ

データ
実際のデータになります。

これらを図解すると以下の様な感じになります。

これらを考えていくつかのタグとデータの流れの組み合わせで何を示しているかを表にしてみました

データの流れ	タグ	意味
c	Backend	使用するバックエンドを示す [backendのTrx] [director/backend] [backend w/index]
c	VCL_call	どのアクションを通過したか [通過アクション名] [(VCL_Returnがない場合)returnで指定したもの]
c	VCL_Return	vcl中でreturn(XXXX)した際のXXXXの内容
c	VCL_trace	optionのvcl_traceをonの場合に出力。VCLのどの行を通過したかを示す [VRT_Count番号] [行数].[行頭からの文字数]
c	SessionOpen	セッションを開いたことを示す [clientのIP] [clientのポート] [LISTEN]
c	ReqStart	リクエストの処理を開始したことを示す [clientのIP] [clientのポート] [req.xid]
c	Hit	キャッシュヒットした [ヒットしたobjectのxid]
c	Hash	Objectのハッシュ生成に使った文字列 [hash_dataの引数]

またVCLでの変数と一緒に扱えるのは以下です

データの流れ	タグ	vclでの変数
c	ObjResponse	obj.response
c	ObjProtocol	obj.proto
c	ObjHeader	obj.http
c	RxRequest	req.request
c	RxURL	req.url
c	RxProtocol	req.proto
c	RxHeader	req.http
c	TxResponse	resp.response
c	TxStatus	resp.status
c	TxProtocol	resp.proto
c	TxHeader	resp.http
b	RxResponse	beresp.response
b	RxStatus	beresp.status
b	RxProtocol	beresp.proto
b	RxHeader	beresp.http
b	TxRequest	req.request
b	TxURL	bereq.url
b	TxProtocol	bereq.proto
b	TxHeader	bereq.http

そして先程の生ログからvcl_callとVCL_Returnをピックアップして読むと

vcl_recv(return:lookup)
　↓
vcl_hash(return:hash)
　↓
vcl_miss(return:fetch)
　↓
vcl_fetch(return:deliver)
　↓
vcl_deliver(return:deliver)

vcl_recv(return:lookup)

　↓

vcl_hash(return:hash)

　↓

vcl_miss(return:fetch)

　↓

vcl_fetch(return:deliver)

　↓

vcl_deliver(return:deliver)

という経路で処理されたのがわかります。
これほどの情報がデバッグフラグをOnにすることなく、本番で稼働しているvarnishから取得できるのは非常に便利だと思います。弊社本番環境でもピークタイムに特に気にせずvarnishlogを叩いたりしていますが問題ありません。

VSLにアクセスしてみよう

さて、varnishでlogを読むにはvarnishlogやvarnishhistやvarnishncsaなどの別のコマンドを使います。先に書いたとおり、これらはVSLからログを読み込んで加工やフィルタリングして出力しています。これらはコマンドはAPI経由でVSLにアクセスしています。そこでPythonを使って簡単にアクセスする方法を説明します。
今回は拙作のVSLにアクセスするpython-varnishapiを使用します。

コード

# coding: utf-8

import varnishapi,time

def main():
    smp = SampleVarnishLog()
    smp.execute()

class SampleVarnishLog:
    def __init__(self):
        #VSLにアクセスする準備をする
        self.vap     = varnishapi.VarnishAPI()

    def execute(self):
        while 1:
            #VSLにデータが書き込まれた時にコールバックする関数を登録する
            self.vap.VSL_NonBlockingDispatch(self.vapCallBack)
            time.sleep(0.1)

    #callbackの関数
    def vapCallBack(self, priv, tag, fd, length, spec, ptr, bm):
        #読みやすい形に整形する
        nml = self.vap.normalizeDic(priv, tag, fd, length, spec, ptr, bm)
        '''
            [元データ]
            12 ObjHeader    c Cache-Control: max-age=0, no-cache
            
            [nmlしたデータ]
            'fd'      : 12,
            'type'    : 1,
            'typeName': 'c',
            'tag'     : 'ObjHeader',
            'msg'     : 'Cache-Control: max-age=0, no-cache',

            'fd'      : トランザクション番号
            'type'    : データの流れ(int)
            'typeName': データの流れ(string)
            'tag'     : タグ
            'msg'     : データ
        '''
        print "%5d %-12s %s %s" % (nml['fd'], nml['tag'], nml['typeName'], nml['msg'])

main()

# coding: utf-8

import varnishapi,time

def main():

smp = SampleVarnishLog()

smp.execute()

class SampleVarnishLog:

def __init__(self):

#VSLにアクセスする準備をする

self.vap = varnishapi.VarnishAPI()

def execute(self):

while 1:

#VSLにデータが書き込まれた時にコールバックする関数を登録する

self.vap.VSL_NonBlockingDispatch(self.vapCallBack)

time.sleep(0.1)

#callbackの関数

def vapCallBack(self, priv, tag, fd, length, spec, ptr, bm):

#読みやすい形に整形する

nml = self.vap.normalizeDic(priv, tag, fd, length, spec, ptr, bm)

'''

[元データ]

12 ObjHeader c Cache-Control: max-age=0, no-cache

[nmlしたデータ]

'fd' : 12,

'type' : 1,

'typeName': 'c',

'tag' : 'ObjHeader',

'msg' : 'Cache-Control: max-age=0, no-cache',

'fd' : トランザクション番号

'type' : データの流れ(int)

'typeName': データの流れ(string)

'tag' : タグ

'msg' : データ

'''

print "%5d %-12s %s %s" % (nml['fd'], nml['tag'], nml['typeName'], nml['msg'])

main()

出力

    0 CLI          - Rd ping
    0 CLI          - Wr 200 19 PONG 1386260241 1.0
   11 SessionOpen  c 127.0.0.1 53623 :80
   11 ReqStart     c 127.0.0.1 53623 1147885118
   11 RxRequest    c GET
   11 RxURL        c /
   11 RxProtocol   c HTTP/1.0
   11 RxHeader     c User-Agent: Wget/1.12 (linux-gnu)
   11 RxHeader     c Accept: */*
   11 RxHeader     c Host: 127.0.0.1
   11 RxHeader     c Connection: Keep-Alive
   11 VCL_call     c recv
   11 VCL_return   c lookup
...省略

0 CLI - Rd ping

0 CLI - Wr 200 19 PONG 1386260241 1.0

11 SessionOpen c 127.0.0.1 53623 :80

11 ReqStart c 127.0.0.1 53623 1147885118

11 RxRequest c GET

11 RxURL c /

11 RxProtocol c HTTP/1.0

11 RxHeader c User-Agent: Wget/1.12 (linux-gnu)

11 RxHeader c Accept: */*

11 RxHeader c Host: 127.0.0.1

11 RxHeader c Connection: Keep-Alive

11 VCL_call c recv

11 VCL_return c lookup

...省略

非常に簡単にvarnishlogと同じ出力が得られました。これを使えば自由な計測を作ることができると思います。
拙作ですがvarnishlogをデバッグする際にどうアクションが呼ばれて、変数がどのような状態かを調べたかったため
vsltransというログを整形するツールを作りました。

このようなものも作れますし、たとえばドメイン別・ディレクトリ別のヒット率の計測ツールもお手軽につくれます。

VSL-Query Expressions(おまけ)

2014Q1でリリースされるかも？と言われているVarnish4ですが、先日technology preview1(以下TP1)が出ましたので、変更点の1つであるログ関係の話をしようと思います。
これはTP1での話で正式リリース時には変更がある可能性がありますのでご注意ください。また、現時点で本番投入はオススメできません。

Varnish4ではログを取る仕組み自体(VSLを通して外部コマンドから読み取る)については変更はありませんが、libvarnishapiのバージョンが1.1から1.3に上がり、ログ関係の新機能が追加されました。
一番大きいのはVSL-Query Expressionsというもので、簡単に言うとログの絞り込みに式が使えます。例えば、現在のversionのvarnishlogだけで複数の条件で絞り込みを行うのは難しいですがVarnish4では非常に簡単に行うことができます。
例えば以下はuser-agentにiPhoneを含みexample.netへのアクセスでミスヒットしたリクエストを出力した例です。

./varnishlog -q "ReqHeader:Host ~ \"^example.net$\" and ReqHeader:user-agent ~ \"iPhone\" and not hit" -g request
*   << Request  >> 32779
-   Begin          req 32778
-   ReqMethod      GET
-   ReqURL         /test.php
-   ReqProtocol    HTTP/1.1
-   ReqHeader      User-Agent: iPhone
-   ReqHeader      Accept: */*
-   ReqHeader      Host: example.net
-   ReqHeader      Connection: Keep-Alive
-   ReqStart       127.0.0.1 35775
-   VCL_call       RECV
-   VCL_return     hash
-   VCL_call       HASH
-   VCL_return     lookup
-   Debug          "XXXX MISS%00"
-   VCL_call       MISS
-   VCL_return     fetch
-   Link           bereq 32780
-   VCL_call       DELIVER
-   VCL_return     deliver
-   Debug          "RES_MODE 48%00"
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespResponse   OK
-   RespHeader     Server: Apache/2.2.22 (Ubuntu)
-   RespHeader     X-Powered-By: PHP/5.2.10-2ubuntu6
-   RespHeader     Vary: Accept-Encoding
-   RespHeader     Content-Type: text/html
-   RespHeader     Date: Thu, 12 Dec 2013 03:58:17 GMT
-   RespHeader     X-Varnish: 32779
-   RespHeader     Age: 2
-   RespHeader     Via: 1.1 varnish
-   RespHeader     Transfer-Encoding: chunked
-   RespHeader     Connection: keep-alive
-   RespHeader     Accept-Ranges: bytes
-   Gzip           U D - 24 4 80 80 122
-   Debug          "XXX REF 2%00"
-   Length         0
-   ReqEnd         1386820695.477391958 1386820695.477348089 -2.001758099 2.001714230 -2.001758099
-   End
**  << BeReq    >> 32780
--  Begin          bereq 32779
--  Debug          "MKBEREQ -> STARTFETCH%00"
--  VCL_call       BACKEND_FETCH
--  VCL_return     fetch
--  Debug          "STARTFETCH -> FETCHHDR%00"
--  Debug          "XXX BOS: 0 -> 1%00"
--  BackendClose   17 default(127.0.0.1,,80) toolate
--  BackendOpen    17 default(127.0.0.1,,80) 127.0.0.1 38138
--  Backend        17 default default(127.0.0.1,,80)
--  BereqMethod    GET
--  BereqURL       /test.php
--  BereqProtocol  HTTP/1.1
--  BereqHeader    User-Agent: iPhone
--  BereqHeader    Accept: */*
--  BereqHeader    Host: example.net
--  BereqHeader    X-Forwarded-For: 127.0.0.1
--  BereqHeader    Accept-Encoding: gzip
--  BereqHeader    X-Varnish: 32780
--  BerespProtocol HTTP/1.1
--  BerespStatus   200
--  BerespResponse OK
--  BerespHeader   Date: Thu, 12 Dec 2013 03:58:15 GMT
--  BerespHeader   Server: Apache/2.2.22 (Ubuntu)
--  BerespHeader   X-Powered-By: PHP/5.2.10-2ubuntu6
--  BerespHeader   Vary: Accept-Encoding
--  BerespHeader   Content-Encoding: gzip
--  BerespHeader   Content-Length: 24
--  BerespHeader   Content-Type: text/html
--  TTL            RFC 20 -1 -1 1386820695 1386820695 1386820695 0 0
--  VCL_call       BACKEND_RESPONSE
--  VCL_return     deliver
--  Debug          "FETCHHDR -> FETCH%00"
--  Storage        malloc s0
--  ObjProtocol    HTTP/1.1
--  ObjResponse    OK
--  ObjHeader      Date: Thu, 12 Dec 2013 03:58:15 GMT
--  ObjHeader      Server: Apache/2.2.22 (Ubuntu)
--  ObjHeader      X-Powered-By: PHP/5.2.10-2ubuntu6
--  ObjHeader      Vary: Accept-Encoding
--  ObjHeader      Content-Encoding: gzip
--  ObjHeader      Content-Type: text/html
--  Debug          "XXX BOS: 1 -> 2%00"
--  Gzip           u F - 24 4 80 80 122
--  BackendReuse   17 default(127.0.0.1,,80)
--  Fetch_Body     3(length)
--  Length         24
--  Debug          "XXX BOS: 2 -> 3%00"
--  Debug          "YYY REF 1 3%00"
--  Debug          "FETCH -> DONE%00"
--  BereqEnd       1386820695.477493525 1386820697.479127645 0.000044999 2.001297996 0.000144575 2.001442571
--  End

./varnishlog -q "ReqHeader:Host ~ \"^example.net$\" and ReqHeader:user-agent ~ \"iPhone\" and not hit" -g request

* << Request >> 32779

- Begin req 32778

- ReqMethod GET

- ReqURL /test.php

- ReqProtocol HTTP/1.1

- ReqHeader User-Agent: iPhone

- ReqHeader Accept: */*

- ReqHeader Host: example.net

- ReqHeader Connection: Keep-Alive

- ReqStart 127.0.0.1 35775

- VCL_call RECV

- VCL_return hash

- VCL_call HASH

- VCL_return lookup

- Debug "XXXX MISS%00"

- VCL_call MISS

- VCL_return fetch

- Link bereq 32780

- VCL_call DELIVER

- VCL_return deliver

- Debug "RES_MODE 48%00"

- RespProtocol HTTP/1.1

- RespStatus 200

- RespResponse OK

- RespHeader Server: Apache/2.2.22 (Ubuntu)

- RespHeader X-Powered-By: PHP/5.2.10-2ubuntu6

- RespHeader Vary: Accept-Encoding

- RespHeader Content-Type: text/html

- RespHeader Date: Thu, 12 Dec 2013 03:58:17 GMT

- RespHeader X-Varnish: 32779

- RespHeader Age: 2

- RespHeader Via: 1.1 varnish

- RespHeader Transfer-Encoding: chunked

- RespHeader Connection: keep-alive

- RespHeader Accept-Ranges: bytes

- Gzip U D - 24 4 80 80 122

- Debug "XXX REF 2%00"

- Length 0

- ReqEnd 1386820695.477391958 1386820695.477348089 -2.001758099 2.001714230 -2.001758099

- End

** << BeReq >> 32780

-- Begin bereq 32779

-- Debug "MKBEREQ -> STARTFETCH%00"

-- VCL_call BACKEND_FETCH

-- VCL_return fetch

-- Debug "STARTFETCH -> FETCHHDR%00"

-- Debug "XXX BOS: 0 -> 1%00"

-- BackendClose 17 default(127.0.0.1,,80) toolate

-- BackendOpen 17 default(127.0.0.1,,80) 127.0.0.1 38138

-- Backend 17 default default(127.0.0.1,,80)

-- BereqMethod GET

-- BereqURL /test.php

-- BereqProtocol HTTP/1.1

-- BereqHeader User-Agent: iPhone

-- BereqHeader Accept: */*

-- BereqHeader Host: example.net

-- BereqHeader X-Forwarded-For: 127.0.0.1

-- BereqHeader Accept-Encoding: gzip

-- BereqHeader X-Varnish: 32780

-- BerespProtocol HTTP/1.1

-- BerespStatus 200

-- BerespResponse OK

-- BerespHeader Date: Thu, 12 Dec 2013 03:58:15 GMT

-- BerespHeader Server: Apache/2.2.22 (Ubuntu)

-- BerespHeader X-Powered-By: PHP/5.2.10-2ubuntu6

-- BerespHeader Vary: Accept-Encoding

-- BerespHeader Content-Encoding: gzip

-- BerespHeader Content-Length: 24

-- BerespHeader Content-Type: text/html

-- TTL RFC 20 -1 -1 1386820695 1386820695 1386820695 0 0

-- VCL_call BACKEND_RESPONSE

-- VCL_return deliver

-- Debug "FETCHHDR -> FETCH%00"

-- Storage malloc s0

-- ObjProtocol HTTP/1.1

-- ObjResponse OK

-- ObjHeader Date: Thu, 12 Dec 2013 03:58:15 GMT

-- ObjHeader Server: Apache/2.2.22 (Ubuntu)

-- ObjHeader X-Powered-By: PHP/5.2.10-2ubuntu6

-- ObjHeader Vary: Accept-Encoding

-- ObjHeader Content-Encoding: gzip

-- ObjHeader Content-Type: text/html

-- Debug "XXX BOS: 1 -> 2%00"

-- Gzip u F - 24 4 80 80 122

-- BackendReuse 17 default(127.0.0.1,,80)

-- Fetch_Body 3(length)

-- Length 24

-- Debug "XXX BOS: 2 -> 3%00"

-- Debug "YYY REF 1 3%00"

-- Debug "FETCH -> DONE%00"

-- BereqEnd 1386820695.477493525 1386820697.479127645 0.000044999 2.001297996 0.000144575 2.001442571

-- End

簡単に複数の条件で絞り込みができました。
他にも1秒以上かかったリクエストだけ、ESIのサブリクエストでかかった時間での絞り込みなども可能です。

また、だいぶ表示が変わった？と思われる人もいると思いますが半分正解です。
ログのグループ分けができるようになり以下の4種類があります。

Session

クライアントからの接続のOpen～Closeまでのトランザクションをグループ化したものです

*   << Session  >> 65556
-   Begin          sess
-   SessOpen       127.0.0.1 35807 :6081 127.0.0.1 6081 1386823033.279824 14
-   Link           req 65557
...
**  << Request  >> 65557
--  Begin          req 65556
--  ReqMethod      GET
...
--  Link           bereq 65558
...
*** << BeReq    >> 65558
--- Begin          bereq 65557
--- Debug          "MKBEREQ -> STARTFETCH%00"

* << Session >> 65556

- Begin sess

- SessOpen 127.0.0.1 35807 :6081 127.0.0.1 6081 1386823033.279824 14

- Link req 65557

...

** << Request >> 65557

-- Begin req 65556

-- ReqMethod GET

...

-- Link bereq 65558

...

*** << BeReq >> 65558

--- Begin bereq 65557

--- Debug "MKBEREQ -> STARTFETCH%00"

ログのprefixの* ** ***ですがネストしていることを表現しています。
上記ログの場合は以下のとおりです。

(Lv1)*Session
(Lv2)**Request
(Lv3)***BeReq

(Lv1)*Session

(Lv2)**Request

(Lv3)***BeReq

また、注目すべきタグにLinkとBeginがあります。例えばリクエスト処理中のバックエンドを呼び出した場合はLink bereq XXXXとなり、それに対応するBegin bereq XXXXがあります。非常にわかりやすくなっています。

ちなみにkeep-aliveでやりとりした場合は

*   << Session  >> 32784
-   Begin          sess
-   SessOpen       127.0.0.1 35849 :6081 127.0.0.1 6081 1386824710.887271 15
-   Link           req 32785
-   Link           req 32787
-   Link           req 32789
-   SessClose      TX_EOF 0.002 3 0 3 3 1015 531
-   End

* << Session >> 32784

- Begin sess

- SessOpen 127.0.0.1 35849 :6081 127.0.0.1 6081 1386824710.887271 15

- Link req 32785

- Link req 32787

- Link req 32789

- SessClose TX_EOF 0.002 3 0 3 3 1015 531

- End

と同一Sessionで3回のリクエストを処理したことがわかります。

Request

上のSessionでのやりとりを除いたものです。

VXID

Session・Requestはネストの情報(* **...)が付与されていましたが、その情報が抜けたものです。

*   << BeReq    >> 65558
-   Begin          bereq 65557
-   Debug          "MKBEREQ -> STARTFETCH%00"
...
*   << Request  >> 65557
-   Begin          req 65556
-   ReqMethod      GET
...
-   Link           bereq 65558
...
*   << Session  >> 65556
-   Begin          sess
-   SessOpen       127.0.0.1 35807 :6081 127.0.0.1 6081 1386823033.279824 14
-   Link           req 65557

* << BeReq >> 65558

- Begin bereq 65557

- Debug "MKBEREQ -> STARTFETCH%00"

...

* << Request >> 65557

- Begin req 65556

- ReqMethod GET

...

- Link bereq 65558

...

* << Session >> 65556

- Begin sess

- SessOpen 127.0.0.1 35807 :6081 127.0.0.1 6081 1386823033.279824 14

- Link req 65557

終了したトランザクションから表示するので、深いとこから表示されていきます。

Raw

     32796 Begin          c sess
     32796 SessOpen       c 127.0.0.1 35858 :6081 127.0.0.1 6081 1386825120.108944 15
     32796 Link           c req 32797
     32798 Begin          b bereq 32797
     32798 Debug          b "MKBEREQ -> STARTFETCH%00"
     32798 VCL_call       b BACKEND_FETCH
     32798 VCL_return     b fetch
     32798 Debug          b "STARTFETCH -> FETCHHDR%00"
     32798 BackendOpen    b 17 default(127.0.0.1,,80) 127.0.0.1 38221
     32798 Backend        b 17 default default(127.0.0.1,,80)
     32798 BereqMethod    b GET
     32798 BereqURL       b /index.html
     32798 BereqProtocol  b HTTP/1.0

32796 Begin c sess

32796 SessOpen c 127.0.0.1 35858 :6081 127.0.0.1 6081 1386825120.108944 15

32796 Link c req 32797

32798 Begin b bereq 32797

32798 Debug b "MKBEREQ -> STARTFETCH%00"

32798 VCL_call b BACKEND_FETCH

32798 VCL_return b fetch

32798 Debug b "STARTFETCH -> FETCHHDR%00"

32798 BackendOpen b 17 default(127.0.0.1,,80) 127.0.0.1 38221

32798 Backend b 17 default default(127.0.0.1,,80)

32798 BereqMethod b GET

32798 BereqURL b /index.html

32798 BereqProtocol b HTTP/1.0

Varnish3までのフォーマットと同じです。タグも変わっていますがだいぶわかりやすくなったと思います。
他にもVarnish4ではログの変更がありますが、エッセンスということでこれぐらいにとどめておきます。

まとめ

以上がvarnishのログの読み方・アクセスの仕方とおまけでした。Varnishを使う場合VSLにアクセスすることでより高度な計測ができると思いますのでみなさんもぜひチャレンジしてみてください。
あと本日12/17は私の誕生日だったりします！プレゼントお待ちしております！

次はScalaとDDDのかとじゅんです！

参考資料

trac(Varnish公式)
Lost in Translation:varnishlog, varnishtest(VUG7)
Varnish VSL Query Expressions
VUG8 Outro & Varnish 4 Release Parties! #v4rp
Varnish 4.0.0 technology preview 1 released