Nginx is eating my client request - multipart/form-data file upload

[addis_a]

I am new to nginx, but am familar with low-level HTTP and apache. When I
try to do a multipart/form file upload, nginx writes some of the client
request body to disk, but never finishes and it never passes it to the
down/upstream script.

My specific setup is I have nginx with /dyn redirected to
localhost:1337, where a node.js instance is listening. It works…
except for the file upload handler. Also in the config is a /debug which
is redirected to localhost:1338, which goes to a simple socket dump
server for viewing the post.

I changed the error log handling to ‘info’. It reports storing the
client body to a file and when I examine it, it is almost as I expected:

–boundary_.oOo._MjM5NzEwOTkxMzU2MjA0NjM5MTQxNDA3MjYwOA==
Content-Type: image/jpeg
Content-Disposition: form-data; name=“file”;
filename=“dccde7b5-25aa-4bb2-96a6-81e9358f2252.jpg”

<binary data, supposed to be ~89k>

The problem with this file is too short, only 81,920 bytes (only 80k,
exactly) when the file is 88,963 bytes, it should be 88,963 + the header
above… But that is literally only half of it. There are 2 files
(about the same size, 90k) that are coming in, so I would expect that
file to be about ~180k. What nginx is then doing is reassigning the
request’s http-level Content-length to 357ish bytes then passes that
header on to the script, that’s it and of course my script complains
that it never finds
–boundary_.oOo._MjM5NzEwOTkxMzU2MjA0NjM5MTQxNDA3MjYwOA==

When I do the same request to my debug service without nginx in the
middle, it correctly sends the data, and the http Content-length is an
appropriate 186943 bytes (both files are around 90k, so this makes
sense)

My nginx config is default aside from what I’ve mentioned here. and the
my experimenting to solve this issue:
client_max_body_size 2m;
client_body_in_file_only on;
client_body_in_single_buffer on;
client_body_buffer_size 1m;

I am not trying to have nginx strip the file attachments, I want them
forwarded to the application.

Any help would be appreciated. I’m perplexed as to why the file is
limited to exactly 80k. Nothing is 80k anywhere in nginx.

[Jason_H]

Hello!

On Sun, Dec 14, 2014 at 04:43:51PM +0100, Jason H wrote:

The problem with this file is too short, only 81,920 bytes (only
80k, exactly) when the file is 88,963 bytes, it should be 88,963

• the header above… But that is literally only half of it.

[…]

Could you please provide “nginx -V” output, full config, and a
debugging log for a request which demonstrates the problem?

See Debugging | NGINX for some hints.

–
Maxim D.
http://nginx.org/

[Jason_H]

As requested. 100k debug log attached. I didn’t see anything obviously
wrong in the log.

Thanks for your help.

nginx -V: --------------------------------
nginx version: nginx/1.6.2
built by gcc 4.8.2 20140120 (Red Hat 4.8.2-16) (GCC)
TLS SNI support enabled
configure arguments: --prefix=/usr/share/nginx
–sbin-path=/usr/sbin/nginx --conf-path=/etc/nginx/nginx.conf
–error-log-path=/var/log/nginx/error.log
–http-log-path=/var/log/nginx/access.log
–http-client-body-temp-path=/var/lib/nginx/tmp/client_body
–http-proxy-temp-path=/var/lib/nginx/tmp/proxy
–http-fastcgi-temp-path=/var/lib/nginx/tmp/fastcgi
–http-uwsgi-temp-path=/var/lib/nginx/tmp/uwsgi
–http-scgi-temp-path=/var/lib/nginx/tmp/scgi
–pid-path=/var/run/nginx.pid --lock-path=/var/lock/subsys/nginx
–user=nginx --group=nginx --with-file-aio --with-ipv6
–with-http_ssl_module --with-http_spdy_module --with-http_realip_module
–with-http_addition_module --with-http_xslt_module
–with-http_image_filter_module --with-http_geoip_module
–with-http_sub_module --with-http_dav_module --with-http_flv_module
–with-http_mp4_module --with-http_gunzip_module
–with-http_gzip_static_module --with-http_random_index_module
–with-http_secure_link_module --with-http_degradation_module
–with-http_stub_status_module --with-http_perl_module --with-mail
–with-mail_ssl_module --with-pcre --with-google_perftools_module
–with-debug --with-cc-opt=’-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2
-fexceptions -fstack-protector --param=ssp-buffer-size=4 -m64
-mtune=generic’ --with-ld-opt=’ -Wl,-E’
----------------end output

nginx.conf:------------------------------
user nginx;
worker_processes 1;

error_log /var/log/nginx/error.log info;
pid /var/run/nginx.pid;
events {
worker_connections 1024;
}
http {
include /etc/nginx/mime.types;
default_type application/octet-stream;
log_format main '$remote_addr - $remote_user [$time_local]
“$request” ’
'$status $body_bytes_sent “$http_referer” ’
‘"$http_user_agent" “$http_x_forwarded_for”’;
access_log /var/log/nginx/access.log main;
sendfile on;
keepalive_timeout 65;
include /etc/nginx/conf.d/*.conf;
index index.html index.htm;

issue testing

client_max_body_size 2m;
client_body_in_file_only on;
client_body_in_single_buffer on;
client_body_buffer_size 1m;

end issue testing

server {
    listen       80;
    server_name  dev.tissue-analytics.com localhost;
    root         /usr/share/nginx/html;
    location / {
  root /data/www;
    }
    location /dyn {
  proxy_pass  http://127.0.0.1:1337;
    }
    location /debug {
  proxy_pass  http://127.0.0.1:1338;
    }
    error_page  404              /404.html;
    location = /40x.html {
    }
    error_page   500 502 503 504  /50x.html;
    location = /50x.html {
    }
}

}
------------------ end conf

[Jason_H]

Hello!

On Mon, Dec 15, 2014 at 04:21:07PM +0100, Jason H wrote:

As requested. 100k debug log attached. I didn’t see anything obviously wrong in
the log.

Some comments about the log below.

[…]

2014/12/15 15:10:37 [debug] 21192#0: *10 http header: “Accept-Encoding: gzip,
deflate”
2014/12/15 15:10:37 [debug] 21192#0: 10 http header: "Accept-Language: en-US,"
2014/12/15 15:10:37 [debug] 21192#0: *10 http header: “User-Agent: Mozilla/5.0”
2014/12/15 15:10:37 [debug] 21192#0: *10 http header: “Host:
dev.tissue-analytics.com”
2014/12/15 15:10:37 [debug] 21192#0: *10 http header done

Good so far, Content-Length is 216619 bytes.

[…]

2014/12/15 15:10:37 [debug] 21192#0: *10 http request body content length filter
2014/12/15 15:10:37 [debug] 21192#0: *10 malloc: 0000000000E7E610:216619
2014/12/15 15:10:37 [debug] 21192#0: *10 http read client request body
2014/12/15 15:10:37 [debug] 21192#0: *10 recv: fd:10 -1 of 216619
2014/12/15 15:10:37 [debug] 21192#0: *10 recv() not ready (11: Resource
temporarily unavailable)
2014/12/15 15:10:37 [debug] 21192#0: *10 http client request body recv -2
2014/12/15 15:10:37 [debug] 21192#0: *10 http client request body rest 216619
2014/12/15 15:10:37 [debug] 21192#0: *10 event timer add: 10:
60000:1418656297413
2014/12/15 15:10:37 [debug] 21192#0: *10 http finalize request: -4,
“/debug/visit/files?” a:1, c:2

Here nginx started reading the request body.

[…]

2014/12/15 15:10:37 [debug] 21192#0: *10 http run request: “/debug/visit/files?”
2014/12/15 15:10:37 [debug] 21192#0: *10 http read client request body
2014/12/15 15:10:37 [debug] 21192#0: *10 recv: fd:10 1424 of 216619
2014/12/15 15:10:37 [debug] 21192#0: *10 http client request body recv 1424
2014/12/15 15:10:37 [debug] 21192#0: *10 http client request body rest 216619

First 1424 bytes received.

[…]

2014/12/15 15:10:38 [debug] 21192#0: epoll timer: 58359
2014/12/15 15:10:38 [debug] 21192#0: epoll: fd:10 ev:0001 d:00007F5631AD21C1
2014/12/15 15:10:38 [debug] 21192#0: *10 http run request: “/debug/visit/files?”
2014/12/15 15:10:38 [debug] 21192#0: *10 http read client request body
2014/12/15 15:10:38 [debug] 21192#0: *10 recv: fd:10 944 of 119259
2014/12/15 15:10:38 [debug] 21192#0: *10 http client request body recv 944
2014/12/15 15:10:38 [debug] 21192#0: *10 http client request body rest 216619

And here is the last successful recv(), of 944 bytes. Counting
all the recvs in total, nginx was able to recieve 98304 bytes of
the body.

2014/12/15 15:10:38 [debug] 21192#0: *10 recv: fd:10 -1 of 118315
2014/12/15 15:10:38 [debug] 21192#0: *10 recv() not ready (11: Resource
temporarily unavailable)
2014/12/15 15:10:38 [debug] 21192#0: *10 http client request body recv -2
2014/12/15 15:10:38 [debug] 21192#0: *10 http client request body rest 216619
2014/12/15 15:10:38 [debug] 21192#0: *10 event timer: 10, old: 1418656298021,
new: 1418656298162
2014/12/15 15:10:38 [debug] 21192#0: timer delta: 6
2014/12/15 15:10:38 [debug] 21192#0: posted events 0000000000000000
2014/12/15 15:10:38 [debug] 21192#0: worker cycle
2014/12/15 15:10:38 [debug] 21192#0: epoll timer: 58353

As expected, nginx still tries to read the rest of the body,
118315 bytes.

[…]

2014/12/15 15:11:38 [debug] 21192#0: timer delta: 1450
2014/12/15 15:11:38 [debug] 21192#0: *10 event timer del: 10: 1418656298021
2014/12/15 15:11:38 [debug] 21192#0: *10 http run request: “/debug/visit/files?”
2014/12/15 15:11:38 [debug] 21192#0: *10 http finalize request: 408,
“/debug/visit/files?” a:1, c:1

The client_body_timeout is triggered and the connection is closed.

That is, from nginx point of view the client failed to send the
request and unexpectedly stopped at some point. It’s not clear
why this happened, but undersized last packet suggests that it’s
the client’s fault.

–
Maxim D.
http://nginx.org/