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
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の起動スクリプトを編集して、ログ出力をパイプで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" &