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
_______________________________________________ varnish-misc mailing list [email protected] https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
