Nginx-ru mailing list archive (nginx-ru@sysoev.ru)
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
Проблема при проксировани и на https бэкенд
- To: nginx-ru@xxxxxxxxx
- Subject: Проблема при проксировани и на https бэкенд
- From: Алексей Малов <scukonick@xxxxxxxxx>
- Date: Mon, 23 May 2011 14:36:51 +0400
- Dkim-signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:mime-version:date:message-id:subject:from:to :content-type; bh=UJrhQl4WVsDh6OKXQY0L4Sku0DGVvuxQNU6Hi2mEZhk=; b=WkxgxB3HOvJ3OEYcN1SoqxcQ+bIKB8w9mFFaDPlxRABzzzwPxspOuYTHODaKnuKZlh RFCIip1B7PF98Hpfrc+qkzwNLVARHMxjmixQ+vmtYOBNhaDtPumOzBSKhb7NweUt/wxP ve27VU5WZvpx+yO8nPduak2n+P9X/Hu5k062E=
- Domainkey-signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=mime-version:date:message-id:subject:from:to:content-type; b=XXeKbnO2KtlYi21ICLH9WILovGvTzbMxk06gYKRy7Jk9QEHt5BP6dlgqX2i6H3xqk0 xWdBpAGbiqqUWKVH+26cHJpJoHZXjewjj0vI6YLVKq6WqYeFNBe/Jr6FbSRyfYuGtZBC 4ANvXFGHYj6gbWvlo6QC/tUtk0BPFHKzMb9ic=
Добрый день.
Возникла следующая проблема. При проксировании запросов по https на
самописный бэкенд (написан не нами, доступа к нему нет) первый запрос
проходит успешно, последующие получают 502-ю ошибку. От этого помогла
директива proxy_ssl_session_reuse off. Однако даже с этим осталась
другая проблема - ответы отдаются спустя большое количество времени,
несколько секунд. В то же время, при заходе браузером напрямую на
бэкенд, все отдается сразу. Если поставить Apache между nginx и
бэкендом - тоже всё отдается сразу.
Судя по дебаг-логу (прикладываю), проблема в том, что долго
закрывается соединение с бэкендом.
Помогает отключение proxy_buffering.
Не мог бы кто-нибудь пояснить, верно ли я понял причину задержек. И
если да, то почему соединение с бэкендом так долго закрывается?
Спасибо!
--
Alexey Malov
2011/05/23 13:36:33 [debug] 4666#0: accept on 89.113.17.51:1443, ready: 0
2011/05/23 13:36:33 [debug] 4666#0: malloc: 00000000007019B0:256
2011/05/23 13:36:33 [debug] 4666#0: *106033 accept: 172.27.3.16 fd:3
2011/05/23 13:36:33 [debug] 4666#0: *106033 event timer add: 3:
60000:1306143453458
2011/05/23 13:36:33 [debug] 4666#0: *106033 epoll add event: fd:3 op:1
ev:80000001
2011/05/23 13:36:33 [debug] 4666#0: *106033 malloc: 00000000006D1C60:1288
2011/05/23 13:36:33 [debug] 4666#0: *106033 malloc: 00000000006DE4D0:256
2011/05/23 13:36:33 [debug] 4666#0: *106033 malloc: 000000000070DA00:1024
2011/05/23 13:36:33 [debug] 4666#0: *106033 malloc: 00000000006F8DF0:4096
2011/05/23 13:36:33 [debug] 4666#0: *106033 http check ssl handshake
2011/05/23 13:36:33 [debug] 4666#0: *106033 https ssl handshake: 0x80
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_do_handshake: -1
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_get_error: 2
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL handshake handler: 0
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_do_handshake: 1
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL: TLSv1, cipher:
"DHE-RSA-AES256-SHA SSLv3 Kx=DH Au=RSA Enc=AES(256) Mac=SHA1"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http process request line
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_read: -1
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_get_error: 2
2011/05/23 13:36:33 [debug] 4666#0: *106033 http process request line
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_read: 125
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_read: -1
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_get_error: 2
2011/05/23 13:36:33 [debug] 4666#0: *106033 http request line: "GET / HTTP/1.0"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http uri: "/"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http args: ""
2011/05/23 13:36:33 [debug] 4666#0: *106033 http exten: ""
2011/05/23 13:36:33 [debug] 4666#0: *106033 http process request header line
2011/05/23 13:36:33 [debug] 4666#0: *106033 http header: "User-Agent: Wget/1.12
(linux-gnu)"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http header: "Accept: */*"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http header: "Host:
mt-ntk-proxy.i-free.ru:1443"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http header: "Connection:
Keep-Alive"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http header done
2011/05/23 13:36:33 [debug] 4666#0: *106033 event timer del: 3: 1306143453458
2011/05/23 13:36:33 [debug] 4666#0: *106033 generic phase: 0
2011/05/23 13:36:33 [debug] 4666#0: *106033 add cleanup: 00000000006F9818
2011/05/23 13:36:33 [debug] 4666#0: *106033 generic phase: 1
2011/05/23 13:36:33 [debug] 4666#0: *106033 test location: "/"
2011/05/23 13:36:33 [debug] 4666#0: *106033 using configuration "/"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http cl:-1 max:20971520
2011/05/23 13:36:33 [debug] 4666#0: *106033 generic phase: 3
2011/05/23 13:36:33 [debug] 4666#0: *106033 post rewrite phase: 4
2011/05/23 13:36:33 [debug] 4666#0: *106033 generic phase: 5
2011/05/23 13:36:33 [debug] 4666#0: *106033 add cleanup: 00000000006F9850
2011/05/23 13:36:33 [debug] 4666#0: *106033 generic phase: 6
2011/05/23 13:36:33 [debug] 4666#0: *106033 generic phase: 7
2011/05/23 13:36:33 [debug] 4666#0: *106033 access phase: 8
2011/05/23 13:36:33 [debug] 4666#0: *106033 access: 10031BAC 00FFFFFF 00117159
2011/05/23 13:36:33 [debug] 4666#0: *106033 access: 10031BAC 00FFFFFF 0014A8C0
2011/05/23 13:36:33 [debug] 4666#0: *106033 access: 10031BAC 00FFFFFF 0052A8C0
2011/05/23 13:36:33 [debug] 4666#0: *106033 access: 10031BAC 0000FFFF 00001BAC
2011/05/23 13:36:33 [debug] 4666#0: *106033 access phase: 9
2011/05/23 13:36:33 [debug] 4666#0: *106033 post access phase: 10
2011/05/23 13:36:33 [debug] 4666#0: *106033 http init upstream, client timer: 0
2011/05/23 13:36:33 [debug] 4666#0: *106033 epoll add event: fd:3 op:3
ev:80000005
2011/05/23 13:36:33 [debug] 4666#0: *106033 malloc: 000000000073B520:4096
2011/05/23 13:36:33 [debug] 4666#0: *106033 http script copy: "Host: "
2011/05/23 13:36:33 [debug] 4666#0: *106033 http script var:
"80.243.68.43:50301"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http script copy: "
"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http script copy: "Connection: close
"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http proxy header: "User-Agent:
Wget/1.12 (linux-gnu)"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http proxy header: "Accept: */*"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http proxy header:
"GET / HTTP/1.0
Host: 80.243.68.43:50301
Connection: close
User-Agent: Wget/1.12 (linux-gnu)
Accept: */*
"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http cleanup add: 000000000073B5E8
2011/05/23 13:36:33 [debug] 4666#0: *106033 get rr peer, try: 1
2011/05/23 13:36:33 [debug] 4666#0: *106033 socket 4
2011/05/23 13:36:33 [debug] 4666#0: *106033 epoll add connection: fd:4
ev:80000005
2011/05/23 13:36:33 [debug] 4666#0: *106033 connect to 80.243.68.43:50301, fd:4
#106034
2011/05/23 13:36:33 [debug] 4666#0: *106033 http upstream connect: -2
2011/05/23 13:36:33 [debug] 4666#0: *106033 event timer add: 4:
60000:1306143453495
2011/05/23 13:36:33 [debug] 4666#0: *106033 http run request: "/?"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http upstream check client, write
event:1, "/"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http upstream recv(): -1 (11:
Resource temporarily unavailable)
2011/05/23 13:36:33 [debug] 4666#0: *106033 http upstream request: "/?"
2011/05/23 13:36:33 [debug] 4666#0: *106033 http upstream send request handler
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_do_handshake: -1
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_get_error: 2
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL handshake handler: 0
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_do_handshake: -1
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_get_error: 2
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL handshake handler: 1
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_do_handshake: -1
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_get_error: 2
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL handshake handler: 0
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_do_handshake: -1
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_get_error: 2
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL handshake handler: 1
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_do_handshake: -1
2011/05/23 13:36:33 [debug] 4666#0: *106033 SSL_get_error: 2
2011/05/23 13:36:34 [debug] 4666#0: *106033 SSL handshake handler: 0
2011/05/23 13:36:34 [debug] 4666#0: *106033 SSL_do_handshake: 1
2011/05/23 13:36:34 [debug] 4666#0: *106033 SSL: TLSv1, cipher:
"EDH-RSA-DES-CBC3-SHA SSLv3 Kx=DH Au=RSA Enc=3DES(168) Mac=SHA1"
2011/05/23 13:36:34 [debug] 4666#0: *106033 http upstream send request
2011/05/23 13:36:34 [debug] 4666#0: *106033 chain writer buf fl:1 s:111
2011/05/23 13:36:34 [debug] 4666#0: *106033 chain writer in: 000000000073B658
2011/05/23 13:36:34 [debug] 4666#0: *106033 malloc: 0000000000748960:16384
2011/05/23 13:36:34 [debug] 4666#0: *106033 SSL buf copy: 111
2011/05/23 13:36:34 [debug] 4666#0: *106033 SSL to write: 111
2011/05/23 13:36:34 [debug] 4666#0: *106033 SSL_write: 111
2011/05/23 13:36:34 [debug] 4666#0: *106033 chain writer out: 0000000000000000
2011/05/23 13:36:34 [debug] 4666#0: *106033 event timer del: 4: 1306143453495
2011/05/23 13:36:34 [debug] 4666#0: *106033 event timer add: 4:
60000:1306143454087
2011/05/23 13:36:34 [debug] 4666#0: *106033 http upstream process header
2011/05/23 13:36:34 [debug] 4666#0: *106033 malloc: 0000000000741370:4096
2011/05/23 13:36:34 [debug] 4666#0: *106033 SSL_read: -1
2011/05/23 13:36:34 [debug] 4666#0: *106033 SSL_get_error: 2
2011/05/23 13:36:34 [debug] 4666#0: *106033 http upstream request: "/?"
2011/05/23 13:36:34 [debug] 4666#0: *106033 http upstream send request handler
2011/05/23 13:36:34 [debug] 4666#0: *106033 http upstream send request
2011/05/23 13:36:34 [debug] 4666#0: *106033 chain writer in: 0000000000000000
2011/05/23 13:36:34 [debug] 4666#0: *106033 event timer: 4, old: 1306143454087,
new: 1306143454087
2011/05/23 13:36:34 [debug] 4666#0: *106033 http upstream request: "/?"
2011/05/23 13:36:34 [debug] 4666#0: *106033 http upstream process header
2011/05/23 13:36:34 [debug] 4666#0: *106033 SSL_read: 588
2011/05/23 13:36:34 [debug] 4666#0: *106033 SSL_read: -1
2011/05/23 13:36:34 [debug] 4666#0: *106033 SSL_get_error: 2
2011/05/23 13:36:34 [debug] 4666#0: *106033 http proxy status 200 "200 OK"
2011/05/23 13:36:34 [debug] 4666#0: *106033 http proxy header: "Server:
w5277c_ContentGateWay_v1.1"
2011/05/23 13:36:34 [debug] 4666#0: *106033 http proxy header: "MIME-version:
1.0"
2011/05/23 13:36:34 [debug] 4666#0: *106033 http proxy header: "Connection:
close"
2011/05/23 13:36:34 [debug] 4666#0: *106033 http proxy header: "Content-Length:
450"
2011/05/23 13:36:34 [debug] 4666#0: *106033 http proxy header: "Content-Type:
text/xml"
2011/05/23 13:36:34 [debug] 4666#0: *106033 http proxy header done
2011/05/23 13:36:34 [debug] 4666#0: *106033 HTTP/1.1 200 OK
Server: nginx/0.7.67
Date: Mon, 23 May 2011 09:36:34 GMT
Content-Type: text/xml
Connection: keep-alive
MIME-version: 1.0
Content-Length: 450
2011/05/23 13:36:34 [debug] 4666#0: *106033 write new buf t:1 f:0
000000000073B958, pos 000000000073B958, size: 166 file: 0, size: 0
2011/05/23 13:36:34 [debug] 4666#0: *106033 http write filter: l:0 f:0 s:166
2011/05/23 13:36:34 [debug] 4666#0: *106033 http cacheable: 0
2011/05/23 13:36:34 [debug] 4666#0: *106033 http upstream process upstream
2011/05/23 13:36:34 [debug] 4666#0: *106033 pipe read upstream: 0
2011/05/23 13:36:34 [debug] 4666#0: *106033 pipe preread: 450
2011/05/23 13:36:34 [debug] 4666#0: *106033 pipe buf free s:0 t:1 f:0
0000000000741370, pos 00000000007413FA, size: 450 file: 0, size: 0
2011/05/23 13:36:34 [debug] 4666#0: *106033 pipe write downstream: 1
2011/05/23 13:36:34 [debug] 4666#0: *106033 pipe write busy: 0
2011/05/23 13:36:34 [debug] 4666#0: *106033 pipe write: out:0000000000000000,
f:0
2011/05/23 13:36:34 [debug] 4666#0: *106033 pipe read upstream: 0
2011/05/23 13:36:34 [debug] 4666#0: *106033 pipe buf free s:0 t:1 f:0
0000000000741370, pos 00000000007413FA, size: 450 file: 0, size: 0
2011/05/23 13:36:34 [debug] 4666#0: *106033 event timer: 4, old: 1306143454087,
new: 1306143454218
2011/05/23 13:36:34 [debug] 4666#0: *106033 http upstream request: "/?"
2011/05/23 13:36:34 [debug] 4666#0: *106033 http upstream dummy handler
2011/05/23 13:37:05 [debug] 4666#0: *106033 http upstream request: "/?"
2011/05/23 13:37:05 [debug] 4666#0: *106033 http upstream process upstream
2011/05/23 13:37:05 [debug] 4666#0: *106033 pipe read upstream: 1
2011/05/23 13:37:05 [debug] 4666#0: *106033 SSL_read: 0
2011/05/23 13:37:05 [debug] 4666#0: *106033 SSL_get_error: 5
2011/05/23 13:37:05 [debug] 4666#0: *106033 peer shutdown SSL cleanly
2011/05/23 13:37:05 [debug] 4666#0: *106033 pipe recv chain: 0
2011/05/23 13:37:05 [debug] 4666#0: *106033 pipe buf free s:0 t:1 f:0
0000000000741370, pos 00000000007413FA, size: 450 file: 0, size: 0
2011/05/23 13:37:05 [debug] 4666#0: *106033 input buf #0
2011/05/23 13:37:05 [debug] 4666#0: *106033 pipe write downstream: 1
2011/05/23 13:37:05 [debug] 4666#0: *106033 pipe write downstream flush in
2011/05/23 13:37:05 [debug] 4666#0: *106033 http output filter "/?"
2011/05/23 13:37:05 [debug] 4666#0: *106033 copy filter: "/?"
2011/05/23 13:37:05 [debug] 4666#0: *106033 http postpone filter "/?"
000000000073BB68
2011/05/23 13:37:05 [debug] 4666#0: *106033 write old buf t:1 f:0
000000000073B958, pos 000000000073B958, size: 166 file: 0, size: 0
2011/05/23 13:37:05 [debug] 4666#0: *106033 write new buf t:1 f:0
0000000000741370, pos 00000000007413FA, size: 450 file: 0, size: 0
2011/05/23 13:37:05 [debug] 4666#0: *106033 http write filter: l:0 f:0 s:616
2011/05/23 13:37:05 [debug] 4666#0: *106033 copy filter: 0 "/?"
2011/05/23 13:37:05 [debug] 4666#0: *106033 pipe write downstream done
2011/05/23 13:37:05 [debug] 4666#0: *106033 event timer del: 4: 1306143454087
2011/05/23 13:37:05 [debug] 4666#0: *106033 event timer add: 4:
60000:1306143485081
2011/05/23 13:37:05 [debug] 4666#0: *106033 http upstream exit: 0000000000000000
2011/05/23 13:37:05 [debug] 4666#0: *106033 finalize http upstream request: 0
2011/05/23 13:37:05 [debug] 4666#0: *106033 finalize http proxy request
2011/05/23 13:37:05 [debug] 4666#0: *106033 free rr peer 1 0
2011/05/23 13:37:05 [debug] 4666#0: *106033 SSL_shutdown: 1
2011/05/23 13:37:05 [debug] 4666#0: *106033 close http upstream connection: 4
2011/05/23 13:37:05 [debug] 4666#0: *106033 event timer del: 4: 1306143485081
2011/05/23 13:37:05 [debug] 4666#0: *106033 http upstream temp fd: -1
2011/05/23 13:37:05 [debug] 4666#0: *106033 http output filter "/?"
2011/05/23 13:37:05 [debug] 4666#0: *106033 copy filter: "/?"
2011/05/23 13:37:05 [debug] 4666#0: *106033 http postpone filter "/?"
00007FFF3C2964A0
2011/05/23 13:37:05 [debug] 4666#0: *106033 write old buf t:1 f:0
000000000073B958, pos 000000000073B958, size: 166 file: 0, size: 0
2011/05/23 13:37:05 [debug] 4666#0: *106033 write old buf t:1 f:0
0000000000741370, pos 00000000007413FA, size: 450 file: 0, size: 0
2011/05/23 13:37:05 [debug] 4666#0: *106033 write new buf t:0 f:0
0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2011/05/23 13:37:05 [debug] 4666#0: *106033 http write filter: l:1 f:0 s:616
2011/05/23 13:37:05 [debug] 4666#0: *106033 http write filter limit 0
2011/05/23 13:37:05 [debug] 4666#0: *106033 malloc: 0000000000742380:256
2011/05/23 13:37:05 [debug] 4666#0: *106033 malloc: 0000000000709690:16384
2011/05/23 13:37:05 [debug] 4666#0: *106033 SSL buf copy: 166
2011/05/23 13:37:05 [debug] 4666#0: *106033 SSL buf copy: 450
2011/05/23 13:37:05 [debug] 4666#0: *106033 SSL to write: 616
2011/05/23 13:37:05 [debug] 4666#0: *106033 SSL_write: 616
2011/05/23 13:37:05 [debug] 4666#0: *106033 http write filter 0000000000000000
2011/05/23 13:37:05 [debug] 4666#0: *106033 copy filter: 0 "/?"
2011/05/23 13:37:05 [debug] 4666#0: *106033 http finalize request: 0, "/?" 1
2011/05/23 13:37:05 [debug] 4666#0: *106033 set http keepalive handler
2011/05/23 13:37:05 [debug] 4666#0: *106033 http close request
2011/05/23 13:37:05 [debug] 4666#0: *106033 http log handler
2011/05/23 13:37:05 [debug] 4666#0: *106033 free: 0000000000741370
2011/05/23 13:37:05 [debug] 4666#0: *106033 free: 0000000000748960
2011/05/23 13:37:05 [debug] 4666#0: *106033 free: 00000000006F8DF0, unused: 2
2011/05/23 13:37:05 [debug] 4666#0: *106033 free: 000000000073B520, unused: 2123
2011/05/23 13:37:05 [debug] 4666#0: *106033 event timer add: 3:
120000:1306143545081
2011/05/23 13:37:05 [debug] 4666#0: *106033 free: 00000000006D1C60
2011/05/23 13:37:05 [debug] 4666#0: *106033 free: 000000000070DA00
2011/05/23 13:37:05 [debug] 4666#0: *106033 hc free: 0000000000000000 0
2011/05/23 13:37:05 [debug] 4666#0: *106033 hc busy: 0000000000000000 0
2011/05/23 13:37:05 [debug] 4666#0: *106033 free: 0000000000709690
2011/05/23 13:37:05 [debug] 4666#0: *106033 tcp_nodelay
2011/05/23 13:37:05 [debug] 4666#0: *106033 http keepalive handler
2011/05/23 13:37:05 [debug] 4666#0: *106033 malloc: 000000000070DA00:1024
2011/05/23 13:37:05 [debug] 4666#0: *106033 SSL_read: 0
2011/05/23 13:37:05 [debug] 4666#0: *106033 SSL_get_error: 5
2011/05/23 13:37:05 [debug] 4666#0: *106033 peer shutdown SSL cleanly
2011/05/23 13:37:05 [info] 4666#0: *106033 client 172.27.3.16 closed keepalive
connection
2011/05/23 13:37:05 [debug] 4666#0: *106033 close http connection: 3
2011/05/23 13:37:05 [debug] 4666#0: *106033 SSL_shutdown: 1
2011/05/23 13:37:05 [debug] 4666#0: *106033 event timer del: 3: 1306143545081
2011/05/23 13:37:05 [debug] 4666#0: *106033 free: 000000000070DA00
2011/05/23 13:37:05 [debug] 4666#0: *106033 free: 0000000000000000
2011/05/23 13:37:05 [debug] 4666#0: *106033 free: 0000000000000000
2011/05/23 13:37:05 [debug] 4666#0: *106033 free: 00000000007019B0, unused: 8
2011/05/23 13:37:05 [debug] 4666#0: *106033 free: 00000000006DE4D0, unused: 56
2011/05/23 13:37:05 [debug] 4666#0: *106033 free: 0000000000742380, unused: 144
_______________________________________________
nginx-ru mailing list
nginx-ru@xxxxxxxxx
http://nginx.org/mailman/listinfo/nginx-ru
|
