503 - Resource temporarily unavailable - When Varnish Connects to Itself

[Bradley Falzon]

Hi,

We're having a bizarre issues with Varnish and 503 errors, when Varnish
calls a Nginx when then calls its own Varnish. This may all sound like a bad
setup, but it came from the fact during development we need to soap to a web
service which currently resides on the same development server.

The script we're calling is called php2.php, the file that is calling is a
different file: brad.css, so it's not looping on itself.

Connection sequence:
1. HTTP GET to Varnish 192.168.1.9:80
2. Connection to Nginx:8080
3. Connection to PHP FastCGI (php2.php does a file_get_contents("
http://192.168.1.9/members/css/brad.css") - http://php.net/file-get-contents
)
4. Connection to Varnish:80
5. Connection to Nginx:8080

Relevant part of the log (rest of the logs, success:
http://dl.dropbox.com/u/3014365/varnishLogSuccess.txt fail:
http://dl.dropbox.com/u/3014365/varnishLogFail.txt):

   12 RxHeader     c Cache-Control: max-age=0
   12 VCL_call     c recv lookup
   12 VCL_call     c hash
   12 Hash         c /retail/php2.php
   12 Hash         c 192.168.1.9
   12 VCL_return   c hash
   12 VCL_call     c miss fetch
   12 Backend      c 14 default default
   12 FetchError   c http first read error: -1 11 (Resource temporarily
unavailable)
   12 VCL_call     c error deliver
   12 VCL_call     c deliver deliver
   12 TxProtocol   c HTTP/1.1
   12 TxStatus     c 503
   12 TxResponse   c Service Unavailable
   12 TxHeader     c Server: Varnish

Varnish configuration fails in the default.vcl supplied (only changes were
removing comments from all lines).

Server Varnish 3.0.0 (Port 80), Nginx 1.0.5 (Port 8080), PHP 5.3.2
(FastCGI), CentOS 6.0, all running on VMWare Fusion.

Client 192.168.1.14 (Firefox 5.0.1) to server 192.168.1.9.

Nginx Logs:
127.0.0.1 - - [16/Aug/2011:17:47:02 +0930] "GET /retail/php2.php HTTP/1.1"
499 0 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:5.0.1)
Gecko/20100101 Firefox/5.0.1"
127.0.0.1 - - [16/Aug/2011:17:47:02 +0930] "GET /members/css/brad.css
HTTP/1.1" 200 3 "-" "-"

Notice the GET responds with a 200 OK, according to Nginx it responded fine
to the GET, BUT it doesn't log that until Varnish finally ends with a 503
(when Varnish finally closed the connection?). The 499 response is Nginx's
way of saying "Client pre-maturely closed connection"

Other notes:
* Disabled keep-alive on nginx
* Disabled gzip on nginx
* Varnish default.vcl:
http://dl.dropbox.com/u/3014365/varnishDefault.vcl.txt
* Varnish sysconfig: http://dl.dropbox.com/u/3014365/varnishSysconfig.txt
* Issue seems to be intermittent, it continues to fail give it a restart and
it's ok again, restart again and it beings to fail all over again. Restart
sometimes it might work again or continue to fail etc etc. No noticeable
pattern.
* I haven't 'actually' done a 'make install' yet, I'm just running it out of
/usr/local/varnish/bin/varnishd/.libs/lt-varnishd
* The fault doesn't happen when the PHP file_get_contents connects to a
remove Nginx server
* The fault doesn't happen when I connect directly to Nginx (ie, skip
previously noted step 1 and connect to step 2 directly).
* Varnish logs in different orders between fails and successes (of 6 tests -
3 success 3 fail).
** During a fail, the first log is the TxURL        b /retail/php2.php
** During a success, the first log is TxURL        b /members/css/brad.css

Any thoughts ?

-- 
Bradley Falzon
brad at teambrad.net
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20110816/794d7e83/attachment-0003.html>