目次

Varnishのログ

Varnish Shared memory Log

Varnishのログは他の一般的なミドルウェアと異なり、ログをメモリ(Varnish Shared memory Log)上に出力します。
varnishlogやvarnishncsaなどのコマンドでVSLを読み込んでファイル出力や、varnishhistでヒストグラムの整形などを行います。

生ログを確認

varnishlogコマンドでリアルタイムの生ログを確認することが可能。
以下、バックエンドのnginxでphpinfoにアクセスしたときのログ

# varnishlog 
*   << BeReq    >> 32783     
-   Begin          bereq 32782 fetch
-   Timestamp      Start: 1415685949.873767 0.000000 0.000000
-   BereqMethod    GET
-   BereqURL       /
-   BereqProtocol  HTTP/1.1
-   BereqHeader    Host: 192.168.24.192:6081
-   BereqHeader    Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
-   BereqHeader    User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36
-   BereqHeader    Accept-Language: ja,en-US;q=0.8,en;q=0.6
-   BereqHeader    X-Forwarded-For: 192.168.26.56
-   BereqHeader    Accept-Encoding: gzip
-   BereqHeader    X-Varnish: 32783
-   VCL_call       BACKEND_FETCH
-   VCL_return     fetch
-   BackendClose   21 default(127.0.0.1,,80) toolate
-   BackendClose   17 default(127.0.0.1,,80) toolate
-   BackendOpen    17 default(127.0.0.1,,80) 127.0.0.1 46330 
-   Backend        17 default default(127.0.0.1,,80)
-   Timestamp      Bereq: 1415685949.888515 0.014749 0.014749
-   Timestamp      Beresp: 1415685950.213864 0.340098 0.325349
-   BerespProtocol HTTP/1.1
-   BerespStatus   200
-   BerespReason   OK
-   BerespHeader   Server: nginx/1.6.2
-   BerespHeader   Date: Tue, 11 Nov 2014 06:05:50 GMT
-   BerespHeader   Content-Type: text/html
-   BerespHeader   Transfer-Encoding: chunked
-   BerespHeader   Connection: keep-alive
-   BerespHeader   X-Powered-By: PHP/5.4.34
-   TTL            RFC 120 -1 -1 1415685950 1415685950 1415685950 0 0
-   VCL_call       BACKEND_RESPONSE
-   VCL_return     deliver
-   Storage        malloc s0
-   ObjProtocol    HTTP/1.1
-   ObjStatus      200
-   ObjReason      OK
-   ObjHeader      Server: nginx/1.6.2
-   ObjHeader      Date: Tue, 11 Nov 2014 06:05:50 GMT
-   ObjHeader      Content-Type: text/html
-   ObjHeader      X-Powered-By: PHP/5.4.34
-   Fetch_Body     2 chunked stream
-   BackendReuse   17 default(127.0.0.1,,80)
-   Timestamp      BerespBody: 1415685950.219570 0.345803 0.005706
-   Length         48669
-   BereqAcct      367 0 367 180 48728 48908
-   End            

生ログをファイルに出力

起動スクリプト(/etc/init.d/varnishlog)に出力するファイル名がハードコーディングされているので、ここを編集して設定可能。

# /etc/init.d/varnishlog start
# ps aux | grep varnishlog
root      6239  0.1  0.0 100384   492 ?        Ss   15:09   0:00 /usr/bin/varnishlog -a -w /var/log/varnish/varnish.log -D -P /var/run/varnishlog.pid
# tail /var/log/varnish/varnish.log
-   End            

*   << Session  >> 10        
-   Begin          sess 0 HTTP/1
-   SessOpen       192.168.26.56 52864 :6081 192.168.24.192 6081 1415685456.258270 12
-   Link           req 11 rxreq
-   Link           req 13 rxreq
-   SessClose      RX_TIMEOUT 5.176
-   End            

NCSA形式のログを出力

apacheなどで使われているNCSA形式のログを出力する。
起動スクリプト(/etc/init.d/varnishncsa )に出力するファイル名がハードコーディングされているので、ここを編集して設定可能。

# /etc/init.d/varnishncsa start
# ps aux | grep varnishncsa
root      6275  0.1  0.0 100400   496 ?        Ss   15:14   0:00 /usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D -P /var/run/varnishncsa.pid
# tail -f /var/log/varnish/varnishncsa.log
192.168.26.56 - - [11/Nov/2014:15:15:21 +0900] "GET http://192.168.24.192:6081/ HTTP/1.1" 200 48714 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
192.168.26.56 - - [11/Nov/2014:15:15:21 +0900] "GET http://192.168.24.192:6081/index.php?=PHPE9568F35-D428-11d2-A769-00AA001ACF42 HTTP/1.1" 200 2160 "http://192.168.24.192:6081/" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"
192.168.26.56 - - [11/Nov/2014:15:15:21 +0900] "GET http://192.168.24.192:6081/index.php?=PHPE9568F34-D428-11d2-A769-00AA001ACF42 HTTP/1.1" 200 2524 "http://192.168.24.192:6081/" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.111 Safari/537.36"

varnishncsaを出力をsyslog-ngに渡す

varnishncsaの起動スクリプトを編集して、ログ出力をパイプでlogger(facility N)に渡す。
ただし、標準のDオプションでdaemon化するとsyslogに渡らないので、Dオプションをつけずに、&でバックグラウンドで処理させる。

# vi /etc/init.d/varnishncsa
#DAEMON_OPTS="-a -w $logfile -D -P $pidfile"
FORMAT_OPTS="%h %l %u %t \"%r\" %s %b \"%{Referer}i\" \"%{User-agent}i\" %D"
SYSLOG_OPTS=" | /usr/bin/logger -t varnish -p local5.info"
DAEMON_OPTS="-P $pidfile -F '$FORMAT_OPTS'"$SYSLOG_OPTS
.
.
.
#daemon --pidfile $pidfile $exec "$DAEMON_OPTS" 
daemon --pidfile $pidfile $exec "$DAEMON_OPTS" &