<div dir="ltr"><div>Folks,</div><div><br></div><div>I'm trying to track down a problem where varnish is sometimes serving</div><div>up empty responses, though the backend claims it sent the full body</div><div>back. I think I've found the source of the problem, and wanted to ask</div>
<div>some advice from you folks as to possible causes and remedies.</div><div><br></div><div>With a packet capture I see the following sequence:</div><div><br></div><div>1. varnish sends a GET request for one URL</div><div>
<br></div><div>2. backend responds with 200 OK, and headers, including</div><div>a Connection:close header</div><div><br></div><div>3. varnish immediately sends a new GET request,</div><div>for a different URL</div><div>
<br>
</div><div>4. backend finishes sending the body of the first URL</div><div><br></div><div>5. the connection is closed.</div><div><br></div><div>If I understand HTTP/1.1 correctly, varnish should be reading the</div><div>
body from the 1st request to the end, and closing the socket, not</div>
<div>sending a new request on the same socket.</div><div><br></div><div>Here's some data from varnishlog, it's the sequence corresponding</div><div>to the 1st request and the 2nd request. It ends up caching the 1st</div>
<div>response as having a 0 length body and returns a failure on the 2nd</div><div>request.</div><div><br></div><div>The VCL that is being used was something we inherited from a person</div><div>who has since left the company, so I'm not very familiar with how</div>
<div>it is supposed to be working.</div><div><br></div><div>I was hoping the description of this problem might sound enough</div><div>like a well known problem, either with a bad VCL configuration or</div><div>possibly a bug with Varnish's handling of Connection: close responses</div>
<div>from the backend.</div><div><br></div><div><br></div><div><font face="courier new, monospace"> 1249 ReqStart c 10.67.117.19 46543 1920805735</font></div><div><font face="courier new, monospace"> 1249 RxRequest c GET</font></div>
<div><font face="courier new, monospace">...</font></div><div><font face="courier new, monospace"> 1249 RxHeader c Connection: keep-alive</font></div><div><font face="courier new, monospace"> 1249 VCL_call c recv</font></div>
<div><font face="courier new, monospace"> 1249 VCL_acl c MATCH highwire_acl <a href="http://10.0.0.0/8">10.0.0.0/8</a></font></div><div><font face="courier new, monospace"> 1249 VCL_return c lookup</font></div><div>
<font face="courier new, monospace"> 1249 VCL_call c hash</font></div><div><font face="courier new, monospace"> 1249 VCL_return c hash</font></div><div><font face="courier new, monospace"> 1249 VCL_call c miss</font></div>
<div><font face="courier new, monospace"> 1249 VCL_return c fetch</font></div><div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace"> 6178 BackendOpen b sass[3] 10.67.121.53 59375 110.67.117.88080</font></div>
<div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace"> 1249 Backend c 6178 sass sass[3]</font></div><div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace"> 6178 TxRequest b GET</font></div>
<div><font face="courier new, monospace">...</font></div><div><font face="courier new, monospace"> 6178 RxProtocol b HTTP/1.1</font></div><div><font face="courier new, monospace"> 6178 RxStatus b 200</font></div><div>
<font face="courier new, monospace"> 6178 RxResponse b OK</font></div><div><font face="courier new, monospace"> ...</font></div><div><font face="courier new, monospace"> 6178 RxHeader b Connection: close</font></div>
<div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace"> 1249 TTL c 1920805735 RFC 3600 1405091160 0 0 3600 0</font></div><div><font face="courier new, monospace"> 1249 VCL_call c fetch</font></div>
<div><font face="courier new, monospace"> 1249 TTL c 1920805735 VCL 86400 1405091160</font></div><div><font face="courier new, monospace"> 1249 VCL_return c deliver</font></div><div><font face="courier new, monospace"> 1249 ObjProtocol c HTTP/1.1</font></div>
<div><font face="courier new, monospace"> 1249 ObjStatus c 200</font></div><div><font face="courier new, monospace"> 1249 ObjResponse c OK</font></div><div><font face="courier new, monospace">...</font></div><div><font face="courier new, monospace"><br>
</font></div><div><font face="courier new, monospace"> 6178 Length b 0</font></div><div><font face="courier new, monospace"> 6178 BackendReuse b sass[3]</font></div><div><font face="courier new, monospace"><br></font></div>
<div><font face="courier new, monospace"> 1249 VCL_call c deliver</font></div><div><font face="courier new, monospace"> 1249 VCL_return c deliver</font></div><div><font face="courier new, monospace"> 1249 TxProtocol c HTTP/1.1</font></div>
<div><font face="courier new, monospace"> 1249 TxStatus c 200</font></div><div><font face="courier new, monospace"> 1249 TxResponse c OK</font></div><div><font face="courier new, monospace">...</font></div><div><font face="courier new, monospace"> 1249 Length c 0</font></div>
<div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace">Right after 1249 is finished I see the data for that 2nd GET:</font></div><div><font face="courier new, monospace"><br></font></div>
<div><font face="courier new, monospace"> 6065 ReqStart c 10.67.127.100 36016 1920805889</font></div><div><font face="courier new, monospace"> 6065 RxRequest c GET</font></div><div><font face="courier new, monospace">...</font></div>
<div><font face="courier new, monospace"> 6065 RxHeader c Connection: keep-alive</font></div><div><font face="courier new, monospace"> 6065 VCL_call c recv</font></div><div><font face="courier new, monospace"> 6065 VCL_return c lookup</font></div>
<div><font face="courier new, monospace"> 6065 VCL_call c hash</font></div><div><font face="courier new, monospace"> 6065 VCL_return c hash</font></div><div><font face="courier new, monospace"> 6065 VCL_call c miss</font></div>
<div><font face="courier new, monospace"> 6065 VCL_return c fetch</font></div><div><font face="courier new, monospace">...</font></div><div><font face="courier new, monospace"><br></font></div><div><font face="courier new, monospace"> 6065 Backend c 6178 sass sass[3]</font></div>
<div><font face="courier new, monospace"> 6178 TxRequest b GET</font></div><div><font face="courier new, monospace">...</font></div><div><font face="courier new, monospace"> 6065 FetchError c http first read error: -1 0 (Success)</font></div>
<div><font face="courier new, monospace"> 6178 BackendClose b sass[3]</font></div><div><font face="courier new, monospace"> 6065 VCL_call c error</font></div><div><font face="courier new, monospace"> 6065 VCL_return c deliver</font></div>
<div><font face="courier new, monospace"> 6065 VCL_call c deliver</font></div><div><font face="courier new, monospace"> 6065 VCL_return c deliver</font></div><div><font face="courier new, monospace"> 6065 TxProtocol c HTTP/1.1</font></div>
<div><font face="courier new, monospace"> 6065 TxStatus c 503</font></div><div><font face="courier new, monospace"> 6065 TxResponse c Service Unavailable</font></div><div><font face="courier new, monospace"> 6065 TxHeader c Server: Varnish</font></div>
<div><font face="courier new, monospace"> 6065 TxHeader c Retry-After: 0</font></div><div><font face="courier new, monospace"> 6065 TxHeader c Content-Type: text/html; charset=utf-8</font></div><div><font face="courier new, monospace"> 6065 TxHeader c Content-Length: 854</font></div>
<div><font face="courier new, monospace"> 6065 TxHeader c Accept-Ranges: bytes</font></div><div><font face="courier new, monospace"> 6065 TxHeader c Date: Fri, 11 Jul 2014 15:06:00 GMT</font></div><div><font face="courier new, monospace"> 6065 TxHeader c X-Varnish: 1920805889</font></div>
<div><font face="courier new, monospace"> 6065 TxHeader c Age: 0</font></div><div><font face="courier new, monospace"> 6065 TxHeader c Via: 1.1 varnish</font></div><div><font face="courier new, monospace"> 6065 TxHeader c Connection: close</font></div>
<div><font face="courier new, monospace"> 6065 TxHeader c Cache-Control: max-age=120</font></div><div><font face="courier new, monospace"> 6065 TxHeader c X-Varnish-Cache: miss</font></div><div><font face="courier new, monospace"> 6065 Length c 854</font></div>
<div><font face="courier new, monospace"> 6065 ReqEnd c 1920805889 1405091160.433222055 1405091160.437772036</font></div><div><font face="courier new, monospace">0.293696165 0.004407883 0.000142097</font></div><div>
<font face="courier new, monospace"> 6065 SessionClose c error</font></div><div><font face="courier new, monospace"> 6065 StatSess c 10.67.127.100 36016 5 1 6 0 3 5 3010 39346</font></div><div><br></div></div>