NginX doesn't close the connection

Question

I have a BE webservice which returns a wsdl, When I access it directly it loads without a issue, But when I access the same through NginX it takes longer time to load(aroung 5-6 mins). When I analyze this it seems although the Server is sending all the data to client the server/NginX is not closing the connection hence the browser is unable to render the content. The Backend server always send the Full response to NginX but NginX doesn't sent everything to client. It seems NginX is waiting for more? Following are some curl out puts.

Direct Call to BE (Request and Response Headers)

> GET /services/echo?wsdl HTTP/1.1
> Host: 172.30.16.47:8280
> User-Agent: curl/7.51.0
> Accept: */*
> 
< HTTP/1.1 200 OK
< Content-Type: text/xml
< Date: Wed, 11 Jan 2017 08:32:35 GMT
< Transfer-Encoding: chunked

Call through Nginx (Request and response)

> GET /services/echo?wsdl HTTP/1.1
> Host: xx.xx.service.xx.gov.yy
> User-Agent: curl/7.51.0
> Accept: */*
> 
< HTTP/1.1 200 OK
< Server: nginx/1.10.0 (Ubuntu)
< Date: Wed, 11 Jan 2017 08:33:10 GMT
< Content-Type: text/xml
< Transfer-Encoding: chunked
< Connection: close

Following are the Debug logs from NginX.

