upstream prematurely closed connection while reading response header from upstream
Jiri Horky
jiri.horky at gmail.com
Thu Oct 16 22:48:43 UTC 2014
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
On 10/17/2014 12:26 AM, Jiri Horky wrote:
> 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
>
>
More information about the nginx
mailing list