grpc-go client disconnect in 60 seconds

[aagrawal]

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