varnish 日志管理

varnish提供了varnishlog和varnishncsa两个工具用于日志处理。varnishlog 用于记录varnish 自身定义的日志格式，varnishncsa 用于记录作类似apache/ncsa定义的日志格式 。两个工具可以说是互相补充，前者便于详细的查看varnish 缓存、接收、发送、是否命中等详细的处理过程，便于对varnish进行性能分析和故障查询；后者便于日常的日志分析和数据挖掘。

一、varnishlog工具详解

varnishlog自带的参数如下：

-a 当把日志写到文件里时，使用附加，而不是覆盖。
-b 只显示 varnishd 和后端服务器的日志。
-C 匹配正则表达式的时候，忽略大小写差异。
-c 只显示 varnishd 和客户端的日志。
-D 以进程方式运行
-d 在启动过程中处理旧的日志，一般情况下，varnishhist 只会在进程写入日志后启动。
-I regex 匹配正则表达式的日志，如果没有使用-i 或者-I，那么所有的日志都会匹配。
-i tag  匹配指定的 tag，如果没有使用-i 或者-I，那么所有的日志都会被匹配。
-k num  只显示开始的 num 个日志记录。
-n 指定 varnish 实例的名字，用来获取日志，如果没有指定，默认使用主机名。
-o 以请求 ID 给日志分组，这个功能没多大用。如果要写到一个文件里使用 -w 选项。
-P file 记录 PID 号的文件
-r file 从一个文件读取日志，而不是从共享内存读取。
-s sum  跳过开始的 num 条日志。
-u 无缓冲的输出。
-V  显示版本，然后退出。
-w file 把日志写到一个文件里代替显示他们，如果不是用-a 参数就会发生覆盖，如果 varnishlog 在写日志时，接收到一个 SIGHUP 信号，他会创建一个新的文件,老的文件可以移走。
-X regex 排除匹配正则表达式的日志。
-x tag  排除匹配 tag 的日志。
如果-o 选项被指定，需要使用正则表达式和tag 来制定需要的日志。 

平时我们用到的最多的几个参数是-a 、-w、-r、-o、-P 。其能用到的tag标签如下：

Backend
BackendClose
BackendOpen
BackendReuse
BackendXID
CLI
ClientAddr
Debug
Error
ExpBan
ExpKill
ExpPick
Hit
HitPass
HttpError
HttpGarbage
Length
ObjHeader
ObjLostHeader
ObjProtocol
ObjRequest
ObjResponse
ObjStatus
ObjURL
ReqEnd
ReqStart
RxHeader
RxLostHeader
RxProtocol
RxRequest
RxResponse
RxStatus
RxURL
SessionClose
SessionOpen
StatAddr
StatSess
TTL
TxHeader
TxLostHeader
TxProtocol
TxRequest
TxResponse
TxStatus
TxURL
VCL_acl
VCL_call
VCL_return
VCL_trace
WorkThread 

下面列举两个常用示例：

下面的命令简单的打印日志到一个文件：
varnishlog -w /var/log/varnish.log
下面这条命令读取一个日志文件，然后显示请求的首页：
varnishlog -r /var/log/varnish.log -c -o RxURL '^/$' 

varnishlog记录的日志格式如下：

