Can't upload big files via nginx as reverse proxy

[Maxim Dounin]

Hello!

On Tue, Jun 05, 2012 at 06:08:30AM -0400, speedfirst wrote:

[...]

> 2012/06/06 01:27:37 [debug] 15621#0: *5 http read client request body
> 2012/06/06 01:27:37 [debug] 15621#0: *5 http client request body recv
> 1528
> 2012/06/06 01:27:37 [debug] 15621#0: *5 http client request body rest 0

Ok, so the request body is read from a client without any problems.

[...]

> 2012/06/06 01:27:37 [debug] 15621#0: *5 zmauth: prepare route for proxy
> ... ..<-- choose the upstream route
> 2012/06/06 01:27:37 [debug] 15621#0: *5 zmauth: prepare upstream
> connection, try: 1

Are you able to reproduce the problem without 3rd party 
modules/patches?  (Unlikely it's related in this particular case, 
but just to make sure.)

> 2012/06/06 01:27:37 [debug] 15621#0: *5 http upstream connect: -2
> 2012/06/06 01:27:37 [debug] 15621#0: *5 http upstream request:
> "/service/home/admin at dev03.test.com/?fmt=tgz&resolve=reset"
> 2012/06/06 01:27:37 [debug] 15621#0: *5 http upstream send request
> handler
> 2012/06/06 01:27:37 [debug] 15621#0: *5 http upstream send request
> 2012/06/06 01:27:37 [debug] 15621#0: *5 http upstream request:
> "/service/home/admin at dev03.test.com/?fmt=tgz&resolve=reset"
> 2012/06/06 01:27:37 [debug] 15621#0: *5 http upstream send request
> handler
> 2012/06/06 01:27:37 [debug] 15621#0: *5 http upstream send request
> 2012/06/06 01:27:40 [debug] 15621#0: *5 http upstream request:
> "/service/home/admin at dev03.test.com/?fmt=tgz&resolve=reset"
> 2012/06/06 01:27:40 [debug] 15621#0: *5 http upstream send request
> handler
> 2012/06/06 01:27:40 [debug] 15621#0: *5 http upstream send request
> 2012/06/06 01:27:44 [debug] 15621#0: *5 http upstream request:
> "/service/home/admin at dev03.test.com/?fmt=tgz&resolve=reset"
> ... ... <--- tens of similar log entires

It's sad you skipped them all, and only did debug_http log.  With 
full debug log it would be clearly visible sending request goes on 
(i.e. how many bytes are sent).

> 2012/06/06 01:28:19 [debug] 15621#0: *5 http upstream send request
> handler
> 2012/06/06 01:28:19 [debug] 15621#0: *5 http upstream send request
> 2012/06/06 01:28:22 [debug] 15621#0: *5 http upstream request:
> "/service/home/admin at dev03.test.com/?fmt=tgz&resolve=reset"
> 2012/06/06 01:28:22 [debug] 15621#0: *5 http upstream send request
> handler
> 2012/06/06 01:28:22 [debug] 15621#0: *5 http upstream send request
> 2012/06/06 01:28:22 [debug] 15621#0: *5 http upstream request:
> "/service/home/admin at dev03.test.com/?fmt=tgz&resolve=reset"
> 2012/06/06 01:28:22 [debug] 15621#0: *5 http upstream process header
> 2012/06/06 01:28:22 [debug] 15621#0: *5 http proxy status 200 "200 OK"

On the other hand, it looks like sending of the request is still 
in progress, and upstream server replies before the request was 
completely sent.  It might indicate it just doesn't wait long 
enough, and the problem is in the backend (and slow connectivity 
to the backend).

I don't see any pause in request sending you've claimed in your 
initial message.

(and see below)

> 2012/06/06 01:28:22 [debug] 15621#0: *5 http proxy header: "Date: Tue,
> 05 Jun 2012 17:27:37 GMT"
> 2012/06/06 01:28:22 [debug] 15621#0: *5 http proxy header:
> "Content-Type: text/html; charset=utf-8"
> 2012/06/06 01:28:22 [debug] 15621#0: *5 http proxy header: "Connection:
> close"
> 2012/06/06 01:28:22 [debug] 15621#0: *5 http proxy header done
> 2012/06/06 01:28:22 [debug] 15621#0: *5 HTTP/1.1 200 OK
> 
> Server: nginx
> 
> Date: Tue, 05 Jun 2012 17:28:22 GMT
> 
> Content-Type: text/html; charset=utf-8
> 
> Transfer-Encoding: chunked
> 
> Connection: keep-alive
> 
> 
> 2012/06/06 01:28:22 [debug] 15621#0: *5 http write filter: l:0 f:0
> s:163
> 2012/06/06 01:28:22 [debug] 15621#0: *5 http cacheable: 0
> 2012/06/06 01:28:22 [debug] 15621#0: *5 http upstream process upstream
> 2012/06/06 01:28:23 [debug] 15621#0: *5 http upstream request:
> "/service/home/admin at dev03.test.com/?fmt=tgz&resolve=reset"
> 2012/06/06 01:28:23 [debug] 15621#0: *5 http upstream send request
> handler
> 2012/06/06 01:28:57 [debug] 15621#0: *5 http upstream request:
> "/service/home/admin at dev03.test.com/?fmt=tgz&resolve=reset"

On the other hand, here is ~ 30s pause you've probably talked 
about.  It might indicate that upstream tries to send headers 
before "receiving and interpreting a request message" (as per HTTP 
RFC2616 it should do it "after"), which confuses nginx and makes 
it to think further body bytes aren't needed.

You may want to dig further into what goes on on the backend to 
understand the real problem.

Maxim Dounin