Sirs: I'm seeing some interesting behavior w/r/t HEAD requests that I'd appreciate some insights on. Some background:
We use a foundry serveriron GT for load balancing. Its IP is 192.168.10.254. The varnish test server is 192.168.10.101 under fedora 7, compiled from source. The current back-end server is nyp-web-1.corp.razz.com, at 192.168.10.80. The foundry makes health checks to varnish every 5 seconds via HEAD requests using HTTP/1.0. For some reason (unless I'm interpreting this wrong), varnish is deciding that the backend of these HEAD requests should be itself, and the timestamp on the lookup is off by several hours: (from varnishncsa) 192.168.10.254 - - [12/Sep/2007:18:32:28 -0700] "HEAD /static/mixer/ playerdefault.swf HTTP/1.0" 200 61986 "-" "-" 192.168.10.254 - - [12/Sep/2007:18:32:33 -0700] "HEAD /static/mixer/ playerdefault.swf HTTP/1.0" 200 61986 "-" "-" 192.168.10.254 - - [12/Sep/2007:18:32:38 -0700] "HEAD /static/mixer/ playerdefault.swf HTTP/1.0" 200 61986 "-" "-" 192.168.10.101 - - [13/Sep/2007:01:32:43 -0700] "GET http://nyp- web-1.corp.razz.com/mixer/playerdefault.swf HTTP/1.1" 200 61986 "-" "-" 192.168.10.254 - - [12/Sep/2007:18:32:43 -0700] "HEAD /static/mixer/ playerdefault.swf HTTP/1.0" 200 61986 "-" "-" 192.168.10.254 - - [12/Sep/2007:18:32:48 -0700] "HEAD /static/mixer/ playerdefault.swf HTTP/1.0" 200 61986 "-" "-" 192.168.10.254 - - [12/Sep/2007:18:32:53 -0700] "HEAD /static/mixer/ playerdefault.swf HTTP/1.0" 200 61986 "-" "-" The GET request is varnish connecting to itself to check the asset when the ttl expires. This request should instead be hitting the backend server. Current config: backend default { set backend.host = "nyp-web-1.corp.razz.com"; set backend.port = "80"; } sub vcl_recv { set req.backend = default; set req.http.host = "nyp-web-1.corp.razz.com"; // block redirect loops if (req.url ~ "^/static/static/") { error 404 "Not found."; } // change all /static/ requests into / backend requests if (req.url ~ "^/static/") { set req.url = regsub(req.url, "^/static/", "/"); } // strip query parameters from all swf requests (so they cache as a single object) if (req.url ~ "\.swf\?.*") { set req.url = regsub(req.url, "\.swf\?.*", ".swf"); } // force lookup on any of the static object types if (req.url ~ "\.(swf|gif|jpg|png|js|bmp|pdf|css|mp3|xml|flv) (\?.*)?$") { lookup; } // deny any other kind of request error 404 "Not found."; } Here's the output of varnishlog for the HEAD requests surrounding the GET: 0 CLI Rd ping 0 CLI Wr 0 200 PONG 1189647149 0 CLI Rd ping 0 CLI Wr 0 200 PONG 1189647152 15 SessionOpen c 192.168.10.254 1720 15 ReqStart c 192.168.10.254 1720 1052036059 15 RxRequest c HEAD 15 RxURL c /static/mixer/playerdefault.swf 15 RxProtocol c HTTP/1.0 15 VCL_call c recv 15 VCL_trace c 1 7.14 15 VCL_trace c 2 13.9 15 VCL_trace c 4 18.5 15 VCL_trace c 5 18.9 15 VCL_trace c 6 18.32 15 VCL_trace c 7 23.5 15 VCL_trace c 8 23.9 15 VCL_trace c 10 28.5 15 VCL_trace c 11 28.9 15 VCL_trace c 12 28.77 15 VCL_return c lookup 15 VCL_call c hash 15 VCL_trace c 41 22.14 15 VCL_return c hash 15 Hit c 1052036036 15 VCL_call c hit 15 VCL_trace c 42 28.13 15 VCL_trace c 43 29.9 15 VCL_trace c 45 32.5 15 VCL_return c deliver 15 Length c 61986 15 VCL_call c deliver 15 VCL_trace c 57 51.17 15 VCL_return c deliver 15 TxProtocol c HTTP/1.1 15 TxStatus c 200 15 TxResponse c OK 15 TxHeader c Date: Thu, 13 Sep 2007 01:30:38 GMT 15 TxHeader c Server: Apache/2.2.4 (Fedora) 15 TxHeader c Last-Modified: Thu, 26 Apr 2007 17:42:49 GMT 15 TxHeader c ETag: "3368c1-f222-42f078c1f9840" 15 TxHeader c Content-Type: application/x-shockwave-flash 15 TxHeader c X-Pad: avoid browser bug 15 TxHeader c Content-Length: 61986 15 TxHeader c X-Varnish: 1052036059 1052036036 15 TxHeader c Age: 115 15 TxHeader c Via: 1.1 varnish 15 TxHeader c Connection: close 15 ReqEnd c 1052036059 1189647153.765747786 1189647153.765867233 0.000073671 0.000063419 0.000056028 0 StatAddr 192.168.10.254 0 115 24 24 0 0 1 8199 0 15 SessionClose c not HTTP/1.1 15 StatSess c 192.168.10.254 1720 0 1 1 0 0 0 343 0 0 CLI Rd ping 0 CLI Wr 0 200 PONG 1189647155 0 CLI Rd ping 0 CLI Wr 0 200 PONG 1189647158 15 SessionOpen c 192.168.10.254 1727 15 ReqStart c 192.168.10.254 1727 1052036060 15 RxRequest c HEAD 15 RxURL c /static/mixer/playerdefault.swf 15 RxProtocol c HTTP/1.0 15 VCL_call c recv 15 VCL_trace c 1 7.14 15 VCL_trace c 2 13.9 15 VCL_trace c 4 18.5 15 VCL_trace c 5 18.9 15 VCL_trace c 6 18.32 15 VCL_trace c 7 23.5 15 VCL_trace c 8 23.9 15 VCL_trace c 10 28.5 15 VCL_trace c 11 28.9 15 VCL_trace c 12 28.77 15 VCL_return c lookup 15 VCL_call c hash 15 VCL_trace c 41 22.14 15 VCL_return c hash 15 Hit c 1052036036 15 VCL_call c hit 15 VCL_trace c 42 28.13 15 VCL_trace c 43 29.9 15 VCL_trace c 45 32.5 15 VCL_return c deliver 15 Length c 61986 15 VCL_call c deliver 15 VCL_trace c 57 51.17 15 VCL_return c deliver 15 TxProtocol c HTTP/1.1 15 TxStatus c 200 15 TxResponse c OK 15 TxHeader c Date: Thu, 13 Sep 2007 01:30:38 GMT 15 TxHeader c Server: Apache/2.2.4 (Fedora) 15 TxHeader c Last-Modified: Thu, 26 Apr 2007 17:42:49 GMT 15 TxHeader c ETag: "3368c1-f222-42f078c1f9840" 15 TxHeader c Content-Type: application/x-shockwave-flash 15 TxHeader c X-Pad: avoid browser bug 15 TxHeader c Content-Length: 61986 15 TxHeader c X-Varnish: 1052036060 1052036036 15 TxHeader c Age: 120 15 TxHeader c Via: 1.1 varnish 15 TxHeader c Connection: close 15 ReqEnd c 1052036060 1189647158.765828848 1189647158.765937805 0.000067711 0.000058413 0.000050545 0 StatAddr 192.168.10.254 0 120 25 25 0 0 1 8542 0 15 SessionClose c not HTTP/1.1 15 StatSess c 192.168.10.254 1727 0 1 1 0 0 0 343 0 0 ExpKill 1052036036 0 0 CLI Rd ping 0 CLI Wr 0 200 PONG 1189647161 15 SessionOpen c 192.168.10.254 1734 15 ReqStart c 192.168.10.254 1734 1052036061 15 RxRequest c HEAD 15 RxURL c /static/mixer/playerdefault.swf 15 RxProtocol c HTTP/1.0 15 VCL_call c recv 15 VCL_trace c 1 7.14 15 VCL_trace c 2 13.9 15 VCL_trace c 4 18.5 15 VCL_trace c 5 18.9 15 VCL_trace c 6 18.32 15 VCL_trace c 7 23.5 15 VCL_trace c 8 23.9 15 VCL_trace c 10 28.5 15 VCL_trace c 11 28.9 15 VCL_trace c 12 28.77 15 VCL_return c lookup 15 VCL_call c hash 15 VCL_trace c 41 22.14 15 VCL_return c hash 15 VCL_call c miss 15 VCL_trace c 46 35.14 15 VCL_return c fetch 18 BackendClose default 18 BackendOpen b default 192.168.10.101 45075 192.168.10.80 80 18 BackendXID b 1052036061 15 Backend c 18 default 18 TxRequest b GET 18 TxURL b /mixer/playerdefault.swf 18 TxProtocol b HTTP/1.1 18 TxHeader b host: nyp-web-1.corp.razz.com 18 TxHeader b X-Varnish: 1052036061 18 TxHeader b X-Forwarded-for: 192.168.10.254 18 RxProtocol b HTTP/1.1 18 RxStatus b 200 18 RxResponse b OK 18 RxHeader b Date: Thu, 13 Sep 2007 01:32:43 GMT 18 RxHeader b Server: Apache/2.2.4 (Fedora) 18 RxHeader b Last-Modified: Thu, 26 Apr 2007 17:42:49 GMT 18 RxHeader b ETag: "3368c1-f222-42f078c1f9840" 18 RxHeader b Accept-Ranges: bytes 18 RxHeader b Content-Length: 61986 18 RxHeader b Content-Type: application/x-shockwave-flash 18 RxHeader b X-Pad: avoid browser bug 15 ObjProtocol c HTTP/1.1 15 ObjStatus c 200 15 ObjResponse c OK 15 ObjHeader c Date: Thu, 13 Sep 2007 01:32:43 GMT 15 ObjHeader c Server: Apache/2.2.4 (Fedora) 15 ObjHeader c Last-Modified: Thu, 26 Apr 2007 17:42:49 GMT 15 ObjHeader c ETag: "3368c1-f222-42f078c1f9840" 15 ObjHeader c Content-Type: application/x-shockwave-flash 15 ObjHeader c X-Pad: avoid browser bug 18 BackendReuse b default 15 TTL c 1052036061 RFC 120 1189647163 1189647163 0 0 0 15 VCL_call c fetch 15 VCL_trace c 14 37.15 15 VCL_trace c 15 39.9 15 VCL_trace c 17 43.5 15 VCL_trace c 18 43.9 15 VCL_trace c 20 47.5 15 VCL_trace c 21 47.9 15 VCL_trace c 23 51.5 15 VCL_trace c 24 51.9 15 VCL_trace c 26 55.5 15 VCL_return c insert 15 Length c 61986 15 VCL_call c deliver 15 VCL_trace c 57 51.17 15 VCL_return c deliver 15 TxProtocol c HTTP/1.1 15 TxStatus c 200 15 TxResponse c OK 15 TxHeader c Date: Thu, 13 Sep 2007 01:32:43 GMT 15 TxHeader c Server: Apache/2.2.4 (Fedora) 15 TxHeader c Last-Modified: Thu, 26 Apr 2007 17:42:49 GMT 15 TxHeader c ETag: "3368c1-f222-42f078c1f9840" 15 TxHeader c Content-Type: application/x-shockwave-flash 15 TxHeader c X-Pad: avoid browser bug 15 TxHeader c Content-Length: 61986 15 TxHeader c X-Varnish: 1052036061 15 TxHeader c Age: 0 15 TxHeader c Via: 1.1 varnish 15 TxHeader c Connection: close 15 ReqEnd c 1052036061 1189647163.765805483 1189647163.767508268 0.000074863 0.001671553 0.000031233 0 StatAddr 192.168.10.254 0 125 26 26 0 0 2 8872 0 15 SessionClose c not HTTP/1.1 15 StatSess c 192.168.10.254 1734 0 1 1 0 0 1 330 0 0 CLI Rd ping 0 CLI Wr 0 200 PONG 1189647164 0 CLI Rd ping 0 CLI Wr 0 200 PONG 1189647167 15 SessionOpen c 192.168.10.254 1741 15 ReqStart c 192.168.10.254 1741 1052036062 15 RxRequest c HEAD 15 RxURL c /static/mixer/playerdefault.swf 15 RxProtocol c HTTP/1.0 15 VCL_call c recv 15 VCL_trace c 1 7.14 15 VCL_trace c 2 13.9 15 VCL_trace c 4 18.5 15 VCL_trace c 5 18.9 15 VCL_trace c 6 18.32 15 VCL_trace c 7 23.5 15 VCL_trace c 8 23.9 15 VCL_trace c 10 28.5 15 VCL_trace c 11 28.9 15 VCL_trace c 12 28.77 15 VCL_return c lookup 15 VCL_call c hash 15 VCL_trace c 41 22.14 15 VCL_return c hash 15 Hit c 1052036061 15 VCL_call c hit 15 VCL_trace c 42 28.13 15 VCL_trace c 43 29.9 15 VCL_trace c 45 32.5 15 VCL_return c deliver 15 Length c 61986 15 VCL_call c deliver 15 VCL_trace c 57 51.17 15 VCL_return c deliver 15 TxProtocol c HTTP/1.1 15 TxStatus c 200 15 TxResponse c OK 15 TxHeader c Date: Thu, 13 Sep 2007 01:32:43 GMT 15 TxHeader c Server: Apache/2.2.4 (Fedora) 15 TxHeader c Last-Modified: Thu, 26 Apr 2007 17:42:49 GMT 15 TxHeader c ETag: "3368c1-f222-42f078c1f9840" 15 TxHeader c Content-Type: application/x-shockwave-flash 15 TxHeader c X-Pad: avoid browser bug 15 TxHeader c Content-Length: 61986 15 TxHeader c X-Varnish: 1052036062 1052036061 15 TxHeader c Age: 5 15 TxHeader c Via: 1.1 varnish 15 TxHeader c Connection: close 15 ReqEnd c 1052036062 1189647168.765779495 1189647168.765885353 0.000075102 0.000062466 0.000043392 0 StatAddr 192.168.10.254 0 130 27 27 0 0 2 9213 0 15 SessionClose c not HTTP/1.1 15 StatSess c 192.168.10.254 1741 0 1 1 0 0 0 341 0 0 CLI Rd ping 0 CLI Wr 0 200 PONG 1189647170 0 CLI Rd ping 0 CLI Wr 0 200 PONG 1189647173 15 SessionOpen c 192.168.10.254 1748 15 ReqStart c 192.168.10.254 1748 1052036063 15 RxRequest c HEAD 15 RxURL c /static/mixer/playerdefault.swf 15 RxProtocol c HTTP/1.0 15 VCL_call c recv 15 VCL_trace c 1 7.14 15 VCL_trace c 2 13.9 15 VCL_trace c 4 18.5 15 VCL_trace c 5 18.9 15 VCL_trace c 6 18.32 15 VCL_trace c 7 23.5 15 VCL_trace c 8 23.9 15 VCL_trace c 10 28.5 15 VCL_trace c 11 28.9 15 VCL_trace c 12 28.77 15 VCL_return c lookup 15 VCL_call c hash 15 VCL_trace c 41 22.14 15 VCL_return c hash 15 Hit c 1052036061 15 VCL_call c hit 15 VCL_trace c 42 28.13 15 VCL_trace c 43 29.9 15 VCL_trace c 45 32.5 15 VCL_return c deliver 15 Length c 61986 15 VCL_call c deliver 15 VCL_trace c 57 51.17 15 VCL_return c deliver 15 TxProtocol c HTTP/1.1 15 TxStatus c 200 15 TxResponse c OK 15 TxHeader c Date: Thu, 13 Sep 2007 01:32:43 GMT 15 TxHeader c Server: Apache/2.2.4 (Fedora) 15 TxHeader c Last-Modified: Thu, 26 Apr 2007 17:42:49 GMT 15 TxHeader c ETag: "3368c1-f222-42f078c1f9840" 15 TxHeader c Content-Type: application/x-shockwave-flash 15 TxHeader c X-Pad: avoid browser bug 15 TxHeader c Content-Length: 61986 15 TxHeader c X-Varnish: 1052036063 1052036061 15 TxHeader c Age: 10 15 TxHeader c Via: 1.1 varnish 15 TxHeader c Connection: close 15 ReqEnd c 1052036063 1189647173.765821457 1189647173.765940905 0.000079632 0.000065804 0.000053644 0 StatAddr 192.168.10.254 0 135 28 28 0 0 2 9555 0 15 SessionClose c not HTTP/1.1 15 StatSess c 192.168.10.254 1748 0 1 1 0 0 0 342 0 Footnote: it looks like requests from the wild are behaving similarly: 192.168.10.254 - - [12/Sep/2007:18:40:23 -0700] "HEAD /static/mixer/ playerdefault.swf HTTP/1.0" 200 61986 "-" "-" 192.168.10.254 - - [12/Sep/2007:18:40:28 -0700] "HEAD /static/mixer/ playerdefault.swf HTTP/1.0" 200 61986 "-" "-" 127.0.0.1 - - [12/Sep/2007:18:40:28 -0700] "(null) (null) (null)" (null) (null) "-" "-" 192.168.10.101 - - [13/Sep/2007:01:40:30 -0700] "GET http://nyp- web-1.corp.razz.com/mixer/player8a.swf HTTP/1.1" 200 59986 "-" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X; en) AppleWebKit/522.11.1 (KHTML, like Gecko) Version/3.0.3 Safari/522.12.1" 208.106.97.31 - - [12/Sep/2007:18:40:30 -0700] "GET http:// www.razz.com/static/mixer/player8a.swf?u=2743&s=1&o=2743 HTTP/1.1" 200 59986 "-" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X; en) AppleWebKit/522.11.1 (KHTML, like Gecko) Version/3.0.3 Safari/522.12.1" 127.0.0.1 - - [13/Sep/2007:01:40:31 -0700] "GET http://nyp- web-1.corp.razz.com/mixer/saved/1/1/1/e0ca0476.flv HTTP/1.1" 200 107712 "http://www.razz.com/static/mixer/player8a.swf? u=2743&s=1&o=2743" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X; en) AppleWebKit/522.11.1 (KHTML, like Gecko) Version/3.0.3 Safari/522.12.1" 208.106.97.31 - - [12/Sep/2007:18:40:32 -0700] "GET http:// www.razz.com/static/mixer/saved/1/1/1/e0ca0476.flv HTTP/1.1" 200 107712 "http://www.razz.com/static/mixer/player8a.swf? u=2743&s=1&o=2743" "Mozilla/5.0 (Macintosh; U; Intel Mac OS X; en) AppleWebKit/522.11.1 (KHTML, like Gecko) Version/3.0.3 Safari/522.12.1" 192.168.10.254 - - [12/Sep/2007:18:40:33 -0700] "HEAD /static/mixer/ playerdefault.swf HTTP/1.0" 200 61986 "-" "-" Thanks for your consideration! -Tom _______________________________________________ varnish-misc mailing list [email protected] http://projects.linpro.no/mailman/listinfo/varnish-misc
