Hi ,
I am using grpc-go client for grpc subscription, and in every 60 seconds
after subscription , it is disconnecting.
I run nginx in debug mode, and found following logs where i see that "408"
error happened , because "client_body_timeout is default value 60 seconds."
i am using nginx 1.16.1
2020/11/10 10:57:05 [debug] 2670#0: *1 event timer del: 3: 12588176
2020/11/10 10:57:05 [debug] 2670#0: *1 http run request:
"/gnmi.gNMI/Subscribe?"
2020/11/10 10:57:05 [debug] 2670#0: *1 http upstream read request handler
2020/11/10 10:57:05 [debug] 2670#0: *1 finalize http upstream request: 408
2020/11/10 10:57:05 [debug] 2670#0: *1 finalize grpc request
2020/11/10 10:57:05 [debug] 2670#0: *1 free rr peer 1 0
2020/11/10 10:57:05 [debug] 2670#0: *1 close http upstream connection: 25
2020/11/10 10:57:05 [debug] 2670#0: *1 run cleanup: 097FE508
2020/11/10 10:57:05 [debug] 2670#0: *1 free: 097FE4E0, unused: 60
2020/11/10 10:57:05 [debug] 2670#0: *1 event timer del: 25: 16184227
2020/11/10 10:57:05 [debug] 2670#0: *1 reusable connection: 0
2020/11/10 10:57:05 [debug] 2670#0: *1 http finalize request: 408,
"/gnmi.gNMI/Subscribe?" a:1, c:1
2020/11/10 10:57:05 [debug] 2670#0: *1 http terminate request count:1
2020/11/10 10:57:05 [debug] 2670#0: *1 http terminate cleanup count:1 blk:0
2020/11/10 10:57:05 [debug] 2670#0: *1 http posted request:
"/gnmi.gNMI/Subscribe?"
2020/11/10 10:57:05 [debug] 2670#0: *1 http terminate handler count:1
2020/11/10 10:57:05 [debug] 2670#0: *1 http request count:1 blk:0
2020/11/10 10:57:05 [debug] 2670#0: *1 http2 close stream 1, queued 0,
processing 1, pushing 0
2020/11/10 10:57:05 [debug] 2670#0: *1 http2 send RST_STREAM frame sid:1,
status:1
2020/11/10 10:57:05 [debug] 2670#0: *1 http close request
2020/11/10 10:57:05 [debug] 2670#0: *1 http log handler
2020/11/10 10:57:05 [debug] 2670#0: *1 run cleanup: 09852B5C
2020/11/10 10:57:05 [debug] 2670#0: *1 free: 09853E38
2020/11/10 10:57:05 [debug] 2670#0: *1 free: 098A3518
2020/11/10 10:57:05 [debug] 2670#0: *1 free: 09851E00, unused: 0
2020/11/10 10:57:05 [debug] 2670#0: *1 free: 09852E20, unused: 2045
2020/11/10 10:57:05 [debug] 2670#0: *1 free: 097FDF40, unused: 847
2020/11/10 10:57:05 [debug] 2670#0: *1 post event 097FA190
2020/11/10 10:57:05 [debug] 2670#0: *1 delete posted event 097FA190
2020/11/10 10:57:05 [debug] 2670#0: *1 http2 handle connection handler
2020/11/10 10:57:05 [debug] 2670#0: *1 http2 frame out: 09831A48 sid:0 bl:0
len:4
2020/11/10 10:57:05 [debug] 2670#0: *1 SSL buf copy: 13
2020/11/10 10:57:05 [debug] 2670#0: *1 SSL to write: 13
2020/11/10 10:57:05 [debug] 2670#0: *1 SSL_write: 13
2020/11/10 10:57:05 [debug] 2670#0: *1 http2 frame sent: 09831A48 sid:0 bl:0
len:4
2020/11/10 10:57:05 [debug] 2670#0: *1 free: 09831A20, unused: 3672
2020/11/10 10:57:05 [debug] 2670#0: *1 free: 098B3520
2020/11/10 10:57:05 [debug] 2670#0: *1 reusable connection: 1
2020/11/10 10:57:05 [debug] 2670#0: *1 event timer add: 3: 180000:12768251
2020/11/10 10:57:06 [debug] 2670#0: *1 http2 idle handler
2020/11/10 10:57:06 [debug] 2670#0: *1 reusable connection: 0
2020/11/10 10:57:06 [debug] 2670#0: *1 posix_memalign: 09831A20:4096 @16
2020/11/10 10:57:06 [debug] 2670#0: *1 http2 read handler
2020/11/10 10:57:06 [debug] 2670#0: *1 SSL_read: -1
2020/11/10 10:57:06 [debug] 2670#0: *1 SSL_get_error: 5
2020/11/10 10:57:06 [debug] 2670#0: *1 peer shutdown SSL cleanly
2020/11/10 10:57:06 [debug] 2670#0: *1 close http connection: 3
2020/11/10 10:57:06 [debug] 2670#0: *1 SSL_shutdown: 1
2020/11/10 10:57:06 [debug] 2670#0: *1 event timer del: 3: 12768251
2020/11/10 10:57:06 [debug] 2670#0: *1 reusable connection: 0
2020/11/10 10:57:06 [debug] 2670#0: *1 run cleanup: 097F5670
2020/11/10 10:57:06 [debug] 2670#0: *1 free: 09831A20, unused: 4056
2020/11/10 10:57:06 [debug] 2670#0: *1 free: 00000000
2020/11/10 10:57:06 [debug] 2670#0: *1 free: 097FCEF8
2020/11/10 10:57:06 [debug] 2670#0: *1 free: 097FE8B0
2020/11/10 10:57:06 [debug] 2670#0: *1 free: 098458E8
2020/11/10 10:57:06 [debug] 2670#0: *1 free: 097F55A0, unused: 4
2020/11/10 10:57:06 [debug] 2670#0: *1 free: 09845CE0, unused: 4
2020/11/10 10:57:06 [debug] 2670#0: *1 free: 09830E40, unused: 136
Following is my nginx conf file
http {
include mime.types;
default_type application/octet-stream;
#log_format main '$remote_addr - $remote_user [$time_local] "$request"
'
# '$status $body_bytes_sent "$http_referer" '
# '"$http_user_agent" "$http_x_forwarded_for"';
#access_log /tmp/access.log main;
access_log /tmp/access.log;
sendfile on;
#tcp_nopush on;
keepalive_timeout 180;
proxy_read_timeout 120s;
proxy_send_timeout 120s;
client_body_timeout 360s;
limit_conn_zone localhost zone=servers:10m;
map $http_upgrade $connection_upgrade {
default upgrade;
'' close;
}
I tried increasing this client_body_timeout directive to 360 seconds, i see
that grpc-go client disconnect in 360 seconds.
Same issue was not observed when i run grpc-java client or grpc-python
client .
Can you please help me to know why this issue may happen ?
Thanks
Posted at Nginx Forum:
https://forum.nginx.org/read.php?2,289945,289945#msg-289945
_______________________________________________
nginx mailing list
nginx@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx
