[size=small]
Hi
I’m seeing some unusual behaviour in one specific client interaction
with nginx and wonder if anyone has seen anything similar or can offer
any explanation as to why this might be happening. I’m running nginx
version 0.7.65.
From a curl command line I’m issuing a POST request to nginx over https.
The POST request has a content-type of multipart/form-data and I’m using
it to send some data and upload a file of just under 1Mb.
nginx is being used as a proxy for upstream web servers built with
mochiweb. Under normal conditions, everything works fine. The file is
uploaded successfully and stored in the back-end database. During
testing I’m deliberately causing a 500 Internal Server Error to be
returned by the upstream web servers to nginx, and this is where I’m
seeing some unusual behaviour.
The 500 status code is indeed returned but there is something strange
going on with the client/nginx/upstream web server interaction. The
whole interaction takes about 10 seconds. Curl rapidly receives the
response headers with the 500 status code but then waits. It never
receives the response body sent by the client - in this case the
content-length is only 200 bytes and the client receives this length in
the Content-Length response header. Curl reports an error code 18,
meaning that it expected a response body of (in this case) 200 bytes but
received less than this (zero in fact as curl reports that the transfer
was closed with 200 bytes remaining to read).
If I reduce the size of the file uploaded by this method, the problem
disappears and curl receives the entire response body just fine. Also,
everything is just fine with other web services where I deliberately
introduce a 500 response code. It’s just for the file upload of a
significantly sized file (about 1Mb) that I see this behaviour.
I know that nginx will receive the file in its entirety and store it in
a temporary location on the server before it talks to the upstream web
server, and it clearly is talking to the upstream web server so it seems
it has received the file completely before it attempts to return the 500
code.
I’ve also bypassed nginx and let curl talk directly to the upstream web
server. In this case, the 500 response is received rapidly and in full
(body intact).
Here’s the interaction as recorded by Curl:
- User-Agent: curl/7.19.5 (i486-pc-linux-gnu) libcurl/7.19.5
OpenSSL/0.9.8g zlib/1.2.3.3 libidn/1.15
- Host: 127.0.0.1
- Accept: /
- Content-Length: 775038
- Expect: 100-continue
- Content-Type: multipart/form-data;
boundary=----------------------------5b3896de4770
-
- HTTP/1.1 100 Continue
- HTTP/1.1 500 Internal Server Error
- Server: nginx/0.7.65
- Date: Fri, 18 Jun 2010 10:31:28 GMT
- Content-Type: text/html
- Connection: keep-alive
- Content-Length: 200
-
- SSLv3, TLS alert, Client hello (1):
- transfer closed with 200 bytes remaining to read
- Closing connection #0
- SSLv3, TLS alert, Client hello (1):
curl: (18) transfer closed with 200 bytes remaining to read
The nginx logs show that a 500 response code was indeed returned, but
the body’s content-length was zero.
This isn’t a showstopper, but it’s behaviour I can’t explain. Can anyone
offer any ideas as to why I might be seeing this?
Thanks!
woodsmar
[/size]
Posted at Nginx Forum:
Hello!
On Fri, Jun 18, 2010 at 07:04:07AM -0400, woodsmar wrote:
mochiweb. Under normal conditions, everything works fine. The file is
content-length is only 200 bytes and the client receives this length in
the Content-Length response header. Curl reports an error code 18,
meaning that it expected a response body of (in this case) 200 bytes but
received less than this (zero in fact as curl reports that the transfer
was closed with 200 bytes remaining to read).
If I reduce the size of the file uploaded by this method, the problem
disappears and curl receives the entire response body just fine. Also,
everything is just fine with other web services where I deliberately
introduce a 500 response code. It’s just for the file upload of a
significantly sized file (about 1Mb) that I see this behaviour.
Please produce debug log. See here for details:
http://wiki.nginx.org/NginxDebugging
If I’m right in my assumption that your backend returns 500 before
actually reading request body - the following patch may help:
diff --git a/src/http/ngx_http_upstream.c b/src/http/ngx_http_upstream.c
— a/src/http/ngx_http_upstream.c
+++ b/src/http/ngx_http_upstream.c
@@ -2003,10 +2003,12 @@ ngx_http_upstream_send_response(ngx_http
u->header_sent = 1;
+#if 0
if (r->request_body && r->request_body->temp_file) {
ngx_pool_run_cleanup_file(r->pool,
r->request_body->temp_file->file.fd);
r->request_body->temp_file->file.fd = NGX_INVALID_FILE;
}
+#endif
clcf = ngx_http_get_module_loc_conf(r, ngx_http_core_module);
Maxim D.
[size=small]
Hi Maxim
Many thanks for your excellent suggestion!
I tried the patch but unfortunately that didn’t work as I still get the
same behaviour. With debugging turned on the following is an excerpt
from the error log:
2010/06/18 13:16:48 [debug] 30676#0: *1 http proxy status 500 “500
Internal Server Error”
2010/06/18 13:16:48 [debug] 30676#0: *1 http proxy header: “Server:
MochiWeb/1.1”
2010/06/18 13:16:48 [debug] 30676#0: *1 http proxy header: “Date: Fri,
18 Jun 2010 12:16:48 GMT”
2010/06/18 13:16:48 [debug] 30676#0: *1 http proxy header:
“Content-Type: text/html”
2010/06/18 13:16:48 [debug] 30676#0: *1 http proxy header:
“Content-Length: 272”
2010/06/18 13:16:48 [debug] 30676#0: *1 http proxy header done
2010/06/18 13:16:48 [debug] 30676#0: *1 HTTP/1.1 500 Internal Server
Error
Server: nginx/0.7.65
Date: Fri, 18 Jun 2010 12:16:48 GMT
Content-Type: text/html
Connection: keep-alive
Content-Length: 272
2010/06/18 13:16:48 [debug] 30676#0: *1 write new buf t:1 f:0 08DAB75C,
pos 08DAB75C, size: 167 file: 0, size: 0
2010/06/18 13:16:48 [debug] 30676#0: *1 http write filter: l:0 f:0
s:167
2010/06/18 13:16:48 [debug] 30676#0: *1 file cleanup: fd:12
2010/06/18 13:16:48 [debug] 30676#0: *1 http cacheable: 0
2010/06/18 13:16:48 [debug] 30676#0: *1 http upstream process upstream
2010/06/18 13:16:48 [debug] 30676#0: *1 pipe read upstream: 1
2010/06/18 13:16:48 [debug] 30676#0: *1 pipe preread: 272
2010/06/18 13:16:48 [debug] 30676#0: *1 readv: 1:3642
2010/06/18 13:16:48 [error] 30676#0: *1 readv() failed (104: Connection
reset by peer) while reading upstream, client: 1
27.0.0.1, server: myserver.com, request: “POST /some/url HTTP/1.1”,
upstream: “http://some/other/url”, host: “127.0.0.1”
2010/06/18 13:16:48 [debug] 30676#0: *1 pipe recv chain: -1
2010/06/18 13:16:48 [debug] 30676#0: *1 pipe write downstream: 1
2010/06/18 13:16:48 [debug] 30676#0: *1 pipe write downstream done
2010/06/18 13:16:48 [debug] 30676#0: *1 event timer add: 13:
60000:1258182058
2010/06/18 13:16:48 [debug] 30676#0: *1 http upstream exit: 00000000
2010/06/18 13:16:48 [debug] 30676#0: *1 finalize http upstream request:
0
2010/06/18 13:16:48 [debug] 30676#0: *1 finalize http proxy request
2010/06/18 13:16:48 [debug] 30676#0: *1 free rr peer 2 0
2010/06/18 13:16:48 [debug] 30676#0: *1 close http upstream connection:
13
2010/06/18 13:16:48 [debug] 30676#0: *1 event timer del: 13: 1258182058
2010/06/18 13:16:48 [debug] 30676#0: *1 event timer del: 13: 1258181956
2010/06/18 13:16:48 [debug] 30676#0: *1 http upstream temp fd: -1
2010/06/18 13:16:48 [debug] 30676#0: *1 http output filter “/some/url”
2010/06/18 13:16:48 [debug] 30676#0: *1 copy filter: “/some/url”
2010/06/18 13:16:48 [debug] 30676#0: *1 http postpone filter “/some/url”
BFAB4798
2010/06/18 13:16:48 [debug] 30676#0: *1 write old buf t:1 f:0 08DAB75C,
pos 08DAB75C, size: 167 file: 0, size: 0
2010/06/18 13:16:48 [debug] 30676#0: *1 write new buf t:0 f:0 00000000,
pos 00000000, size: 0 file: 0, size: 0
There is in fact an error in there - “readv() failed (104: Connection
reset by peer)”. So is this the upstream server closing the connection
before it received the entire body, because it already responded?
[/size]
Posted at Nginx Forum:
Hello!
On Fri, Jun 18, 2010 at 10:25:10AM -0400, woodsmar wrote:
I tried the patch but unfortunately that didn’t work as I still get the
same behaviour. With debugging turned on the following is an excerpt
from the error log:
[…]
2010/06/18 13:16:48 [debug] 30676#0: *1 readv: 1:3642
2010/06/18 13:16:48 [error] 30676#0: *1 readv() failed (104: Connection
reset by peer) while reading upstream, client: 1
27.0.0.1, server: myserver.com, request: “POST /some/url HTTP/1.1”,
upstream: “http://some/other/url”, host: “127.0.0.1”
Backend reseted connection instead of closing it, that’s the
reason why you don’t see reply.
In your particular case nginx actually got full reply but
discarded body as it got error from backend before it was able to
send it. This theoretically may be handled gracefully (and I even
posted patches for this a while ago). But note that with reset
there is a good chance that nginx won’t see data at all as they
will be discarded in socket buffer by OS.
Maxim D.
[size=small]
Ah, I see…That makes a lot of sense!
Many thanks again, Maxim. Your help has been really really useful!
Now I’ll turn my attention to the backend…
Kind regards,
woodsmar
[/size]
Posted at Nginx Forum: