Upstream prematurely closed connection while reading response header from upstream

Server NGINX
1

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

2

Hello!

On Thu, Oct 16, 2014 at 10:17:15AM +0200, Jiri Horky wrote:

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.

[…]

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).

Looking into the packet trace I suspect this commit may be
relevant to your case:

http://hg.nginx.org/nginx/rev/9d3a9c45fc43

Please test with nginx 1.7.3+ to see if it helps.

–
Maxim D.
http://nginx.org/

3

Hi,

thanks for the quick response. I tried it with nginx/1.7.6 but
unfortunately, the errors still show up. However, I did not try to
confirm that these were with the same trace, but I strongly suspect so.
I will confirm that hopefully tomorrow. Anything other I should try?

Regards
Jiri Horky

4

Hello!

On Thu, Oct 16, 2014 at 09:35:14PM +0200, Jiri Horky wrote:

Hi,

thanks for the quick response. I tried it with nginx/1.7.6 but
unfortunately, the errors still show up. However, I did not try to
confirm that these were with the same trace, but I strongly suspect so.
I will confirm that hopefully tomorrow. Anything other I should try?

Debug log may be helpful, see
A debugging log.

–
Maxim D.
http://nginx.org/

5

Hi Maxim,

here is the debug log of one failed connection:

2014/10/17 00:18:30 [debug] 25783#0: *8190 http keepalive handler
2014/10/17 00:18:30 [debug] 25783#0: *8190 malloc: 0000000000BE44F0:1024
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_read: 1024
2014/10/17 00:18:30 [debug] 25783#0: *8190 reusable connection: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 posix_memalign:
0000000000D41510:4096 @16
2014/10/17 00:18:30 [debug] 25783#0: *8190 event timer del: 104:
1413497973959
2014/10/17 00:18:30 [debug] 25783#0: *8190 http process request line
2014/10/17 00:18:30 [debug] 25783#0: *8190 http request line: “GET
/es-mx/ HTTP/1.1”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http uri: “/es-mx/”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http args: “”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http exten: “”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http process request header
line
2014/10/17 00:18:30 [debug] 25783#0: *8190 http header: “Host:
my.upstream.com”
2014/10/17 00:18:30 [debug] 25783#0: 8190 http header: “Connection:
keep-alive”
2014/10/17 00:18:30 [debug] 25783#0: 8190 http header: "Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,/;q=0.8"
2014/10/17 00:18:30 [debug] 25783#0: *8190 http header: “User-Agent:
Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like
Gecko) Chrome/37.0.2062.124 Safari/537.36”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http header: “Referer:
https://id.upstream.com/es-mx/confirm/registration?token=TOKEN”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http header:
“Accept-Encoding: gzip,deflate”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http header:
“Accept-Language: es-ES,es;q=0.8”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http alloc large header
buffer
2014/10/17 00:18:30 [debug] 25783#0: *8190 posix_memalign:
0000000000C66DE0:256 @16
2014/10/17 00:18:30 [debug] 25783#0: *8190 malloc: 0000000000E8A030:8192
2014/10/17 00:18:30 [debug] 25783#0: *8190 http large header alloc:
0000000000E8A030 8192
2014/10/17 00:18:30 [debug] 25783#0: *8190 http large header copy: 572
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_read: 326
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_read: -1
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_get_error: 2
2014/10/17 00:18:30 [debug] 25783#0: *8190 http header: "Cookie:
locale2=es-mx; osc_ot=wr%3E%3Eun%3Eun; x-otid=wr%3E%3Eun%3Eun;
ld893_pop_g=1413877218; ld893_pop_s=1413877218;
ID-params-prod=“registered=true&refreshIdSession=true&LOGIN_SUCCESS=true”;
IDT2=IDTN-33612-GIxblg2ptOvu5R5nlevAy39OTcsyK3i1U6f35444; s_cc=true;
s_nr2=1413877237532-New; osc_v12=Website;
osc_v13=Website%20%7C%20Referral;
osc_v14=Website%20%7C%20Referral%20%7C%20;
osc_v15=Website%20%7C%20Referral%20%7C%20;
osc_v27=Website%20%7C%20Referral; osc_v42=web; s_sq=%5B%5BB%5D%5D;
s_vi=[CS]v1|2A2021EC0531011A-6000010F20029A71[CE];
__utma=1.338233621.1413877155.1413877155.1413877155.1;
__utmb=1.2.10.1413877155; __utmc=1;
__utmz=1.1413877155.1.1.utmcsr=dub126.mail.live.com|utmccn=(referral)|utmcmd=referral|utmcct=/;
s_fid=5230BF2FDF8FC79B-2A08DC4D856F30C9; osc_omcid=undefined;
mySessionId=pYb401tEc5En9InZ;
myLocalIdSession=“IDTN-33612-GIxblg2ptOvu5R5nlevAy39OTcsyK3i1U6f35444:2"”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http header done
2014/10/17 00:18:30 [debug] 25783#0: *8190 generic phase: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 rewrite phase: 1
2014/10/17 00:18:30 [debug] 25783#0: *8190 test location: “/”
2014/10/17 00:18:30 [debug] 25783#0: *8190 using configuration “/”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http cl:-1 max:10485760
2014/10/17 00:18:30 [debug] 25783#0: *8190 rewrite phase: 3
2014/10/17 00:18:30 [debug] 25783#0: *8190 post rewrite phase: 4
2014/10/17 00:18:30 [debug] 25783#0: *8190 generic phase: 5
2014/10/17 00:18:30 [debug] 25783#0: *8190 generic phase: 6
2014/10/17 00:18:30 [debug] 25783#0: *8190 generic phase: 7
2014/10/17 00:18:30 [debug] 25783#0: *8190 access phase: 8
2014/10/17 00:18:30 [debug] 25783#0: *8190 access phase: 9
2014/10/17 00:18:30 [debug] 25783#0: *8190 access phase: 10
2014/10/17 00:18:30 [debug] 25783#0: *8190 post access phase: 11
2014/10/17 00:18:30 [debug] 25783#0: *8190 posix_memalign:
0000000000E03DA0:4096 @16
2014/10/17 00:18:30 [debug] 25783#0: *8190 http init upstream, client
timer: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 http script copy: "Host: "
2014/10/17 00:18:30 [debug] 25783#0: *8190 http script var:
“my.upstream.com”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http script copy: "
2014/10/17 00:18:30 [debug] 25783#0: *8190 http script copy: "X-Real-IP:
"
2014/10/17 00:18:30 [debug] 25783#0: *8190 http script var:
“201.138.52.240”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http script copy: "
2014/10/17 00:18:30 [debug] 25783#0: *8190 http script copy:
"X-Forwarded-For: "
2014/10/17 00:18:30 [debug] 25783#0: *8190 http script var:
“201.138.52.240”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http script copy: "
2014/10/17 00:18:30 [debug] 25783#0: *8190 http script copy:
“Connection: close
2014/10/17 00:18:30 [debug] 25783#0: *8190 http script copy: “”
2014/10/17 00:18:30 [debug] 25783#0: 8190 http script copy: “”
2014/10/17 00:18:30 [debug] 25783#0: 8190 http proxy header: "Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,/;q=0.8”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
“User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36
(KHTML, like Gecko) Chrome/37.0.2062.124 Safari/537.36”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header: “Referer:
https://id.upstream.com/es-mx/confirm/registration?token=TOKEN”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
“Accept-Encoding: gzip,deflate”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
“Accept-Language: es-ES,es;q=0.8”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header: "Cookie:
locale2=es-mx; osc_ot=wr%3E%3Eun%3Eun; x-otid=wr%3E%3Eun%3Eun;
ld893_pop_g=1413877218; ld893_pop_s=1413877218;
ID-params-prod=“registered=true&refreshIdSession=true&LOGIN_SUCCESS=true”;
IDT2=IDTN-33612-GIxblg2ptOvu5R5nlevAy39OTcsyK3i1U6f35444; s_cc=true;
s_nr2=1413877237532-New; osc_v12=Website;
osc_v13=Website%20%7C%20Referral;
osc_v14=Website%20%7C%20Referral%20%7C%20;
osc_v15=Website%20%7C%20Referral%20%7C%20;
osc_v27=Website%20%7C%20Referral; osc_v42=web; s_sq=%5B%5BB%5D%5D;
s_vi=[CS]v1|2A2021EC0531011A-6000010F20029A71[CE];
__utma=1.338233621.1413877155.1413877155.1413877155.1;
__utmb=1.2.10.1413877155; __utmc=1;
__utmz=1.1413877155.1.1.utmcsr=dub126.mail.live.com|utmccn=(referral)|utmcmd=referral|utmcct=/;
s_fid=5230BF2FDF8FC79B-2A08DC4D856F30C9; osc_omcid=undefined;
mySessionId=pYb401tEc5En9InZ;
myLocalIdSession=“IDTN-33612-GIxblg2ptOvu5R5nlevAy39OTcsyK3i1U6f35444:2"”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
2014/10/17 00:18:30 [debug] 25783#0: *8190 http cleanup add:
0000000000D424F8
2014/10/17 00:18:30 [debug] 25783#0: *8190 init keepalive peer
2014/10/17 00:18:30 [debug] 25783#0: *8190 get keepalive peer
2014/10/17 00:18:30 [debug] 25783#0: *8190 get ip hash peer, try: 1
2014/10/17 00:18:30 [debug] 25783#0: *8190 get rr peer, try: 1
2014/10/17 00:18:30 [debug] 25783#0: *8190 get keepalive peer: using
connection 0000000000A7D4F0
2014/10/17 00:18:30 [debug] 25783#0: *8190 http upstream connect: -4
2014/10/17 00:18:30 [debug] 25783#0: *8190 http upstream send request
2014/10/17 00:18:30 [debug] 25783#0: *8190 chain writer buf fl:1 s:1405
2014/10/17 00:18:30 [debug] 25783#0: *8190 chain writer in:
0000000000E04A58
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL buf copy: 1405
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL to write: 1405
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_write: 1405
2014/10/17 00:18:30 [debug] 25783#0: *8190 chain writer out:
0000000000000000
2014/10/17 00:18:30 [debug] 25783#0: *8190 event timer add: 219:
90000:1413498000113
2014/10/17 00:18:30 [debug] 25783#0: *8190 http finalize request: -4,
“/es-mx/?” a:1, c:2
2014/10/17 00:18:30 [debug] 25783#0: *8190 http request count:2 blk:0
2014/10/17 00:18:30 [debug] 25783#0: *8190 http run request: “/es-mx/?”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http upstream check client,
write event:1, “/es-mx/”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http upstream recv(): -1 (11:
Resource temporarily unavailable)
2014/10/17 00:18:30 [debug] 25783#0: *8190 http upstream request:
“/es-mx/?”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http upstream process header
2014/10/17 00:18:30 [debug] 25783#0: *8190 malloc: 0000000000C44D60:8192
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_read: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_get_error: 6
2014/10/17 00:18:30 [debug] 25783#0: *8190 peer shutdown SSL cleanly
2014/10/17 00:18:30 [error] 25783#0: *8190 upstream prematurely closed
connection while reading response header from upstream, client:
201.138.52.240, server: my.upstream.com, request: “GET /es-mx/
HTTP/1.1”, upstream: “https://1.1.1.1:8888/es-mx/”, host:
“my.upstream.com”, referrer:
“https://id.upstream.com/es-mx/confirm/registration?token=TOKEN”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http next upstream, 2
2014/10/17 00:18:30 [debug] 25783#0: *8190 free keepalive peer
2014/10/17 00:18:30 [debug] 25783#0: *8190 free rr peer 1 4
2014/10/17 00:18:30 [debug] 25783#0: *8190 close http upstream
connection: 219
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_shutdown: 1
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000E8D020
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000CF6D30
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000A93A90
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000A93A00,
unused: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 event timer del: 219:
1413498000113
2014/10/17 00:18:30 [debug] 25783#0: *8190 reusable connection: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 get keepalive peer
2014/10/17 00:18:30 [debug] 25783#0: *8190 get ip hash peer, try: 1
2014/10/17 00:18:30 [debug] 25783#0: *8190 get rr peer, try: 1
2014/10/17 00:18:30 [debug] 25783#0: *8190 get keepalive peer: using
connection 0000000000A799E0
2014/10/17 00:18:30 [debug] 25783#0: *8190 http upstream connect: -4
2014/10/17 00:18:30 [debug] 25783#0: *8190 posix_memalign:
0000000000E6D280:4096 @16
2014/10/17 00:18:30 [debug] 25783#0: *8190 http upstream send request
2014/10/17 00:18:30 [debug] 25783#0: *8190 chain writer buf fl:1 s:1405
2014/10/17 00:18:30 [debug] 25783#0: *8190 chain writer in:
0000000000E04C68
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL buf copy: 1405
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL to write: 1405
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_write: 1405
2014/10/17 00:18:30 [debug] 25783#0: *8190 chain writer out:
0000000000000000
2014/10/17 00:18:30 [debug] 25783#0: *8190 event timer add: 65:
90000:1413498000114
2014/10/17 00:18:30 [debug] 25783#0: *8190 http upstream request:
“/es-mx/?”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http upstream process header
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_read: 8192
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy status 200 “200
OK”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
“Content-Length: 9960”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
“Content-Type: text/html”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
“Set-Cookie: mySessionId=pYb401tEc5En9InZ; Expires=Thu, 16 Oct 2014
22:33:30 GMT; Path=/; Domain=.my.upstream.com; Secure; HTTPOnly”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
“Set-Cookie: MY-params=; Expires=Thu, 16 Oct 2014 22:18:30 GMT; Path=/;
Domain=.ff.upstream.com; Secure; HTTPOnly”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
“Set-Cookie: locale2=es-mx; Expires=Wed, 04 Nov 2082 01:32:37 GMT;
Path=/; Domain=.upstream.com; Secure; HTTPOnly”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
“Set-Cookie: ID-params-prod=; Expires=Thu, 16 Oct 2014 22:18:30 GMT;
Path=/; Domain=.upstream.com; Secure; HTTPOnly”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
“Set-Cookie: fbSecThr=true; Path=/; Domain=.my.upstream.com; Secure;
HTTPOnly”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
“Set-Cookie:
myLocalIdSession=“IDTN-33612-GIxblg2ptOvu5R5nlevAy39OTcsyK3i1U6f35444:2”;
Expires=Thu,
16 Oct 2014 22:33:30 GMT; Path=/; Domain=.my.upstream.com; Secure;
HTTPOnly”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
“Last-Modified: Wed, 15 Oct 2014 16:26:53 GMT”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
“Cache-Control: max-age=0, private”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header:
“Strict-Transport-Security: max-age=31536000”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header: “Date:
Thu, 16 Oct 2014 22:18:30 GMT”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy header done
2014/10/17 00:18:30 [debug] 25783#0: *8190 HTTP/1.1 200 OK
2014/10/17 00:18:30 [debug] 25783#0: *8190 write new buf t:1 f:0
0000000000E6DAC8, pos 0000000000E6DAC8, size: 1016 file: 0, size: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 http write filter: l:0 f:0
s:1016
2014/10/17 00:18:30 [debug] 25783#0: *8190 http cacheable: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 http proxy filter init s:200
h:0 c:0 l:9960
2014/10/17 00:18:30 [debug] 25783#0: *8190 http upstream process
upstream
2014/10/17 00:18:30 [debug] 25783#0: *8190 pipe read upstream: 1
2014/10/17 00:18:30 [debug] 25783#0: *8190 pipe preread: 7251
2014/10/17 00:18:30 [debug] 25783#0: *8190 input buf #0
2014/10/17 00:18:30 [debug] 25783#0: *8190 malloc: 0000000000D1EBE0:4096
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_read: 2709
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_read: -1
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_get_error: 2
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_read: -1
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_get_error: 2
2014/10/17 00:18:30 [debug] 25783#0: *8190 pipe recv chain: 2709
2014/10/17 00:18:30 [debug] 25783#0: *8190 pipe buf in s:1 t:1 f:0
0000000000C44D60, pos 0000000000C4510D, size: 7251 file: 0, size: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 pipe buf free s:0 t:1 f:0
0000000000D1EBE0, pos 0000000000D1EBE0, size: 2709 file: 0, size: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 pipe length: 2709
2014/10/17 00:18:30 [debug] 25783#0: *8190 input buf #1
2014/10/17 00:18:30 [debug] 25783#0: *8190 pipe write downstream: 1
2014/10/17 00:18:30 [debug] 25783#0: *8190 pipe write downstream flush
in
2014/10/17 00:18:30 [debug] 25783#0: *8190 http output filter “/es-mx/?”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http copy filter: “/es-mx/?”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http postpone filter
“/es-mx/?” 0000000000E6DFD0
2014/10/17 00:18:30 [debug] 25783#0: *8190 http gzip filter
2014/10/17 00:18:30 [debug] 25783#0: *8190 malloc:
0000000000EB9680:139264
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip alloc: n:1 s:5928 a:8192
p:0000000000EB9680
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip alloc: n:16384 s:2
a:32768 p:0000000000EBB680
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip alloc: n:16384 s:2
a:32768 p:0000000000EC3680
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip alloc: n:16384 s:2
a:32768 p:0000000000ECB680
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip alloc: n:8192 s:4
a:32768 p:0000000000ED3680
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip in: 0000000000E6E190
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip in_buf:0000000000E6DFF0
ni:0000000000C4510D ai:7251
2014/10/17 00:18:30 [debug] 25783#0: *8190 malloc: 0000000000DF5FB0:4096
2014/10/17 00:18:30 [debug] 25783#0: *8190 deflate in:
ni:0000000000C4510D no:0000000000DF5FB0 ai:7251 ao:4096 fl:0 redo:0
2014/10/17 00:18:30 [debug] 25783#0: *8190 deflate out:
ni:0000000000C46D60 no:0000000000DF5FB0 ai:0 ao:4096 rc:0
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip in_buf:0000000000E6DFF0
pos:0000000000C4510D
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip in: 0000000000E6E1A0
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip in_buf:0000000000E6E0B0
ni:0000000000D1EBE0 ai:2709
2014/10/17 00:18:30 [debug] 25783#0: *8190 deflate in:
ni:0000000000D1EBE0 no:0000000000DF5FB0 ai:2709 ao:4096 fl:0 redo:0
2014/10/17 00:18:30 [debug] 25783#0: *8190 deflate out:
ni:0000000000D1F675 no:0000000000DF5FB0 ai:0 ao:4096 rc:0
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip in_buf:0000000000E6E0B0
pos:0000000000D1EBE0
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip in: 0000000000000000
2014/10/17 00:18:30 [debug] 25783#0: *8190 http copy filter: 0
“/es-mx/?”
2014/10/17 00:18:30 [debug] 25783#0: *8190 pipe write downstream done
2014/10/17 00:18:30 [debug] 25783#0: *8190 event timer: 65, old:
1413498000114, new: 1413498000129
2014/10/17 00:18:30 [debug] 25783#0: *8190 http upstream exit:
0000000000000000
2014/10/17 00:18:30 [debug] 25783#0: *8190 finalize http upstream
request: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 finalize http proxy request
2014/10/17 00:18:30 [debug] 25783#0: *8190 free keepalive peer
2014/10/17 00:18:30 [debug] 25783#0: *8190 free keepalive peer: saving
connection 0000000000A799E0
2014/10/17 00:18:30 [debug] 25783#0: *8190 event timer del: 65:
1413498000114
2014/10/17 00:18:30 [debug] 25783#0: *8190 free rr peer 1 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 http upstream temp fd: -1
2014/10/17 00:18:30 [debug] 25783#0: *8190 http output filter “/es-mx/?”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http copy filter: “/es-mx/?”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http postpone filter
“/es-mx/?” 00007FFFE5A241B0
2014/10/17 00:18:30 [debug] 25783#0: *8190 http gzip filter
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip in: 0000000000E6E170
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip in_buf:0000000000E6E210
ni:0000000000000000 ai:0
2014/10/17 00:18:30 [debug] 25783#0: *8190 deflate in:
ni:0000000000000000 no:0000000000DF5FB0 ai:0 ao:4096 fl:4 redo:0
2014/10/17 00:18:30 [debug] 25783#0: *8190 deflate out:
ni:0000000000000000 no:0000000000DF6C2F ai:0 ao:897 rc:1
2014/10/17 00:18:30 [debug] 25783#0: *8190 gzip in_buf:0000000000E6E210
pos:0000000000000000
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000EB9680
2014/10/17 00:18:30 [debug] 25783#0: *8190 posix_memalign:
0000000000E18990:4096 @16
2014/10/17 00:18:30 [debug] 25783#0: *8190 http chunk: 10
2014/10/17 00:18:30 [debug] 25783#0: *8190 http chunk: 3207
2014/10/17 00:18:30 [debug] 25783#0: *8190 write old buf t:1 f:0
0000000000E6DAC8, pos 0000000000E6DAC8, size: 1016 file: 0, size: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 write new buf t:1 f:0
0000000000E18A70, pos 0000000000E18A70, size: 5 file: 0, size: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 write new buf t:0 f:0
0000000000000000, pos 00000000006D7C08, size: 10 file: 0, size: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 write new buf t:1 f:0
0000000000DF5FB0, pos 0000000000DF5FB0, size: 3207 file: 0, size: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 write new buf t:0 f:0
0000000000000000, pos 00000000004B0C38, size: 7 file: 0, size: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 http write filter: l:1 f:1
s:4245
2014/10/17 00:18:30 [debug] 25783#0: *8190 http write filter limit 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 malloc:
0000000000D2E0F0:16384
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL buf copy: 1016
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL buf copy: 5
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL buf copy: 10
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL buf copy: 3207
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL buf copy: 7
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL to write: 4245
2014/10/17 00:18:30 [debug] 25783#0: *8190 SSL_write: 4245
2014/10/17 00:18:30 [debug] 25783#0: *8190 http write filter
0000000000000000
2014/10/17 00:18:30 [debug] 25783#0: *8190 http copy filter: 0
“/es-mx/?”
2014/10/17 00:18:30 [debug] 25783#0: *8190 http finalize request: 0,
“/es-mx/?” a:1, c:1
2014/10/17 00:18:30 [debug] 25783#0: *8190 set http keepalive handler
2014/10/17 00:18:30 [debug] 25783#0: *8190 http close request
2014/10/17 00:18:30 [debug] 25783#0: *8190 http log handler
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000DF5FB0
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000000000
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000D1EBE0
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000C44D60
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000D41510,
unused: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000E03DA0,
unused: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000E6D280,
unused: 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000E18990,
unused: 3356
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000BE44F0
2014/10/17 00:18:30 [debug] 25783#0: *8190 hc free: 0000000000000000 0
2014/10/17 00:18:30 [debug] 25783#0: *8190 hc busy: 0000000000E075C0 1
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000E8A030
2014/10/17 00:18:30 [debug] 25783#0: *8190 free: 0000000000D2E0F0
2014/10/17 00:18:30 [debug] 25783#0: *8190 reusable connection: 1
2014/10/17 00:18:30 [debug] 25783#0: *8190 event timer add: 104:
65000:1413497975129

