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 [email protected] http://mailman.nginx.org/mailman/listinfo/nginx
