Torrance, Can you upload a full tcpdump packet trace both between client and varnish, and varnish and backend, together with the varnish logs and varnish config, and I'll take a look.
Rob Torrance wrote: > I've no response to this on list, and the problem is ongoing. Should I > file this as a bug? > > Torrance > > > > On 30/01/10 12:32 PM, Torrance wrote: > >> Hi Tollef, >> >> I've pasted the logs of two failed requests below. As you can see, >> they're both in response to POST requests, though I was overstating the >> frequency at which these errors are occurring: they're occurring about >> 10% of the time. >> >> To be honest, I don't entirely understand the logs or their format, but >> I hope I've captured the important details. (Session IDs have been >> deleted, btw). >> >> Many thanks, >> Torrance >> >> >> 15 ReqStart c 125.236.128.219 51361 561006524 >> 15 RxRequest c POST >> 15 RxURL c /node/78063/edit >> 15 RxProtocol c HTTP/1.1 >> 15 RxHeader c Host: indymedia.org.nz >> 15 RxHeader c User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS >> X 10.6; en-GB; rv:1.9.2) Gecko/20100115 Firefox/3.6 >> 15 RxHeader c Accept: >> text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 >> 15 RxHeader c Accept-Language: en-gb,en;q=0.5 >> 15 RxHeader c Accept-Encoding: gzip,deflate >> 15 RxHeader c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7 >> 15 RxHeader c Keep-Alive: 115 >> 15 RxHeader c Connection: keep-alive >> 15 RxHeader c Referer: http://indymedia.org.nz/node/78063/edit >> 15 RxHeader c Cookie: comment_info_name=Tester; >> SESSxxxxxxxxxxxxxxxxxxxxxxxxxxxxx=xxxxxxxxxxxxxxxxxxxxxxxxxxxxx; >> SESSxxxxxxxxxxxxxxxxxxxxxxxxxxxxx=xxxxxxxxxxxxxxxxxxxxxxxxxxxxx; has_js=1 >> 15 RxHeader c Content-Type: multipart/form-data; >> boundary=---------------------------1850078892860212931738819713 >> 15 RxHeader c Content-Length: 16978 >> 15 VCL_call c recv >> 15 VCL_return c pass >> 15 VCL_call c pass >> 15 VCL_return c pass >> 15 Backend c 10 default default >> 10 TxRequest b POST >> 10 TxURL b /node/78063/edit >> 10 TxProtocol b HTTP/1.1 >> 10 TxHeader b Host: indymedia.org.nz >> 10 TxHeader b User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS >> X 10.6; en-GB; rv:1.9.2) Gecko/20100115 Firefox/3.6 >> 10 TxHeader b Accept: >> text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 >> 10 TxHeader b Accept-Language: en-gb,en;q=0.5 >> 10 TxHeader b Accept-Encoding: gzip,deflate >> 10 TxHeader b Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7 >> 10 TxHeader b Referer: http://indymedia.org.nz/node/78063/edit >> 10 TxHeader b Cookie: comment_info_name=Tester; >> SESSxxxxxxxxxxxxxxxxxxxxxxxxxxxxx=xxxxxxxxxxxxxxxxxxxxxxxxxxxxx; >> SESSxxxxxxxxxxxxxxxxxxxxxxxxxxxxx=xxxxxxxxxxxxxxxxxxxxxxxxxxxxx; has_js=1 >> 10 TxHeader b Content-Type: multipart/form-data; >> boundary=---------------------------1850078892860212931738819713 >> 10 TxHeader b Content-Length: 16978 >> 10 TxHeader b X-Forwarded-For: 125.236.128.219 >> 10 TxHeader b X-Varnish: 561006524 >> 10 TxHeader b X-Forwarded-For: 125.236.128.219 >> 10 BackendClose b default >> 15 VCL_call c error >> 15 VCL_return c deliver >> 15 Length c 465 >> 15 VCL_call c deliver >> 15 VCL_return c deliver >> 15 TxProtocol c HTTP/1.1 >> 15 TxStatus c 503 >> 15 TxResponse c Service Unavailable >> 15 TxHeader c Server: Varnish >> 15 TxHeader c Retry-After: 0 >> 15 TxHeader c Content-Type: text/html; charset=utf-8 >> 15 TxHeader c Content-Length: 465 >> 15 TxHeader c Date: Fri, 29 Jan 2010 23:00:42 GMT >> 15 TxHeader c X-Varnish: 561006524 >> 15 TxHeader c Age: 1 >> 15 TxHeader c Via: 1.1 varnish >> 15 TxHeader c Connection: close >> 15 ReqEnd c 561006524 1264806040.957435846 1264806042.241542339 >> 4.125935793 1.284075260 0.000031233 >> 15 SessionClose c error >> 15 StatSess c 125.236.128.219 51361 14 1 3 0 3 2 1410 49426 >> 0 StatAddr - 125.236.128.219 0 1102 34 74 0 32 42 38287 1054700 >> >> >> 21 ReqStart c 125.236.128.219 53669 561007510 >> 21 RxRequest c POST >> 21 RxURL c /node/78063/edit >> 21 RxProtocol c HTTP/1.1 >> 21 RxHeader c Host: indymedia.org.nz >> 21 RxHeader c User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS >> X 10.6; en-GB; rv:1.9.2) Gecko/20100115 Firefox/3.6 >> 21 RxHeader c Accept: >> text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 >> 21 RxHeader c Accept-Language: en-gb,en;q=0.5 >> 21 RxHeader c Accept-Encoding: gzip,deflate >> 21 RxHeader c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7 >> 21 RxHeader c Keep-Alive: 115 >> 21 RxHeader c Connection: keep-alive >> 21 RxHeader c Referer: http://indymedia.org.nz/node/78063/edit >> 21 RxHeader c Cookie: comment_info_name=Tester; >> SESSxxxxxxxxxxxxxxxxxxxxxxxxxxxxx=xxxxxxxxxxxxxxxxxxxxxxxxxxxxx; >> SESSxxxxxxxxxxxxxxxxxxxxxxxxxxxxx=xxxxxxxxxxxxxxxxxxxxxxxxxxxxx; has_js=1 >> 21 RxHeader c Content-Type: multipart/form-data; >> boundary=---------------------------84863282515329900481602423677 >> 21 RxHeader c Content-Length: 17019 >> 21 VCL_call c recv >> 21 VCL_return c pass >> 21 VCL_call c pass >> 21 VCL_return c pass >> 21 Backend c 15 default default >> 15 TxRequest b POST >> 15 TxURL b /node/78063/edit >> 15 TxProtocol b HTTP/1.1 >> 15 TxHeader b Host: indymedia.org.nz >> 15 TxHeader b User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS >> X 10.6; en-GB; rv:1.9.2) Gecko/20100115 Firefox/3.6 >> 15 TxHeader b Accept: >> text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 >> 15 TxHeader b Accept-Language: en-gb,en;q=0.5 >> 15 TxHeader b Accept-Encoding: gzip,deflate >> 15 TxHeader b Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7 >> 15 TxHeader b Referer: http://indymedia.org.nz/node/78063/edit >> 15 TxHeader b Cookie: comment_info_name=Tester; >> SESSxxxxxxxxxxxxxxxxxxxxxxxxxxxxx=xxxxxxxxxxxxxxxxxxxxxxxxxxxxx; >> SESSxxxxxxxxxxxxxxxxxxxxxxxxxxxxx=xxxxxxxxxxxxxxxxxxxxxxxxxxxxx; has_js=1 >> 15 TxHeader b Content-Type: multipart/form-data; >> boundary=---------------------------84863282515329900481602423677 >> 15 TxHeader b Content-Length: 17019 >> 15 TxHeader b X-Forwarded-For: 125.236.128.219 >> 15 TxHeader b X-Varnish: 561007510 >> 15 TxHeader b X-Forwarded-For: 125.236.128.219 >> 15 BackendClose b default >> 21 VCL_call c error >> 21 VCL_return c deliver >> 21 Length c 465 >> 21 VCL_call c deliver >> 21 VCL_return c deliver >> 21 TxProtocol c HTTP/1.1 >> 21 TxStatus c 503 >> 21 TxResponse c Service Unavailable >> 21 TxHeader c Server: Varnish >> 21 TxHeader c Retry-After: 0 >> 21 TxHeader c Content-Type: text/html; charset=utf-8 >> 21 TxHeader c Content-Length: 465 >> 21 TxHeader c Date: Fri, 29 Jan 2010 23:22:15 GMT >> 21 TxHeader c X-Varnish: 561007510 >> 21 TxHeader c Age: 2 >> 21 TxHeader c Via: 1.1 varnish >> 21 TxHeader c Connection: close >> 21 ReqEnd c 561007510 1264807333.799563885 1264807335.335580826 >> 3.151196718 1.535988092 0.000028849 >> 21 SessionClose c error >> 21 StatSess c 125.236.128.219 53669 35 1 9 0 5 4 4595 137808 >> 0 StatAddr - 125.236.128.219 0 2395 45 114 0 53 61 58675 1768498 >> >> On 29/01/10 11:26 PM, Tollef Fog Heen wrote: >> >> >>> ]] Torrance >>> >>> | I am running a drupal site behind Varnish and when posts or comments are >>> | submitted there's about a 50/50 chance the user will get one of >>> | Varnish's 503 error pages. These errors aren't after waiting a little >>> | while or even a few seconds - they are returned with no delay >>> | whatsoever. I can only presume that this is somehow linked to the fact >>> | that these are POST requests, as the errors do not come up at any other >>> | time. >>> >>> If you can capture a varnishlog from a good and a failing request, that >>> might shed some light on what's going on. >>> >>> >>> _______________________________________________ varnish-misc mailing list varnish-misc@projects.linpro.no http://projects.linpro.no/mailman/listinfo/varnish-misc