6

Hi again,

I just realized that the debug log I posted previously was with a
different setting (thus the SSL and keepalive there):

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

upstream my-upstream {
ip_hash ;
server 1.1.1.1:8888;
keepalive 1024 ;
}

Here is another debug output with previous settings:

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

upstream my-upstream {
ip_hash ;
server 1.1.1.1:8888;
keepalive;
}

2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL NPN advertised
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_do_handshake: -1
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_get_error: 2
2014/10/17 00:41:55 [debug] 27396#0: *12485 reusable connection: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL handshake handler: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_do_handshake: 1
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL: TLSv1.2, cipher:
“ECDHE-RSA-AES256-SHA SSLv3 Kx=ECDH Au=RSA Enc=AES(256) Mac=SHA1”
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL reused session
2014/10/17 00:41:55 [debug] 27396#0: *12485 reusable connection: 1
2014/10/17 00:41:55 [debug] 27396#0: *12485 http wait request handler
2014/10/17 00:41:55 [debug] 27396#0: *12485 malloc:
00000000010BE9E0:1024
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_read: -1
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_get_error: 2
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 00000000010BE9E0
2014/10/17 00:41:55 [debug] 27396#0: *12485 http wait request handler
2014/10/17 00:41:55 [debug] 27396#0: *12485 malloc:
00000000010BE9E0:1024
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_read: 1024
2014/10/17 00:41:55 [debug] 27396#0: *12485 reusable connection: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 posix_memalign:
0000000001078940:4096 @16
2014/10/17 00:41:55 [debug] 27396#0: *12485 http process request line
2014/10/17 00:41:55 [debug] 27396#0: *12485 http request line: “GET /
HTTP/1.1”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http uri: “/”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http args: “”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http exten: “”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http process request header
line
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header: “Host:
my.upstream.com”
2014/10/17 00:41:55 [debug] 27396#0: 12485 http header: “Connection:
keep-alive”
2014/10/17 00:41:55 [debug] 27396#0: 12485 http header: "Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,/;q=0.8"
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header: “User-Agent:
Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like
Gecko) Chrome/38.0.2125.104 Safari/537.36”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header: “DNT: 1”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header: “Referer:
https://id.upstream.com/en-us/confirm/registration?token=TOKEN”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header:
“Accept-Encoding: gzip,deflate”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header:
“Accept-Language: en-US,en;q=0.8”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http alloc large header
buffer
2014/10/17 00:41:55 [debug] 27396#0: *12485 posix_memalign:
0000000000FFBFA0:256 @16
2014/10/17 00:41:55 [debug] 27396#0: *12485 malloc:
0000000000F84000:8192
2014/10/17 00:41:55 [debug] 27396#0: *12485 http large header alloc:
0000000000F84000 8192
2014/10/17 00:41:55 [debug] 27396#0: *12485 http large header copy: 565
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_read: 535
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_read: -1
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_get_error: 2
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header: “Cookie:
_ga=GA1.2.2132928230.1413413645; locale2=en-us; osc_ot=wd%3E%3Eun%3Eun;
x-otid=wd%3E%3Eun%3Eun;
ID-params-prod=“registered=true&refreshIdSession=true&LOGIN_SUCCESS=true”;
IDT2=IDTN-34432-uxPmpoQ9sF6EuHAKTQWvy7ciHMBIbpBXGBU35444;
mySessionId=nDvMqjksghRHnlUW;
myLocalIdSession=“IDTN-34432-uxPmpoQ9sF6EuHAKTQWvy7ciHMBIbpBXGBU35444:2”;
s_cc=true;
s_vi=[CS]v1|2A202483853125BA-600001144001021A[CE];
__utma=1.2132928230.1413413645.1413499144.1413499144.1;
__utmb=1.3.10.1413499144; __utmc=1;
__utmz=1.1413499144.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none);
s_fid=59C41CF31B464520-25F08D3F0A8EAB2B; osc_omcid=undefined;
s_nr2=1413499315275-New; 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_sq=upstream-dev%3D%2526pid%253DID%252520Avast%252520%25257C%252520undefineden-us%25252Fconfirm%25252Fregistration%25253Ftoken%25253DTOKEN%2526pidt%253D1%2526oid%253Dhttps%25253A%25252F%25252Fmy.upstream.com%25252F%2526ot%253DA”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header done
2014/10/17 00:41:55 [debug] 27396#0: *12485 event timer del: 174:
1413499375418
2014/10/17 00:41:55 [debug] 27396#0: *12485 generic phase: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 rewrite phase: 1
2014/10/17 00:41:55 [debug] 27396#0: *12485 test location: “/”
2014/10/17 00:41:55 [debug] 27396#0: *12485 using configuration “/”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http cl:-1 max:10485760
2014/10/17 00:41:55 [debug] 27396#0: *12485 rewrite phase: 3
2014/10/17 00:41:55 [debug] 27396#0: *12485 post rewrite phase: 4
2014/10/17 00:41:55 [debug] 27396#0: *12485 generic phase: 5
2014/10/17 00:41:55 [debug] 27396#0: *12485 generic phase: 6
2014/10/17 00:41:55 [debug] 27396#0: *12485 generic phase: 7
2014/10/17 00:41:55 [debug] 27396#0: *12485 access phase: 8
2014/10/17 00:41:55 [debug] 27396#0: *12485 access phase: 9
2014/10/17 00:41:55 [debug] 27396#0: *12485 access phase: 10
2014/10/17 00:41:55 [debug] 27396#0: *12485 post access phase: 11
2014/10/17 00:41:55 [debug] 27396#0: *12485 posix_memalign:
0000000000F186D0:4096 @16
2014/10/17 00:41:55 [debug] 27396#0: *12485 http init upstream, client
timer: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 epoll add event: fd:174 op:3
ev:80002005
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy: "Host: "
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script var:
“my.upstream.com”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy: "
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy:
"X-Real-IP: "
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script var:
“68.39.176.125”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy: "
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy:
“X-Forwarded-For: "
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script var:
“68.39.176.125”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy: "
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy:
“Connection: close
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy: “”
2014/10/17 00:41:55 [debug] 27396#0: 12485 http script copy: “”
2014/10/17 00:41:55 [debug] 27396#0: 12485 http proxy header: "Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,/;q=0.8”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header:
“User-Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36
(KHTML, like Gecko) Chrome/38.0.2125.104 Safari/537.36”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header: “DNT: 1”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header: “Referer:
https://id.upstream.com/en-us/confirm/registration?token=TOKEN”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header:
“Accept-Encoding: gzip,deflate”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header:
“Accept-Language: en-US,en;q=0.8”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header: “Cookie:
_ga=GA1.2.2132928230.1413413645; locale2=en-us; osc_ot=wd%3E%3Eun%3Eun;
x-otid=wd%3E%3Eun%3Eun;
ID-params-prod=“registered=true&refreshIdSession=true&LOGIN_SUCCESS=true”;
IDT2=IDTN-34432-uxPmpoQ9sF6EuHAKTQWvy7ciHMBIbpBXGBU35444;
mySessionId=nDvMqjksghRHnlUW;
myLocalIdSession=“IDTN-34432-uxPmpoQ9sF6EuHAKTQWvy7ciHMBIbpBXGBU35444:2”;
s_cc=true;
s_vi=[CS]v1|2A202483853125BA-600001144001021A[CE];
__utma=1.2132928230.1413413645.1413499144.1413499144.1;
__utmb=1.3.10.1413499144; __utmc=1;
__utmz=1.1413499144.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none);
s_fid=59C41CF31B464520-25F08D3F0A8EAB2B; osc_omcid=undefined;
s_nr2=1413499315275-New; 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_sq=upstream-dev%3D%2526pid%253DID%252520Avast%252520%25257C%252520undefineden-us%25252Fconfirm%25252Fregistration%25253Ftoken%25253DTOKEN%2526pidt%253D1%2526oid%253Dhttps%25253A%25252F%25252Fmy.upstream.com%25252F%2526ot%253DA”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header:
2014/10/17 00:41:55 [debug] 27396#0: *12485 http cleanup add:
0000000001079928
2014/10/17 00:41:55 [debug] 27396#0: *12485 get ip hash peer, try: 1
2014/10/17 00:41:55 [debug] 27396#0: *12485 get rr peer, try: 1
2014/10/17 00:41:55 [debug] 27396#0: *12485 socket 183
2014/10/17 00:41:55 [debug] 27396#0: *12485 epoll add connection: fd:183
ev:80002005
2014/10/17 00:41:55 [debug] 27396#0: *12485 connect to 1.1.1.1:8888,
fd:183 #12523
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream connect: -2
2014/10/17 00:41:55 [debug] 27396#0: *12485 posix_memalign:
0000000000EF9C80:128 @16
2014/10/17 00:41:55 [debug] 27396#0: *12485 event timer add: 183:
90000:1413499405518
2014/10/17 00:41:55 [debug] 27396#0: *12485 http finalize request: -4,
“/?” a:1, c:2
2014/10/17 00:41:55 [debug] 27396#0: *12485 http request count:2 blk:0
2014/10/17 00:41:55 [debug] 27396#0: *12485 http run request: “/?”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream check client,
write event:1, “/”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream recv(): -1
(11: Resource temporarily unavailable)
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream request: “/?”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream send request
handler
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream send request
2014/10/17 00:41:55 [debug] 27396#0: *12485 chain writer buf fl:1 s:1612
2014/10/17 00:41:55 [debug] 27396#0: *12485 chain writer in:
0000000000F19420
2014/10/17 00:41:55 [debug] 27396#0: *12485 writev: 1612
2014/10/17 00:41:55 [debug] 27396#0: *12485 chain writer out:
0000000000000000
2014/10/17 00:41:55 [debug] 27396#0: *12485 event timer del: 183:
1413499405518
2014/10/17 00:41:55 [debug] 27396#0: *12485 event timer add: 183:
90000:1413499405519
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream request: “/?”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream process header
2014/10/17 00:41:55 [debug] 27396#0: *12485 malloc:
0000000000F0A040:8192
2014/10/17 00:41:55 [debug] 27396#0: *12485 recv: fd:183 412 of 8192
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy status 303 “303
See Other”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header:
“Content-Length: 0”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header:
“Content-Type: text/plain”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header:
“Location: https://my.upstream.com/en-us/”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header:
“Set-Cookie: mySessionId=nDvMqjksghRHnlUW; Expires=Thu, 16 Oct 2014
22:56:55 GMT; Path=/; Domain=.my.upstream.com; Secure; HTTPOnly”
2014/10/17 00:41:55 [debug] 27396#0: *12485 posix_memalign:
0000000000DC56D0:4096 @16
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header:
“Set-Cookie:
myLocalIdSession=“IDTN-34432-uxPmpoQ9sF6EuHAKTQWvy7ciHMBIbpBXGBU35444:2”;
Expires=Thu,
16 Oct 2014 22:56:55 GMT; Path=/; Domain=.my.upstream.com; Secure;
HTTPOnly”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header done
2014/10/17 00:41:55 [debug] 27396#0: *12485 HTTP/1.1 303 See Other
2014/10/17 00:41:55 [debug] 27396#0: *12485 write new buf t:1 f:0
0000000000DC5808, pos 0000000000DC5808, size: 494 file: 0, size: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 http write filter: l:0 f:0
s:494
2014/10/17 00:41:55 [debug] 27396#0: *12485 http cacheable: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy filter init s:303
h:0 c:0 l:0
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream process
upstream
2014/10/17 00:41:55 [debug] 27396#0: *12485 pipe read upstream: 1
2014/10/17 00:41:55 [debug] 27396#0: *12485 pipe preread: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 readv: 1, last:7780
2014/10/17 00:41:55 [debug] 27396#0: *12485 pipe recv chain: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 pipe buf free s:0 t:1 f:0
0000000000F0A040, pos 0000000000F0A1DC, size: 0 file: 0, size: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 pipe length: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 pipe write downstream: 1
2014/10/17 00:41:55 [debug] 27396#0: *12485 pipe write downstream done
2014/10/17 00:41:55 [debug] 27396#0: *12485 event timer del: 183:
1413499405519
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream exit:
0000000000000000
2014/10/17 00:41:55 [debug] 27396#0: *12485 finalize http upstream
request: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 finalize http proxy request
2014/10/17 00:41:55 [debug] 27396#0: *12485 free rr peer 1 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 close http upstream
connection: 183
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 0000000000EF9C80,
unused: 48
2014/10/17 00:41:55 [debug] 27396#0: *12485 reusable connection: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream temp fd: -1
2014/10/17 00:41:55 [debug] 27396#0: *12485 http output filter “/?”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http copy filter: “/?”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http postpone filter “/?”
00007FFFA7DBA4E0
2014/10/17 00:41:55 [debug] 27396#0: *12485 write old buf t:1 f:0
0000000000DC5808, pos 0000000000DC5808, size: 494 file: 0, size: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 write new buf t:0 f:0
0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 http write filter: l:1 f:0
s:494
2014/10/17 00:41:55 [debug] 27396#0: *12485 http write filter limit 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 malloc:
00000000010DA150:16384
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL buf copy: 494
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL to write: 494
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_write: 494
2014/10/17 00:41:55 [debug] 27396#0: *12485 http write filter
0000000000000000
2014/10/17 00:41:55 [debug] 27396#0: *12485 http copy filter: 0 “/?”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http finalize request: 0,
“/?” a:1, c:1
2014/10/17 00:41:55 [debug] 27396#0: *12485 set http keepalive handler
2014/10/17 00:41:55 [debug] 27396#0: *12485 http close request
2014/10/17 00:41:55 [debug] 27396#0: *12485 http log handler
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 0000000000F0A040
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 0000000001078940,
unused: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 0000000000F186D0,
unused: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 0000000000DC56D0,
unused: 2454
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 00000000010BE9E0
2014/10/17 00:41:55 [debug] 27396#0: *12485 hc free: 0000000000000000 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 hc busy: 0000000000FFBFC0 1
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 0000000000F84000
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 00000000010DA150
2014/10/17 00:41:55 [debug] 27396#0: *12485 tcp_nodelay
2014/10/17 00:41:55 [debug] 27396#0: *12485 reusable connection: 1
2014/10/17 00:41:55 [debug] 27396#0: *12485 event timer add: 174:
65000:1413499380529
2014/10/17 00:41:55 [debug] 27396#0: *12485 post event 0000000000D2F7F8
2014/10/17 00:41:55 [debug] 27396#0: *12485 post event 0000000000D36008
2014/10/17 00:41:55 [debug] 27396#0: *12485 delete posted event
0000000000D2F7F8
2014/10/17 00:41:55 [debug] 27396#0: *12485 http keepalive handler
2014/10/17 00:41:55 [debug] 27396#0: *12485 malloc:
00000000010BE9E0:1024
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_read: 1024
2014/10/17 00:41:55 [debug] 27396#0: *12485 reusable connection: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 posix_memalign:
0000000000F186D0:4096 @16
2014/10/17 00:41:55 [debug] 27396#0: *12485 event timer del: 174:
1413499380529
2014/10/17 00:41:55 [debug] 27396#0: *12485 http process request line
2014/10/17 00:41:55 [debug] 27396#0: *12485 http request line: “GET
/en-us/ HTTP/1.1”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http uri: “/en-us/”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http args: “”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http exten: “”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http process request header
line
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header: “Host:
my.upstream.com”
2014/10/17 00:41:55 [debug] 27396#0: 12485 http header: “Connection:
keep-alive”
2014/10/17 00:41:55 [debug] 27396#0: 12485 http header: "Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,/;q=0.8”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header: “User-Agent:
Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like
Gecko) Chrome/38.0.2125.104 Safari/537.36”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header: “DNT: 1”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header: “Referer:
https://id.upstream.com/en-us/confirm/registration?token=TOKEN”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header:
“Accept-Encoding: gzip,deflate”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header:
“Accept-Language: en-US,en;q=0.8”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http alloc large header
buffer
2014/10/17 00:41:55 [debug] 27396#0: *12485 posix_memalign:
0000000000E82F60:256 @16
2014/10/17 00:41:55 [debug] 27396#0: *12485 malloc:
0000000000F84000:8192
2014/10/17 00:41:55 [debug] 27396#0: *12485 http large header alloc:
0000000000F84000 8192
2014/10/17 00:41:55 [debug] 27396#0: *12485 http large header copy: 559
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_read: 541
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_read: -1
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_get_error: 2
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header: "Cookie:
_ga=GA1.2.2132928230.1413413645; locale2=en-us; osc_ot=wd%3E%3Eun%3Eun;
x-otid=wd%3E%3Eun%3Eun;
ID-params-prod=“registered=true&refreshIdSession=true&LOGIN_SUCCESS=true”;
IDT2=IDTN-34432-uxPmpoQ9sF6EuHAKTQWvy7ciHMBIbpBXGBU35444; s_cc=true;
s_vi=[CS]v1|2A202483853125BA-600001144001021A[CE];
__utma=1.2132928230.1413413645.1413499144.1413499144.1;
__utmb=1.3.10.1413499144; __utmc=1;
__utmz=1.1413499144.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none);
s_fid=59C41CF31B464520-25F08D3F0A8EAB2B; osc_omcid=undefined;
s_nr2=1413499315275-New; 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_sq=upstream-dev%3D%2526pid%253DID%252520Avast%252520%25257C%252520undefineden-us%25252Fconfirm%25252Fregistration%25253Ftoken%25253DTOKEN%2526pidt%253D1%2526oid%253Dhttps%25253A%25252F%25252Fmy.upstream.com%25252F%2526ot%253DA;
mySessionId=nDvMqjksghRHnlUW;
myLocalIdSession=“IDTN-34432-uxPmpoQ9sF6EuHAKTQWvy7ciHMBIbpBXGBU35444:2"”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http header done
2014/10/17 00:41:55 [debug] 27396#0: *12485 generic phase: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 rewrite phase: 1
2014/10/17 00:41:55 [debug] 27396#0: *12485 test location: “/”
2014/10/17 00:41:55 [debug] 27396#0: *12485 using configuration “/”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http cl:-1 max:10485760
2014/10/17 00:41:55 [debug] 27396#0: *12485 rewrite phase: 3
2014/10/17 00:41:55 [debug] 27396#0: *12485 post rewrite phase: 4
2014/10/17 00:41:55 [debug] 27396#0: *12485 generic phase: 5
2014/10/17 00:41:55 [debug] 27396#0: *12485 generic phase: 6
2014/10/17 00:41:55 [debug] 27396#0: *12485 generic phase: 7
2014/10/17 00:41:55 [debug] 27396#0: *12485 access phase: 8
2014/10/17 00:41:55 [debug] 27396#0: *12485 access phase: 9
2014/10/17 00:41:55 [debug] 27396#0: *12485 access phase: 10
2014/10/17 00:41:55 [debug] 27396#0: *12485 post access phase: 11
2014/10/17 00:41:55 [debug] 27396#0: *12485 posix_memalign:
0000000001040640:4096 @16
2014/10/17 00:41:55 [debug] 27396#0: *12485 http init upstream, client
timer: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy: "Host: "
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script var:
“my.upstream.com”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy: "
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy:
"X-Real-IP: "
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script var:
“68.39.176.125”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy: "
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy:
"X-Forwarded-For: "
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script var:
“68.39.176.125”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy: "
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy:
“Connection: close
2014/10/17 00:41:55 [debug] 27396#0: *12485 http script copy: “”
2014/10/17 00:41:55 [debug] 27396#0: 12485 http script copy: “”
2014/10/17 00:41:55 [debug] 27396#0: 12485 http proxy header: "Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,/;q=0.8”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header:
“User-Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36
(KHTML, like Gecko) Chrome/38.0.2125.104 Safari/537.36”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header: “DNT: 1”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header: “Referer:
https://id.upstream.com/en-us/confirm/registration?token=TOKEN”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header:
“Accept-Encoding: gzip,deflate”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header:
“Accept-Language: en-US,en;q=0.8”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header: "Cookie:
_ga=GA1.2.2132928230.1413413645; locale2=en-us; osc_ot=wd%3E%3Eun%3Eun;
x-otid=wd%3E%3Eun%3Eun;
ID-params-prod=“registered=true&refreshIdSession=true&LOGIN_SUCCESS=true”;
IDT2=IDTN-34432-uxPmpoQ9sF6EuHAKTQWvy7ciHMBIbpBXGBU35444; s_cc=true;
s_vi=[CS]v1|2A202483853125BA-600001144001021A[CE];
__utma=1.2132928230.1413413645.1413499144.1413499144.1;
__utmb=1.3.10.1413499144; __utmc=1;
__utmz=1.1413499144.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none);
s_fid=59C41CF31B464520-25F08D3F0A8EAB2B; osc_omcid=undefined;
s_nr2=1413499315275-New; 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_sq=upstream-dev%3D%2526pid%253DID%252520Avast%252520%25257C%252520undefineden-us%25252Fconfirm%25252Fregistration%25253Ftoken%25253DTOKEN%2526pidt%253D1%2526oid%253Dhttps%25253A%25252F%25252Fmy.upstream.com%25252F%2526ot%253DA;
mySessionId=nDvMqjksghRHnlUW;
myLocalIdSession=“IDTN-34432-uxPmpoQ9sF6EuHAKTQWvy7ciHMBIbpBXGBU35444:2"”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http proxy header:
2014/10/17 00:41:55 [debug] 27396#0: *12485 http cleanup add:
0000000000F196B8
2014/10/17 00:41:55 [debug] 27396#0: *12485 get ip hash peer, try: 1
2014/10/17 00:41:55 [debug] 27396#0: *12485 get rr peer, try: 1
2014/10/17 00:41:55 [debug] 27396#0: *12485 socket 184
2014/10/17 00:41:55 [debug] 27396#0: *12485 epoll add connection: fd:184
ev:80002005
2014/10/17 00:41:55 [debug] 27396#0: *12485 connect to 1.1.1.1:8888,
fd:184 #12552
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream connect: -2
2014/10/17 00:41:55 [debug] 27396#0: *12485 posix_memalign:
0000000000FD3720:128 @16
2014/10/17 00:41:55 [debug] 27396#0: *12485 event timer add: 184:
90000:1413499405670
2014/10/17 00:41:55 [debug] 27396#0: *12485 http finalize request: -4,
“/en-us/?” a:1, c:2
2014/10/17 00:41:55 [debug] 27396#0: *12485 http request count:2 blk:0
2014/10/17 00:41:55 [debug] 27396#0: *12485 delete posted event
0000000000D36008
2014/10/17 00:41:55 [debug] 27396#0: *12485 http run request: “/en-us/?”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream check client,
write event:1, “/en-us/”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream recv(): -1
(11: Resource temporarily unavailable)
2014/10/17 00:41:55 [debug] 27396#0: *12485 post event 0000000000D39818
2014/10/17 00:41:55 [debug] 27396#0: *12485 delete posted event
0000000000D39818
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream request:
“/en-us/?”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream send request
handler
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream send request
2014/10/17 00:41:55 [debug] 27396#0: *12485 chain writer buf fl:1 s:1618
2014/10/17 00:41:55 [debug] 27396#0: *12485 chain writer in:
0000000001041398
2014/10/17 00:41:55 [debug] 27396#0: *12485 writev: 1618
2014/10/17 00:41:55 [debug] 27396#0: *12485 chain writer out:
0000000000000000
2014/10/17 00:41:55 [debug] 27396#0: *12485 event timer del: 184:
1413499405670
2014/10/17 00:41:55 [debug] 27396#0: *12485 event timer add: 184:
90000:1413499405670
2014/10/17 00:41:55 [debug] 27396#0: *12485 post event 0000000000D33008
2014/10/17 00:41:55 [debug] 27396#0: *12485 post event 0000000000D39818
2014/10/17 00:41:55 [debug] 27396#0: *12485 delete posted event
0000000000D33008
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream request:
“/en-us/?”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream process header
2014/10/17 00:41:55 [debug] 27396#0: *12485 malloc:
0000000000FAB620:8192
2014/10/17 00:41:55 [debug] 27396#0: *12485 recv: fd:184 0 of 8192
2014/10/17 00:41:55 [error] 27396#0: *12485 upstream prematurely closed
connection while reading response header from upstream, client:
68.39.176.125, server: my.upstream.com, request: “GET /en-us/ HTTP/1.1”,
upstream: “http://1.1.1.1:8888/en-us/”, host: “my.upstream.com”,
referrer:
“https://id.upstream.com/en-us/confirm/registration?token=TOKEN”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http next upstream, 2
2014/10/17 00:41:55 [debug] 27396#0: *12485 free rr peer 1 4
2014/10/17 00:41:55 [debug] 27396#0: *12485 finalize http upstream
request: 502
2014/10/17 00:41:55 [debug] 27396#0: *12485 finalize http proxy request
2014/10/17 00:41:55 [debug] 27396#0: *12485 close http upstream
connection: 184
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 0000000000FD3720,
unused: 48
2014/10/17 00:41:55 [debug] 27396#0: *12485 event timer del: 184:
1413499405670
2014/10/17 00:41:55 [debug] 27396#0: *12485 delete posted event
0000000000D39818
2014/10/17 00:41:55 [debug] 27396#0: *12485 reusable connection: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 http finalize request: 502,
“/en-us/?” a:1, c:1
2014/10/17 00:41:55 [debug] 27396#0: *12485 http special response: 502,
“/en-us/?”
2014/10/17 00:41:55 [debug] 27396#0: *12485 HTTP/1.1 502 Bad Gateway
2014/10/17 00:41:55 [debug] 27396#0: *12485 posix_memalign:
0000000001078940:4096 @16
2014/10/17 00:41:55 [debug] 27396#0: *12485 write new buf t:1 f:0
0000000001041588, pos 0000000001041588, size: 156 file: 0, size: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 http write filter: l:0 f:0
s:156
2014/10/17 00:41:55 [debug] 27396#0: *12485 http output filter
“/en-us/?”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http copy filter: “/en-us/?”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http postpone filter
“/en-us/?” 0000000001078AD0
2014/10/17 00:41:55 [debug] 27396#0: *12485 write old buf t:1 f:0
0000000001041588, pos 0000000001041588, size: 156 file: 0, size: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 write new buf t:0 f:0
0000000000000000, pos 00000000006D4760, size: 120 file: 0, size: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 write new buf t:0 f:0
0000000000000000, pos 00000000006D3520, size: 52 file: 0, size: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 write new buf t:0 f:0
0000000000000000, pos 00000000006D35A0, size: 402 file: 0, size: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 http write filter: l:1 f:0
s:730
2014/10/17 00:41:55 [debug] 27396#0: *12485 http write filter limit 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 malloc:
0000000000ECBAA0:16384
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL buf copy: 156
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL buf copy: 120
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL buf copy: 52
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL buf copy: 402
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL to write: 730
2014/10/17 00:41:55 [debug] 27396#0: *12485 SSL_write: 730
2014/10/17 00:41:55 [debug] 27396#0: *12485 http write filter
0000000000000000
2014/10/17 00:41:55 [debug] 27396#0: *12485 http copy filter: 0
“/en-us/?”
2014/10/17 00:41:55 [debug] 27396#0: *12485 http finalize request: 0,
“/en-us/?” a:1, c:1
2014/10/17 00:41:55 [debug] 27396#0: *12485 set http keepalive handler
2014/10/17 00:41:55 [debug] 27396#0: *12485 http close request
2014/10/17 00:41:55 [debug] 27396#0: *12485 http log handler
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 0000000000FAB620
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 0000000000F186D0,
unused: 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 0000000001040640,
unused: 11
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 0000000001078940,
unused: 3264
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 00000000010BE9E0
2014/10/17 00:41:55 [debug] 27396#0: *12485 hc free: 0000000000000000 0
2014/10/17 00:41:55 [debug] 27396#0: *12485 hc busy: 0000000000FFBFC0 1
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 0000000000F84000
2014/10/17 00:41:55 [debug] 27396#0: *12485 free: 0000000000ECBAA0