2017/01/11 19:36:32 [debug] 9258#0: accept on 0.0.0.0:80, ready: 0
2017/01/11 19:36:32 [debug] 9262#0: accept on 0.0.0.0:80, ready: 0
2017/01/11 19:36:32 [debug] 9264#0: accept on 0.0.0.0:80, ready: 0
2017/01/11 19:36:32 [debug] 9265#0: accept on 0.0.0.0:80, ready: 0
2017/01/11 19:36:32 [debug] 9259#0: accept on 0.0.0.0:80, ready: 0
2017/01/11 19:36:32 [debug] 9261#0: accept on 0.0.0.0:80, ready: 0
2017/01/11 19:36:32 [debug] 9263#0: accept on 0.0.0.0:80, ready: 0
2017/01/11 19:36:32 [debug] 9258#0: posix_memalign: 000056056AF30BB0:512 @16
2017/01/11 19:36:32 [debug] 9262#0: accept() not ready (11: Resource temporarily unavailable)
2017/01/11 19:36:32 [debug] 9264#0: accept() not ready (11: Resource temporarily unavailable)
2017/01/11 19:36:32 [debug] 9265#0: accept() not ready (11: Resource temporarily unavailable)
2017/01/11 19:36:32 [debug] 9259#0: accept() not ready (11: Resource temporarily unavailable)
2017/01/11 19:36:32 [debug] 9261#0: accept() not ready (11: Resource temporarily unavailable)
2017/01/11 19:36:32 [debug] 9258#0: *5 accept: 172.16.8.2:26355 fd:18
2017/01/11 19:36:32 [debug] 9263#0: accept() not ready (11: Resource temporarily unavailable)
2017/01/11 19:36:32 [debug] 9258#0: *5 event timer add: 18: 60000:1484141852366
2017/01/11 19:36:32 [debug] 9258#0: *5 reusable connection: 1
2017/01/11 19:36:32 [debug] 9258#0: *5 epoll add event: fd:18 op:1 ev:80002001
2017/01/11 19:36:32 [debug] 9258#0: *5 http wait request handler
2017/01/11 19:36:32 [debug] 9258#0: *5 malloc: 000056056AF30DC0:1024
2017/01/11 19:36:32 [debug] 9258#0: *5 recv: eof:0, avail:1
2017/01/11 19:36:32 [debug] 9258#0: *5 recv: fd:18 122 of 1024
2017/01/11 19:36:32 [debug] 9258#0: *5 reusable connection: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 posix_memalign: 000056056AEB3F10:4096 @16
2017/01/11 19:36:32 [debug] 9258#0: *5 http process request line
2017/01/11 19:36:32 [debug] 9258#0: *5 http request line: "GET /services/Test_property?wsdl HTTP/1.1"
2017/01/11 19:36:32 [debug] 9258#0: *5 http uri: "/services/Test_property"
2017/01/11 19:36:32 [debug] 9258#0: *5 http args: "wsdl"
2017/01/11 19:36:32 [debug] 9258#0: *5 http exten: ""
2017/01/11 19:36:32 [debug] 9258#0: *5 http process request header line
2017/01/11 19:36:32 [debug] 9258#0: *5 http header: "Host: xxx.esb.service.yyy.gov.zzz"
2017/01/11 19:36:32 [debug] 9258#0: *5 posix_memalign: 000056056AF20990:4096 @16
2017/01/11 19:36:32 [debug] 9258#0: *5 http header: "User-Agent: curl/7.51.0"
2017/01/11 19:36:32 [debug] 9258#0: *5 http header: "Accept: */*"
2017/01/11 19:36:32 [debug] 9258#0: *5 http header done
2017/01/11 19:36:32 [debug] 9258#0: *5 event timer del: 18: 1484141852366
2017/01/11 19:36:32 [debug] 9258#0: *5 generic phase: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 rewrite phase: 1
2017/01/11 19:36:32 [debug] 9258#0: *5 test location: "/"
2017/01/11 19:36:32 [debug] 9258#0: *5 using configuration "/"
2017/01/11 19:36:32 [debug] 9258#0: *5 http cl:-1 max:1048576
2017/01/11 19:36:32 [debug] 9258#0: *5 rewrite phase: 3
2017/01/11 19:36:32 [debug] 9258#0: *5 post rewrite phase: 4
2017/01/11 19:36:32 [debug] 9258#0: *5 generic phase: 5
2017/01/11 19:36:32 [debug] 9258#0: *5 generic phase: 6
2017/01/11 19:36:32 [debug] 9258#0: *5 generic phase: 7
2017/01/11 19:36:32 [debug] 9258#0: *5 access phase: 8
2017/01/11 19:36:32 [debug] 9258#0: *5 access phase: 9
2017/01/11 19:36:32 [debug] 9258#0: *5 access phase: 10
2017/01/11 19:36:32 [debug] 9258#0: *5 post access phase: 11
2017/01/11 19:36:32 [debug] 9258#0: *5 try files phase: 12
2017/01/11 19:36:32 [debug] 9258#0: *5 http init upstream, client timer: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 epoll add event: fd:18 op:3 ev:80002005
2017/01/11 19:36:32 [debug] 9258#0: *5 http script copy: "X-Forwarded-Host: "
2017/01/11 19:36:32 [debug] 9258#0: *5 http script var: "xxx.yyy.service.xxx.gov.zzz"
2017/01/11 19:36:32 [debug] 9258#0: *5 http script copy: "
"
2017/01/11 19:36:32 [debug] 9258#0: *5 http script copy: "X-Forwarded-Server: "
2017/01/11 19:36:32 [debug] 9258#0: *5 http script var: "xxx.yyy.service.xxx.gov.zzz"
2017/01/11 19:36:32 [debug] 9258#0: *5 http script copy: "
"
2017/01/11 19:36:32 [debug] 9258#0: *5 http script copy: "X-Forwarded-For: "
2017/01/11 19:36:32 [debug] 9258#0: *5 http script var: "172.16.8.2"
2017/01/11 19:36:32 [debug] 9258#0: *5 http script copy: "
"
2017/01/11 19:36:32 [debug] 9258#0: *5 http script copy: "Host: "
2017/01/11 19:36:32 [debug] 9258#0: *5 http script var: "xxx.esb.service.yyy.gov.zzz"
2017/01/11 19:36:32 [debug] 9258#0: *5 http script copy: "
"
2017/01/11 19:36:32 [debug] 9258#0: *5 http script copy: "Connection: close
"
2017/01/11 19:36:32 [debug] 9258#0: *5 http script copy: ""
2017/01/11 19:36:32 [debug] 9258#0: *5 http script copy: ""
2017/01/11 19:36:32 [debug] 9258#0: *5 http script copy: ""
2017/01/11 19:36:32 [debug] 9258#0: *5 http script copy: ""
2017/01/11 19:36:32 [debug] 9258#0: *5 http proxy header: "User-Agent: curl/7.51.0"
2017/01/11 19:36:32 [debug] 9258#0: *5 http proxy header: "Accept: */*"
2017/01/11 19:36:32 [debug] 9258#0: *5 http proxy header:
"GET /services/Test_property?wsdl HTTP/1.0
X-Forwarded-Host: xxx.esb.service.yyy.gov.zzz
X-Forwarded-Server: xxx.esb.service.yyy.gov.zzz
X-Forwarded-For: 172.16.8.2
Host: xxx.esb.service.yyy.gov.zzz
Connection: close
User-Agent: curl/7.51.0
Accept: */*

"
2017/01/11 19:36:32 [debug] 9258#0: *5 http cleanup add: 000056056AF211F0
2017/01/11 19:36:32 [debug] 9258#0: *5 get rr peer, try: 2
2017/01/11 19:36:32 [debug] 9258#0: *5 get rr peer, current: 000056056AF00070 0
2017/01/11 19:36:32 [debug] 9258#0: *5 stream socket 19
2017/01/11 19:36:32 [debug] 9258#0: *5 epoll add connection: fd:19 ev:80002005
2017/01/11 19:36:32 [debug] 9258#0: *5 connect to 172.30.16.47:8280, fd:19 #6
2017/01/11 19:36:32 [debug] 9258#0: *5 http upstream connect: -2
2017/01/11 19:36:32 [debug] 9258#0: *5 posix_memalign: 000056056AF30300:128 @16
2017/01/11 19:36:32 [debug] 9258#0: *5 event timer add: 19: 60000:1484141852368
2017/01/11 19:36:32 [debug] 9258#0: *5 http finalize request: -4, "/services/Test_property?wsdl" a:1, c:2
2017/01/11 19:36:32 [debug] 9258#0: *5 http request count:2 blk:0
2017/01/11 19:36:32 [debug] 9258#0: *5 http run request: "/services/Test_property?wsdl"
2017/01/11 19:36:32 [debug] 9258#0: *5 http upstream check client, write event:1, "/services/Test_property"
2017/01/11 19:36:32 [debug] 9258#0: *5 http upstream request: "/services/Test_property?wsdl"
2017/01/11 19:36:32 [debug] 9258#0: *5 http upstream send request handler
2017/01/11 19:36:32 [debug] 9258#0: *5 http upstream send request
2017/01/11 19:36:32 [debug] 9258#0: *5 http upstream send request body
2017/01/11 19:36:32 [debug] 9258#0: *5 chain writer buf fl:1 s:274
2017/01/11 19:36:32 [debug] 9258#0: *5 chain writer in: 000056056AF21230
2017/01/11 19:36:32 [debug] 9258#0: *5 writev: 274 of 274
2017/01/11 19:36:32 [debug] 9258#0: *5 chain writer out: 0000000000000000
2017/01/11 19:36:32 [debug] 9258#0: *5 event timer del: 19: 1484141852368
2017/01/11 19:36:32 [debug] 9258#0: *5 event timer add: 19: 300000:1484142092368
2017/01/11 19:36:32 [debug] 9258#0: *5 http upstream request: "/services/Test_property?wsdl"
2017/01/11 19:36:32 [debug] 9258#0: *5 http upstream process header
2017/01/11 19:36:32 [debug] 9258#0: *5 malloc: 000056056AF219A0:4096
2017/01/11 19:36:32 [debug] 9258#0: *5 recv: eof:0, avail:1
2017/01/11 19:36:32 [debug] 9258#0: *5 recv: fd:19 4096 of 4096
2017/01/11 19:36:32 [debug] 9258#0: *5 http proxy status 200 "200 OK"
2017/01/11 19:36:32 [debug] 9258#0: *5 http proxy header: "Content-Type: text/xml"
2017/01/11 19:36:32 [debug] 9258#0: *5 http proxy header: "Date: Wed, 11 Jan 2017 13:36:32 GMT"
2017/01/11 19:36:32 [debug] 9258#0: *5 http proxy header: "Connection: Close"
2017/01/11 19:36:32 [debug] 9258#0: *5 http proxy header done
2017/01/11 19:36:32 [debug] 9258#0: *5 xslt filter header
2017/01/11 19:36:32 [debug] 9258#0: *5 HTTP/1.1 200 OK
Server: nginx/1.11.8
Date: Wed, 11 Jan 2017 13:36:32 GMT
Content-Type: text/xml
Transfer-Encoding: chunked
Connection: keep-alive

2017/01/11 19:36:32 [debug] 9258#0: *5 write new buf t:1 f:0 000056056AF214A8, pos 000056056AF214A8, size: 154 file: 0, size: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 http write filter: l:0 f:0 s:154
2017/01/11 19:36:32 [debug] 9258#0: *5 http cacheable: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 http proxy filter init s:200 h:0 c:0 l:-1
2017/01/11 19:36:32 [debug] 9258#0: *5 http upstream process upstream
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe read upstream: 1
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe preread: 3997
2017/01/11 19:36:32 [debug] 9258#0: *5 input buf #0
2017/01/11 19:36:32 [debug] 9258#0: *5 malloc: 000056056AF229B0:4096
2017/01/11 19:36:32 [debug] 9258#0: *5 readv: eof:0, avail:1
2017/01/11 19:36:32 [debug] 9258#0: *5 readv: 1, last:4096
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe recv chain: 561
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe buf in   s:1 t:1 f:0 000056056AF219A0, pos 000056056AF21A03, size: 3997 file: 0, size: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe buf free s:0 t:1 f:0 000056056AF229B0, pos 000056056AF229B0, size: 561 file: 0, size: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe length: -1
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe write downstream: 1
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe write busy: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe write buf ls:1 000056056AF21A03 3997
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe write: out:000056056AF21650, f:0
2017/01/11 19:36:32 [debug] 9258#0: *5 http output filter "/services/Test_property?wsdl"
2017/01/11 19:36:32 [debug] 9258#0: *5 http copy filter: "/services/Test_property?wsdl"
2017/01/11 19:36:32 [debug] 9258#0: *5 image filter
2017/01/11 19:36:32 [debug] 9258#0: *5 xslt filter body
2017/01/11 19:36:32 [debug] 9258#0: *5 http postpone filter "/services/Test_property?wsdl" 000056056AF21650
2017/01/11 19:36:32 [debug] 9258#0: *5 http chunk: 3997
2017/01/11 19:36:32 [debug] 9258#0: *5 write old buf t:1 f:0 000056056AF214A8, pos 000056056AF214A8, size: 154 file: 0, size: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 write new buf t:1 f:0 000056056AF217E8, pos 000056056AF217E8, size: 5 file: 0, size: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 write new buf t:1 f:0 000056056AF219A0, pos 000056056AF21A03, size: 3997 file: 0, size: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 write new buf t:0 f:0 0000000000000000, pos 000056056A20868A, size: 2 file: 0, size: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 http write filter: l:0 f:1 s:4158
2017/01/11 19:36:32 [debug] 9258#0: *5 http write filter limit 0
2017/01/11 19:36:32 [debug] 9258#0: *5 writev: 4158 of 4158
2017/01/11 19:36:32 [debug] 9258#0: *5 http write filter 0000000000000000
2017/01/11 19:36:32 [debug] 9258#0: *5 http copy filter: 0 "/services/Test_property?wsdl"
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe write busy: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe write: out:0000000000000000, f:0
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe read upstream: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe buf free s:0 t:1 f:0 000056056AF229B0, pos 000056056AF229B0, size: 561 file: 0, size: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe buf free s:0 t:1 f:0 000056056AF219A0, pos 000056056AF219A0, size: 0 file: 0, size: 0
2017/01/11 19:36:32 [debug] 9258#0: *5 pipe length: -1
2017/01/11 19:36:32 [debug] 9258#0: *5 event timer: 19, old: 1484142092368, new: 1484142092387
2017/01/11 19:36:32 [debug] 9258#0: *5 http upstream request: "/services/Test_property?wsdl"
2017/01/11 19:36:32 [debug] 9258#0: *5 http upstream dummy handler

What I have tried

I tried removing the Connection Keep-alive property. But with no luck. Disabled BE server side connection keep-alive.

Nothing worked for me. Does anyone have a idea whats going on here?

Answer 1

I got the issue solved. It seems that my BE Server is sending Non Chunked Responses by default (Using HTTP 1.0). So Forcing BE to use HTTP 1.1 solved the issue. I used the following property in Nginx.

proxy_http_version 1.1;