Hi list,

we are seeing sporadic nginx errors "upstream prematurely closed
connection while reading response header from upstream" with nginx/1.6.2
which seems to be some kind of race condition.
For debugging purposes we only setup 1 upstream server on a public IP
address of the same server as nginx, there is no keepalive configured
between nginx and the upstream server. The upstream HTTP server is
written in a way that it forcibly closes the connection when the
response status code is 303. This may be part of the problem as well.

The error message in the logs is this:

2014/10/16 08:19:39 [error] 21664#0: *7504970 upstream prematurely
closed connection while reading response header from upstream, client:
109.3.1.2, server: my.avast.com, request: "GET /fr-fr/ HTTP/1.1",
upstream: "https://1.1.1.1:8888/ru-ru/", host: "my.upstream.com",
referrer: "https://id.upstream.com/ru-ru/confirm/registration?token=TOKEN"

The configuration looks like follows:

location / {
proxy_pass http://my-upstream;
proxy_read_timeout 90;
}

upstream my-upstream {
ip_hash ; #it was here because normally, we use more upstream
servers
server 1.1.1.1:8888;
}


Now, we tracked down, that this only happens when FIN packet from
upstream server reaches nginx sooner than it's finished with parsing the
response (headers) and thus sooner than nginx closes the connection
itself. For example this packet order will trigger the problem:
No. Time Source SrcPrt Destination Protocol
Length Info
25571 10.297569 1.1.1.1 35481 1.1.1.1 TCP 76 35481 > 8888 [SYN] Seq=0 Win=3072 Len=0 MSS=16396 SACK_PERM=1 TSval=1902164528 TSecr=0 WS=8192
25572 10.297580 1.1.1.1 8888 1.1.1.1 TCP 76 8888 > 35481 [SYN, ACK] Seq=0 Ack=1 Win=3072 Len=0 MSS=16396 SACK_PERM=1 TSval=1902164528 TSecr=1902164528 WS=8192
25573 10.297589 1.1.1.1 35481 1.1.1.1 TCP 68 35481 > 8888 [ACK] Seq=1 Ack=1 Win=8192 Len=0 TSval=1902164528 TSecr=1902164528
25574 10.297609 1.1.1.1 35481 1.1.1.1 HTTP 1533 GET / HTTP/1.0
25575 10.297617 1.1.1.1 8888 1.1.1.1 TCP 68 8888 > 35481 [ACK] Seq=1 Ack=1466 Win=8192 Len=0 TSval=1902164528 TSecr=1902164528
25596 10.323092 1.1.1.1 8888 1.1.1.1 HTTP 480 HTTP/1.1 303 See Other
25597 10.323106 1.1.1.1 35481 1.1.1.1 TCP 68 35481 > 8888 [ACK] Seq=1466 Ack=413 Win=8192 Len=0 TSval=1902164554 TSecr=1902164554
25598 10.323161 1.1.1.1 8888 1.1.1.1 TCP 68 8888 > 35481 [FIN, ACK] Seq=413 Ack=1466 Win=8192 Len=0 TSval=1902164554 TSecr=1902164554
25599 10.323167 1.1.1.1 35481 1.1.1.1 TCP 68 35481 > 8888 [FIN, ACK] Seq=1466 Ack=413 Win=8192 Len=0 TSval=1902164554 TSecr=1902164554
25600 10.323180 1.1.1.1 8888 1.1.1.1 TCP 68 8888 > 35481 [ACK] Seq=414 Ack=1467 Win=8192 Len=0 TSval=1902164554 TSecr=1902164554
25601 10.323189 1.1.1.1 35481 1.1.1.1 TCP 68 35481 > 8888 [ACK] Seq=1467 Ack=414 Win=8192 Len=0 TSval=1902164554 TSecr=1902164554

Note that the upstream HTTP (port 8888) sends the FIN packet sooner than
nginx (port 35481 in this case).

This is example of OK connection:

No. Time Source SrcPrt Destination
Protocol Length Info
27746 11.472853 1.1.1.1 35959 1.1.1.1 TCP 76 35959 > 8888 [SYN] Seq=0 Win=3072 Len=0 MSS=16396 SACK_PERM=1 TSval=1902165703 TSecr=0 WS=8192
27747 11.472867 1.1.1.1 8888 1.1.1.1 TCP 76 8888 > 35959 [SYN, ACK] Seq=0 Ack=1 Win=3072 Len=0 MSS=16396 SACK_PERM=1 TSval=1902165704 TSecr=1902165703 WS=8192
27748 11.472881 1.1.1.1 35959 1.1.1.1 TCP 68 35959 > 8888 [ACK] Seq=1 Ack=1 Win=8192 Len=0 TSval=1902165704 TSecr=1902165704
27749 11.472907 1.1.1.1 35959 1.1.1.1 HTTP 1187 GET /es-co/tab HTTP/1.0
27750 11.472917 1.1.1.1 8888 1.1.1.1 TCP 68 8888 > 35959 [ACK] Seq=1 Ack=1120 Win=8192 Len=0 TSval=1902165704 TSecr=1902165704
27751 11.473818 1.1.1.1 8888 1.1.1.1 HTTP 354 HTTP/1.1 303 See Other
27752 11.473830 1.1.1.1 35959 1.1.1.1 TCP 68 35959 > 8888 [ACK] Seq=1120 Ack=287 Win=8192 Len=0 TSval=1902165704 TSecr=1902165704
27753 11.473865 1.1.1.1 35959 1.1.1.1 TCP 68 35959 > 8888 [FIN, ACK] Seq=1120 Ack=287 Win=8192 Len=0 TSval=1902165705 TSecr=1902165704
27754 11.473877 1.1.1.1 8888 1.1.1.1 TCP 68 8888 > 35959 [FIN, ACK] Seq=287 Ack=1120 Win=8192 Len=0 TSval=1902165705 TSecr=1902165704
27755 11.473885 1.1.1.1 35959 1.1.1.1 TCP 68 35959 > 8888 [ACK] Seq=1121 Ack=288 Win=8192 Len=0 TSval=1902165705 TSecr=1902165705
27756 11.473892 1.1.1.1 8888 1.1.1.1 TCP 68 8888 > 35959 [ACK] Seq=288 Ack=1121 Win=8192 Len=0 TSval=1902165705 TSecr=1902165705

Example of the request and response from wireshark when the problem
occurred is attached below.

From looking at the code, it seems to me that the error message is
printed only when recv() function returns 0 (i.e. there are no bytes to
read and the connection is closed):
src/http/ngx_http_upstream.c:
1653 n = c->recv(c, u->buffer.last, u->buffer.end - u->buffer.last);
1654
.....
1669 if (n == 0) {
1670 ngx_log_error(NGX_LOG_ERR, c->log, 0,
1671 "upstream prematurely closed connection");
1672 }

From my limited understanding, this only can happen when one has read
everything which was in the stream, so function:

1687 rc = u->process_header(r);
1688

should have had everything, i.e. complete header (verified in
wireshark), so it should never return NGX_AGAIN and thus reach the line
1670.

Any pointers will be much appreciated.

Regards
Jiri Horky



GET / HTTP/1.0
Host: my.upstream.com
X-Real-IP: 213.87.240.82
X-Forwarded-For: 213.87.240.82
Connection: close
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Cookie: __utma=1.1091156737.1413387695.1413387695.1413387695.1;
__utmb=1.2.10.1413387695; __utmc=1;
__utmz=1.1413387695.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none);
ID-params-prod="registered=true&refreshIdSession=true&LOGIN_SUCCESS=true";
IDT2=IDTN-21229-MJfdls0NsfrjlHeztlBobHdPetEXXXXXX4; locale2=ru-ru;
osc_omcid=undefined; osc_ot=wd%3E%3Eun%3Eun; osc_v12=Website;
osc_v13=Website%20%7C%20Direct; osc_v14=Website%20%7C%20Direct%20%7C%20;
osc_v15=Website%20%7C%20Direct%20%7C%20; osc_v27=Website%20%7C%20Direct;
osc_v42=web; s_cc=true; s_fid=10F5314146A83D94-160DXXXXXX;
s_nr2=1413387748541-New; x-otid=wd%3E%3Eun%3Eun
User-Agent: Mozilla/5.0 (iPhone; CPU iPhone OS 8_0 like Mac OS X)
AppleWebKit/600.1.4 (KHTML, like Gecko) Version/8.0 Mobile/12A365
Safari/600.1.4
Accept-Language: ru
Referer: https://id.upstream.com/ru-ru/confirm/registration?token=TOKEN
Accept-Encoding: gzip, deflate

HTTP/1.1 303 See Other
Content-Length: 0
Content-Type: text/plain
Location: https://my.upstream.com/ru-ru/
Set-Cookie: mySessionId=3KNJXXXXXXqX; Expires=Wed, 15 Oct 2014 15:57:30
GMT; Path=/; Domain=.my.upstream.com; Secure; HTTPOnly
Set-Cookie:
myLocalIdSession="IDTN-21229-MJfdls0NsfrjlHeztlBobHdPetEXXXXXXXX4:2";
Expires=Wed, 15 Oct 2014 15:57:30 GMT; Path=/; Domain=.my.upstream.com;
Secure; HTTPOnly


_______________________________________________
nginx mailing list
nginx@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx