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

[Maxim Dounin]

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 process request line
> 2014/12/15 15:10:37 [debug] 21192#0: *10 http request line: "POST /debug/visit/files HTTP/1.1"
> 2014/12/15 15:10:37 [debug] 21192#0: *10 http uri: "/debug/visit/files"
> 2014/12/15 15:10:37 [debug] 21192#0: *10 http args: ""
> 2014/12/15 15:10:37 [debug] 21192#0: *10 http exten: ""
> 2014/12/15 15:10:37 [debug] 21192#0: *10 http process request header line
> 2014/12/15 15:10:37 [debug] 21192#0: *10 http header: "Content-Type: multipart/form-data; boundary="boundary_.oOo._MTMyNDQwMjY1MA==MTgwNjg0NzQyMQ==MTM2OTc5MjA=""
> 2014/12/15 15:10:37 [debug] 21192#0: *10 http header: "MIME-Version: 1.0"
> 2014/12/15 15:10:37 [debug] 21192#0: *10 http header: "Content-Length: 216619"
> 2014/12/15 15:10:37 [debug] 21192#0: *10 http header: "Connection: Keep-Alive"
> 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 Dounin
http://nginx.org/