auth_request called multiple times for same single request

[Valentin V. Bartenev]

On Monday 25 September 2017 22:14:04 Valentin V. Bartenev wrote:
> On Monday 25 September 2017 07:17:08 garyc wrote:
> > Apologies, I posted this issue to the wrong list (php-fpm), the link is:
> > 
> > > https://forum.nginx.org/read.php?3,276451,276475#msg-276475
> > 
> > It has debug log file extracts that seem to suggest the location redirect to
> > a static error page is attempted but doesn't resolve.
> > 
> > Many thanks
> > 
> [..]
> 
> I don't see from your logs that it's the same single request.
> 
> 
> 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: "/lowDiskSpace.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
> 
> Here's the request processing was completed.
> 
> 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 
> 
> Here's the connection #1 was closed.
> 
> 2017/09/21 12:09:31 [debug] 22090#0: *60 http keepalive handler
> 2017/09/21 12:09:31 [debug] 22090#0: *60 malloc: 0000000000EA46D0:1024
> 2017/09/21 12:09:31 [debug] 22090#0: *60 recv: eof:0, avail:1
> 2017/09/21 12:09:31 [debug] 22090#0: *60 recv: fd:22 1024 of 1024
> 2017/09/21 12:09:31 [debug] 22090#0: *60 reusable connection: 0
> 2017/09/21 12:09:31 [debug] 22090#0: *60 posix_memalign: 0000000000E92E20:4096 @16
> 2017/09/21 12:09:31 [debug] 22090#0: *60 event timer del: 22: 1505995796403
> 2017/09/21 12:09:31 [debug] 22090#0: *60 http process request line
> 
> Here's a new request received in different connection #60.
> 
[..]

Your Chrome doesn't stop sending data after it received the 413 response.
It continues sending while nginx continues reading up to the "lingering_time":
http://nginx.org/en/docs/http/ngx_http_core_module.html#lingering_time

After 30 seconds of default lingering time nginx closes the connection.

Chrome tries to repeat request again, and again, probably 4 or 5 times.

That's what actually happens as I can assume based on my knowledge and
from the parts of your debug logs.

  wbr, Valentin V. Bartenev