2月 092012
Do you use a Varnish? I’ve been using.
I think to using varnishlog for VCL debugging.
For example, the output of the varnishlog that include ESI request.
varnishlog(include ESI)
13 BackendOpen b default 192.168.1.199 36011 192.168.1.199 81 ★Open backend here. 13 TxRequest b GET 13 TxURL b /test2.html 13 TxProtocol b HTTP/1.1 13 TxHeader b User-Agent: Wget/1.12 (linux-gnu) 13 TxHeader b Accept: */* 13 TxHeader b Host: 192.168.1.199:6081 13 TxHeader b X-Varnish: 171551254 13 TxHeader b Accept-Encoding: gzip 13 RxProtocol b HTTP/1.1 13 RxStatus b 200 13 RxResponse b OK 13 RxHeader b Date: Sat, 28 Jan 2012 05:05:59 GMT 13 RxHeader b Server: Apache/2.2.15 (Scientific Linux) 13 RxHeader b Last-Modified: Sat, 23 Jul 2011 08:09:05 GMT 13 RxHeader b ETag: "5a28-51-4a8b8187f8177" 13 RxHeader b Accept-Ranges: bytes 13 RxHeader b Content-Length: 81 13 RxHeader b Connection: close 13 RxHeader b Content-Type: text/html; charset=UTF-8 13 Fetch_Body b 4(length) cls 0 mklen 1 13 Length b 81 13 BackendClose b default ★Close backend here. 13 BackendOpen b default 192.168.1.199 36012 192.168.1.199 81 ★Open backend for ESI request here. 13 TxRequest b GET 13 TxURL b /test3.html 13 TxProtocol b HTTP/1.1 13 TxHeader b User-Agent: Wget/1.12 (linux-gnu) 13 TxHeader b Accept: */* 13 TxHeader b Host: 192.168.1.199:6081 13 TxHeader b X-Varnish: 171551254 13 TxHeader b Accept-Encoding: gzip 13 RxProtocol b HTTP/1.1 13 RxStatus b 200 13 RxResponse b OK 13 RxHeader b Date: Sat, 28 Jan 2012 05:05:59 GMT 13 RxHeader b Server: Apache/2.2.15 (Scientific Linux) 13 RxHeader b Last-Modified: Sat, 23 Jul 2011 08:08:59 GMT 13 RxHeader b ETag: "5a29-14-4a8b81829c835" 13 RxHeader b Accept-Ranges: bytes 13 RxHeader b Content-Length: 20 13 RxHeader b Connection: close 13 RxHeader b Content-Type: text/html; charset=UTF-8 13 Fetch_Body b 4(length) cls 0 mklen 1 13 Length b 20 13 BackendClose b default ★Close backend here. 12 SessionOpen c 192.168.1.199 55115 :6081 12 ReqStart c 192.168.1.199 55115 171551254 ★Start Request (/test2.html) 12 RxRequest c GET 12 RxURL c /test2.html 12 RxProtocol c HTTP/1.0 12 RxHeader c User-Agent: Wget/1.12 (linux-gnu) 12 RxHeader c Accept: */* 12 RxHeader c Host: 192.168.1.199:6081 12 RxHeader c Connection: Keep-Alive 12 VCL_call c recv 1 7.1 12 VCL_Log c a 12 VCL_trace c 2 9.1 12 VCL_Log c b 12 VCL_trace c 3 11.1 12 VCL_Log c a 12 VCL_return c lookup 12 VCL_call c hash 18 85.5 12 Hash c /test2.html 12 VCL_trace c 19 87.9 12 Hash c 192.168.1.199:6081 12 VCL_return c hash 12 VCL_call c miss 22 99.5 fetch 12 Backend c 13 default default ★Call backend. 12 TTL c 171551254 RFC 120 -1 -1 1327727160 0 1327727159 0 0 12 VCL_call c fetch 4 18.1 deliver 12 ObjProtocol c HTTP/1.1 12 ObjResponse c OK 12 ObjHeader c Date: Sat, 28 Jan 2012 05:05:59 GMT 12 ObjHeader c Server: Apache/2.2.15 (Scientific Linux) 12 ObjHeader c Last-Modified: Sat, 23 Jul 2011 08:09:05 GMT 12 ObjHeader c ETag: "5a28-51-4a8b8187f8177" 12 ObjHeader c Content-Type: text/html; charset=UTF-8 12 VCL_call c deliver 26 116.5 deliver 12 TxProtocol c HTTP/1.1 12 TxStatus c 200 12 TxResponse c OK 12 TxHeader c Server: Apache/2.2.15 (Scientific Linux) 12 TxHeader c Last-Modified: Sat, 23 Jul 2011 08:09:05 GMT 12 TxHeader c ETag: "5a28-51-4a8b8187f8177" 12 TxHeader c Content-Type: text/html; charset=UTF-8 12 TxHeader c Date: Sat, 28 Jan 2012 05:05:59 GMT 12 TxHeader c X-Varnish: 171551254 12 TxHeader c Age: 0 12 TxHeader c Via: 1.1 varnish 12 TxHeader c Connection: close 12 VCL_call c recv 1 7.1 ★Start ESI log. 12 VCL_Log c a 12 VCL_trace c 2 9.1 12 VCL_Log c b 12 VCL_trace c 3 11.1 12 VCL_Log c a 12 VCL_return c lookup 12 VCL_call c hash 18 85.5 12 Hash c /test3.html 12 VCL_trace c 19 87.9 12 Hash c 192.168.1.199:6081 12 VCL_return c hash 12 VCL_call c miss 22 99.5 fetch 12 Backend c 13 default default 12 TTL c 171551254 RFC 120 -1 -1 1327727160 0 1327727159 0 0 12 VCL_call c fetch 4 18.1 deliver 12 ObjProtocol c HTTP/1.1 12 ObjResponse c OK 12 ObjHeader c Date: Sat, 28 Jan 2012 05:05:59 GMT 12 ObjHeader c Server: Apache/2.2.15 (Scientific Linux) 12 ObjHeader c Last-Modified: Sat, 23 Jul 2011 08:08:59 GMT 12 ObjHeader c ETag: "5a29-14-4a8b81829c835" 12 ObjHeader c Content-Type: text/html; charset=UTF-8 12 VCL_call c deliver 26 116.5 deliver 12 Length c 20 12 ReqEnd c 171551254 1327727159.889132023 1327727159.890880346 -0.001736164 nan nan ★Request end. 12 SessionClose c EOF mode 12 StatSess c 192.168.1.199 55115 0 1 1 0 0 2 282 20 0 CLI - Rd ping 0 CLI - Wr 200 19 PONG 1327727160 1.0
little too difficult for me.
Therefore, I tried to make a tool to format and display.
varnishlog | php vltrans.php
client ip | 192.168.1.199 client request host | 192.168.1.199:6081 client request url | /test2.html response size | 20 byte response status | HTTP/1.1 200 OK Total time | 0.0017483234405518 sec restart count | 0 ESI count | 1 call backend | 2 default(192.168.1.199:81) default(192.168.1.199:81) Cache | HIT:0 MISS:2 ------------------------------------------------------------ ------------------- | recv | ------------------- | | trace | vrt_count:1 vcl_line:7 vcl_pos:1 | log | a | trace | vrt_count:2 vcl_line:9 vcl_pos:1 | log | b | trace | vrt_count:3 vcl_line:11 vcl_pos:1 | log | a | | | return | lookup | ------------------- | hash | ------------------- | | trace | vrt_count:18 vcl_line:85 vcl_pos:5 | trace | vrt_count:19 vcl_line:87 vcl_pos:9 | | | hash | /test2.html + 192.168.1.199:6081 | return | hash | ------------------- | miss | ------------------- | | trace | vrt_count:22 vcl_line:99 vcl_pos:5 | | | return | fetch | ------------------- | fetch | ------------------- | | trace | vrt_count:4 vcl_line:18 vcl_pos:1 | | | return | deliver | ------------------- | deliver | ------------------- | | trace | vrt_count:26 vcl_line:116 vcl_pos:5 | | | return | deliver | <<ESI request>> ------------------- | recv | ------------------- | | trace | vrt_count:1 vcl_line:7 vcl_pos:1 | log | a | trace | vrt_count:2 vcl_line:9 vcl_pos:1 | log | b | trace | vrt_count:3 vcl_line:11 vcl_pos:1 | log | a | | | return | lookup | ------------------- | hash | ------------------- | | trace | vrt_count:18 vcl_line:85 vcl_pos:5 | trace | vrt_count:19 vcl_line:87 vcl_pos:9 | | | hash | /test3.html + 192.168.1.199:6081 | return | hash | ------------------- | miss | ------------------- | | trace | vrt_count:22 vcl_line:99 vcl_pos:5 | | | return | fetch | ------------------- | fetch | ------------------- | | trace | vrt_count:4 vcl_line:18 vcl_pos:1 | | | return | deliver | ------------------- | deliver | ------------------- | | trace | vrt_count:26 vcl_line:116 vcl_pos:5 | | | return | deliver | ############################################################ variable infomation. | hash | /test2.html + 192.168.1.199:6081 ------------------------------------------------------------ client.ip | 192.168.1.199 ------------------------------------------------------------ req.request | GET req.url | /test2.html req.proto | HTTP/1.0 req.http.User-Agent | Wget/1.12 (linux-gnu) req.http.Accept | */* req.http.Host | 192.168.1.199:6081 req.http.Connection | Keep-Alive ------------------------------------------------------------ bereq.request | GET bereq.url | /test2.html bereq.proto | HTTP/1.1 bereq.http.User-Agent | Wget/1.12 (linux-gnu) bereq.http.Accept | */* bereq.http.Host | 192.168.1.199:6081 bereq.http.X-Varnish | 171551254 bereq.http.Accept-Encoding | gzip ------------------------------------------------------------ beresp.proto | HTTP/1.1 beresp.status | 200 beresp.response | OK beresp.http.Date | Sat, 28 Jan 2012 05:05:59 GMT beresp.http.Server | Apache/2.2.15 (Scientific Linux) beresp.http.Last-Modified | Sat, 23 Jul 2011 08:09:05 GMT beresp.http.ETag | "5a28-51-4a8b8187f8177" beresp.http.Accept-Ranges | bytes beresp.http.Content-Length | 81 beresp.http.Connection | close beresp.http.Content-Type | text/html; charset=UTF-8 ------------------------------------------------------------ obj.proto | HTTP/1.1 obj.response | OK obj.http.Date | Sat, 28 Jan 2012 05:05:59 GMT obj.http.Server | Apache/2.2.15 (Scientific Linux) obj.http.Last-Modified | Sat, 23 Jul 2011 08:09:05 GMT obj.http.ETag | "5a28-51-4a8b8187f8177" obj.http.Content-Type | text/html; charset=UTF-8 ------------------------------------------------------------ resp.proto | HTTP/1.1 resp.status | 200 resp.response | OK resp.http.Server | Apache/2.2.15 (Scientific Linux) resp.http.Last-Modified | Sat, 23 Jul 2011 08:09:05 GMT resp.http.ETag | "5a28-51-4a8b8187f8177" resp.http.Content-Type | text/html; charset=UTF-8 resp.http.Date | Sat, 28 Jan 2012 05:05:59 GMT resp.http.X-Varnish | 171551254 resp.http.Age | 0 resp.http.Via | 1.1 varnish resp.http.Connection | close ############################################################ variable infomation. | ESI | yes hash | /test3.html + 192.168.1.199:6081 ------------------------------------------------------------ bereq.request | GET bereq.url | /test3.html bereq.proto | HTTP/1.1 bereq.http.User-Agent | Wget/1.12 (linux-gnu) bereq.http.Accept | */* bereq.http.Host | 192.168.1.199:6081 bereq.http.X-Varnish | 171551254 bereq.http.Accept-Encoding | gzip ------------------------------------------------------------ beresp.proto | HTTP/1.1 beresp.status | 200 beresp.response | OK beresp.http.Date | Sat, 28 Jan 2012 05:05:59 GMT beresp.http.Server | Apache/2.2.15 (Scientific Linux) beresp.http.Last-Modified | Sat, 23 Jul 2011 08:08:59 GMT beresp.http.ETag | "5a29-14-4a8b81829c835" beresp.http.Accept-Ranges | bytes beresp.http.Content-Length | 20 beresp.http.Connection | close beresp.http.Content-Type | text/html; charset=UTF-8 ------------------------------------------------------------ obj.proto | HTTP/1.1 obj.response | OK obj.http.Date | Sat, 28 Jan 2012 05:05:59 GMT obj.http.Server | Apache/2.2.15 (Scientific Linux) obj.http.Last-Modified | Sat, 23 Jul 2011 08:08:59 GMT obj.http.ETag | "5a29-14-4a8b81829c835" obj.http.Content-Type | text/html; charset=UTF-8 ############################################################ ############################################################ ############################################################
I think so understood without explanation.
function summary.
show request summary
client ip | 192.168.1.199 client request host | 192.168.1.199:6081 client request url | /test2.html response size | 20 byte response status | HTTP/1.1 200 OK Total time | 0.0017483234405518 sec restart count | 0 ESI count | 1 call backend | 2 default(192.168.1.199:81) default(192.168.1.199:81) Cache | HIT:0 MISS:2 ------------------------------------------------------------
show execution sequence
<<ESI request>> ★ESI or restart work is display here. ------------------- | recv | ★call action name ------------------- | | trace | vrt_count:1 vcl_line:7 vcl_pos:1 | log | a | trace | vrt_count:2 vcl_line:9 vcl_pos:1 | log | b | trace | vrt_count:3 vcl_line:11 vcl_pos:1 | log | a | | | return | lookup ★return value
show variable
variable infomation. | ESI | yes ★ESI or restart work is display here. hash | /test3.html + 192.168.1.199:6081 ★this request used hash value. ------------------------------------------------------------ bereq.request | GET bereq.url | /test3.html bereq.proto | HTTP/1.1
I’m not quite satisfied with the code.
But, it may useful.
download here.
varnishlogTrans