GRPC request is sometimes buffered to a temporary file

[ric...@kramphub.com]

I'm making use of ESP in front of a Java GRPC service (running in the same POD in a Kubernetes cluster) and noticed that our logs often contain a warning about the client request being buffered.

E.g.: a client request body is buffered to a temporary file /var/cache/nginx/client_temp/0000000001

When searching for more information about the message it seemed that the client_body_buffer_size setting needed to be configured with a higher value.

Therefore I created an issue and pull request that would make this possible (https://github.com/cloudendpoints/endpoints-tools/issues/54).

This change was included in endpoints-runtime:1.16.0. But unfortunately the warning is still being logged when making use of this version.

In attempt to reproduce it locally I started the ESP Docker image (not making use of Kubernetes) and pointed it to the Java GRPC service running locally as well.

With a Java GRPC client I then called the service and indeed the warning message was logged.

But I noticed that the warning message about buffering is not logged for all requests.

Only after waiting a while before making a new request (~ 2 minutes) then the warning is logged again.

When capturing the requests with client_body_in_file_only on; then I can see that these files are only about 55 bytes in size.

So the requests from the client aren't really that large at all.

I'm hoping that somebody can tell me where this message is coming from and how I can disable this buffering.

It is not something critical but it would be nice to reduce the log messages from the ESP container in our logs.

I included the log that shows that for the second call the warning isn't logged:

INFO:Constructing an access token with scope https://www.googleapis.com/auth/service.management.readonly
INFO:Service account email: xxxxxxxxxxxx.iam.gserviceaccount.com
INFO:Refreshing access_token
INFO:Fetching the service configuration from the service management service
nginx: [warn] Using trusted CA certificates file: /etc/nginx/trusted-ca-certificates.crt
2018/04/17 10:18:42[info]11#11: Check_aggregation_options: num_entries: 10000, flush_interval_ms: 60000, expiration_ms: 300000, Report_aggregation_options: num_entries: 10000, flush_interval_ms: 1000
2018/04/17 10:18:43[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
2018/04/17 10:18:44[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
2018/04/17 10:18:45[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
2018/04/17 10:18:46[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
2018/04/17 10:18:47[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
2018/04/17 10:18:48[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
2018/04/17 10:18:49[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
//
// Making the first request
//
2018/04/17 10:18:50[debug]11#11: Request method SET TO: POST
2018/04/17 10:18:50[debug]11#11: Auth not required.
2018/04/17 10:18:50[info]11#11: Skipping Firebase Rules checks since it is disabled.
2018/04/17 10:18:50 [debug] 11#11: *1 GrpcBackendHandler: Handling request
2018/04/17 10:18:50 [debug] 11#11: *1 GrpcGetBackendAddress: using override address "docker.for.mac.localhost:9090"
2018/04/17 10:18:50 [debug] 11#11: *1 GrpcGetStub: connecting to backend=docker.for.mac.localhost:9090
2018/04/17 10:18:50 [warn] 11#11: *1 a client request body is buffered to a temporary file /var/cache/nginx/client_temp/0000000001, client: 172.17.0.1, server: , request: "POST /ContentService/GetContent HTTP/2.0", host: "localhost:9000"
172.17.0.1 - - [17/Apr/2018:10:18:50 +0000] "POST /ContentService/GetContent HTTP/2.0" 200 19605 "-" "grpc-java-netty/1.7.0"
2018/04/17 10:18:50[debug]11#11: Request method SET TO: POST
2018/04/17 10:18:50[debug]11#11: Received non-matching report response service config ID: '', requested: '2018-04-16r0'
2018/04/17 10:18:50[debug]11#11: Sending request to Cloud Trace.
2018/04/17 10:18:50[debug]11#11: {"traces": xxxxx omitted xxxxxx}
2018/04/17 10:18:51[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
2018/04/17 10:18:52[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
2018/04/17 10:18:53[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
2018/04/17 10:18:54[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
2018/04/17 10:18:55[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
2018/04/17 10:18:56[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
//
// Making the second request
//
2018/04/17 10:18:56[debug]11#11: Request method SET TO: POST
2018/04/17 10:18:56[debug]11#11: Auth not required.
2018/04/17 10:18:56[info]11#11: Skipping Firebase Rules checks since it is disabled.
2018/04/17 10:18:56 [debug] 11#11: *6 GrpcBackendHandler: Handling request
2018/04/17 10:18:56 [debug] 11#11: *6 GrpcGetBackendAddress: using override address "docker.for.mac.localhost:9090"
2018/04/17 10:18:56 [debug] 11#11: *6 GrpcGetStub: connecting to backend=docker.for.mac.localhost:9090
172.17.0.1 - - [17/Apr/2018:10:18:56 +0000] "POST /ContentService/GetContent HTTP/2.0" 200 19605 "-" "grpc-java-netty/1.7.0"
2018/04/17 10:18:56[debug]11#11: Request method SET TO: POST
2018/04/17 10:18:57[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
2018/04/17 10:18:58[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
2018/04/17 10:18:59[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.
2018/04/17 10:19:00[debug]11#11: Not sending request to CloudTrace: no traces or project_id is empty.

The nginx configuration from the container (I modified it here by reducing the number of blank lines):

# Auto-generated by start_esp
# Copyright 2017 Google Inc.
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
#     http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.


daemon off;

user nginx nginx;

pid /var/run/nginx.pid;

# Worker/connection processing limits
worker_processes 1;
worker_rlimit_nofile 10240;
events { worker_connections 10240; }


# Logging to stderr enables better integration with Docker and GKE/Kubernetes.
error_log stderr warn;


http {
  include /etc/nginx/mime.types;
  server_tokens off;
  client_max_body_size 32m;
  client_body_buffer_size 33m;

  error_log /dev/stdout debug;

  # HTTP subrequests
  endpoints_resolver 8.8.8.8;
  endpoints_certificates /etc/nginx/trusted-ca-certificates.crt;

  set_real_ip_from  0.0.0.0/0;
  set_real_ip_from  0::/0;
  real_ip_header    X-Forwarded-For;
  real_ip_recursive on;

  server {
    server_name "";


    listen 9000 http2 backlog=16384;

    access_log /dev/stdout;


    location / {
      # Begin Endpoints v2 Support
      endpoints {
        on;
        server_config /etc/nginx/server_config.pb.txt;
        google_authentication_secret /esp/serviceaccount.json;
      }
      # End Endpoints v2 Support


      # WARNING: only first backend is used
      grpc_pass docker.for.mac.localhost:9090 override;
    }

    include /var/lib/nginx/extra/*.conf;
  }


  server {
    # expose /nginx_status and /endpoints_status but on a different port to
    # avoid external visibility / conflicts with the app.
    listen 8090;
    location /nginx_status {
      stub_status on;
      access_log off;
    }
    location /endpoints_status {
      endpoints_status;
      access_log off;
    }
    location /healthz {
      return 200;
      access_log off;
    }
    location / {
      root /dev/null;
    }
  }
}

[lei...@google.com]

Forwarded to Lizan Zhou.

[tv...@slb.com]

Hi there, did you ever figure out something on this one? I also see these warnings and haven't found a configuration that resolves it.

Thanks

T.

On Tuesday, April 17, 2018 at 4:01:37 AM UTC-7, ric...@kramphub.com wrote:

[lei...@google.com]

ESP is based on nginx. The log message "a client request body is buffered to a temporary file" is not generated by ESP but by nginx (https://github.com/nginx/nginx/blob/master/src/http/ngx_http_request_body.c#L454). 

To filter out such log messages, you can pipe the log output through the sed command. Here are two examples to filter lines from a file, quoted from https://stackoverflow.com/questions/5410757/delete-lines-in-a-text-file-that-contain-a-specific-string:

- To remove the line and print the log output to standard out:

    sed '/pattern to match/d' ./infile
- To directly modify the log file:

    sed -i '/pattern to match/d' ./infile

On Tuesday, April 17, 2018 at 4:01:37 AM UTC-7, ric...@kramphub.com wrote:

[tv...@slb.com]

I'm less interested in filtering out the log messages than stopping the buffering from happening in the first place... Is there a way to achieve/reduce this? Playing with the buffer-sizes doesn't seem to have an effect, and it seems to happen for me pretty much independently of the size of the messages.

[lei...@google.com]

nginx buffers a request to either RAM or a temporary file before forwarding the request to the backend. When the request is buffered to a file, there is the log message "a client request body is buffered to a temporary file". There are articles on Internet about reducing these nginx log messages by increasing the RAM reserved for buffering the requests. When the RAM reserved is big enough to store the requests, the requests will be buffered in RAM, rather than in temporary files. The following are the links of a few of such articles:

- https://serverfault.com/questions/511789/nginx-client-request-body-is-buffered-to-a-temporary-file

- https://www.svennd.be/a-client-request-body-is-buffered-to-a-temporary-file/

- https://www.ruby-forum.com/topic/4410280

[ric...@kramphub.com]

That is also the behaviour I observed.