Hi all

I'm setting up a nginx/varnish/Plone stack. Some of the pages are heavy and can take up to a minute to load. Faster pages are returned OK, but for the slow pages, the connection is closing prematurely most of the time (but not all the time) when I'm going through varnish or nginx.

I'd appreciate a sanity check. In short, I'd like to find out what in my varnish or nginx config is dropping the connection, or whether it's some other factor. To get things started, I just want everything to be passed through.

I should mention that pages load successfully directly on the server, and also that a similar stack (nginx/varnish/Plone) has been working fine on another server; however that was a managed server where the host took care of nginx.

Here's the nginx config::

upstream project-direct { server 127.0.0.1:56729; }
upstream varnish-passthrough { server 127.0.0.1:38191; }

server {
listen 80;
server_name my.example.org;
access_log /var/log/nginx/example.org.access.log;
error_log /var/log/nginx/example.org.error.log;
location / {
proxy_connect_timeout 75s;
proxy_read_timeout 300s;
proxy_send_timeout 300s;
rewrite ^(.*)$ /VirtualHostBase/http/$http_host:80/project/VirtualHostRoot$1 break;
# proxy_pass http://project-direct;
proxy_pass http://varnish-passthrough;
proxy_set_header X-Real-IP $remote_addr;
}
}

I switched `proxy_pass` lines and the request completed, but other requests still failed. Here's the varnish config::

backend my_project {
.host = "127.0.0.1";
.port = "56729";
.connect_timeout = 60s;
.first_byte_timeout = 300s;
.between_bytes_timeout = 60s;
}

sub vcl_recv {
set req.grace = 120s;

if (req.url ~ "my.example.org") {
set req.backend = my_project ;
}

I request a page which spins for a while and doesn't load. The varnishncsa log looks like this::

127.0.0.1 - - [20/May/2012:04:07:10 +0300] "GET http://varnish-passthrough/VirtualHostBase/http/my.example.org:80/project/VirtualHostRoot/61d08afcf1f4bf83e066842b26cfe85c/EditDocument?openwithform=frmOverviewEdit HTTP/1.0" 200 125336 "-" "Mozilla/5.0 (X11; Linux i686; rv:12.0) Gecko/20100101 Firefox/12.0"

Watching varnishlog, I see lines like this::

12 TxHeader c Server: Zope/(unreleased version, python 2.4.4, linux2) ZServer/1.1 Plone/3.3.5
12 TxHeader c Content-Language: en
12 TxHeader c Expires: Sat, 1 Jan 2000 00:00:00 GMT
12 TxHeader c Pragma: no-cache
12 TxHeader c Cache-Control: no-cache
12 TxHeader c Content-Type: text/html;charset=utf-8
12 TxHeader c X-Varnish-Action: FETCH (pass - not cacheable)
12 TxHeader c Content-Length: 125336
12 TxHeader c Date: Sun, 20 May 2012 01:07:10 GMT
12 TxHeader c X-Varnish: 634959635
12 TxHeader c Age: 0
12 TxHeader c Via: 1.1 varnish
12 TxHeader c Connection: close
12 Length c 125336

I'm watching the connection using a proxy, which shows me::

[00:00.030 - server connected]
[00:31.445 - server closed]

The connection drops after 30s every time, for any of the slow pages. This is true whether I'm going through varnish and nginx, or only nginx.

Here's what's logged for an unsuccessful request, going straight via nginx::

# From /var/log/nginx/example.org.access.log
171.98.250.96 - - [20/May/2012:05:05:01 +0300] "GET /61d08afcf1f4bf83e066842b26cfe85c/OpenDocument?openwithform=frmDisplayProject HTTP/1.1" 200 8678 "-" "Mozilla/5.0 (X11; Linux i686; rv:12.0) Gecko/20100101 Firefox/12.0"

# var/client1/Z2.log
127.0.0.1 - Anonymous [20/May/2012:05:05:01 +0300] "GET /VirtualHostBase/http/my.example.org:80/project/VirtualHostRoot/61d08afcf1f4bf83e066842b26cfe85c/OpenDocument?openwithform=frmDisplayProject HTTP/1.0" 200 44119 "" "Mozilla/5.0 (X11; Linux i686; rv:12.0) Gecko/20100101 Firefox/12.0"

The only funny thing I see is that the page size is smaller in the first case.

Nothing reaches the browser.