upstream prematurely closed connection while reading response header from upstream

Jiri Horky jiri.horky at gmail.com
Thu Oct 16 08:17:15 UTC 2014


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


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20141016/8eb18eac/attachment.html>


More information about the nginx mailing list