Welcome! Log In Create A New Profile

Advanced

grpc-go client disconnect in 60 seconds

November 10, 2020 07:56AM
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
Subject Author Posted

grpc-go client disconnect in 60 seconds

aagrawal November 10, 2020 07:56AM

Re: grpc-go client disconnect in 60 seconds

Maxim Dounin November 10, 2020 08:42AM

Re: grpc-go client disconnect in 60 seconds

aagrawal November 10, 2020 08:59AM

Re: grpc-go client disconnect in 60 seconds

Maxim Dounin November 10, 2020 09:32AM



Sorry, only registered users may post in this forum.

Click here to login

Online Users

Guests: 71
Record Number of Users: 6 on February 13, 2018
Record Number of Guests: 421 on December 02, 2018
Powered by nginx      Powered by FreeBSD      PHP Powered      Powered by MariaDB      ipv6 ready