grpc keepalive does not effect, nginx will close connection by the minute
Sergey Kandaurov
pluknet at nginx.com
Thu Jan 24 15:41:40 UTC 2019
> On 24 Jan 2019, at 06:05, Roar <nginx-forum at forum.nginx.org> wrote:
>
> I recompile nginx with debug module follow your instruction and check all
> keepalive_timeout parameter.
> I tested my application at 2019/01/24 10:49:53 and it responsed correctly,
> and the connection between nginx and grpc server was closed as expected at
> 2019/01/24 10:50:53. Oops!
Ok, looking at debug log I see that keepalive settings don't apply
for your case since connection is closed during request processing.
> What sad is that I don't understand the output nginx debug log. Could you
> help me analyze the log?
>
TL;DR you need to tune client_body_timeout.
Looks like this is some sort of HTTP long polling.
Here's incomplete client request body seen in debug log.
While it's being received, an additional timer is installed, which
is controlled by the client_body_timeout directive (60s by default).
Since the next part of client request body was not received in time,
the connection is closed by timeout.
See comments inline for more details.
> Here is my nginx,application conf and debug output log:
>
> 【my nginx.conf】
> #user nobody;
> worker_processes 2;
> error_log logs/error.log debug;
> pid ./nginx.pid;
>
> events {
> worker_connections 1024;
> }
>
> http {
> include mime.types;
> default_type application/octet-stream;
>
> sendfile on;
> keepalive_timeout 120;
>
> server {
> listen 80;
> server_name localhost;
>
> location / {
> root html;
> index index.html index.htm;
> }
>
> error_page 500 502 503 504 /50x.html;
> location = /50x.html {
> root html;
> }
> }
>
> include /export/apps/middlewares/confd/conf.d/application.conf;
> }
>
>
> 【my application.conf】
> upstream ID_PUMPER {
> server 127.0.0.1:58548;
> }
>
> server {
> listen 8080 http2;
> grpc_read_timeout 300s;
> grpc_send_timeout 300s;
>
> location /utoProto.idProduce.IdProduce {
> grpc_pass grpc://ID_PUMPER;
> }
> }
>
>
> 【Debug output log】
> 2019/01/24 10:49:53 [debug] 36109#0: kevent events: 1
> 2019/01/24 10:49:53 [debug] 36108#0: kevent events: 1
> 2019/01/24 10:49:53 [debug] 36109#0: kevent: 10: ft:-1 fl:0005 ff:00000000
> d:1 ud:00007FBA2F01A868
> 2019/01/24 10:49:53 [debug] 36108#0: kevent: 10: ft:-1 fl:0005 ff:00000000
> d:1 ud:00007FBA2E02FC68
> 2019/01/24 10:49:53 [debug] 36109#0: accept on 0.0.0.0:8080, ready: 1
> 2019/01/24 10:49:53 [debug] 36108#0: accept on 0.0.0.0:8080, ready: 1
> 2019/01/24 10:49:53 [debug] 36108#0: accept() not ready (35: Resource
> temporarily unavailable)
> 2019/01/24 10:49:53 [debug] 36108#0: timer delta: 16721
> 2019/01/24 10:49:53 [debug] 36108#0: worker cycle
> 2019/01/24 10:49:53 [debug] 36109#0: posix_memalign: 00007FBA2D500D90:512
> @16
> 2019/01/24 10:49:53 [debug] 36108#0: kevent timer: -1, changes: 0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 accept: 127.0.0.1:50905 fd:3
> 2019/01/24 10:49:53 [debug] 36109#0: *10 event timer add: 3:
> 60000:266893796
client_header_timeout is installed,
to be removed after the entire header is read
> 2019/01/24 10:49:53 [debug] 36109#0: *10 reusable connection: 1
> 2019/01/24 10:49:53 [debug] 36109#0: *10 kevent set event: 3: ft:-1 fl:0025
> 2019/01/24 10:49:53 [debug] 36109#0: timer delta: 16721
> 2019/01/24 10:49:53 [debug] 36109#0: worker cycle
> 2019/01/24 10:49:53 [debug] 36109#0: kevent timer: 60000, changes: 1
> 2019/01/24 10:49:53 [debug] 36109#0: kevent events: 1
> 2019/01/24 10:49:53 [debug] 36109#0: kevent: 3: ft:-1 fl:0025 ff:00000000
> d:99 ud:00007FBA2F01A938
> 2019/01/24 10:49:53 [debug] 36109#0: *10 init http2 connection
> 2019/01/24 10:49:53 [debug] 36109#0: malloc: 000000010737C000:262144
> 2019/01/24 10:49:53 [debug] 36109#0: *10 posix_memalign:
> 00007FBA2D700180:512 @16
> 2019/01/24 10:49:53 [debug] 36109#0: *10 posix_memalign:
> 00007FBA2F003000:4096 @16
> 2019/01/24 10:49:53 [debug] 36109#0: *10 add cleanup: 00007FBA2D500E98
> 2019/01/24 10:49:53 [debug] 36109#0: *10 posix_memalign:
> 00007FBA2D700580:512 @16
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 send SETTINGS frame
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 send WINDOW_UPDATE frame
> sid:0, window:2147418112
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 read handler
> 2019/01/24 10:49:53 [debug] 36109#0: *10 recv: eof:0, avail:99, err:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 recv: fd:3 368 of 262112
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 preface verified
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame type:4 f:0 l:36 sid:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 SETTINGS frame
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 setting 2:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 setting 3:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 setting 4:4194304
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 setting 5:4194304
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 setting 6:8192
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 setting 65027:1
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame complete
> pos:000000010737C045 end:000000010737C170
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame type:8 f:0 l:4 sid:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 WINDOW_UPDATE frame sid:0
> window:4128769
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame complete
> pos:000000010737C052 end:000000010737C170
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame type:6 f:0 l:8 sid:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 PING frame
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame complete
> pos:000000010737C063 end:000000010737C170
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame type:1 f:4 l:242 sid:1
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 HEADERS frame sid:1 depends
> on 0 excl:0 weight:16
> 2019/01/24 10:49:53 [debug] 36109#0: *10 posix_memalign:
> 00007FBA2E02E600:1024 @16
> 2019/01/24 10:49:53 [debug] 36109#0: *10 posix_memalign:
> 00007FBA2E02EA00:4096 @16
> 2019/01/24 10:49:53 [debug] 36109#0: *10 posix_memalign:
> 00007FBA2E800400:4096 @16
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 get indexed header: 6
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 header: ":scheme: http"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 get indexed header: 3
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 header: ":method: POST"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 raw string, len:10
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 raw string, len:14
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 table add: ":authority:
> 127.0.0.1:8080"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 malloc: 00007FBA2D6005B0:512
> 2019/01/24 10:49:53 [debug] 36109#0: *10 malloc: 00007FBA2E801400:4096
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 table account: 56 free:4096
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 header: ":authority:
> 127.0.0.1:8080"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 raw string, len:5
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 raw string, len:42
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 table add: ":path:
> /utoProto.idProduce.IdProduce/getUniqueIds"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 table account: 79 free:4040
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http uri:
> "/utoProto.idProduce.IdProduce/getUniqueIds"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http args: ""
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http exten: ""
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 header: ":path:
> /utoProto.idProduce.IdProduce/getUniqueIds"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 raw string, len:2
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 raw string, len:8
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 table add: "te: trailers"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 table account: 42 free:3961
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 header: "te: trailers"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 raw string, len:12
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 raw string, len:16
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 table add: "content-type:
> application/grpc"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 table account: 60 free:3919
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 header: "content-type:
> application/grpc"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 raw string, len:10
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 raw string, len:31
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 table add: "user-agent:
> grpc-c/6.0.0 (osx; chttp2; gao)"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 table account: 73 free:3859
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 header: "user-agent:
> grpc-c/6.0.0 (osx; chttp2; gao)"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 raw string, len:20
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 raw string, len:21
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 table add:
> "grpc-accept-encoding: identity,deflate,gzip"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 table account: 73 free:3786
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 header:
> "grpc-accept-encoding: identity,deflate,gzip"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 raw string, len:15
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 raw string, len:13
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 table add: "accept-encoding:
> identity,gzip"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 table account: 60 free:3713
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 header: "accept-encoding:
> identity,gzip"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 request line: "POST
> /utoProto.idProduce.IdProduce/getUniqueIds HTTP/2.0"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 generic phase: 0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 rewrite phase: 1
> 2019/01/24 10:49:53 [debug] 36109#0: *10 test location:
> "/utoProto.idProduce.IdProduce"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 using configuration
> "/utoProto.idProduce.IdProduce"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http cl:-1 max:1048576
> 2019/01/24 10:49:53 [debug] 36109#0: *10 rewrite phase: 3
> 2019/01/24 10:49:53 [debug] 36109#0: *10 post rewrite phase: 4
> 2019/01/24 10:49:53 [debug] 36109#0: *10 generic phase: 5
> 2019/01/24 10:49:53 [debug] 36109#0: *10 generic phase: 6
> 2019/01/24 10:49:53 [debug] 36109#0: *10 generic phase: 7
> 2019/01/24 10:49:53 [debug] 36109#0: *10 access phase: 8
> 2019/01/24 10:49:53 [debug] 36109#0: *10 access phase: 9
> 2019/01/24 10:49:53 [debug] 36109#0: *10 post access phase: 10
> 2019/01/24 10:49:53 [debug] 36109#0: *10 generic phase: 11
> 2019/01/24 10:49:53 [debug] 36109#0: *10 generic phase: 12
> 2019/01/24 10:49:53 [debug] 36109#0: *10 malloc: 00007FBA2D837800:65536
> 2019/01/24 10:49:53 [debug] 36109#0: *10 event timer add: 3:
> 60000:266893810
client_body_timeout is installed since we're awaiting client body
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http init upstream, client timer:
> 1
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc header: ":method: POST"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc header: ":scheme: http"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc header: ":path:
> /utoProto.idProduce.IdProduce/getUniqueIds"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc header: ":authority:
> ID_PUMPER"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http script copy: ""
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http script copy: "TE"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http script var: "trailers"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc header: "te: trailers"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc header: "content-type:
> application/grpc"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc header: "user-agent:
> grpc-c/6.0.0 (osx; chttp2; gao)"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc header: "grpc-accept-encoding:
> identity,deflate,gzip"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc header: "accept-encoding:
> identity,gzip"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc header:
> 505249202a20485454502f322e300d0a0d0a534d0d0a0d0a00001204000000000000010000000000020000000000047fffffff0000040800000000007fff00000000aa0104000000018386449f62d49f5d8749d7349aec3c9690abe4935d8792d215898a9e151bb5a5c9223f4188c97e2d7c346bc1b700027465864d833505b11f008921ea496a4ac9f5597f8b1d75d0620d263d4c4d65640087b505b161cc5a93989acac8b11871702e053fa3a3cfda849d29ac5f6a4c33ff7f008e9acac8b0c842d6958b510f21aa9b903485a9264fafa90b2d03497ea6f66aff008b19085ad2b16a21e435537f8a3485a9264fafa9bd9abf,
> len: 243
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http cleanup add: 00007FBA2E801220
> 2019/01/24 10:49:53 [debug] 36109#0: *10 get rr peer, try: 1
> 2019/01/24 10:49:53 [debug] 36109#0: *10 stream socket 5
> 2019/01/24 10:49:53 [debug] 36109#0: *10 connect to 127.0.0.1:58548, fd:5
> #11
> 2019/01/24 10:49:53 [debug] 36109#0: *10 kevent set event: 5: ft:-1 fl:0025
> 2019/01/24 10:49:53 [debug] 36109#0: *10 kevent set event: 5: ft:-2 fl:0025
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream connect: -2
> 2019/01/24 10:49:53 [debug] 36109#0: *10 posix_memalign:
> 00007FBA2D500BB0:128 @16
> 2019/01/24 10:49:53 [debug] 36109#0: *10 event timer add: 5:
> 60000:266893810
grpc_connect_timeout is installed, to be removed after connection establishment
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http finalize request: -4,
> "/utoProto.idProduce.IdProduce/getUniqueIds?" a:1, c:2
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http request count:2 blk:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame complete
> pos:000000010737C15E end:000000010737C170
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame type:0 f:0 l:9 sid:1
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 DATA frame
> 2019/01/24 10:49:53 [debug] 36109#0: *10 event timer: 3, old: 266893810,
> new: 266893810
client_body_timeout is renewed after receiving client body part
the timer is not removed since this is not a final HTTP/2 DATA frame,
f:0 shows HTTP/2 frame flags, and there's no END_STREAM flag (0x1) set.
> 2019/01/24 10:49:53 [debug] 36109#0: *10 post event 00007FBA2F003400
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame complete
> pos:000000010737C170 end:000000010737C170
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame out: 00007FBA2F003268
> sid:0 bl:0 len:8
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame out: 00007FBA2F0031B8
> sid:0 bl:0 len:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame out: 00007FBA2F003108
> sid:0 bl:0 len:4
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame out: 00007FBA2F003050
> sid:0 bl:0 len:18
> 2019/01/24 10:49:53 [debug] 36109#0: *10 writev: 66 of 66
> 2019/01/24 10:49:53 [debug] 36109#0: *10 tcp_nodelay
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame sent: 00007FBA2F003050
> sid:0 bl:0 len:18
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame sent: 00007FBA2F003108
> sid:0 bl:0 len:4
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame sent: 00007FBA2F0031B8
> sid:0 bl:0 len:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame sent: 00007FBA2F003268
> sid:0 bl:0 len:8
> 2019/01/24 10:49:53 [debug] 36109#0: *10 event timer del: 3: 266893796
client_header_timeout is removed
> 2019/01/24 10:49:53 [debug] 36109#0: timer delta: 14
> 2019/01/24 10:49:53 [debug] 36109#0: posted event 00007FBA2F003400
> 2019/01/24 10:49:53 [debug] 36109#0: *10 delete posted event
> 00007FBA2F003400
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http run request:
> "/utoProto.idProduce.IdProduce/getUniqueIds?"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream check client, write
> event:0, "/utoProto.idProduce.IdProduce/getUniqueIds"
> 2019/01/24 10:49:53 [debug] 36109#0: worker cycle
> 2019/01/24 10:49:53 [debug] 36109#0: kevent timer: 60000, changes: 2
> 2019/01/24 10:49:53 [debug] 36109#0: kevent events: 2
> 2019/01/24 10:49:53 [debug] 36109#0: kevent: 5: ft:-1 fl:0025 ff:00000000
> d:9 ud:00007FBA2F01A9A0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream request:
> "/utoProto.idProduce.IdProduce/getUniqueIds?"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream process header
> 2019/01/24 10:49:53 [debug] 36109#0: *10 malloc: 00007FBA2E802400:4096
> 2019/01/24 10:49:53 [debug] 36109#0: *10 posix_memalign:
> 00007FBA2E00A600:4096 @16
> 2019/01/24 10:49:53 [debug] 36109#0: *10 recv: eof:0, avail:9, err:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 recv: fd:5 9 of 4096
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc response: 000000040000000000,
> len: 9
> 2019/01/24 10:49:53 [debug] 36109#0: *10 posix_memalign:
> 00007FBA2D500C30:128 @16
> 2019/01/24 10:49:53 [debug] 36109#0: *10 add cleanup: 00007FBA2D500C00
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc frame: 4, len: 0, f:0, i:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc send settings ack
> 2019/01/24 10:49:53 [debug] 36109#0: *10 recv: eof:0, avail:0, err:0
> 2019/01/24 10:49:53 [debug] 36109#0: kevent: 5: ft:-2 fl:0025 ff:00000000
> d:146988 ud:00007FBA2F0349A0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream request:
> "/utoProto.idProduce.IdProduce/getUniqueIds?"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream send request handler
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream send request
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream send request body
> 2019/01/24 10:49:53 [debug] 36109#0: *10 tcp_nodelay
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output filter
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output header
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output limit: 65535
> w:65535:65535
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output out l:0 f:0
> 00007FBA2E801008, pos 00007FBA2E801008, size: 243 file: 0, size: 0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output out l:0 f:0
> 00007FBA2E00A6D0, pos 00007FBA2E00A6D0, size: 9 file: 0, size: 0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output limit: 65535
> w:65535:65535
> 2019/01/24 10:49:53 [debug] 36109#0: *10 chain writer buf fl:1 s:243
> 2019/01/24 10:49:53 [debug] 36109#0: *10 chain writer buf fl:1 s:9
> 2019/01/24 10:49:53 [debug] 36109#0: *10 chain writer in: 00007FBA2E00A700
> 2019/01/24 10:49:53 [debug] 36109#0: *10 writev: 252 of 252
> 2019/01/24 10:49:53 [debug] 36109#0: *10 chain writer out: 0000000000000000
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http body new buf t:1 f:0
> 00007FBA2D837800, pos 00007FBA2D837800, size: 9 file: 0, size: 0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output filter
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output limit: 65535
> w:65535:65535
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output in l:0 f:0
> 00007FBA2D837800, pos 00007FBA2D837800, size: 9 file: 0, size: 0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output out l:0 f:0
> 00007FBA2E00A6D0, pos 00007FBA2E00A6D0, size: 9 file: 0, size: 0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output out l:0 f:0
> 0000000000000000, pos 00007FBA2D837800, size: 9 file: 0, size: 0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output limit: 65526
> w:65526:65526
> 2019/01/24 10:49:53 [debug] 36109#0: *10 chain writer buf fl:1 s:9
> 2019/01/24 10:49:53 [debug] 36109#0: *10 chain writer buf fl:1 s:9
> 2019/01/24 10:49:53 [debug] 36109#0: *10 chain writer in: 00007FBA2E00A7C0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 writev: 18 of 18
> 2019/01/24 10:49:53 [debug] 36109#0: *10 chain writer out: 0000000000000000
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 send WINDOW_UPDATE frame
> sid:1, window:9
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame out: 00007FBA2F003268
> sid:0 bl:0 len:4
> 2019/01/24 10:49:53 [debug] 36109#0: *10 writev: 13 of 13
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame sent: 00007FBA2F003268
> sid:0 bl:0 len:4
> 2019/01/24 10:49:53 [debug] 36109#0: *10 event timer del: 5: 266893810
grpc_connect_timeout is removed
> 2019/01/24 10:49:53 [debug] 36109#0: timer delta: 4
> 2019/01/24 10:49:53 [debug] 36109#0: worker cycle
> 2019/01/24 10:49:53 [debug] 36109#0: kevent timer: 59996, changes: 0
> 2019/01/24 10:49:53 [debug] 36109#0: kevent events: 2
> 2019/01/24 10:49:53 [debug] 36109#0: kevent: 5: ft:-2 fl:0025 ff:00000000
> d:146988 ud:00007FBA2F0349A0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream request:
> "/utoProto.idProduce.IdProduce/getUniqueIds?"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream send request handler
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream send request
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream send request body
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output filter
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output limit: 65526
> w:65526:65526
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output limit: 65526
> w:65526:65526
> 2019/01/24 10:49:53 [debug] 36109#0: *10 chain writer in: 0000000000000000
> 2019/01/24 10:49:53 [debug] 36109#0: kevent: 5: ft:-1 fl:0025 ff:00000000
> d:39 ud:00007FBA2F01A9A0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream request:
> "/utoProto.idProduce.IdProduce/getUniqueIds?"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream process header
> 2019/01/24 10:49:53 [debug] 36109#0: *10 recv: eof:0, avail:39, err:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 recv: fd:5 39 of 4096
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc response:
> 0000000401000000000000040800000000000000000900000806000000000002041010090e0707,
> len: 39
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc frame: 4, len: 0, f:1, i:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc settings ack
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc frame: 8, len: 4, f:0, i:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc window update: 9
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc frame: 6, len: 8, f:0, i:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc ping
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc send ping ack
> 2019/01/24 10:49:53 [debug] 36109#0: *10 post event 00007FBA2F0349A0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 recv: eof:0, avail:0, err:0
> 2019/01/24 10:49:53 [debug] 36109#0: timer delta: 1
> 2019/01/24 10:49:53 [debug] 36109#0: posted event 00007FBA2F0349A0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 delete posted event
> 00007FBA2F0349A0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream request:
> "/utoProto.idProduce.IdProduce/getUniqueIds?"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream send request handler
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream send request
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream send request body
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output filter
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output limit: 65526
> w:65526:65535
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output out l:0 f:0
> 00007FBA2E00A7E0, pos 00007FBA2E00A7E0, size: 17 file: 0, size: 0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output limit: 65526
> w:65526:65535
> 2019/01/24 10:49:53 [debug] 36109#0: *10 chain writer buf fl:1 s:17
> 2019/01/24 10:49:53 [debug] 36109#0: *10 chain writer in: 00007FBA2E00A6F0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 writev: 17 of 17
> 2019/01/24 10:49:53 [debug] 36109#0: *10 chain writer out: 0000000000000000
> 2019/01/24 10:49:53 [debug] 36109#0: worker cycle
> 2019/01/24 10:49:53 [debug] 36109#0: kevent timer: 59995, changes: 0
> 2019/01/24 10:49:53 [debug] 36109#0: kevent events: 1
> 2019/01/24 10:49:53 [debug] 36109#0: kevent: 5: ft:-2 fl:0025 ff:00000000
> d:146988 ud:00007FBA2F0349A0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream request:
> "/utoProto.idProduce.IdProduce/getUniqueIds?"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream send request handler
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream send request
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream send request body
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output filter
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output limit: 65526
> w:65526:65535
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output limit: 65526
> w:65526:65535
> 2019/01/24 10:49:53 [debug] 36109#0: *10 chain writer in: 0000000000000000
> 2019/01/24 10:49:53 [debug] 36109#0: timer delta: 1
> 2019/01/24 10:49:53 [debug] 36109#0: worker cycle
> 2019/01/24 10:49:53 [debug] 36109#0: kevent timer: 59994, changes: 0
> 2019/01/24 10:49:53 [debug] 36109#0: kevent events: 1
> 2019/01/24 10:49:53 [debug] 36109#0: kevent: 5: ft:-1 fl:0025 ff:00000000
> d:131 ud:00007FBA2F01A9A0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream request:
> "/utoProto.idProduce.IdProduce/getUniqueIds?"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream process header
> 2019/01/24 10:49:53 [debug] 36109#0: *10 recv: eof:0, avail:131, err:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 recv: fd:5 131 of 4096
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc response:
> 00001001040000000120880f108b1d75d0620d263d4c4d6564000061000000000001000000005c125ac6c0faa8f69b8fa404c7c0faa8f69b8fa404c8c0faa8f69b8fa404c9c0faa8f69b8fa404cac0faa8f69b8fa404cbc0faa8f69b8fa404ccc0faa8f69b8fa404cdc0faa8f69b8fa404cec0faa8f69b8fa404cfc0faa8f69b8fa404,
> len: 131
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc frame: 1, len: 16, f:4, i:1
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc parse header: start
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc table size update: 0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc indexed header: 8
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc header: ":status: 200"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc header index: 31
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc value: len:11 h:1 last:11,
> rest:11
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc header: "content-type:
> application/grpc"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc header done
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 header filter
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 output header: ":status:
> 200"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 output header: "server:
> nginx/1.15.8"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 output header: "date: Thu, 24
> Jan 2019 02:49:53 GMT"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 output header: "content-type:
> application/grpc"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2:1 create HEADERS frame
> 00007FBA2E00A898: len:49 fin:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http cleanup add: 00007FBA2E00A980
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame out: 00007FBA2E00A898
> sid:1 bl:1 len:49
> 2019/01/24 10:49:53 [debug] 36109#0: *10 writev: 58 of 58
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2:1 HEADERS frame
> 00007FBA2E00A898 was sent
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame sent: 00007FBA2E00A898
> sid:1 bl:1 len:49
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc filter bytes:106
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc frame: 0, len: 97, f:0, i:1
gRPC response part is received,
f:0 flag means it is not a final HTTP/2 DATA frame
> 2019/01/24 10:49:53 [debug] 36109#0: *10 grpc output buf 00007FBA2E802422
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http upstream process non buffered
> downstream
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http output filter
> "/utoProto.idProduce.IdProduce/getUniqueIds?"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http copy filter:
> "/utoProto.idProduce.IdProduce/getUniqueIds?"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http postpone filter
> "/utoProto.idProduce.IdProduce/getUniqueIds?" 00007FBA2E00A7C0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 write new buf t:0 f:0
> 0000000000000000, pos 00007FBA2E802422, size: 97 file: 0, size: 0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http write filter: l:0 f:1 s:97
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http write filter limit 0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2:1 windows: conn:4194304
> stream:4194304
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2:1 create DATA frame
> 00007FBA2E00A898: len:97 flags:0
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame out: 00007FBA2E00A898
> sid:1 bl:0 len:97
> 2019/01/24 10:49:53 [debug] 36109#0: *10 writev: 106 of 106
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2:1 DATA frame 00007FBA2E00A898
> was sent
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http2 frame sent: 00007FBA2E00A898
> sid:1 bl:0 len:97
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http write filter 0000000000000000
> 2019/01/24 10:49:53 [debug] 36109#0: *10 http copy filter: 0
> "/utoProto.idProduce.IdProduce/getUniqueIds?"
> 2019/01/24 10:49:53 [debug] 36109#0: *10 event timer add: 5:
> 300000:267133817
grpc_read_timeout is installed after response started to be received
> 2019/01/24 10:49:53 [debug] 36109#0: timer delta: 1
> 2019/01/24 10:49:53 [debug] 36109#0: worker cycle
> 2019/01/24 10:49:53 [debug] 36109#0: kevent timer: 59993, changes: 0
At this time two timers are active:
- client_body_timeout, since client body is incomplete
- grpc_read_timeout, gRPC response is incomplete.
> 2019/01/24 10:50:53 [debug] 36109#0: kevent events: 0
> 2019/01/24 10:50:53 [debug] 36109#0: timer delta: 59995
The lowest of timers is fired, and the connection is closed
since no more client request body parts were received for the next 60s.
> 2019/01/24 10:50:53 [debug] 36109#0: *10 event timer del: 3: 266893810
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http run request:
> "/utoProto.idProduce.IdProduce/getUniqueIds?"
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http upstream read request handler
> 2019/01/24 10:50:53 [debug] 36109#0: *10 finalize http upstream request:
> 408
> 2019/01/24 10:50:53 [debug] 36109#0: *10 finalize grpc request
> 2019/01/24 10:50:53 [debug] 36109#0: *10 free rr peer 1 0
> 2019/01/24 10:50:53 [debug] 36109#0: *10 close http upstream connection: 5
> 2019/01/24 10:50:53 [debug] 36109#0: *10 run cleanup: 00007FBA2D500C00
> 2019/01/24 10:50:53 [debug] 36109#0: *10 free: 00007FBA2D500BB0, unused: 24
> 2019/01/24 10:50:53 [debug] 36109#0: *10 free: 00007FBA2D500C30, unused: 64
> 2019/01/24 10:50:53 [debug] 36109#0: *10 event timer del: 5: 267133817
> 2019/01/24 10:50:53 [debug] 36109#0: *10 reusable connection: 0
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http finalize request: 408,
> "/utoProto.idProduce.IdProduce/getUniqueIds?" a:1, c:1
the request is finalized with "408 Request Time-out"
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http terminate request count:1
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http terminate cleanup count:1
> blk:0
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http posted request:
> "/utoProto.idProduce.IdProduce/getUniqueIds?"
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http terminate handler count:1
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http request count:1 blk:0
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http2 close stream 1, queued 0,
> processing 1, pushing 0
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http2 send RST_STREAM frame sid:1,
> status:1
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http close request
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http log handler
> 2019/01/24 10:50:53 [debug] 36109#0: *10 free: 00007FBA2E802400
> 2019/01/24 10:50:53 [debug] 36109#0: *10 free: 00007FBA2D837800
> 2019/01/24 10:50:53 [debug] 36109#0: *10 free: 00007FBA2E02EA00, unused: 0
> 2019/01/24 10:50:53 [debug] 36109#0: *10 free: 00007FBA2E800400, unused: 0
> 2019/01/24 10:50:53 [debug] 36109#0: *10 free: 00007FBA2E00A600, unused:
> 2778
> 2019/01/24 10:50:53 [debug] 36109#0: *10 free: 00007FBA2E02E600, unused:
> 711
> 2019/01/24 10:50:53 [debug] 36109#0: *10 post event 00007FBA2F01A938
> 2019/01/24 10:50:53 [debug] 36109#0: posted event 00007FBA2F01A938
> 2019/01/24 10:50:53 [debug] 36109#0: *10 delete posted event
> 00007FBA2F01A938
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http2 handle connection handler
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http2 frame out: 00007FBA2F003268
> sid:0 bl:0 len:4
> 2019/01/24 10:50:53 [debug] 36109#0: *10 writev: 13 of 13
> 2019/01/24 10:50:53 [debug] 36109#0: *10 http2 frame sent: 00007FBA2F003268
> sid:0 bl:0 len:4
> 2019/01/24 10:50:53 [debug] 36109#0: *10 free: 00007FBA2F003000, unused:
> 2760
> 2019/01/24 10:50:53 [debug] 36109#0: *10 reusable connection: 1
> 2019/01/24 10:50:53 [debug] 36109#0: *10 event timer add: 3:
> 180000:267073812
> 2019/01/24 10:50:53 [debug] 36109#0: worker cycle
> 2019/01/24 10:50:53 [debug] 36109#0: kevent timer: 180000, changes: 0
--
Sergey Kandaurov
More information about the nginx
mailing list