Proxy big file upload issue

elanorsophia · 2014-12-24T00:43:09+00:00

Hello! On Tue, Dec 23, 2014 at 5:41 AM, Vladislav Manchev wrote: > What I'm asking for is mostly some general pointers as to how to go about > this an...

Proxy big file upload issue

elanorsophia

Hey!

I have this interesting issue.. I have a setup that looks like this Nginx < - >Apache.. and when I try to upload files over proxy (nginx) then it gives me: 413 Request Entity Too Large (by nginx).

Here is my config: http://pastebin.com/9t02sPtm

Also Apache and PHP both have 200mb upload limit (upload works perfect there)

It is able to upload tiny files.. like max up to 6kb I think.. but everything bigger than that will get instantly that error.

I have really no idea what's wrong.

I'm using openresty 1.7.4.1

Here's how I installed it:

wget http://openresty.org/download/ngx_openresty-1.7.4.1.tar.gz

tar -zxvf ngx_openresty-1.7.4.1.tar.gz

cd ngx_openresty-1.7.4.1

./configure --with-pcre-jit

make && make install

Any ideas what might be wrong?

Thanks!

agentzh

Hello!

On Tue, Dec 23, 2014 at 8:43 AM, Sophia Elanor wrote:
> I have this interesting issue.. I have a setup that looks like this Nginx <
> - >Apache.. and when I try to upload files over proxy (nginx) then it gives
> me: 413 Request Entity Too Large (by nginx).
>

Do you see anything interesting in your nginx error logs?

BTW, (temporarily) enabling the nginx debugging logs for your test can
be more helpful:

http://nginx.org/en/docs/debugging_log.html

Regards,
-agentzh

elanorsophia

Hey!

Unfortunately there is nothing in error log.. as well in access log. Everything looks completely normal.

On Tuesday, December 23, 2014 9:39:11 PM UTC+2, agentzh wrote:

Hello!

On Tue, Dec 23, 2014 at 8:43 AM, Sophia Elanor wrote:
> I have this interesting issue.. I have a setup that looks like this Nginx <
> - >Apache.. and when I try to upload files over proxy (nginx) then it gives
> me: 413 Request Entity Too Large (by nginx).
>

Do you see anything interesting in your nginx error logs?

BTW, (temporarily) enabling the nginx debugging logs for your test can
be more helpful:

http://nginx.org/en/docs/debugging_log.html

Regards,
-agentzh

agentzh

Hello!

On Tue, Dec 23, 2014 at 11:51 AM, Sophia Elanor wrote:
> Unfortunately there is nothing in error log.. as well in access log.
> Everything looks completely normal.
>

You're not seeing anything in your error log file just because you
have incorrectly configured the error_log directive in your
nginx.conf:

   error_log logs/error.log crit;

Essentially you're hiding all those error messages with the level
lower than "crit", including "alert", "error", "warn", and etc. Better
use "debug" instead of "crit" during debugging.

Also, as I've already suggested, you should (temporarily) rebuild your
OpenResty with --with-debug so that you can see all those "debug"
level error messages in your error.log file, which are usually *a lot*
even for a single request. For obvious performance reasons, debug
builds are discouraged for production use though.

Regards,
-agentzh

elanorsophia

Hey!

I added debug, but I didn't compile.. I'll do it right now. Hopefully it will show something.

Thank you

On Tuesday, December 23, 2014 9:55:08 PM UTC+2, agentzh wrote:

Hello!

On Tue, Dec 23, 2014 at 11:51 AM, Sophia Elanor wrote:
> Unfortunately there is nothing in error log.. as well in access log.
> Everything looks completely normal.
>

You're not seeing anything in your error log file just because you
have incorrectly configured the error_log directive in your
nginx.conf:

error_log logs/error.log crit;

Essentially you're hiding all those error messages with the level
lower than "crit", including "alert", "error", "warn", and etc. Better
use "debug" instead of "crit" during debugging.

