varnish-2.1.4 (SVN 5447M) w/ backend Connection: close

[James A. Robinson]

Folks,

I'm trying to track down a problem where varnish is sometimes serving
up empty responses, though the backend claims it sent the full body
back.  I think I've found the source of the problem, and wanted to ask
some advice from you folks as to possible causes and remedies.

With a packet capture I see the following sequence:

1. varnish sends a GET request for one URL

2. backend responds with 200 OK, and headers, including
a Connection:close header

3. varnish immediately sends a new GET request,
for a different URL

4. backend finishes sending the body of the first URL

5. the connection is closed.

If I understand HTTP/1.1 correctly, varnish should be reading the
body from the 1st request to the end, and closing the socket, not
sending a new request on the same socket.

Here's some data from varnishlog, it's the sequence corresponding
to the 1st request and the 2nd request.  It ends up caching the 1st
response as having a 0 length body and returns a failure on the 2nd
request.

The VCL that is being used was something we inherited from a person
who has since left the company, so I'm not very familiar with how
it is supposed to be working.

I was hoping the description of this problem might sound enough
like a well known problem, either with a bad VCL configuration or
possibly a bug with Varnish's handling of Connection: close responses
from the backend.


 1249 ReqStart     c 10.67.117.19 46543 1920805735
 1249 RxRequest    c GET
...
 1249 RxHeader     c Connection: keep-alive
 1249 VCL_call     c recv
 1249 VCL_acl      c MATCH highwire_acl 10.0.0.0/8
 1249 VCL_return   c lookup
 1249 VCL_call     c hash
 1249 VCL_return   c hash
 1249 VCL_call     c miss
 1249 VCL_return   c fetch

 6178 BackendOpen  b sass[3] 10.67.121.53 59375 110.67.117.88080

 1249 Backend      c 6178 sass sass[3]

 6178 TxRequest    b GET
...
 6178 RxProtocol   b HTTP/1.1
 6178 RxStatus     b 200
 6178 RxResponse   b OK
 ...
 6178 RxHeader     b Connection: close

 1249 TTL          c 1920805735 RFC 3600 1405091160 0 0 3600 0
 1249 VCL_call     c fetch
 1249 TTL          c 1920805735 VCL 86400 1405091160
 1249 VCL_return   c deliver
 1249 ObjProtocol  c HTTP/1.1
 1249 ObjStatus    c 200
 1249 ObjResponse  c OK
...

 6178 Length       b 0
 6178 BackendReuse b sass[3]

 1249 VCL_call     c deliver
 1249 VCL_return   c deliver
 1249 TxProtocol   c HTTP/1.1
 1249 TxStatus     c 200
 1249 TxResponse   c OK
...
 1249 Length       c 0

Right after 1249 is finished I see the data for that 2nd GET:

 6065 ReqStart     c 10.67.127.100 36016 1920805889
 6065 RxRequest    c GET
...
 6065 RxHeader     c Connection: keep-alive
 6065 VCL_call     c recv
 6065 VCL_return   c lookup
 6065 VCL_call     c hash
 6065 VCL_return   c hash
 6065 VCL_call     c miss
 6065 VCL_return   c fetch
...

 6065 Backend      c 6178 sass sass[3]
 6178 TxRequest    b GET
...
 6065 FetchError   c http first read error: -1 0 (Success)
 6178 BackendClose b sass[3]
 6065 VCL_call     c error
 6065 VCL_return   c deliver
 6065 VCL_call     c deliver
 6065 VCL_return   c deliver
 6065 TxProtocol   c HTTP/1.1
 6065 TxStatus     c 503
 6065 TxResponse   c Service Unavailable
 6065 TxHeader     c Server: Varnish
 6065 TxHeader     c Retry-After: 0
 6065 TxHeader     c Content-Type: text/html; charset=utf-8
 6065 TxHeader     c Content-Length: 854
 6065 TxHeader     c Accept-Ranges: bytes
 6065 TxHeader     c Date: Fri, 11 Jul 2014 15:06:00 GMT
 6065 TxHeader     c X-Varnish: 1920805889
 6065 TxHeader     c Age: 0
 6065 TxHeader     c Via: 1.1 varnish
 6065 TxHeader     c Connection: close
 6065 TxHeader     c Cache-Control: max-age=120
 6065 TxHeader     c X-Varnish-Cache: miss
 6065 Length       c 854
 6065 ReqEnd       c 1920805889 1405091160.433222055 1405091160.437772036
0.293696165 0.004407883 0.000142097
 6065 SessionClose c error
 6065 StatSess     c 10.67.127.100 36016 5 1 6 0 3 5 3010 39346
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20140711/4b699f89/attachment-0001.html>