Prematurely deleting request body temp files on fast response

[nickfajones@…]

In a situation similar to: #1519:
if a request body is spooled to disk in a temp file,
and it is sufficiently large,
and the upstream response (headers) return before the request body has finished writing to upstream,

then the response handler will clean up the request body temp file, confounding the request that is still in progress.

I have a very rough and simple solution in the form of:

diff --git a/src/http/ngx_http_upstream.c b/src/http/ngx_http_upstream.c
index 3b69bf7..e80ceaf 100644
--- a/src/http/ngx_http_upstream.c
+++ b/src/http/ngx_http_upstream.c
@@ -2083,6 +2083,14 @@ ngx_http_upstream_send_request(ngx_http_request_t *r, ngx_http_upstream_t *u,
 
     /* rc == NGX_OK */
 
+    if (r->request_body && r->request_body->temp_file
+        && r->request_body->temp_file->file.fd != NGX_INVALID_FILE
+        && r == r->main && !r->preserve_body)
+    {
+        ngx_pool_run_cleanup_file(r->pool, r->request_body->temp_file->file.fd);
+        r->request_body->temp_file->file.fd = NGX_INVALID_FILE;
+    }
+
     if (c->write->timer_set) {
         ngx_del_timer(c->write);
     }
@@ -2993,7 +3001,8 @@ ngx_http_upstream_send_response(ngx_http_request_t *r, ngx_http_upstream_t *u)
     }
 
     if (r->request_body && r->request_body->temp_file
-        && r == r->main && !r->preserve_body)
+        && r->request_body->temp_file->file.fd != NGX_INVALID_FILE
+        && r == r->main && !r->preserve_body && u->request_body_sent)
     {
         ngx_pool_run_cleanup_file(r->pool, r->request_body->temp_file->file.fd);
         r->request_body->temp_file->file.fd = NGX_INVALID_FILE;

However, I am not convinced this is the best solution as subrequests share the request body temp file structure with the main request, and therefore need to participate in the cleanup decision.

I hope that someone who knows the codebase better can help to form a more complete solution to the problem.

Thanks.

[Maxim Dounin]

In a situation similar to: #1519:
if a request body is spooled to disk in a temp file,
and it is sufficiently large,
and the upstream response (headers) return before the request body has finished writing to upstream,
then the response handler will clean up the request body temp file, confounding the request that is still in progress.

Could you please provide exact configuration you seeing the issue with? With gRPC proxying nginx is not expected to work with disk-buffered request bodies (except in very specific situations), and without gRPC proxying nginx will stop sending the body after receiving response headers anyway.

However, I am not convinced this is the best solution as subrequests share the request body temp file structure with the main request, and therefore need to participate in the cleanup decision.

Clearly the suggested patch will break preserving body for SSI, see f583559aadc7 and #585.

[nickfajones@…]

Hi, sorry to take so long to get back to you.

First let me show you the original proof of concept minimal config I used to force this situation to occur:

daemon off;
master_process off;

worker_processes 1;

http {
  sendfile on;

  upstream fast_responder {
      server unix:/tmp/nginx/fast_responder.sock;

      keepalive 10;
    }

  server {
    listen 127.0.0.1:10080;

    server_name delete_request_file;

    root /tmp/nginx/prefix/www;

    error_log /dev/stderr debug;
    access_log /dev/null combined;

    location / {
      proxy_pass http://fast_responder;
      proxy_buffering off;
    }

  }
}

I created a fake upstream responder with the command:

echo -n -e "HTTP/1.1 200 OK\r\nContent-Length: 0\r\n\r\n" | nc -l -U /tmp/nginx/fast_responder.sock -q 20

I forgot to mention: In my current test environment, where I am using the suggested patch that I attached above, in that situation I am raising the preserve_output flag explicitly from an external module. I forgot to mention this previously, sorry about the confusion.

However, looking at my original proof of concept, I have demonstrated this is an issue for HTTP/1.1 and HTTP in general, not solely for gRPC over HTTP/2

Regarding your comment on my suggested solution:
I am not sure how it would break SSI, as it is careful to check that the request is the main request, and that the preserve_output flag is raised before deleting the file, in fact, it is probably too restrictive as the file might fail to be deleted.

How about this idea: move the final cleanup to: ngx_http_upstream_finalize_request
Clean up if the request is main however, don't check preserve_output as the main request should be the last user of the request body file, so don't need to preserve it for subrequests any more.

[Maxim Dounin]

In my current test environment, where I am using the suggested patch that I attached above, in that situation I am raising the preserve_output flag explicitly from an external module.

This is certainly not something supported.

However, looking at my original proof of concept, I have demonstrated this is an issue for HTTP/1.1 and HTTP in general, not solely for gRPC over HTTP/2

This is not an issue as long as u->conf->preserve_output is not set, since nginx will stop sending the body after receiving response headers from the upstream server. That is, this can only be a problem with gRPC proxying via grpc_pass, as this is the only module which is expected to set u->conf->preserve_output.

I think it is possible to reproduce the problem with grpc_pass though. Despite the fact that grpc_pass uses non-buffered request body reading, it still can happen to be disk-buffered due to previous processing. I was able to trigger the problem using the following configuration:

client_max_body_size 1g;

server {
    listen 8080;

    location / {
        proxy_pass http://127.0.0.1:8081;
        error_page 502 = @fallback;
    }

    location @fallback {
        grpc_pass 127.0.0.1:9000;
    }
}

server {
    listen 8081;
    return 444;
}

server {
    listen 9000 http2;
    limit_rate 10;
}

Tested with:

$ curl --data-binary @32m http://127.0.0.1:8080/
curl: (18) transfer closed with 173 bytes remaining to read

Seen in logs:

2018/06/07 06:20:27 [crit] 2550#0: *11 pread() "/path/to/client_body_temp/0000000003" failed (9: Bad file descriptor) while sending request to upstream, client: 127.0.0.1, server: , request: "POST / HTTP/1.1", upstream: "grpc://127.0.0.1:9000", host: "127.0.0.1:8080"

Or with sendfile enabled:

2018/06/07 06:22:26 [alert] 2574#0: *1 sendfile() failed (9: Bad file descriptor) while sending request to upstream, client: 127.0.0.1, server: , request: "POST / HTTP/1.1", upstream: "grpc://127.0.0.1:9000", host: "127.0.0.1:8080"

I am not sure how it would break SSI, as it is careful to check that the request is the main request, and that the preserve_output flag is raised before deleting the file

You check that r->preserve_body is not set, but this is not enough since in most cases the check will happen before calling ngx_http_send_header(), and so the r->preserve_body won't be set yet. As such, the bug described in #585 will be re-introduced.

How about this idea: move the final cleanup to: ngx_http_upstream_finalize_request

This will mean that nginx won't be able to free a no-longer-needed request body till it obtains full response from the upstream server. In some cases this might be much later than obtaining response headers, and hence will degrade existing optimization.

Rather, most simple solution would be to disable the early cleanup completely if u->conf->preserve_output is set:

# HG changeset patch
# User Maxim Dounin <mdounin@mdounin.ru>
# Date 1528342838 -10800
#      Thu Jun 07 06:40:38 2018 +0300
# Node ID 9079895bad5b9d8b5941c78105926d76b189a3b3
# Parent  3482c069e050592f074dfd0e8222efae770fbbbd
Upstream: disable body cleanup with preserve_output (ticket #1565).

With u->conf->preserve_output set the request body file might be used
after the response header is sent, so avoid cleaning it.  (Normally
this is not a problem as u->conf->preserve_output is only set with
r->request_body_no_buffering, but the request body might be already
read to a file in a different context.)

diff --git a/src/http/ngx_http_upstream.c b/src/http/ngx_http_upstream.c
--- a/src/http/ngx_http_upstream.c
+++ b/src/http/ngx_http_upstream.c
@@ -2901,7 +2901,8 @@ ngx_http_upstream_send_response(ngx_http
     }
 
     if (r->request_body && r->request_body->temp_file
-        && r == r->main && !r->preserve_body)
+        && r == r->main && !r->preserve_body
+        && !u->conf->preserve_output)
     {
         ngx_pool_run_cleanup_file(r->pool, r->request_body->temp_file->file.fd);
         r->request_body->temp_file->file.fd = NGX_INVALID_FILE;

[Maxim Dounin <mdounin@…>]

In 7297:a10e5fe44762/nginx:

Upstream: disable body cleanup with preserve_output (ticket #1565).

With u->conf->preserve_output set the request body file might be used
after the response header is sent, so avoid cleaning it. (Normally
this is not a problem as u->conf->preserve_output is only set with
r->request_body_no_buffering, but the request body might be already
written to a file in a different context.)

[Maxim Dounin]

Patch committed, thanks for reporting this.

[Sergey Kandaurov <pluknet@…>]

In 1353:65730ba03b42/nginx-tests:

Tests: body cleanup test with preserve_output (ticket #1565).

[Maxim Dounin <mdounin@…>]

In 7409:17ee239ae2e6/nginx:

Upstream: disable body cleanup with preserve_output (ticket #1565).

With u->conf->preserve_output set the request body file might be used
after the response header is sent, so avoid cleaning it. (Normally
this is not a problem as u->conf->preserve_output is only set with
r->request_body_no_buffering, but the request body might be already
written to a file in a different context.)