Hi, last night, I have tried to understand a strange issue where varnish delivers a 503 for a POST after issuing the maximum number of retries to the backend.
This is with 2.1.4 with c5476 applied (fix for #780 fetch_chunked fails to read trailing CRLF), on Linux debian 5.0.5 / kernel 2.6.26-2-amd64 64bit. Because the POST data from the client is not stored, the retries will have no body, but this is only a secondary effect. Network traces of the actual backend request/response are looking good (for the first one, the retries have empty bodies). I would like to ask if anyone else has seen anything similar to avoid duplicate work. Otherwise I will look after this issue. Here's the client side from varnishlog (edited) 373 ReqStart c a.b.c.d 52409 584964428 373 RxRequest c POST 373 RxURL c /AjaxFunction 373 RxProtocol c HTTP/1.1 373 RxHeader c Host: www 373 RxHeader c User-Agent: Mozilla/5.0 (Windows; U; Windows NT 6.1; fi; rv:1.9.2.12) Gecko/20101026 Firefox/3.6 .12 373 RxHeader c Accept: text/javascript, text/html, application/xml, text/xml, */* 373 RxHeader c Accept-Language: fi-fi,fi;q=0.8,en-us;q=0.5,en;q=0.3 373 RxHeader c Accept-Encoding: gzip,deflate 373 RxHeader c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7 373 RxHeader c Keep-Alive: 115 373 RxHeader c Connection: keep-alive 373 RxHeader c X-Requested-With: XMLHttpRequest 373 RxHeader c X-Prototype-Version: 1.6.1 373 RxHeader c Content-Type: application/x-www-form-urlencoded; charset=UTF-8 373 RxHeader c Referer: http://www/url 373 RxHeader c Content-Length: 159382 373 RxHeader c Cookie: many=values 373 RxHeader c Pragma: no-cache 373 RxHeader c Cache-Control: no-cache 373 VCL_call c recv 373 VCL_return c pass 373 VCL_call c hash 373 VCL_return c hash 373 VCL_call c pass 373 VCL_return c pass 373 Backend c 361 name name 373 FetchError c backend write error: 0 (Success) 373 Backend c 414 name name 373 FetchError c backend write error: 0 (Success) 373 VCL_call c error 373 VCL_return c restart 373 VCL_call c recv 373 VCL_return c pass 373 VCL_call c hash 373 VCL_return c hash 373 VCL_call c pass 373 VCL_return c pass 373 Backend c 71 name name 373 FetchError c backend write error: 0 (Success) 373 Backend c 350 name name 373 FetchError c backend write error: 0 (Success) 373 VCL_call c error 373 VCL_return c restart 373 VCL_call c recv 373 VCL_return c pass 373 VCL_call c hash 373 VCL_return c hash 373 VCL_call c pass 373 VCL_return c pass 373 Backend c 348 name name 373 FetchError c backend write error: 0 (Success) 373 Backend c 211 name name 373 FetchError c backend write error: 0 (Success) 373 VCL_call c error 373 VCL_return c restart 373 VCL_call c recv 373 VCL_return c pass 373 VCL_call c hash 373 VCL_return c hash 373 VCL_call c pass 373 VCL_return c pass 373 Backend c 111 name name 373 FetchError c backend write error: 0 (Success) 373 Backend c 71 name name 373 FetchError c backend write error: 0 (Success) 373 VCL_call c error 373 VCL_return c restart 373 VCL_call c recv 373 VCL_return c pass 373 VCL_call c error 373 VCL_return c restart 373 VCL_call c deliver 373 VCL_return c deliver 373 TxProtocol c HTTP/1.1 373 TxStatus c 503 373 TxResponse c Service Unavailable 373 TxHeader c Retry-After: 0 373 TxHeader c Date: Thu, 02 Dec 2010 19:59:13 GMT 373 TxHeader c X-Varnish: 584964428 373 TxHeader c Age: 0 373 TxHeader c Via: 1.1 varnish 373 TxHeader c Connection: close 373 TxHeader c Server: Apache 373 Length c 0 373 ReqEnd c 584964428 1291319953.163419962 1291319953.520179033 0.192537069 0.356723547 0.000035524 373 SessionClose c error 373 StatSess c a.b.c.d 52409 1 1 2 0 4 0 516 923 This issue seems to relate to the fact that the client closes the connection in the last tcp segment containing HTTP post payload: snoop -t r -rV -i 503.snoop (edited) 143 44.12160 __client__ -> __server__ ETHER Type=0800 (IP), size=98 bytes 143 44.12160 __client__ -> __server__ IP D=__server__ S=__client__ LEN=84, ID=13026, TOS=0x0, TTL=57 143 44.12160 __client__ -> __server__ TCP D=80 S=50055 Fin Push Ack=497128928 Seq=937286087 Len=32 Win=65535 Options=<nop,nop,tstamp 1049891629 160779712> 143 44.12160 __client__ -> __server__ HTTP **last*bytes*of*POST**DATA** notice the Fin flag This is way before Varnish gets around to generate a reply: 189 44.32979 __server__ -> __client__ ETHER Type=0800 (IP), size=238 bytes 189 44.32979 __server__ -> __client__ IP D=__client__ S=__server__ LEN=224, ID=46017, TOS=0x0, TTL=64 189 44.32979 __server__ -> __client__ TCP D=50055 S=80 Push Ack=937286120 Seq=497128928 Len=172 Win=518 Options=<nop,nop,tstamp 160779840 1049891632> 189 44.32979 __server__ -> __client__ HTTP HTTP/1.1 503 Service Unavailable Any ideas? Nils _______________________________________________ varnish-dev mailing list [email protected] http://www.varnish-cache.org/lists/mailman/listinfo/varnish-dev
