issue with premature TCP FIN ("half close") from client

[Nils Goroll]

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