13 SessionOpen  c 192.168.10.168 6605 0.0.0.0:80
13 ReqStart  c 192.168.10.168 6605 356267494
13 RxRequest c GET
13 RxURL  c /web/index/css/index_beta30.css
13 RxProtocolc HTTP/1.1
13 RxHeader  c Host: img.361way.com
13 RxHeader  c Connection: keep-alive
13 RxHeader  c Cache-Control: max-age=0
13 RxHeader  c If-Modified-Since: Sat, 16 Feb 2013 05:18:03 GMT
13 RxHeader  c User-Agent: Mozilla/5.0 (Windows NT 5.1) AppleWebKit/537.1 (KHTML, like Gecko) Chrome/21.0.1180.89 Safari/537.1
13 RxHeader  c Accept: text/css,*/*;q=0.1
13 RxHeader  c Referer: http://www.361way.com/
13 RxHeader  c Accept-Encoding: gzip,deflate,sdch
13 RxHeader  c Accept-Language: zh-CN,zh;q=0.8
13 RxHeader  c Accept-Charset: GBK,utf-8;q=0.7,*;q=0.3
13 VCL_call  c recv lookup
13 VCL_call  c hash
13 Hashc /web/index/css/index_beta30.css
13 Hashc img.361way.com
13 VCL_returnc hash
13 Hit c 356267177
13 VCL_call  c hit deliver
13 VCL_call  c deliver deliver
13 TxProtocolc HTTP/1.1
13 TxStatus  c 304
13 TxResponsec Not Modified
13 TxHeader  c Server: nginx
13 TxHeader  c Content-Type: text/css
13 TxHeader  c Last-Modified: Sat, 16 Feb 2013 05:18:03 GMT
13 TxHeader  c Expires: Sat, 16 Mar 2013 03:39:18 GMT
13 TxHeader  c Cache-Control: max-age=86400
13 TxHeader  c Content-Encoding: gzip
13 TxHeader  c Accept-Ranges: bytes
13 TxHeader  c Date: Fri, 15 Mar 2013 06:00:53 GMT
13 TxHeader  c Age: 8686
13 TxHeader  c Connection: keep-alive
13 TxHeader  c X-Cache: HIT from TEST.com
13 TxHeader  c Via: 361way-CACHE
13 Length c 0
13 ReqEnd c 356267494 1363327253.501475096 1363327253.501555920 0.000028133 0.000038862 0.000041962
13 Debug  c herding

从上面不难看出，其显示的过程是比较详细的。另外需要注意的是varnishlog记录的日志文件只能通过varnishlog工具去读取，不支持cat、more、less、vim等工具查看。

二、varnishncsa 工具详解

varnishncsa 工具读取共享内存的日志，然后以 apache/NCSA 的格式显示出来。其自带参数如下：

-a 当把日志写到文件里时，使用附加，而不是覆盖。
-b 只显示varnishd和后端服务器的日志。
-C 匹配正则表达式的时候，忽略大小写差异。
-c 只显示varnishd和客户端的日志。
-D 以进程方式运行
-d 在启动过程中处理旧的日志，一般情况下，varnishhist只会在进程写入日志后启动。
-f 在日志输出中使用X-Forwarded-ForHTTP头代替client.ip。
-I regex 匹配正则表达式的日志，如果没有使用-i或者-I，那么所有的日志都会匹配。
-i tag 匹配指定的tag，如果没有使用-i或者-I，那么所有的日志都会被匹配。
-n 指定varnish实例的名字，用来获取日志，如果没有指定，默认使用主机名。
-P file记录PID号的文件
-r file从一个文件读取日志，而不是从共享内存读取。
-w file把日志写到一个文件里代替显示他们，如果不是用-a参数就会发生覆盖，如果varnishlog在写日志时，接收到一个SIGHUP信号，他会创建一个新的文件，老的文件可以移走。
-X regex 排除匹配正则表达式的日志。
-x tag 排除匹配tag的日志。

常用到的varnishncsa语句如下：

/App/varnish/bin/varnishncsa -a -w /logs/varnish.log &

varnishncsa产生的日志文件可以通过cat、more、less、vim都工具读取或打开，打开后的文件格式和apache日志并没有太大区别，如下：

192.168.10.168 - - [15/Mar/2013:14:14:39 +0800] "GET http://img.361way.com/web/index/img/beta30_head_line.jpg HTTP/1.1" 304 0 "http://www.361way.com/" "Mozilla/5.0 (Windows N
T 5.1) AppleWebKit/537.1 (KHTML, like Gecko) Chrome/21.0.1180.89 Safari/537.1"

注：varnishncsa输出的日志格式也有可能并不是我们想要的格式，这时可以通过-F参数更改其输出格式。一个现网中经常会碰到的例子是，varnish被置于nginx之后，此时varnish记录的client.IP就会是前端nginx的IP。该问题的解决方法也很简单，在前端nginx上设置X-Forwarder-For头 ，而varnish通过-F对日志整形，获取客户的真实IP 。如下：

varnishncsa -F "%{X-Forwarded-For}i %h %l %u %t "%r" %s %b "%{Referer}i" "%{User-agent}i""

varnishncsa默认的日志格式是：

"%h %l %u %t "%r" %s %b "%{Referer}i" "%{User-agent}i""

三、varnish日志轮询

日志文件过大，会影响到主机IO的读写，对机器的性能也有很大挑战。因此，我们需要按时间对日志进行cut切割。rpm安装的varnish自带了varnishlog、varnishncsa两个脚本（位于/etc/init.d下）用于启动和关闭日志。而对于日志的轮询上，其会在/etc/logrotate.d目录下生成一个varnish文件，用于通过logrotate工具进行日志轮询。

当然源码包安装的也会带有上面三个文件，其在源码包的redhat 目录下。不过不能真接拿来用，需要根据我们的安装目录进行相应的修改，感觉麻烦的也可以通过自定义脚本来实现日志的切割。如下：

#!/bin/bash
stop() {
	pid=`ps -ef | grep "/App/varnish/sbin/varnishd" | grep -v grep | awk '{print $2}'`
	num=`ps -ef | grep "/App/varnish/sbin/varnishd" | grep -v grep | wc -l`
	if [ $num -gt 0 ] ; then
		kill -9 $pid
		echo -e "kill varnish 33[32;40mOK33[0m"
	fi
}
start() {
	echo "start..."
	/App/varnish/sbin/varnishd -u www -g www -f /App/varnish/etc/varnish/default.vcl -s malloc,25G -a 0.0.0.0:80 -T 127.0.0.1:2000
	num=`ps -ef | grep "/App/varnish/sbin/varnishd" | grep -v grep | wc -l`
	if [ $num -gt 0 ] ; then
		echo -e "start varnish 33[32;40mOK33[0m"
		ps -ef | grep "/App/varnish/sbin/varnishd" | grep -v grep | awk '{print "pid="$2}'
	else
		echo -e "start varnish 33[31;40FAIL33[0m"
		stop
	fi
}
stoplog() {
        pid=`ps -ef | grep "/App/varnish/bin/varnishncsa" | grep -v grep | awk '{print $2}'`
        num=`ps -ef | grep "/App/varnish/bin/varnishncsa" | grep -v grep | wc -l`
        if [ $num -gt 0 ] ; then
                kill -9 $pid
                echo -e "kill varnishlog 33[32;40mOK33[0m"
        fi
}
startlog() {
        echo "startlog..."
	/App/varnish/bin/varnishncsa -a -w /logs/varnish.log &
	sleep 1
        num=`ps -ef | grep "/App/varnish/bin/varnishncsa" | grep -v grep | wc -l`
        if [ $num -gt 0 ] ; then
                echo -e "start varnishlog 33[32;40mOK33[0m"
                ps -ef | grep "/App/varnish/bin/varnishncsa" | grep -v grep | awk '{print "pid="$2}'
        else
                echo -e "start varnishlog 33[31;40FAIL33[0m"
		stoplog
        fi
}
cutlog() {
	_yesdate=$(date -d "yesterday" +"%Y-%m-%d")
	stoplog
	mv /logs/varnish.log /logs/${_yesdate}.log
	startlog
}
case $1 in
	"start")
		stop
		start
	;;
	"stop")
		stop
	;;
	"startlog")
		stoplog
		startlog
	;;
	"stoplog")
		stoplog
	;;
	"cutlog")
		cutlog
	;;
	"startall")
		stop
		stoplog
		start
		startlog
	;;
	"stopall")
		stop
		stoplog
	;;
	*)
		echo "$0 start stop startlog stoplog startall stopall cutlog"
	;;
esac
exit 0

该脚本包含了varnish的启动、关闭、varnishnsca的启动、关闭与切割。当然部分内容可能和自己的现网应用有出入的，可以再自行修改。日志cut，可以配合crontab工具定时进行。