"a client request body is buffered to a temporary file"

[robertlemmen]

hi, we are seeing many entries of the above type in the esp logs, and also observe unexplained latencies that could be related:

2018/05/24 06:52:13 [warn] 12#12: 1 a client request body is buffered to a temporary file /var/cache/nginx/client_temp/0000000002, client: , server: , request: "POST /************************ HTTP/2.0", host: "*******************************"

the call is a GRPC call, and less than 200 bytes in body size. /etc/nginx/endpoints/nginx.conf in the container says "client_body_buffer_size 128k;", so it's not "just" nginx config or a large request.

please let me know if there is anything I can do to shed some more light on this

[robertlemmen]

fwiw, the stack trace where that line is emitted:

#0 0x0000000000717074 in ngx_http_write_request_body ()
#1 0x0000000000717cb3 in ngx_http_request_body_save_filter ()
#2 0x000000000070280c in ngx_http_v2_filter_request_body ()
#3 0x0000000000702cc8 in ngx_http_v2_process_request_body ()
#4 0x0000000000705741 in ngx_http_v2_read_request_body ()
#5 0x0000000000717663 in ngx_http_read_client_request_body ()
#6 0x000000000041690a in google::api_manager::nginx::NgxEspGrpcServerCall::ProcessPrereadRequestBody() ()
#7 0x0000000000415cee in google::api_manager::nginx::NgxEspGrpcPassThroughServerCall::Create(ngx_http_request_s*, std::shared_ptrgoogle::api_manager::nginx::NgxEspGrpcPassThroughServerCall) ()
#8 0x0000000000412a6b in google::api_manager::nginx::(anonymous namespace)::GrpcBackendHandler(ngx_http_request_s)
()
#9 0x0000000000729552 in ngx_http_core_content_phase ()
#10 0x0000000000723c75 in ngx_http_core_run_phases ()
#11 0x0000000000758e78 in ngx_event_process_posted ()
#12 0x00000000007552c2 in ngx_worker_process_cycle ()
#13 0x000000000075705e in ngx_spawn_process ()
#14 0x00000000007554a4 in ngx_start_worker_processes ()
#15 0x0000000000755e9b in ngx_master_process_cycle ()
#16 0x00000000007457f4 in ngx_main ()

[qiwzhang]

@lizan @PiotrSikora Any ideas?

[marwan-at-work]

I'm experiencing the same issue.

[marwan-at-work]

@qiwzhang @lizan @PiotrSikora any idea how this can be fixed or at least suppress until fixed?

[qiwzhang]

@marwan-at-work and @robertlemmen

could you help provide: 1) which version of ESP are you using, in which platform, FLEX, or GKE? 2) Is it possible to generate debug log when this happen? If you login into ESP container, there is a script /usr/sbin/debug_nginx.sh. You can run it as /usr/sbin/debug_nginx.sh start.

[marwan-at-work]

@qiwzhang

1. I'm running ESP on GKE, this is the image/version that I run image: gcr.io/endpoints-release/endpoints-runtime:1

2. I've ran the script as you suggested and it exited right away. Will I see the debug output in a specific file or directly on the UI logs in GCP?

[marwan-at-work]

@qiwzhang also i have 4 replicas for the ESP container, should I run the debug script on all of them or just one? I have it on on only one so far.

[qiwzhang]

@marwan-at-work you can use "kubectl logs POD -c esp " to get the debug log after you run that script.

If you can capture the debug log with the error "a client request body is buffered to a temporary file " for that pod, it should be good enough. Otherwise, you may have to turn it for all your pods.

[marwan-at-work]

@qiwzhang ah, I was already seeing that log (I wasn't sure if the debug flag would have given it more info) but here is what im getting (obfuscating service name):

2018/09/24 17:37:45 [warn] 14#14: *5 a client request body is buffered to a temporary file /var/cache/nginx/client_temp/0000000315, client: 10.254.0.6, server: , request: "POST /serviceName/serviceMethod HTTP/2.0", host: "service-name:9000"

[qiwzhang]

Could you give me the logs around this line? I hope it has debug on.

[qiwzhang]

Otherwise, the script to turn debug on is not working. may have to debug the script.

[qiwzhang]

Could you check the size of this file /usr/sbin/nginx-debug. It should be very big, it is the nginx binary with debug symbol.