Hello, thanks to the support of this forum I managed to configure nginx to use the http_auth_request module to intercept a file upload request and verify there is enough disk space left to store the file, rejecting the request if there isn't.

This works fine for smaller files; the auth_request redirects to the php script which either validates (returning 200) or rejects the request (returning 403).

When I attempt to upload a file of 1GB in size the POST request is sent, processed for 2 minutes and returns with a 'failed net::ERR_CONNECTION_RESET'

From php logging I can see that while the POST request is being processed the 'pcapAuthUploadScript.php' is called 4/5 times. Each time the script appears complete with the expected 403 however the POST request does not return.

The failed POST request can be seen in the browser network debug view however the 'Request Headers' section states that only 'Provisional headers are shown' and detail such as the 'Content-Length' is not available which suggests (to me) that the request has not been accepted.

The odd thing is that this works in a virtual machine environment, it was just during testing on an actual piece of hardware (essentially just a PC in a crate) that we get this problem.

The next step will be to get a debug version of nginx setup to see if there is any indication of the problem, the default nginx error log is not reporting any problems.

Given that this is all fairly new to me I would appreciate if someone could cast their eye over my configuration and php script in case i have missed something obvious.

In the nginx configuration file i have:

...

location /api/analysis/upload {
auth_request /bigfile/auth;
error_page 403 =413 /lowDiskSpace.html;
error_page 413 /fileTooBigError.html

fastcgi_request_buffering off;
fastcgi_read_timeout 1h;
fastcgi_pass unix:/opt/tmp/php-fpm.sock;

include fastcgi_params;
fastcgi_param PERMITTED_FILETYPE "bigf";
fastcgi_param HOME_FOLDER "/home/instrument";
fastcgi_param DEST_FOLDER "Analysis/Filters";
fastcgi_param SCRIPT_FILENAME $document_root/PHP/uploadFile.php;
}

location /bigfile/auth {
internal;

fastcgi_pass_request_body off;
fastcgi_pass_request_headers off;
fastcgi_pass unix:/opt/tmp/php-fpm.sock;
fastcgi_intercept_errors on;

include fastcgi_params;
fastcgi_param BIGFILE_UPLOAD_SIZE $content_length;
fastcgi_param BIGFILE_UPLOAD_MARGIN_BYTES 10737418240;
fastcgi_param HOME_FOLDER "/home/instrument";
fastcgi_param DEST_FOLDER "Analysis/Filters";
fastcgi_param SCRIPT_FILENAME $document_root/PHP/pcapAuthUpload.php;
}

...

My script doesn't do very much:

<?php
// The size of the upload request is passed in here (represents the file size plus a little for the http header)
$upload_target_size = $_SERVER['BIGFILE_UPLOAD_SIZE'];
// The intended destination for the file being uploaded
$upload_target_dir = $_SERVER['HOME_FOLDER'] . "/" . $_SERVER['DEST_FOLDER'];
// Permissible minimum free space in bytes after the intended upload
$upload_margin = $_SERVER['BIGFILE_UPLOAD_MARGIN_BYTES'];

// How much space do we currently have?
$space_available = diskfreespace($upload_target_dir);

error_log('space_available = ' . $space_available . ' bytes.');

if (($space_available - $upload_target_size) > $upload_margin) {
http_response_code(200);
exit('upload request validated');
}

http_response_code(403);
error_log('not enough disk space to safely upload the file!');
?>

In both working and failing scenarios I have dumped the $_SERVER variable received by my script, it looks like the following:

...

[19-Sep-2017 15:50:04 UTC] Array
(
[USER] => instrument
[HOME] => /home/instrument
[FCGI_ROLE] => RESPONDER
[QUERY_STRING] =>
[REQUEST_METHOD] => POST
[CONTENT_TYPE] => multipart/form-data; boundary=----WebKitFormBoundaryJvDVM6DSgXzw7dCv
[CONTENT_LENGTH] =>
[SCRIPT_NAME] => /bigfile/auth
[REQUEST_URI] => /api/analysis/upload
[DOCUMENT_URI] => /bigfile/auth
[DOCUMENT_ROOT] => /opt/lib/endor
[SERVER_PROTOCOL] => HTTP/1.1
[GATEWAY_INTERFACE] => CGI/1.1
[SERVER_SOFTWARE] => nginx/1.13.0
[REMOTE_ADDR] => 192.168.202.49
[REMOTE_PORT] => 56951
[SERVER_ADDR] => 127.0.0.1
[SERVER_PORT] => 8000
[SERVER_NAME] =>
[PATH_INFO] =>
[SCRIPT_FILENAME] => /opt/lib/PHP/pcapAuthUpload.php
[REDIRECT_STATUS] => 200
[PHP_VALUE] => upload_max_filesize=10G
post_max_size=10G
[BIGFILE_UPLOAD_SIZE] => 1135591215
[BIGFILE_UPLOAD_MARGIN_BYTES] => 10737418240
[HOME_FOLDER] => /home/instrument
[DEST_FOLDER] => Analysis/Filters
[PHP_SELF] => /pcap/auth
[REQUEST_TIME_FLOAT] => 1505836204.8134
[REQUEST_TIME] => 1505836204
[argv] => Array
(
)

[argc] => 0
)

[19-Sep-2017 15:50:04 UTC] not enough disk space to safely upload the file!

Many thanks for reading

garyc Wrote:
-------------------------------------------------------
> The next step will be to get a debug version of nginx setup to see if
> there is any indication of the problem, the default nginx error log is
> not reporting any problems.

Further to this I have run some tests with the debug information active in nginx. I placed an error log statement with the debug option at the top level in my script (nginx-error-all.log) to log everything and another in the location block for the upload url that uses auth_request:

...
location /api/analysis/upload {

error_log /home/instrument/LogFiles/nginx-upload-error.log debug;

auth_request /bigfile/auth;
error_page 403 =413 /lowDiskSpace.html;
error_page 413 /fileTooBigError.html
...

Having created a scenario where our instrument is low on disk space and so the auth_request script will return 403 for any upload attempt I ran 2 scenarios;

1. Attempt to upload a file of around 5MB in size which the auth_request script rejects and the client receives the expected static error page 'lowDiskSpace.html' as directed from the nginx configuration file:

...
location /api/analysis/upload {
auth_request /bigfile/auth;
error_page 403 =413 /lowDiskSpace.html;
error_page 413 /fileTooBigError.html
...

i.e. the script at '/bigfile/auth' returns 403 which is converted to 413 and directed to location /lowDiskSpace.html which looks like:

location /lowDiskSpace.html {
root /opt/lib/endor/errorPages;
allow all;
}

2. Attempt to upload a file of 1.1GB in size. Although, from the logs, the auth_request redirect is routing to the authorization script which correctly rejects the request, the upstream request to route to /lowDiskSpace.html is made but it fails to resolve. It looks like, after 30 seconds, the attempt to route to /lowDiskSpace.html is abandoned and the auth_request script is called again. This repeats 4 times which each attempt failing.

From the nginx-error-all.log (i have shown extract from the 1.1GB attempt but the successful 5MB file log shows the same information) I can see the incoming POST request...

2017/09/21 12:06:40 [debug] 21560#0: *1 http request line: "POST /api/analysis/upload HTTP/1.1"
2017/09/21 12:06:40 [debug] 21560#0: *1 http uri: "/api/analysis/upload"
2017/09/21 12:06:40 [debug] 21560#0: *1 http args: ""
2017/09/21 12:06:40 [debug] 21560#0: *1 http exten: ""
2017/09/21 12:06:40 [debug] 21560#0: *1 http process request header line
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Host: 192.168.204.4"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Connection: keep-alive"
2017/09/21 12:06:40 [debug] 21560#0: *1 posix_memalign: 00000000019037C0:4096 @16
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Content-Length: 5660732"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Pragma: no-cache"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Cache-Control: no-cache"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Accept: application/json, text/plain, */*"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Origin: http://192.168.204.4"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "User-Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.113 Safari/537.36"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Content-Type: multipart/form-data; boundary=----WebKitFormBoundaryDObNmPYMI9IBeoRn"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Referer: http://192.168.204.4/?debug=true"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Accept-Encoding: gzip, deflate"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Accept-Language: en-US,en;q=0.8"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header done
2017/09/21 12:06:40 [debug] 21560#0: *1 rewrite phase: 0
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: "/"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: "bigfile/auth"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: "api/analysis/upload"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ ".*\.(js|css|png|jpg|jpeg|gif|tif)?$"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ "[^/]\.php(/|$)"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ "^/SystemDocumentation"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ "^/LicensingDocumentation"
2017/09/21 12:06:40 [debug] 21560#0: *1 using configuration "/api/analysis/upload"
2017/09/21 12:06:40 [debug] 21560#0: *1 rewrite phase: 0
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: "/"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: "bigfile/auth"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: "fileTooBigError.html"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: "lowDiskSpace.html"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ ".*\.(js|css|png|jpg|jpeg|gif|tif)?$"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ "[^/]\.php(/|$)"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ "^/SystemDocumentation"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ "^/LicensingDocumentation"
2017/09/21 12:06:40 [debug] 21560#0: *1 using configuration "/lowDiskSpace.html"

2017/09/21 12:06:40 [debug] 21560#0: *1 http cl:5660732 max:10737418240
2017/09/21 12:06:40 [debug] 21560#0: *1 rewrite phase: 2
2017/09/21 12:06:40 [debug] 21560#0: *1 post rewrite phase: 3
2017/09/21 12:06:40 [debug] 21560#0: *1 generic phase: 4
2017/09/21 12:06:40 [debug] 21560#0: *1 generic phase: 5
2017/09/21 12:06:40 [debug] 21560#0: *1 access phase: 6
2017/09/21 12:06:40 [debug] 21560#0: *1 access: 31CAA8C0 00000000 00000000
2017/09/21 12:06:40 [debug] 21560#0: *1 access phase: 7
2017/09/21 12:06:40 [debug] 21560#0: *1 access phase: 8
2017/09/21 12:06:40 [debug] 21560#0: *1 post access phase: 9
2017/09/21 12:06:40 [debug] 21560#0: *1 content phase: 10
2017/09/21 12:06:40 [debug] 21560#0: *1 content phase: 11
2017/09/21 12:06:40 [debug] 21560#0: *1 content phase: 12
2017/09/21 12:06:40 [debug] 21560#0: *1 http filename: "/opt/lib/endor/errorPages/lowDiskSpace.html"
2017/09/21 12:06:40 [debug] 21560#0: *1 add cleanup: 0000000001904FA0
2017/09/21 12:06:40 [debug] 21560#0: *1 http static fd: 21
2017/09/21 12:06:40 [debug] 21560#0: *1 http set discard body
2017/09/21 12:06:40 [debug] 21560#0: *1 http read discarded body
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 2596 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 HTTP/1.1 413 Request Entity Too Large
Server: nginx/1.13.0
Date: Thu, 21 Sep 2017 12:06:40 GMT
Content-Type: text/html
Content-Length: 310
Connection: keep-alive
ETag: "59bbd611-136"

2017/09/21 12:06:40 [debug] 21560#0: *1 write new buf t:1 f:0 0000000001905168, pos 0000000001905168, size: 192 file: 0, size: 0
2017/09/21 12:06:40 [debug] 21560#0: *1 http write filter: l:0 f:0 s:192
2017/09/21 12:06:40 [debug] 21560#0: *1 http output filter "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http copy filter: "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http postpone filter "/lowDiskSpace.html?" 00007FFC563CCB90
2017/09/21 12:06:40 [debug] 21560#0: *1 write old buf t:1 f:0 0000000001905168, pos 0000000001905168, size: 192 file: 0, size: 0
2017/09/21 12:06:40 [debug] 21560#0: *1 write new buf t:0 f:1 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 310
2017/09/21 12:06:40 [debug] 21560#0: *1 http write filter: l:1 f:0 s:502
2017/09/21 12:06:40 [debug] 21560#0: *1 http write filter limit 0
2017/09/21 12:06:40 [debug] 21560#0: *1 no tcp_nodelay
2017/09/21 12:06:40 [debug] 21560#0: *1 tcp_nopush
2017/09/21 12:06:40 [debug] 21560#0: *1 writev: 192 of 192
2017/09/21 12:06:40 [debug] 21560#0: *1 sendfile: @0 310
2017/09/21 12:06:40 [debug] 21560#0: *1 sendfile: 310 of 310 @0
2017/09/21 12:06:40 [debug] 21560#0: *1 http write filter 0000000000000000
2017/09/21 12:06:40 [debug] 21560#0: *1 http copy filter: 0 "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http finalize request: 0, "/lowDiskSpace.html?" a:1, c:3
2017/09/21 12:06:40 [debug] 21560#0: *1 event timer add: 3: 5000:1505995605607
2017/09/21 12:06:40 [debug] 21560#0: *1 http request count:3 blk:0

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

2017/09/21 12:06:40 [debug] 21560#0: *1 event timer: 3, old: 1505995605607, new: 1505995605607
2017/09/21 12:06:40 [debug] 21560#0: *1 http request count:2 blk:0

2017/09/21 12:06:40 [debug] 21560#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http read discarded body
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 2920 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 event timer: 3, old: 1505995605607, new: 1505995605608

2017/09/21 12:06:40 [debug] 21560#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http request empty handler
2017/09/21 12:06:40 [debug] 21560#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http read discarded body
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 2920 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 event timer: 3, old: 1505995605607, new: 1505995605608

2017/09/21 12:06:40 [debug] 21560#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http request empty handler
2017/09/21 12:06:40 [debug] 21560#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http read discarded body
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 2920 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 event timer: 3, old: 1505995605607, new: 1505995605608

...

The above http run request, request empty handler, read discarded body blocks repeat many times. In the majority of cases the

2017/09/21 12:09:01 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:01 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:01 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:01 [debug] 22090#0: *1 recv: fd:3 284 of 4096

entries are like this i.e. 2 - 4 lines of logs, very occasionally i am seeing a large block of identical paired recv: log entires (this extract is from the 1.1GB log file but in the successful 5MB log i see something similar):

2017/09/21 12:09:02 [debug] 22090#0: *1 http run request: "/pcapLowDiskSpace.html?"
2017/09/21 12:09:02 [debug] 22090#0: *1 http read discarded body
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 1254 of 4096

In the 1.1GB failure case this repeats for 30 seconds (so many thousands on lines of logs). At the 30 second boundary the log shows:

2017/09/21 12:09:30 [debug] 22090#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:09:30 [debug] 22090#0: *1 http request empty handler
2017/09/21 12:09:30 [debug] 22090#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:09:30 [debug] 22090#0: *1 http read discarded body
2017/09/21 12:09:30 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:30 [debug] 22090#0: *1 recv: fd:3 2920 of 4096
2017/09/21 12:09:30 [debug] 22090#0: *1 event timer: 3, old: 1505995771900, new: 1505995771999

2017/09/21 12:09:30 [debug] 22090#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:09:30 [debug] 22090#0: *1 http request empty handler
2017/09/21 12:09:31 [debug] 22090#0: *1 http run request: "/lowDiskSpace.html?"

2017/09/21 12:09:31 [debug] 22090#0: *1 http finalize request: -1, "/lowDiskSpace.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: "/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
2017/09/21 12:09:31 [debug] 22090#0: *1 http log handler

The finalize request: -1 appears to be the point at which the attempt to move to the /lowDiskSpace.html location is abandoned, what follows looks to me like some cleanup and another attempt to authenticate the request:

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
2017/09/21 12:09:31 [debug] 22090#0: *1 free: 0000000000EA46D0
2017/09/21 12:09:31 [debug] 22090#0: *1 free: 0000000000E8B350, unused: 136
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
2017/09/21 12:09:31 [debug] 22090#0: *60 http request line: "POST /api/analysis/upload HTTP/1.1"
2017/09/21 12:09:31 [debug] 22090#0: *60 http uri: "/api/analysis/upload"
2017/09/21 12:09:31 [debug] 22090#0: *60 http args: ""
2017/09/21 12:09:31 [debug] 22090#0: *60 http exten: ""
2017/09/21 12:09:31 [debug] 22090#0: *60 http process request header line
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Host: 192.168.204.4"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Connection: keep-alive"
2017/09/21 12:09:31 [debug] 22090#0: *60 posix_memalign: 0000000000EE37C0:4096 @16
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Content-Length: 1135591215"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Pragma: no-cache"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Cache-Control: no-cache"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Accept: application/json, text/plain, */*"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Origin: http://192.168.204.4"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "User-Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.113 Safari/537.36"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Content-Type: multipart/form-data; boundary=----WebKitFormBoundaryhlOaPFKP1MDW9O73"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Referer: http://192.168.204.4/?debug=true"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Accept-Encoding: gzip, deflate"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Accept-Language: en-US,en;q=0.8"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header done
2017/09/21 12:09:31 [debug] 22090#0: *60 rewrite phase: 0
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: "/"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: "bigfile/auth"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: "api/analysis/upload"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ ".*\.(js|css|png|jpg|jpeg|gif|tif)?$"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ "[^/]\.php(/|$)"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ "^/SystemDocumentation"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ "^/LicensingDocumentation"
2017/09/21 12:09:31 [debug] 22090#0: *60 using configuration "/api/analysis/upload"
2017/09/21 12:09:31 [debug] 22090#0: *60 rewrite phase: 0
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: "/"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: "bigfile/auth"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: "fileTooBigError.html"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: "lowDiskSpace.html"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ ".*\.(js|css|png|jpg|jpeg|gif|tif)?$"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ "[^/]\.php(/|$)"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ "^/SystemDocumentation"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ "^/LicensingDocumentation"
2017/09/21 12:09:31 [debug] 22090#0: *60 using configuration "/lowDiskSpace.html"
2017/09/21 12:09:31 [debug] 22090#0: *60 http cl:1135591215 max:10737418240
2017/09/21 12:09:31 [debug] 22090#0: *60 rewrite phase: 2
2017/09/21 12:09:31 [debug] 22090#0: *60 post rewrite phase: 3
2017/09/21 12:09:31 [debug] 22090#0: *60 generic phase: 4
2017/09/21 12:09:31 [debug] 22090#0: *60 generic phase: 5
2017/09/21 12:09:31 [debug] 22090#0: *60 access phase: 6
2017/09/21 12:09:31 [debug] 22090#0: *60 access: 31CAA8C0 00000000 00000000
2017/09/21 12:09:31 [debug] 22090#0: *60 access phase: 7
2017/09/21 12:09:31 [debug] 22090#0: *60 access phase: 8
2017/09/21 12:09:31 [debug] 22090#0: *60 post access phase: 9
2017/09/21 12:09:31 [debug] 22090#0: *60 content phase: 10
2017/09/21 12:09:31 [debug] 22090#0: *60 content phase: 11
2017/09/21 12:09:31 [debug] 22090#0: *60 content phase: 12
2017/09/21 12:09:31 [debug] 22090#0: *60 http filename: "/opt/lib/endor/errorPages/lowDiskSpace.html"
2017/09/21 12:09:31 [debug] 22090#0: *60 add cleanup: 0000000000EE4FA0
2017/09/21 12:09:31 [debug] 22090#0: *60 http static fd: 3
2017/09/21 12:09:31 [debug] 22090#0: *60 http set discard body
2017/09/21 12:09:31 [debug] 22090#0: *60 http read discarded body
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 4096 of 4096
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 4096 of 4096
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 4096 of 4096
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 4096 of 4096
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 4096 of 4096
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 4096 of 4096
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 2699 of 4096
2017/09/21 12:09:31 [debug] 22090#0: *60 HTTP/1.1 413 Request Entity Too Large
Server: nginx/1.13.0
Date: Thu, 21 Sep 2017 12:09:31 GMT
Content-Type: text/html
Content-Length: 310
Connection: keep-alive
ETag: "59bbd611-136"

And the process repeats every 30 seconds, a total of 4 times, the final attempt is terminated and cleaned up:

2017/09/21 12:11:00 [debug] 22090#0: *74 http run request: "/lowDiskSpace.html?"
2017/09/21 12:11:00 [debug] 22090#0: *74 http request empty handler
2017/09/21 12:11:00 [debug] 22090#0: *74 http run request: "/lowDiskSpace.html?"
2017/09/21 12:11:00 [debug] 22090#0: *74 http read discarded body
2017/09/21 12:11:00 [debug] 22090#0: *74 recv: eof:0, avail:1
2017/09/21 12:11:00 [debug] 22090#0: *74 recv: fd:3 4096 of 4096
2017/09/21 12:11:00 [debug] 22090#0: *74 recv: eof:0, avail:1
2017/09/21 12:11:00 [debug] 22090#0: *74 recv: fd:3 284 of 4096
2017/09/21 12:11:00 [debug] 22090#0: *74 event timer: 3, old: 1505995861900, new: 1505995861999

2017/09/21 12:11:00 [debug] 22090#0: *74 http run request: "/lowDiskSpace.html?"
2017/09/21 12:11:00 [debug] 22090#0: *74 http request empty handler
2017/09/21 12:11:00 [debug] 22090#0: *74 http run request: "/lowDiskSpace.html?"
2017/09/21 12:11:00 [debug] 22090#0: *74 http read discarded body
2017/09/21 12:11:00 [debug] 22090#0: *74 recv: eof:0, avail:1
2017/09/21 12:11:00 [debug] 22090#0: *74 recv: fd:3 2920 of 4096
2017/09/21 12:11:00 [debug] 22090#0: *74 event timer: 3, old: 1505995861900, new: 1505995861999

2017/09/21 12:11:00 [debug] 22090#0: *74 http run request: "/lowDiskSpace.html?"
2017/09/21 12:11:00 [debug] 22090#0: *74 http request empty handler
2017/09/21 12:11:01 [debug] 22090#0: *74 http run request: "/lowDiskSpace.html?"

2017/09/21 12:11:01 [debug] 22090#0: *74 http finalize request: -1, "/lowDiskSpace.html?" a:1, c:1

2017/09/21 12:11:01 [debug] 22090#0: *74 http terminate request count:1
2017/09/21 12:11:01 [debug] 22090#0: *74 http terminate cleanup count:1 blk:0
2017/09/21 12:11:01 [debug] 22090#0: *74 http posted request: "/lowDiskSpace.html?"
2017/09/21 12:11:01 [debug] 22090#0: *74 http terminate handler count:1
2017/09/21 12:11:01 [debug] 22090#0: *74 http request count:1 blk:0
2017/09/21 12:11:01 [debug] 22090#0: *74 http close request
2017/09/21 12:11:01 [debug] 22090#0: *74 http log handler

2017/09/21 12:11:01 [debug] 22090#0: *74 run cleanup: 0000000000EE4FA0
2017/09/21 12:11:01 [debug] 22090#0: *74 file cleanup: fd:15
2017/09/21 12:11:01 [debug] 22090#0: *74 free: 0000000000EE57E0
2017/09/21 12:11:01 [debug] 22090#0: *74 free: 0000000000E92E20, unused: 4
2017/09/21 12:11:01 [debug] 22090#0: *74 free: 0000000000EE37C0, unused: 3
2017/09/21 12:11:01 [debug] 22090#0: *74 free: 0000000000EE47D0, unused: 1304
2017/09/21 12:11:01 [debug] 22090#0: *74 close http connection: 3
2017/09/21 12:11:01 [debug] 22090#0: *74 event timer del: 3: 1505995861900
2017/09/21 12:11:01 [debug] 22090#0: *74 reusable connection: 0
2017/09/21 12:11:01 [debug] 22090#0: *74 free: 0000000000E8B350
2017/09/21 12:11:01 [debug] 22090#0: *74 free: 0000000000EAEFD0, unused: 136

In the 5MB log file a similar process is logged however it appears to resolve (http finalize request: -4) within a second of logs:


..

2017/09/21 12:06:41 [debug] 21560#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:06:41 [debug] 21560#0: *1 http request empty handler
2017/09/21 12:06:41 [debug] 21560#0: *1 http run request: "/lowDiskSpace.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, "/lowDiskSpace.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
2017/09/21 12:06:41 [debug] 21560#0: *1 event timer del: 3: 1505995606279
2017/09/21 12:06:41 [debug] 21560#0: *1 event timer add: 3: 65000:1505995666379
2017/09/21 12:06:41 [debug] 21560#0: *1 post event 00000000018F7860
2017/09/21 12:06:41 [debug] 21560#0: *1 http empty handler
2017/09/21 12:06:41 [debug] 21560#0: *1 delete posted event 00000000018F7860
2017/09/21 12:06:41 [debug] 21560#0: *1 http keepalive handler
2017/09/21 12:06:41 [debug] 21560#0: *1 malloc: 00000000018B4450:1024
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 -1 of 1024
2017/09/21 12:06:41 [debug] 21560#0: *1 recv() not ready (11: Resource temporarily unavailable)
2017/09/21 12:06:41 [debug] 21560#0: *1 free: 00000000018B4450

The nginx-upload-error.log shows:

2017/09/21 12:09:01 [debug] 22090#0: *1 http cl:1135591215 max:10737418240
2017/09/21 12:09:01 [debug] 22090#0: *1 rewrite phase: 2
2017/09/21 12:09:01 [debug] 22090#0: *1 post rewrite phase: 3
2017/09/21 12:09:01 [debug] 22090#0: *1 generic phase: 4
2017/09/21 12:09:01 [debug] 22090#0: *1 generic phase: 5
2017/09/21 12:09:01 [debug] 22090#0: *1 access phase: 6
2017/09/21 12:09:01 [debug] 22090#0: *1 access phase: 7
2017/09/21 12:09:01 [debug] 22090#0: *1 access phase: 8
2017/09/21 12:09:01 [debug] 22090#0: *1 auth request handler
2017/09/21 12:09:01 [debug] 22090#0: *1 http subrequest "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http posted request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 rewrite phase: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 test location: "/"
2017/09/21 12:09:01 [debug] 22090#0: *1 test location: "bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 test location: ~ ".*\.(js|css|png|jpg|jpeg|gif|tif)?$"
2017/09/21 12:09:01 [debug] 22090#0: *1 test location: ~ "[^/]\.php(/|$)"
2017/09/21 12:09:01 [debug] 22090#0: *1 test location: ~ "^/SystemDocumentation"
2017/09/21 12:09:01 [debug] 22090#0: *1 test location: ~ "^/LicensingDocumentation"
2017/09/21 12:09:01 [debug] 22090#0: *1 using configuration "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http cl:1135591215 max:10737418240
2017/09/21 12:09:01 [debug] 22090#0: *1 rewrite phase: 2
2017/09/21 12:09:01 [debug] 22090#0: *1 post rewrite phase: 3
2017/09/21 12:09:01 [debug] 22090#0: *1 generic phase: 4
2017/09/21 12:09:01 [debug] 22090#0: *1 generic phase: 5
2017/09/21 12:09:01 [debug] 22090#0: *1 posix_memalign: 0000000000EE47D0:4096 @16

2017/09/21 12:09:01 [debug] 22090#0: *1 http init upstream, client timer: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "QUERY_STRING"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "QUERY_STRING: "
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "REQUEST_METHOD"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "POST"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "REQUEST_METHOD: POST"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "CONTENT_TYPE"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "multipart/form-data; boundary=----WebKitFormBoundaryhlOaPFKP1MDW9O73"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "CONTENT_TYPE: multipart/form-data; boundary=----WebKitFormBoundaryhlOaPFKP1MDW9O73"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "CONTENT_LENGTH"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "1135591215"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "CONTENT_LENGTH: 1135591215"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SCRIPT_NAME"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SCRIPT_NAME: /bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "REQUEST_URI"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "/api/analysis/upload"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "REQUEST_URI: /api/analysis/upload"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "DOCUMENT_URI"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "DOCUMENT_URI: /bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "DOCUMENT_ROOT"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "/opt/lib/endor"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "DOCUMENT_ROOT: /opt/lib/endor"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SERVER_PROTOCOL"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "HTTP/1.1"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SERVER_PROTOCOL: HTTP/1.1"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: ""
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "GATEWAY_INTERFACE"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "CGI/1.1"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "GATEWAY_INTERFACE: CGI/1.1"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SERVER_SOFTWARE"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "nginx/"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "1.13.0"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SERVER_SOFTWARE: nginx/1.13.0"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "REMOTE_ADDR"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "192.168.202.49"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "REMOTE_ADDR: 192.168.202.49"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "REMOTE_PORT"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "56912"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "REMOTE_PORT: 56912"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SERVER_ADDR"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "127.0.0.1"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SERVER_ADDR: 127.0.0.1"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SERVER_PORT"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "8000"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SERVER_PORT: 8000"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SERVER_NAME"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: ""
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SERVER_NAME: "
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "PATH_INFO"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "PATH_INFO: "
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SCRIPT_FILENAME"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "/opt/lib/endor"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SCRIPT_FILENAME: /opt/lib/endor/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "REDIRECT_STATUS"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "200"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "REDIRECT_STATUS: 200"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "PHP_VALUE"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "upload_max_filesize=10G
post_max_size=10G"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "PHP_VALUE: upload_max_filesize=10G
post_max_size=10G"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "BIGFILE_UPLOAD_SIZE"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "1135591215"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "BIGFILE_UPLOAD_SIZE: 1135591215"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "BIGFILE_UPLOAD_MARGIN_BYTES"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "10737418240"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "BIGFILE_UPLOAD_MARGIN_BYTES: 10737418240"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "HOME_FOLDER"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "/home/instrument"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "HOME_FOLDER: /home/instrument"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "DEST_FOLDER"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "Analysis/Filters"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "DEST_FOLDER: Analysis/Filters"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "CONTENT_LENGTH"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "CONTENT_LENGTH: "
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SCRIPT_FILENAME"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "/opt/lib/endor"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "/PHP/pcapAuthUpload.php"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SCRIPT_FILENAME: /opt/lib/endor/PHP/pcapAuthUpload.php"

2017/09/21 12:09:01 [debug] 22090#0: *1 http cleanup add: 0000000000EE4D00
2017/09/21 12:09:01 [debug] 22090#0: *1 get rr peer, try: 1
2017/09/21 12:09:01 [debug] 22090#0: *1 stream socket 21
2017/09/21 12:09:01 [debug] 22090#0: *1 epoll add connection: fd:21 ev:80002005
2017/09/21 12:09:01 [debug] 22090#0: *1 connect to unix:/opt/tmp/php-fpm.sock, fd:21 #70
2017/09/21 12:09:01 [debug] 22090#0: *1 connected
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream connect: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 posix_memalign: 0000000000E8B1F0:128 @16
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream send request
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream send request body
2017/09/21 12:09:01 [debug] 22090#0: *1 chain writer buf fl:0 s:808
2017/09/21 12:09:01 [debug] 22090#0: *1 chain writer in: 0000000000EE4D40
2017/09/21 12:09:01 [debug] 22090#0: *1 writev: 808 of 808
2017/09/21 12:09:01 [debug] 22090#0: *1 chain writer out: 0000000000000000
2017/09/21 12:09:01 [debug] 22090#0: *1 event timer add: 21: 60000:1505995801838
2017/09/21 12:09:01 [debug] 22090#0: *1 http finalize request: -4, "/bigfile/auth?" a:1, c:3
2017/09/21 12:09:01 [debug] 22090#0: *1 http request count:3 blk:0
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:1, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:0, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bgifile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:1, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream request: "/bigfile/auth?"

2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream dummy handler

2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:0, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:1, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bgifile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:0, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:1, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:0, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:1, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:0, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:1, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:0, "/bgifile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"

2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:1, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream process header
2017/09/21 12:09:01 [debug] 22090#0: *1 malloc: 0000000000EE57E0:4096
2017/09/21 12:09:01 [debug] 22090#0: *1 recv: eof:1, avail:1
2017/09/21 12:09:01 [debug] 22090#0: *1 recv: fd:21 120 of 4096
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 01
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 06
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 00
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 01
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 00
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 5B
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 05
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 00
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record length: 91
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi parser: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi header: "Status: 403 Forbidden"
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi parser: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi header: "X-Powered-By: PHP/5.6.27"
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi parser: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi header: "Content-type: text/html; charset=UTF-8"
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi parser: 1
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi header done

2017/09/21 12:09:01 [debug] 22090#0: *1 finalize http upstream request: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 finalize http fastcgi request
2017/09/21 12:09:01 [debug] 22090#0: *1 free rr peer 1 0

2017/09/21 12:09:01 [debug] 22090#0: *1 close http upstream connection: 21
2017/09/21 12:09:01 [debug] 22090#0: *1 free: 0000000000E8B1F0, unused: 48
2017/09/21 12:09:01 [debug] 22090#0: *1 event timer del: 21: 1505995801838
2017/09/21 12:09:01 [debug] 22090#0: *1 reusable connection: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 http finalize request: 0, "/bigfile/auth?" a:1, c:2

2017/09/21 12:09:01 [debug] 22090#0: *1 auth request done s:403
2017/09/21 12:09:01 [debug] 22090#0: *1 http wake parent request: "/api/analysis/upload?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http posted request: "/api/analysis/upload?"

2017/09/21 12:09:01 [debug] 22090#0: *1 access phase: 8
2017/09/21 12:09:01 [debug] 22090#0: *1 auth request handler
2017/09/21 12:09:01 [debug] 22090#0: *1 auth request set variables

2017/09/21 12:09:01 [debug] 22090#0: *1 http finalize request: 403, "/api/analysis/upload?" a:1, c:1
2017/09/21 12:09:01 [debug] 22090#0: *1 http special response: 403, "/api/analysis/upload?"
2017/09/21 12:09:01 [debug] 22090#0: *1 internal redirect: "/lowDiskSpace.html?"

In the 5MB file case this log has the same content as above (other than the time stamps), the above is an extract from the 1.1GB case where the above is repeated 4 times matching the 4 calls to the authorization script (subsequent blocks have different log ids i.e.

2017/09/21 12:09:31 [debug] 22090#0: *60 http cl:1135591215 max:10737418240
..
2017/09/21 12:10:01 [debug] 22090#0: *57 http cl:1135591215 max:10737418240
..
2017/09/21 12:10:31 [debug] 22090#0: *74 http cl:1135591215 max:10737418240
..
In each case the log suggests that the script is returning successfully with the expected 403 error.

In the nginx-error-all.log the only other logging is from our XSockets processing:

2017/09/21 12:09:02 [debug] 22090#0: *47 http upstream request: "/Realtime?XSocketsClientStorageGuid=e1aedac6d2b7457f8a1d7d1207a77497"
2017/09/21 12:09:02 [debug] 22090#0: *47 http upstream process upgraded, fu:1
2017/09/21 12:09:02 [debug] 22090#0: *47 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *47 recv: fd:20 98 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *47 send: fd:19 98 of 98
2017/09/21 12:09:02 [debug] 22090#0: *47 event timer del: 20: 1506600541965
2017/09/21 12:09:02 [debug] 22090#0: *47 event timer add: 20: 604800000:1506600542421
2017/09/21 12:09:02 [debug] 22090#0: *47 http upstream request: "/Realtime?XSocketsClientStorageGuid=e1aedac6d2b7457f8a1d7d1207a77497"
2017/09/21 12:09:02 [debug] 22090#0: *47 http upstream process upgraded, fu:0
2017/09/21 12:09:02 [debug] 22090#0: *47 event timer: 20, old: 1506600542421, new: 1506600542421

It is present in both 1.1GB & 5MB file logs and doesn't appear to be causing any problems, this processing reflects a regular update to instrument statistics gathered in our instrument database, ordinarily clients would respond to this notification by requesting updated stats data, i deliberately disabled this mechanism before running these tests to avoid extra noise in the logs.

Hopefully this sheds some light on the problem? I can provide the raw log files if it would help.

Could it be the file size and the fact that i am not buffering the request that is aggravating the issue? I need to disable buffering as the point of this is to avoid filling up the disk.

All suggestions/pointers as to what to try next are very welcome, many thanks for reading.

garyc Wrote:
-------------------------------------------------------
> The next step will be to get a debug version of nginx setup to see if
> there is any indication of the problem, the default nginx error log is
> not reporting any problems.

Further to this I have run some tests with the debug information active in nginx. I placed an error log statement with the debug option at the top level in my script (nginx-error-all.log) to log everything and another in the location block for the upload url that uses auth_request:

...
location /api/analysis/upload {

error_log /home/instrument/LogFiles/nginx-upload-error.log debug;

auth_request /bigfile/auth;
error_page 403 =413 /lowDiskSpace.html;
error_page 413 /fileTooBigError.html
...

Having created a scenario where our instrument is low on disk space and so the auth_request script will return 403 for any upload attempt I ran 2 scenarios;

1. Attempt to upload a file of around 5MB in size which the auth_request script rejects and the client receives the expected static error page 'lowDiskSpace.html' as directed from the nginx configuration file:

...
location /api/analysis/upload {
auth_request /bigfile/auth;
error_page 403 =413 /lowDiskSpace.html;
error_page 413 /fileTooBigError.html
...

i.e. the script at '/bigfile/auth' returns 403 which is converted to 413 and directed to location /lowDiskSpace.html which looks like:

location /lowDiskSpace.html {
root /opt/lib/endor/errorPages;
allow all;
}

2. Attempt to upload a file of 1.1GB in size. Although, from the logs, the auth_request redirect is routing to the authorization script which correctly rejects the request, the upstream request to route to /lowDiskSpace.html is made but it fails to resolve. It looks like, after 30 seconds, the attempt to route to /lowDiskSpace.html is abandoned and the auth_request script is called again. This repeats 4 times which each attempt failing.

From the nginx-error-all.log (i have shown extract from the 1.1GB attempt but the successful 5MB file log shows the same information) I can see the incoming POST request...

2017/09/21 12:06:40 [debug] 21560#0: *1 http request line: "POST /api/analysis/upload HTTP/1.1"
2017/09/21 12:06:40 [debug] 21560#0: *1 http uri: "/api/analysis/upload"
2017/09/21 12:06:40 [debug] 21560#0: *1 http args: ""
2017/09/21 12:06:40 [debug] 21560#0: *1 http exten: ""
2017/09/21 12:06:40 [debug] 21560#0: *1 http process request header line
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Host: 192.168.204.4"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Connection: keep-alive"
2017/09/21 12:06:40 [debug] 21560#0: *1 posix_memalign: 00000000019037C0:4096 @16
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Content-Length: 5660732"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Pragma: no-cache"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Cache-Control: no-cache"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Accept: application/json, text/plain, */*"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Origin: http://192.168.204.4"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "User-Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.113 Safari/537.36"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Content-Type: multipart/form-data; boundary=----WebKitFormBoundaryDObNmPYMI9IBeoRn"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Referer: http://192.168.204.4/?debug=true"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Accept-Encoding: gzip, deflate"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header: "Accept-Language: en-US,en;q=0.8"
2017/09/21 12:06:40 [debug] 21560#0: *1 http header done
2017/09/21 12:06:40 [debug] 21560#0: *1 rewrite phase: 0
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: "/"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: "bigfile/auth"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: "api/analysis/upload"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ ".*\.(js|css|png|jpg|jpeg|gif|tif)?$"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ "[^/]\.php(/|$)"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ "^/SystemDocumentation"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ "^/LicensingDocumentation"
2017/09/21 12:06:40 [debug] 21560#0: *1 using configuration "/api/analysis/upload"
2017/09/21 12:06:40 [debug] 21560#0: *1 rewrite phase: 0
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: "/"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: "bigfile/auth"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: "fileTooBigError.html"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: "lowDiskSpace.html"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ ".*\.(js|css|png|jpg|jpeg|gif|tif)?$"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ "[^/]\.php(/|$)"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ "^/SystemDocumentation"
2017/09/21 12:06:40 [debug] 21560#0: *1 test location: ~ "^/LicensingDocumentation"
2017/09/21 12:06:40 [debug] 21560#0: *1 using configuration "/lowDiskSpace.html"

2017/09/21 12:06:40 [debug] 21560#0: *1 http cl:5660732 max:10737418240
2017/09/21 12:06:40 [debug] 21560#0: *1 rewrite phase: 2
2017/09/21 12:06:40 [debug] 21560#0: *1 post rewrite phase: 3
2017/09/21 12:06:40 [debug] 21560#0: *1 generic phase: 4
2017/09/21 12:06:40 [debug] 21560#0: *1 generic phase: 5
2017/09/21 12:06:40 [debug] 21560#0: *1 access phase: 6
2017/09/21 12:06:40 [debug] 21560#0: *1 access: 31CAA8C0 00000000 00000000
2017/09/21 12:06:40 [debug] 21560#0: *1 access phase: 7
2017/09/21 12:06:40 [debug] 21560#0: *1 access phase: 8
2017/09/21 12:06:40 [debug] 21560#0: *1 post access phase: 9
2017/09/21 12:06:40 [debug] 21560#0: *1 content phase: 10
2017/09/21 12:06:40 [debug] 21560#0: *1 content phase: 11
2017/09/21 12:06:40 [debug] 21560#0: *1 content phase: 12
2017/09/21 12:06:40 [debug] 21560#0: *1 http filename: "/opt/lib/endor/errorPages/lowDiskSpace.html"
2017/09/21 12:06:40 [debug] 21560#0: *1 add cleanup: 0000000001904FA0
2017/09/21 12:06:40 [debug] 21560#0: *1 http static fd: 21
2017/09/21 12:06:40 [debug] 21560#0: *1 http set discard body
2017/09/21 12:06:40 [debug] 21560#0: *1 http read discarded body
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 2596 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 HTTP/1.1 413 Request Entity Too Large
Server: nginx/1.13.0
Date: Thu, 21 Sep 2017 12:06:40 GMT
Content-Type: text/html
Content-Length: 310
Connection: keep-alive
ETag: "59bbd611-136"

2017/09/21 12:06:40 [debug] 21560#0: *1 write new buf t:1 f:0 0000000001905168, pos 0000000001905168, size: 192 file: 0, size: 0
2017/09/21 12:06:40 [debug] 21560#0: *1 http write filter: l:0 f:0 s:192
2017/09/21 12:06:40 [debug] 21560#0: *1 http output filter "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http copy filter: "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http postpone filter "/lowDiskSpace.html?" 00007FFC563CCB90
2017/09/21 12:06:40 [debug] 21560#0: *1 write old buf t:1 f:0 0000000001905168, pos 0000000001905168, size: 192 file: 0, size: 0
2017/09/21 12:06:40 [debug] 21560#0: *1 write new buf t:0 f:1 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 310
2017/09/21 12:06:40 [debug] 21560#0: *1 http write filter: l:1 f:0 s:502
2017/09/21 12:06:40 [debug] 21560#0: *1 http write filter limit 0
2017/09/21 12:06:40 [debug] 21560#0: *1 no tcp_nodelay
2017/09/21 12:06:40 [debug] 21560#0: *1 tcp_nopush
2017/09/21 12:06:40 [debug] 21560#0: *1 writev: 192 of 192
2017/09/21 12:06:40 [debug] 21560#0: *1 sendfile: @0 310
2017/09/21 12:06:40 [debug] 21560#0: *1 sendfile: 310 of 310 @0
2017/09/21 12:06:40 [debug] 21560#0: *1 http write filter 0000000000000000
2017/09/21 12:06:40 [debug] 21560#0: *1 http copy filter: 0 "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http finalize request: 0, "/lowDiskSpace.html?" a:1, c:3
2017/09/21 12:06:40 [debug] 21560#0: *1 event timer add: 3: 5000:1505995605607
2017/09/21 12:06:40 [debug] 21560#0: *1 http request count:3 blk:0

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

2017/09/21 12:06:40 [debug] 21560#0: *1 event timer: 3, old: 1505995605607, new: 1505995605607
2017/09/21 12:06:40 [debug] 21560#0: *1 http request count:2 blk:0

2017/09/21 12:06:40 [debug] 21560#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http read discarded body
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 2920 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 event timer: 3, old: 1505995605607, new: 1505995605608

2017/09/21 12:06:40 [debug] 21560#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http request empty handler
2017/09/21 12:06:40 [debug] 21560#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http read discarded body
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 2920 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 event timer: 3, old: 1505995605607, new: 1505995605608

2017/09/21 12:06:40 [debug] 21560#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http request empty handler
2017/09/21 12:06:40 [debug] 21560#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:06:40 [debug] 21560#0: *1 http read discarded body
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: eof:0, avail:1
2017/09/21 12:06:40 [debug] 21560#0: *1 recv: fd:3 2920 of 4096
2017/09/21 12:06:40 [debug] 21560#0: *1 event timer: 3, old: 1505995605607, new: 1505995605608

...

The above http run request, request empty handler, read discarded body blocks repeat many times. In the majority of cases the

2017/09/21 12:09:01 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:01 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:01 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:01 [debug] 22090#0: *1 recv: fd:3 284 of 4096

entries are like this i.e. 2 - 4 lines of logs, very occasionally i am seeing a large block of identical paired recv: log entires (this extract is from the 1.1GB log file but in the successful 5MB log i see something similar):

2017/09/21 12:09:02 [debug] 22090#0: *1 http run request: "/pcapLowDiskSpace.html?"
2017/09/21 12:09:02 [debug] 22090#0: *1 http read discarded body
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 4096 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *1 recv: fd:3 1254 of 4096

In the 1.1GB failure case this repeats for 30 seconds (so many thousands on lines of logs). At the 30 second boundary the log shows:

2017/09/21 12:09:30 [debug] 22090#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:09:30 [debug] 22090#0: *1 http request empty handler
2017/09/21 12:09:30 [debug] 22090#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:09:30 [debug] 22090#0: *1 http read discarded body
2017/09/21 12:09:30 [debug] 22090#0: *1 recv: eof:0, avail:1
2017/09/21 12:09:30 [debug] 22090#0: *1 recv: fd:3 2920 of 4096
2017/09/21 12:09:30 [debug] 22090#0: *1 event timer: 3, old: 1505995771900, new: 1505995771999

2017/09/21 12:09:30 [debug] 22090#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:09:30 [debug] 22090#0: *1 http request empty handler
2017/09/21 12:09:31 [debug] 22090#0: *1 http run request: "/lowDiskSpace.html?"

2017/09/21 12:09:31 [debug] 22090#0: *1 http finalize request: -1, "/lowDiskSpace.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: "/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
2017/09/21 12:09:31 [debug] 22090#0: *1 http log handler

The finalize request: -1 appears to be the point at which the attempt to move to the /lowDiskSpace.html location is abandoned, what follows looks to me like some cleanup and another attempt to authenticate the request:

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
2017/09/21 12:09:31 [debug] 22090#0: *1 free: 0000000000EA46D0
2017/09/21 12:09:31 [debug] 22090#0: *1 free: 0000000000E8B350, unused: 136
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
2017/09/21 12:09:31 [debug] 22090#0: *60 http request line: "POST /api/analysis/upload HTTP/1.1"
2017/09/21 12:09:31 [debug] 22090#0: *60 http uri: "/api/analysis/upload"
2017/09/21 12:09:31 [debug] 22090#0: *60 http args: ""
2017/09/21 12:09:31 [debug] 22090#0: *60 http exten: ""
2017/09/21 12:09:31 [debug] 22090#0: *60 http process request header line
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Host: 192.168.204.4"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Connection: keep-alive"
2017/09/21 12:09:31 [debug] 22090#0: *60 posix_memalign: 0000000000EE37C0:4096 @16
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Content-Length: 1135591215"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Pragma: no-cache"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Cache-Control: no-cache"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Accept: application/json, text/plain, */*"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Origin: http://192.168.204.4"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "User-Agent: Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.113 Safari/537.36"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Content-Type: multipart/form-data; boundary=----WebKitFormBoundaryhlOaPFKP1MDW9O73"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Referer: http://192.168.204.4/?debug=true"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Accept-Encoding: gzip, deflate"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header: "Accept-Language: en-US,en;q=0.8"
2017/09/21 12:09:31 [debug] 22090#0: *60 http header done
2017/09/21 12:09:31 [debug] 22090#0: *60 rewrite phase: 0
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: "/"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: "bigfile/auth"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: "api/analysis/upload"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ ".*\.(js|css|png|jpg|jpeg|gif|tif)?$"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ "[^/]\.php(/|$)"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ "^/SystemDocumentation"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ "^/LicensingDocumentation"
2017/09/21 12:09:31 [debug] 22090#0: *60 using configuration "/api/analysis/upload"
2017/09/21 12:09:31 [debug] 22090#0: *60 rewrite phase: 0
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: "/"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: "bigfile/auth"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: "fileTooBigError.html"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: "lowDiskSpace.html"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ ".*\.(js|css|png|jpg|jpeg|gif|tif)?$"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ "[^/]\.php(/|$)"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ "^/SystemDocumentation"
2017/09/21 12:09:31 [debug] 22090#0: *60 test location: ~ "^/LicensingDocumentation"
2017/09/21 12:09:31 [debug] 22090#0: *60 using configuration "/lowDiskSpace.html"
2017/09/21 12:09:31 [debug] 22090#0: *60 http cl:1135591215 max:10737418240
2017/09/21 12:09:31 [debug] 22090#0: *60 rewrite phase: 2
2017/09/21 12:09:31 [debug] 22090#0: *60 post rewrite phase: 3
2017/09/21 12:09:31 [debug] 22090#0: *60 generic phase: 4
2017/09/21 12:09:31 [debug] 22090#0: *60 generic phase: 5
2017/09/21 12:09:31 [debug] 22090#0: *60 access phase: 6
2017/09/21 12:09:31 [debug] 22090#0: *60 access: 31CAA8C0 00000000 00000000
2017/09/21 12:09:31 [debug] 22090#0: *60 access phase: 7
2017/09/21 12:09:31 [debug] 22090#0: *60 access phase: 8
2017/09/21 12:09:31 [debug] 22090#0: *60 post access phase: 9
2017/09/21 12:09:31 [debug] 22090#0: *60 content phase: 10
2017/09/21 12:09:31 [debug] 22090#0: *60 content phase: 11
2017/09/21 12:09:31 [debug] 22090#0: *60 content phase: 12
2017/09/21 12:09:31 [debug] 22090#0: *60 http filename: "/opt/lib/endor/errorPages/lowDiskSpace.html"
2017/09/21 12:09:31 [debug] 22090#0: *60 add cleanup: 0000000000EE4FA0
2017/09/21 12:09:31 [debug] 22090#0: *60 http static fd: 3
2017/09/21 12:09:31 [debug] 22090#0: *60 http set discard body
2017/09/21 12:09:31 [debug] 22090#0: *60 http read discarded body
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 4096 of 4096
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 4096 of 4096
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 4096 of 4096
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 4096 of 4096
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 4096 of 4096
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 4096 of 4096
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 2699 of 4096
2017/09/21 12:09:31 [debug] 22090#0: *60 HTTP/1.1 413 Request Entity Too Large
Server: nginx/1.13.0
Date: Thu, 21 Sep 2017 12:09:31 GMT
Content-Type: text/html
Content-Length: 310
Connection: keep-alive
ETag: "59bbd611-136"

And the process repeats every 30 seconds, a total of 4 times, the final attempt is terminated and cleaned up:

2017/09/21 12:11:00 [debug] 22090#0: *74 http run request: "/lowDiskSpace.html?"
2017/09/21 12:11:00 [debug] 22090#0: *74 http request empty handler
2017/09/21 12:11:00 [debug] 22090#0: *74 http run request: "/lowDiskSpace.html?"
2017/09/21 12:11:00 [debug] 22090#0: *74 http read discarded body
2017/09/21 12:11:00 [debug] 22090#0: *74 recv: eof:0, avail:1
2017/09/21 12:11:00 [debug] 22090#0: *74 recv: fd:3 4096 of 4096
2017/09/21 12:11:00 [debug] 22090#0: *74 recv: eof:0, avail:1
2017/09/21 12:11:00 [debug] 22090#0: *74 recv: fd:3 284 of 4096
2017/09/21 12:11:00 [debug] 22090#0: *74 event timer: 3, old: 1505995861900, new: 1505995861999

2017/09/21 12:11:00 [debug] 22090#0: *74 http run request: "/lowDiskSpace.html?"
2017/09/21 12:11:00 [debug] 22090#0: *74 http request empty handler
2017/09/21 12:11:00 [debug] 22090#0: *74 http run request: "/lowDiskSpace.html?"
2017/09/21 12:11:00 [debug] 22090#0: *74 http read discarded body
2017/09/21 12:11:00 [debug] 22090#0: *74 recv: eof:0, avail:1
2017/09/21 12:11:00 [debug] 22090#0: *74 recv: fd:3 2920 of 4096
2017/09/21 12:11:00 [debug] 22090#0: *74 event timer: 3, old: 1505995861900, new: 1505995861999

2017/09/21 12:11:00 [debug] 22090#0: *74 http run request: "/lowDiskSpace.html?"
2017/09/21 12:11:00 [debug] 22090#0: *74 http request empty handler
2017/09/21 12:11:01 [debug] 22090#0: *74 http run request: "/lowDiskSpace.html?"

2017/09/21 12:11:01 [debug] 22090#0: *74 http finalize request: -1, "/lowDiskSpace.html?" a:1, c:1

2017/09/21 12:11:01 [debug] 22090#0: *74 http terminate request count:1
2017/09/21 12:11:01 [debug] 22090#0: *74 http terminate cleanup count:1 blk:0
2017/09/21 12:11:01 [debug] 22090#0: *74 http posted request: "/lowDiskSpace.html?"
2017/09/21 12:11:01 [debug] 22090#0: *74 http terminate handler count:1
2017/09/21 12:11:01 [debug] 22090#0: *74 http request count:1 blk:0
2017/09/21 12:11:01 [debug] 22090#0: *74 http close request
2017/09/21 12:11:01 [debug] 22090#0: *74 http log handler

2017/09/21 12:11:01 [debug] 22090#0: *74 run cleanup: 0000000000EE4FA0
2017/09/21 12:11:01 [debug] 22090#0: *74 file cleanup: fd:15
2017/09/21 12:11:01 [debug] 22090#0: *74 free: 0000000000EE57E0
2017/09/21 12:11:01 [debug] 22090#0: *74 free: 0000000000E92E20, unused: 4
2017/09/21 12:11:01 [debug] 22090#0: *74 free: 0000000000EE37C0, unused: 3
2017/09/21 12:11:01 [debug] 22090#0: *74 free: 0000000000EE47D0, unused: 1304
2017/09/21 12:11:01 [debug] 22090#0: *74 close http connection: 3
2017/09/21 12:11:01 [debug] 22090#0: *74 event timer del: 3: 1505995861900
2017/09/21 12:11:01 [debug] 22090#0: *74 reusable connection: 0
2017/09/21 12:11:01 [debug] 22090#0: *74 free: 0000000000E8B350
2017/09/21 12:11:01 [debug] 22090#0: *74 free: 0000000000EAEFD0, unused: 136

In the 5MB log file a similar process is logged however it appears to resolve (http finalize request: -4) within a second of logs:


..

2017/09/21 12:06:41 [debug] 21560#0: *1 http run request: "/lowDiskSpace.html?"
2017/09/21 12:06:41 [debug] 21560#0: *1 http request empty handler
2017/09/21 12:06:41 [debug] 21560#0: *1 http run request: "/lowDiskSpace.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, "/lowDiskSpace.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
2017/09/21 12:06:41 [debug] 21560#0: *1 event timer del: 3: 1505995606279
2017/09/21 12:06:41 [debug] 21560#0: *1 event timer add: 3: 65000:1505995666379
2017/09/21 12:06:41 [debug] 21560#0: *1 post event 00000000018F7860
2017/09/21 12:06:41 [debug] 21560#0: *1 http empty handler
2017/09/21 12:06:41 [debug] 21560#0: *1 delete posted event 00000000018F7860
2017/09/21 12:06:41 [debug] 21560#0: *1 http keepalive handler
2017/09/21 12:06:41 [debug] 21560#0: *1 malloc: 00000000018B4450:1024
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 -1 of 1024
2017/09/21 12:06:41 [debug] 21560#0: *1 recv() not ready (11: Resource temporarily unavailable)
2017/09/21 12:06:41 [debug] 21560#0: *1 free: 00000000018B4450

The nginx-upload-error.log shows:

2017/09/21 12:09:01 [debug] 22090#0: *1 http cl:1135591215 max:10737418240
2017/09/21 12:09:01 [debug] 22090#0: *1 rewrite phase: 2
2017/09/21 12:09:01 [debug] 22090#0: *1 post rewrite phase: 3
2017/09/21 12:09:01 [debug] 22090#0: *1 generic phase: 4
2017/09/21 12:09:01 [debug] 22090#0: *1 generic phase: 5
2017/09/21 12:09:01 [debug] 22090#0: *1 access phase: 6
2017/09/21 12:09:01 [debug] 22090#0: *1 access phase: 7
2017/09/21 12:09:01 [debug] 22090#0: *1 access phase: 8
2017/09/21 12:09:01 [debug] 22090#0: *1 auth request handler
2017/09/21 12:09:01 [debug] 22090#0: *1 http subrequest "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http posted request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 rewrite phase: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 test location: "/"
2017/09/21 12:09:01 [debug] 22090#0: *1 test location: "bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 test location: ~ ".*\.(js|css|png|jpg|jpeg|gif|tif)?$"
2017/09/21 12:09:01 [debug] 22090#0: *1 test location: ~ "[^/]\.php(/|$)"
2017/09/21 12:09:01 [debug] 22090#0: *1 test location: ~ "^/SystemDocumentation"
2017/09/21 12:09:01 [debug] 22090#0: *1 test location: ~ "^/LicensingDocumentation"
2017/09/21 12:09:01 [debug] 22090#0: *1 using configuration "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http cl:1135591215 max:10737418240
2017/09/21 12:09:01 [debug] 22090#0: *1 rewrite phase: 2
2017/09/21 12:09:01 [debug] 22090#0: *1 post rewrite phase: 3
2017/09/21 12:09:01 [debug] 22090#0: *1 generic phase: 4
2017/09/21 12:09:01 [debug] 22090#0: *1 generic phase: 5
2017/09/21 12:09:01 [debug] 22090#0: *1 posix_memalign: 0000000000EE47D0:4096 @16

2017/09/21 12:09:01 [debug] 22090#0: *1 http init upstream, client timer: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "QUERY_STRING"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "QUERY_STRING: "
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "REQUEST_METHOD"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "POST"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "REQUEST_METHOD: POST"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "CONTENT_TYPE"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "multipart/form-data; boundary=----WebKitFormBoundaryhlOaPFKP1MDW9O73"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "CONTENT_TYPE: multipart/form-data; boundary=----WebKitFormBoundaryhlOaPFKP1MDW9O73"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "CONTENT_LENGTH"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "1135591215"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "CONTENT_LENGTH: 1135591215"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SCRIPT_NAME"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SCRIPT_NAME: /bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "REQUEST_URI"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "/api/analysis/upload"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "REQUEST_URI: /api/analysis/upload"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "DOCUMENT_URI"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "DOCUMENT_URI: /bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "DOCUMENT_ROOT"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "/opt/lib/endor"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "DOCUMENT_ROOT: /opt/lib/endor"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SERVER_PROTOCOL"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "HTTP/1.1"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SERVER_PROTOCOL: HTTP/1.1"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: ""
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "GATEWAY_INTERFACE"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "CGI/1.1"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "GATEWAY_INTERFACE: CGI/1.1"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SERVER_SOFTWARE"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "nginx/"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "1.13.0"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SERVER_SOFTWARE: nginx/1.13.0"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "REMOTE_ADDR"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "192.168.202.49"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "REMOTE_ADDR: 192.168.202.49"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "REMOTE_PORT"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "56912"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "REMOTE_PORT: 56912"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SERVER_ADDR"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "127.0.0.1"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SERVER_ADDR: 127.0.0.1"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SERVER_PORT"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "8000"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SERVER_PORT: 8000"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SERVER_NAME"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: ""
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SERVER_NAME: "
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "PATH_INFO"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "PATH_INFO: "
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SCRIPT_FILENAME"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "/opt/lib/endor"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SCRIPT_FILENAME: /opt/lib/endor/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "REDIRECT_STATUS"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "200"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "REDIRECT_STATUS: 200"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "PHP_VALUE"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "upload_max_filesize=10G
post_max_size=10G"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "PHP_VALUE: upload_max_filesize=10G
post_max_size=10G"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "BIGFILE_UPLOAD_SIZE"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "1135591215"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "BIGFILE_UPLOAD_SIZE: 1135591215"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "BIGFILE_UPLOAD_MARGIN_BYTES"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "10737418240"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "BIGFILE_UPLOAD_MARGIN_BYTES: 10737418240"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "HOME_FOLDER"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "/home/instrument"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "HOME_FOLDER: /home/instrument"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "DEST_FOLDER"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "Analysis/Filters"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "DEST_FOLDER: Analysis/Filters"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "CONTENT_LENGTH"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "CONTENT_LENGTH: "
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "SCRIPT_FILENAME"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script var: "/opt/lib/endor"
2017/09/21 12:09:01 [debug] 22090#0: *1 http script copy: "/PHP/pcapAuthUpload.php"
2017/09/21 12:09:01 [debug] 22090#0: *1 fastcgi param: "SCRIPT_FILENAME: /opt/lib/endor/PHP/pcapAuthUpload.php"

2017/09/21 12:09:01 [debug] 22090#0: *1 http cleanup add: 0000000000EE4D00
2017/09/21 12:09:01 [debug] 22090#0: *1 get rr peer, try: 1
2017/09/21 12:09:01 [debug] 22090#0: *1 stream socket 21
2017/09/21 12:09:01 [debug] 22090#0: *1 epoll add connection: fd:21 ev:80002005
2017/09/21 12:09:01 [debug] 22090#0: *1 connect to unix:/opt/tmp/php-fpm.sock, fd:21 #70
2017/09/21 12:09:01 [debug] 22090#0: *1 connected
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream connect: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 posix_memalign: 0000000000E8B1F0:128 @16
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream send request
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream send request body
2017/09/21 12:09:01 [debug] 22090#0: *1 chain writer buf fl:0 s:808
2017/09/21 12:09:01 [debug] 22090#0: *1 chain writer in: 0000000000EE4D40
2017/09/21 12:09:01 [debug] 22090#0: *1 writev: 808 of 808
2017/09/21 12:09:01 [debug] 22090#0: *1 chain writer out: 0000000000000000
2017/09/21 12:09:01 [debug] 22090#0: *1 event timer add: 21: 60000:1505995801838
2017/09/21 12:09:01 [debug] 22090#0: *1 http finalize request: -4, "/bigfile/auth?" a:1, c:3
2017/09/21 12:09:01 [debug] 22090#0: *1 http request count:3 blk:0
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:1, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:0, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bgifile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:1, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream request: "/bigfile/auth?"

2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream dummy handler

2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:0, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:1, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bgifile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:0, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:1, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:0, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:1, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:0, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:1, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:0, "/bgifile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http run request: "/bigfile/auth?"

2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream check client, write event:1, "/bigfile/auth"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream request: "/bigfile/auth?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http upstream process header
2017/09/21 12:09:01 [debug] 22090#0: *1 malloc: 0000000000EE57E0:4096
2017/09/21 12:09:01 [debug] 22090#0: *1 recv: eof:1, avail:1
2017/09/21 12:09:01 [debug] 22090#0: *1 recv: fd:21 120 of 4096
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 01
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 06
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 00
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 01
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 00
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 5B
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 05
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record byte: 00
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi record length: 91
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi parser: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi header: "Status: 403 Forbidden"
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi parser: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi header: "X-Powered-By: PHP/5.6.27"
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi parser: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi header: "Content-type: text/html; charset=UTF-8"
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi parser: 1
2017/09/21 12:09:01 [debug] 22090#0: *1 http fastcgi header done

2017/09/21 12:09:01 [debug] 22090#0: *1 finalize http upstream request: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 finalize http fastcgi request
2017/09/21 12:09:01 [debug] 22090#0: *1 free rr peer 1 0

2017/09/21 12:09:01 [debug] 22090#0: *1 close http upstream connection: 21
2017/09/21 12:09:01 [debug] 22090#0: *1 free: 0000000000E8B1F0, unused: 48
2017/09/21 12:09:01 [debug] 22090#0: *1 event timer del: 21: 1505995801838
2017/09/21 12:09:01 [debug] 22090#0: *1 reusable connection: 0
2017/09/21 12:09:01 [debug] 22090#0: *1 http finalize request: 0, "/bigfile/auth?" a:1, c:2

2017/09/21 12:09:01 [debug] 22090#0: *1 auth request done s:403
2017/09/21 12:09:01 [debug] 22090#0: *1 http wake parent request: "/api/analysis/upload?"
2017/09/21 12:09:01 [debug] 22090#0: *1 http posted request: "/api/analysis/upload?"

2017/09/21 12:09:01 [debug] 22090#0: *1 access phase: 8
2017/09/21 12:09:01 [debug] 22090#0: *1 auth request handler
2017/09/21 12:09:01 [debug] 22090#0: *1 auth request set variables

2017/09/21 12:09:01 [debug] 22090#0: *1 http finalize request: 403, "/api/analysis/upload?" a:1, c:1
2017/09/21 12:09:01 [debug] 22090#0: *1 http special response: 403, "/api/analysis/upload?"
2017/09/21 12:09:01 [debug] 22090#0: *1 internal redirect: "/lowDiskSpace.html?"

In the 5MB file case this log has the same content as above (other than the time stamps), the above is an extract from the 1.1GB case where the above is repeated 4 times matching the 4 calls to the authorization script (subsequent blocks have different log ids i.e.

2017/09/21 12:09:31 [debug] 22090#0: *60 http cl:1135591215 max:10737418240
..
2017/09/21 12:10:01 [debug] 22090#0: *57 http cl:1135591215 max:10737418240
..
2017/09/21 12:10:31 [debug] 22090#0: *74 http cl:1135591215 max:10737418240
..
In each case the log suggests that the script is returning successfully with the expected 403 error.

In the nginx-error-all.log the only other logging is from our XSockets processing:

2017/09/21 12:09:02 [debug] 22090#0: *47 http upstream request: "/Realtime?XSocketsClientStorageGuid=e1aedac6d2b7457f8a1d7d1207a77497"
2017/09/21 12:09:02 [debug] 22090#0: *47 http upstream process upgraded, fu:1
2017/09/21 12:09:02 [debug] 22090#0: *47 recv: eof:0, avail:1
2017/09/21 12:09:02 [debug] 22090#0: *47 recv: fd:20 98 of 4096
2017/09/21 12:09:02 [debug] 22090#0: *47 send: fd:19 98 of 98
2017/09/21 12:09:02 [debug] 22090#0: *47 event timer del: 20: 1506600541965
2017/09/21 12:09:02 [debug] 22090#0: *47 event timer add: 20: 604800000:1506600542421
2017/09/21 12:09:02 [debug] 22090#0: *47 http upstream request: "/Realtime?XSocketsClientStorageGuid=e1aedac6d2b7457f8a1d7d1207a77497"
2017/09/21 12:09:02 [debug] 22090#0: *47 http upstream process upgraded, fu:0
2017/09/21 12:09:02 [debug] 22090#0: *47 event timer: 20, old: 1506600542421, new: 1506600542421

It is present in both 1.1GB & 5MB file logs and doesn't appear to be causing any problems, this processing reflects a regular update to instrument statistics gathered in our instrument database, ordinarily clients would respond to this notification by requesting updated stats data, i deliberately disabled this mechanism before running these tests to avoid extra noise in the logs.

Hopefully this sheds some light on the problem? I can provide the raw log files if it would help.

Could it be the file size and the fact that i am not buffering the request that is aggravating the issue? I need to disable buffering as the point of this is to avoid filling up the disk.

All suggestions/pointers as to what to try next are very welcome, many thanks for reading.

The log extract

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

should have read

2017/09/21 12:09:02 [debug] 22090#0: *1 http run request: "/lowDiskSpace.html?"