Also, as I've already suggested, you should (temporarily) rebuild your
OpenResty with --with-debug so that you can see all those "debug"
level error messages in your error.log file, which are usually *a lot*
even for a single request. For obvious performance reasons, debug
builds are discouraged for production use though.

Regards,
-agentzh

elanorsophia

Interesting thing is that I saw stuff like this:

2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body rest 3337675
2014/12/23 15:11:37 [debug] 16187#0: *59 recv: fd:3 -1 of 2744832
2014/12/23 15:11:37 [debug] 16187#0: *59 recv() not ready (11: Resource temporarily unavailable)
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body recv -2
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body rest 3337675
2014/12/23 15:11:37 [debug] 16187#0: *59 event timer: 3, old: 1419365676923, new: 1419365677040
2014/12/23 15:11:37 [debug] 16187#0: timer delta: 1
2014/12/23 15:11:37 [debug] 16187#0: posted events 0000000000000000
2014/12/23 15:11:37 [debug] 16187#0: worker cycle
2014/12/23 15:11:37 [debug] 16187#0: epoll timer: 4122
2014/12/23 15:11:37 [debug] 16187#0: epoll: fd:3 ev:0001 d:00007FD85CF1D1C0
2014/12/23 15:11:37 [debug] 16187#0: *59 http run request: "/?"
2014/12/23 15:11:37 [debug] 16187#0: *59 http read client request body
2014/12/23 15:11:37 [debug] 16187#0: *59 recv: fd:3 8688 of 2744832
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body recv 8688
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body rest 3337675
2014/12/23 15:11:37 [debug] 16187#0: *59 recv: fd:3 1448 of 2736144
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body recv 1448
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body rest 3337675
2014/12/23 15:11:37 [debug] 16187#0: *59 recv: fd:3 -1 of 2734696
2014/12/23 15:11:37 [debug] 16187#0: *59 recv() not ready (11: Resource temporarily unavailable)
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body recv -2
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body rest 3337675
2014/12/23 15:11:37 [debug] 16187#0: *59 event timer: 3, old: 1419365676923, new: 1419365677043
2014/12/23 15:11:37 [debug] 16187#0: timer delta: 3
2014/12/23 15:11:37 [debug] 16187#0: posted events 0000000000000000
2014/12/23 15:11:37 [debug] 16187#0: worker cycle
2014/12/23 15:11:37 [debug] 16187#0: epoll timer: 4119
2014/12/23 15:11:37 [debug] 16187#0: epoll: fd:3 ev:0001 d:00007FD85CF1D1C0
2014/12/23 15:11:37 [debug] 16187#0: *59 http run request: "/?"
2014/12/23 15:11:37 [debug] 16187#0: *59 http read client request body
2014/12/23 15:11:37 [debug] 16187#0: *59 recv: fd:3 5792 of 2734696
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body recv 5792
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body rest 3337675
2014/12/23 15:11:37 [debug] 16187#0: *59 recv: fd:3 1448 of 2728904
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body recv 1448
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body rest 3337675
2014/12/23 15:11:37 [debug] 16187#0: *59 recv: fd:3 1448 of 2727456
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body recv 1448
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body rest 3337675
2014/12/23 15:11:37 [debug] 16187#0: *59 recv: fd:3 1448 of 2726008
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body recv 1448
2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body rest 3337675

On Tuesday, December 23, 2014 10:01:15 PM UTC+2, Sophia Elanor wrote:

Hey!

I added debug, but I didn't compile.. I'll do it right now. Hopefully it will show something.

Thank you

On Tuesday, December 23, 2014 9:55:08 PM UTC+2, agentzh wrote:
Hello!

On Tue, Dec 23, 2014 at 11:51 AM, Sophia Elanor wrote:
> Unfortunately there is nothing in error log.. as well in access log.
> Everything looks completely normal.
>