7

Hello!

On Fri, Oct 17, 2014 at 12:48:43AM +0200, Jiri Horky wrote:

[…]

2014/10/17 00:41:55 [debug] 27396#0: *12485 connect to 1.1.1.1:8888,
fd:184 #12552

Here connection is stablished to an upstream server.

2014/10/17 00:41:55 [debug] 27396#0: *12485 http run request: “/en-us/?”
handler
2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream send request
2014/10/17 00:41:55 [debug] 27396#0: *12485 chain writer buf fl:1 s:1618
2014/10/17 00:41:55 [debug] 27396#0: *12485 chain writer in:
0000000001041398
2014/10/17 00:41:55 [debug] 27396#0: *12485 writev: 1618
2014/10/17 00:41:55 [debug] 27396#0: *12485 chain writer out:
0000000000000000

Request is written into the socket.

2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream process header
2014/10/17 00:41:55 [debug] 27396#0: *12485 malloc: 0000000000FAB620:8192
2014/10/17 00:41:55 [debug] 27396#0: *12485 recv: fd:184 0 of 8192
2014/10/17 00:41:55 [error] 27396#0: *12485 upstream prematurely closed
connection while reading response header from upstream, client:
68.39.176.125, server: my.upstream.com, request: “GET /en-us/ HTTP/1.1”,
upstream: “http://1.1.1.1:8888/en-us/”, host: “my.upstream.com”,
referrer: “https://id.upstream.com/en-us/confirm/registration?token=TOKEN”

And reading from the socket indicate that it’s closed.

Packet traces you previously posted look unrelated to this debug
log. In this case, there is either no response from the upstream
at all, or the response contents are lost due to RST from the
upstream.

If, as you wrote, your backend “forcibly closes the connection”,
the reason may be that it does so by using close() with SO_LINGER,
and this in turn results in RST being send to nginx in some cases.

In either case debug log suggests there is nothing wrong on nginx
side, you should focus on your backend instead.

–
Maxim D.
http://nginx.org/

8

Hi Max,

thanks for the explanation, I agree that from the traces, it really
looks like there were no data available in the socket from the upstream,
thus a different situation than I posted the first time. I will try to
reproduce the problem with both, debug log and wireshark traces that
will match and will get back to you.

Jirka H.

9

Hi Maxim,

so I dig into it a bit further and it seems as that I made an error in
pairing of tcpdump outputs with nginx error logs. I triple checked it
now and the upstream server really killed the connection without sending
a response in cases nginx triggers an error.

I am sorry for the noise.

Regards
Jiri Horky

10

Hi Jiri,

I’m experiencing similar difficulties. What does your upstream server
configuration look like? What did you do to fix your problem?
In my tcpdumps I’m not seeing the 0 byte chunk that should be at the end
of
a request. My upstreams are running Apache2 2.2.22 (debian) and PHP
5.5.13.

Greetings, Casper

Posted at Nginx Forum: