auth_request called multiple times for same single request

[garyc]

Hello, thanks for explaining, can I ask, in the 5MB scenario (client
accepted 413 response) the logs show:

2017/09/21 12:06:41 [debug] 21560#0: *1 http run request:
"/pcapLowDiskSpace.html?"
2017/09/21 12:06:41 [debug] 21560#0: *1 http read discarded body
2017/09/21 12:06:41 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:41 [debug] 21560#0: *1 recv: fd:3 2159 of 2159
2017/09/21 12:06:41 [debug] 21560#0: *1 http finalize request: -4,
"/pcapLowDiskSpace.html?" a:1, c:1
2017/09/21 12:06:41 [debug] 21560#0: *1 set http keepalive handler
2017/09/21 12:06:41 [debug] 21560#0: *1 http close request

2017/09/21 12:06:41 [debug] 21560#0: *1 http log handler
2017/09/21 12:06:41 [debug] 21560#0: *1 run cleanup: 0000000001904FA0
2017/09/21 12:06:41 [debug] 21560#0: *1 file cleanup: fd:21
2017/09/21 12:06:41 [debug] 21560#0: *1 free: 00000000019057E0
2017/09/21 12:06:41 [debug] 21560#0: *1 free: 00000000018B2E20, unused: 4
2017/09/21 12:06:41 [debug] 21560#0: *1 free: 00000000019037C0, unused: 3
2017/09/21 12:06:41 [debug] 21560#0: *1 free: 00000000019047D0, unused:
1304
2017/09/21 12:06:41 [debug] 21560#0: *1 free: 00000000018B4450
2017/09/21 12:06:41 [debug] 21560#0: *1 hc free: 0000000000000000
2017/09/21 12:06:41 [debug] 21560#0: *1 hc busy: 0000000000000000 0
2017/09/21 12:06:41 [debug] 21560#0: *1 reusable connection: 1

Is the above line

>2017/09/21 12:06:41 [debug] 21560#0: *1 http finalize request: -4,
"/pcapLowDiskSpace.html?" a:1, c:1

an indication that the response was accepted by the client? hence the http
request is closed and the connection is set reusable?

Comparing with the 1GB scenario:

2017/09/21 12:09:31 [debug] 22090#0: *1 http run request:
"/pcapLowDiskSpace.html?"
2017/09/21 12:09:31 [debug] 22090#0: *1 http finalize request: -1,
"/pcapLowDiskSpace.html?" a:1, c:1
2017/09/21 12:09:31 [debug] 22090#0: *1 http terminate request count:1
2017/09/21 12:09:31 [debug] 22090#0: *1 http terminate cleanup count:1
blk:0
2017/09/21 12:09:31 [debug] 22090#0: *1 http posted request:
"/pcapLowDiskSpace.html?"
2017/09/21 12:09:31 [debug] 22090#0: *1 http terminate handler count:1
2017/09/21 12:09:31 [debug] 22090#0: *1 http request count:1 blk:0
2017/09/21 12:09:31 [debug] 22090#0: *1 http close request

2017/09/21 12:09:31 [debug] 22090#0: *1 http log handler
2017/09/21 12:09:31 [debug] 22090#0: *1 run cleanup: 0000000000EE4FA0
2017/09/21 12:09:31 [debug] 22090#0: *1 file cleanup: fd:21
2017/09/21 12:09:31 [debug] 22090#0: *1 free: 0000000000EE57E0
2017/09/21 12:09:31 [debug] 22090#0: *1 free: 0000000000E92E20, unused: 4
2017/09/21 12:09:31 [debug] 22090#0: *1 free: 0000000000EE37C0, unused: 3
2017/09/21 12:09:31 [debug] 22090#0: *1 free: 0000000000EE47D0, unused:
1304
2017/09/21 12:09:31 [debug] 22090#0: *1 close http connection: 3
2017/09/21 12:09:31 [debug] 22090#0: *1 event timer del: 3: 1505995771900
2017/09/21 12:09:31 [debug] 22090#0: *1 reusable connection: 0

Do the lines
> 2017/09/21 12:09:31 [debug] 22090#0: *1 http finalize request: -1,
"/pcapLowDiskSpace.html?" a:1, c:1

> 2017/09/21 12:09:31 [debug] 22090#0: *1 http posted request:
"/pcapLowDiskSpace.html?"

indicate that the request was unacknowledged by the client hence the http
request is closed along with the connection:

> 2017/09/21 12:09:31 [debug] 22090#0: *1 close http connection: 3

and it is marked as non re-usable?

> 2017/09/21 12:09:31 [debug] 22090#0: *1 reusable connection: 0


I will have a closer look at our client code, we use a third party angular
library to manage our uploads and as far as i can tell (from the network
debug window in chrome) a single POST request is sent in all scenarios; in
the 1.1GB file case the POST request times out with an ERR_CONNECTION_RESET
error.

Many thanks
Gary

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,276512,276541#msg-276541