You're not seeing anything in your error log file just because you
have incorrectly configured the error_log directive in your
nginx.conf:

error_log logs/error.log crit;

Essentially you're hiding all those error messages with the level
lower than "crit", including "alert", "error", "warn", and etc. Better
use "debug" instead of "crit" during debugging.

Also, as I've already suggested, you should (temporarily) rebuild your
OpenResty with --with-debug so that you can see all those "debug"
level error messages in your error.log file, which are usually *a lot*
even for a single request. For obvious performance reasons, debug
builds are discouraged for production use though.

Regards,
-agentzh

agentzh

Hello!

On Tue, Dec 23, 2014 at 12:16 PM, Sophia Elanor wrote:
> Interesting thing is that I saw stuff like this:
>
> 2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body rest
> 3337675

The debug logs you provided are incomplete and please provide *all*
the logs for your guilty request. And from this snippet I don't see
anything interesting at all.

BTW, to avoid flooding this list, please paste the debug logs
somewhere like pastebin and just share the link here. Thanks for your
cooperation.

Regards,
-agentzh

elanorsophia

Hey!

Here it is: http://pastebin.centos.org/14746/67300141/

On Tuesday, December 23, 2014 10:24:05 PM UTC+2, agentzh wrote:

Hello!

On Tue, Dec 23, 2014 at 12:16 PM, Sophia Elanor wrote:
> Interesting thing is that I saw stuff like this:
>
> 2014/12/23 15:11:37 [debug] 16187#0: *59 http client request body rest
> 3337675

The debug logs you provided are incomplete and please provide *all*
the logs for your guilty request. And from this snippet I don't see
anything interesting at all.

BTW, to avoid flooding this list, please paste the debug logs
somewhere like pastebin and just share the link here. Thanks for your
cooperation.

Regards,
-agentzh

agentzh

Hello!

On Tue, Dec 23, 2014 at 12:41 PM, Sophia Elanor wrote:
> Here it is: http://pastebin.centos.org/14746/67300141/
>

Okay, this is what I need.

Short answer: the 413 response was generated by your backend server
and nginx just forwarded it to the client.

Long answer: the request body was successfully read by nginx, as
evidenced by the following messages:

2014/12/23 15:33:44 [debug] 16238#0: *1 http client request body rest 0
2014/12/23 15:33:44 [debug] 16238#0: *1 event timer del: 3: 1419367004512
2014/12/23 15:33:44 [debug] 16238#0: *1 http init upstream, client timer: 0

We can see that "rest 0" means no unread data left and "http init
upstream" means nginx proceeds to the next step, forwarding the
request (which has been read completely) to the backend server.

The 413 response was from your backend server because of the following
log messages:

2014/12/23 15:33:44 [debug] 16238#0: *1 http proxy status 413 "413
Request Entity Too Large"
2014/12/23 15:33:44 [debug] 16238#0: *1 http proxy header: "Server:
openresty/1.7.4.1"
2014/12/23 15:33:44 [debug] 16238#0: *1 http proxy header: "Date: Tue,
23 Dec 2014 20:35:27 GMT"
2014/12/23 15:33:44 [debug] 16238#0: *1 http proxy header:
"Content-Type: text/html"
2014/12/23 15:33:44 [debug] 16238#0: *1 http proxy header: "Content-Length: 204"
2014/12/23 15:33:44 [debug] 16238#0: *1 http proxy header: "Connection: close"
2014/12/23 15:33:44 [debug] 16238#0: *1 http proxy header done

We can see that 413 was actually received by the proxy (i.e., the
"proxy status" line).

Also, Interestingly the backend server is not Apache as you claimed?
See the "Server: openresty/1.7.4.1" response header received from your
backend server. In addition, from the debug logs, your "proxy_pass"
actually points to 23.235.227.133:80, instead of the 192.168.15.1
address in your nginx.conf pasted in your first email. What's
happening here?

Regards,
-agentzh