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@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@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@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@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@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@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@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@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

_______________________________________________
nginx mailing list
nginx@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx