grpc keepalive does not effect, nginx will close connection by the minute
Roar
nginx-forum at forum.nginx.org
Thu Jan 24 03:05:21 UTC 2019
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!
What sad is that I don't understand the output nginx debug log. Could you
help me analyze the log?
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
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
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
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
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
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
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
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
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
2019/01/24 10:50:53 [debug] 36109#0: kevent events: 0
2019/01/24 10:50:53 [debug] 36109#0: timer delta: 59995
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
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
Posted at Nginx Forum: https://forum.nginx.org/read.php?2,282769,282806#msg-282806
More information about the nginx
mailing list