gRPC server shutdown with ERROR: Endpoint read failed
24 views
Skip to first unread message
sku...@gmail.com
Oct 18, 2018, 5:18:22 AM10/18/18
to grpc.io
I am trying to run a very basic example of gRPC client and server with SSL
Client sends just one request and server sends back just one response.
Client and server are running on the same machine in this case WSL (Ubuntu 18.04) on Windows 10
What I am observing is that SSL handshake pass successful.
Server receives the client request.
Server state changes to WRITING
Server state changes from WRITING to IDLE
At this point an error occurs "Endpoint read failed"
Server transport state changes to SHUTDOWN
This is reproducible every time
NOTE: I have read about other issues related to the same type of error on the client side but here it appears to be on the server side
Both client and server are running on node 8.12.0
gRPC package version is 1.15.1
Logs from the server (starting after HANDSHAKE is completed):
I1018 12:09:53.858667100 12206 ssl_transport_security.cc:213] HANDSHAKE DONE - SSL negotiation finished succe - SSLOK
I1018 12:09:53.858721000 12206 tcp_custom.cc:234] WRITE 0x3b71470 (peer=ipv4:127.0.0.1:60785): 16 03 03 00 ba 04 00 00 b6 00 00 1c 20 00 b0 d5 8a 01 11 37 2c 68 06 ab
19 0a 63 13 8c 83 f0 1f 32 21 ee c8 06 73 65 10 7d 27 33 1f 7a 50 cb dc 32 ca 7d 90 7b 4e 42 7d a1 2a b5 49 de 29 86 eb 23 33 31 12 f2 e7 76 1a 4a f1 43 c3 cf 62 03 6f 31 6c c8 14 ac 81 5a cb fd 3c b1 2c fc 95 e6 86 0b 22 4e 7a a3 94 8f 46 2a d6 fe 52 97 16 55 85 49 89 6b 0d ea bd f5 5f 82 f9 ea 96 64 05 43 f3 13 33 8d 52 2e 26 ca cf a2 fa 43 05 1f ea 2b 40 14 07 79 3e 3c e3 ba 5b 83 3a 56 fd b1 79 29 30 30 7e 44 eb 3f b1 75 b1 7a c7 67 64 06 2f 33 d8 2e 6d 84 3a 2e 1f c7 11 38 68 45 04 bb c4 67 14 03 03 00 01 01 16 03 03 00 28
3d 5b 96 9e 87 a7 a0 eb c2 19 88 a0 3c 35 01 d6 c8 db 4a 83 6c 24 1b d8 86 24 f2 5d 52 54 18 d2 c3 53 e8 dc 8c c8 f1 45 '............ ......7,h....c.....2!...se.}'3.zP..2.}.{NB}.*.I.)..#31...v.J.C..b.o1l....Z..<.,....."Nz...F*..R..U.I.k...._....d.C..3.R.&....C...+@..y><..[.:V..y)00~D.?.u.z.gd./3..m.:....8hE...g..........(=[..........<5....J.l$...$.]RT...S.....E'
I1018 12:09:53.858876600 12206 tcp_custom.cc:217] write complete on 0x3b71470: error="No Error"
I1018 12:09:53.858947400 12206 security_context.cc:295] grpc_auth_context_add_cstring_property(ctx=0x3b5e4c0, name=transport_security_type, value=ssl)
I1018 12:09:53.858997800 12206 security_context.cc:279] grpc_auth_context_add_property(ctx=0x3b5e4c0, name=ssl_session_reused, value=false, value_length=5)
I1018 12:09:53.859073400 12206 handshaker.cc:212] handshake_manager 0x3b73130: error="No Error" shutdown=0 index=1, args={endpoint=0x3b759f0, args=0x3b764a0 {size=4: grpc.primary_user_agent=grpc-node/1.15.1, grpc.server_credentials=0x3a41540, grpc.security_connector=0x3a4f220, grpc.auth_context=0x3b5e4c0}, read_buffer=0x3b14310 (length=0), exit_early=0}
I1018 12:09:53.859141800 12206 handshaker.cc:245] handshake_manager 0x3b73130: handshaking complete -- scheduling on_handshake_done with error="No Error"
I1018 12:09:53.859269800 12206 bdp_estimator.h:53] bdp[ipv4:127.0.0.1:60785]:sched acc=0 est=65536
I1018 12:09:53.859344000 12206 chttp2_transport.cc:813] W:0x3b2e980 SERVER state IDLE -> WRITING [TRANSPORT_FLOW_CONTROL]
I1018 12:09:53.859398300 12206 chttp2_transport.cc:813] W:0x3b2e980 SERVER state WRITING -> WRITING+MORE [INITIAL_WRITE]
I1018 12:09:53.859480700 12206 chttp2_transport.cc:1822] perform_transport_op[t=0x3b2e980]: ON_CONNECTIVITY_STATE_CHANGE:p=0x3b29208:from=IDLE SET_ACCEPT_STREAM:0x7fd4b8b52eb0(0x3b291a0,...)
I1018 12:09:53.859547100 12206 connectivity_state.cc:116] CONWATCH: 0x3b2ec20 server_transport: from IDLE [cur=READY] notify=0x3b29208
I1018 12:09:53.859602400 12206 chttp2_transport.cc:1822] perform_transport_op[t=0x3b2e980]: ON_CONNECTIVITY_STATE_CHANGE:p=0x3b29208:from=READY
I1018 12:09:53.859651900 12206 resource_quota.cc:873] RQ anonymous_pool_3b6e0f0 ipv4:127.0.0.1:60785: alloc 8192; free_pool -> 0
I1018 12:09:53.859701300 12206 tcp_custom.cc:174] TCP:0x3b71470 read_allocation_done: "No Error"
I1018 12:09:53.859749800 12206 tcp_custom.cc:191] Initiating read on 0x3b71470: error="No Error"
I1018 12:09:53.859797300 12206 connectivity_state.cc:116] CONWATCH: 0x3b2ec20 server_transport: from READY [cur=READY] notify=0x3b29208
D1018 12:09:53.859860800 12206 flow_control.cc:113] 0x3b2ffc0[0][svr] | t updt sent | trw: 65535, ttw: 4194304, taw:
65535 -> 4194304, srw: , slw: , saw:
I1018 12:09:53.859936000 12206 writing.cc:110] SERVER: Ping sent [0x3b735f0]: 2/2
I1018 12:09:53.859986400 12206 chttp2_transport.cc:813] W:0x3b2e980 SERVER state WRITING+MORE -> WRITING [begin write in current thread]
I1018 12:09:53.860036800 12206 secure_endpoint.cc:272] WRITE 0x3b759f0: 00 00 18 04 00 00 00 00 00 00 04 00 40 00 00 00 05 00 40 00 00 00 06 00 00 20 00 fe 03 00 00 00 01 '............@.....@...... .......'
I1018 12:09:53.860107600 12206 secure_endpoint.cc:272] WRITE 0x3b759f0: 00 00 04 08 00 00 00 00 00 00 3f 00 01 00 00 08 06 00 00 00 00 00 00 '..........?............'
I1018 12:09:53.860156600 12206 secure_endpoint.cc:272] WRITE 0x3b759f0: 00 00 00 00 00 00 00 '.......'
I1018 12:09:53.860213800 12206 tcp_custom.cc:234] WRITE 0x3b71470 (peer=ipv4:127.0.0.1:60785): 17 03 03 00 57 3d 5b 96 9e 87 a7 a0 ec d8 76 f1 55 85 bf 6c dd bb f6 c2
c0 5c 54 09 27 64 e9 4b ae c0 d8 6d 96 f5 e3 8a b6 5f ea 9d c6 df 85 35 d9 bd 1b eb 61 ba a5 8a bb e1 d9 9e c0 a3 0c 74 c4 70 ff 0a 11 d4 d2 99 14 e7 fc 6f 9c 36 d3 a9 62 d3 d1 da d3 a7 48 3d 1f e9 93 44 '....W=[.......v.U..l.....\T.'d.K...m....._.....5....a..........t.p.........o.6..b.....H=...D'
I1018 12:09:53.860315600 12206 chttp2_transport.cc:2553] ipv4:127.0.0.1:60785: Start BDP ping err="No Error"
I1018 12:09:53.860377200 12206 bdp_estimator.h:66] bdp[ipv4:127.0.0.1:60785]:start acc=0 est=65536
I1018 12:09:53.860476100 12206 tcp_custom.cc:217] write complete on 0x3b71470: error="No Error"
I1018 12:09:53.860524600 12206 chttp2_transport.cc:813] W:0x3b2e980 SERVER state WRITING -> IDLE [finish writing]
I1018 12:09:53.860575000 12206 completion_queue.cc:954] grpc_completion_queue_next(cq=0x3b152f0, deadline=gpr_timespec { tv_sec: -9223372036854775808, tv_nsec: 0, clock_type: 0 }, reserved=(nil))
I1018 12:09:53.860630800 12206 completion_queue.cc:1054] RETURN_EVENT[0x3b152f0]: QUEUE_TIMEOUT
I1018 12:09:53.860701600 12206 resource_quota.cc:896] RQ anonymous_pool_3b6e0f0 ipv4:127.0.0.1:60785: free 8192; free_pool -> 8192
I1018 12:09:53.860750000 12206 tcp_custom.cc:128] TCP:0x3b71470 call_cb 0x3b75a48 0x7fd4b8bb5740:0x3b759f0
I1018 12:09:53.860806300 12206 tcp_custom.cc:132] read: error={"created":"@1539853793.860693800","description":"EOF","file":"../deps/grpc/src/core/lib/iomgr/tcp_uv.cc","file_line":107}
I1018 12:09:53.860869300 12206 chttp2_transport.cc:2743] set connectivity_state=4
I1018 12:09:53.860928500 12206 connectivity_state.cc:164] SET: 0x3b2ec20 server_transport: READY --> SHUTDOWN [close_transport] error=0x3b5dc90 {"created":"@1539853793.860862000","description":"Endpoint read failed","file":"../deps/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2467,"grpc_status":14,"occurred_during_write":0,"referenced_errors":[{"created":"@1539853793.860860600","description":"Secure read failed","file":"../deps/grpc/src/core/lib/security/transport/secure_endpoint.cc","file_line":156,"referenced_errors":[{"created":"@1539853793.860693800","description":"EOF","file":"../deps/grpc/src/core/lib/iomgr/tcp_uv.cc","file_line":107}]}]}
I1018 12:09:53.861054000 12206 connectivity_state.cc:190] NOTIFY: 0x3b2ec20 server_transport: 0x3b29208
I1018 12:09:53.861149600 12206 tcp_custom.cc:286] TCP 0x3b71470 shutdown why={"created":"@1539853793.860862000","description":"Endpoint read failed","file":"../deps/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2467,"grpc_status":14,"occurred_during_write":0,"referenced_errors":[{"created":"@1539853793.860860600","description":"Secure read failed","file":"../deps/grpc/src/core/lib/security/transport/secure_endpoint.cc","file_line":156,"referenced_errors":[{"created":"@1539853793.860693800","description":"EOF","file":"../deps/grpc/src/core/lib/iomgr/tcp_uv.cc","file_line":107}]}]}
I1018 12:09:53.861245100 12206 server.cc:426] Disconnected client: {"created":"@1539853793.860862000","description":"Endpoint read failed","file":"../deps/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2467,"grpc_status":14,"occurred_during_write":0,"referenced_errors":[{"created":"@1539853793.860860600","description":"Secure read failed","file":"../deps/grpc/src/core/lib/security/transport/secure_endpoint.cc","file_line":156,"referenced_errors":[{"created":"@1539853793.860693800","description":"EOF","file":"../deps/grpc/src/core/lib/iomgr/tcp_uv.cc","file_line":107}]}]}
I1018 12:09:53.861328500 12206 chttp2_transport.cc:1822] perform_transport_op[t=0x3b2e980]: SET_ACCEPT_STREAM:(nil)((nil),...)
I1018 12:09:53.861393400 12206 chttp2_transport.cc:2566] ipv4:127.0.0.1:60785: Complete BDP ping err={"created":"@1539853793.860862000","description":"Endpoint read failed","file":"../deps/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc","file_line":2467,"occurred_during_write":0,"referenced_errors":[{"created":"@1539853793.860860600","description":"Secure read failed","file":"../deps/grpc/src/core/lib/security/transport/secure_endpoint.cc","file_line":156,"referenced_errors":[{"created":"@1539853793.860693800","description":"EOF","file":"../deps/grpc/src/core/lib/iomgr/tcp_uv.cc","file_line":107}]}]}
I1018 12:09:53.861499100 12206 resource_quota.cc:532] RU shutdown 0x3b70ee0
I1018 12:09:53.861564600 12206 completion_queue.cc:954] grpc_completion_queue_next(cq=0x3b152f0, deadline=gpr_timespec { tv_sec: -9223372036854775808, tv_nsec: 0, clock_type: 0 }, reserved=(nil))
I1018 12:09:53.861662000 12206 completion_queue.cc:1054] RETURN_EVENT[0x3b152f0]: QUEUE_TIMEOUT
I1018 12:09:55.603482700 12206 completion_queue.cc:954] grpc_completion_queue_next(cq=0x3b152f0, deadline=gpr_timespec { tv_sec: -9223372036854775808, tv_nsec: 0, clock_type: 0 }, reserved=(nil))
I1018 12:09:55.610302100 12206 completion_queue.cc:1054] RETURN_EVENT[0x3b152f0]: QUEUE_TIMEOUT
I1018 12:09:55.701036800 12206 completion_queue.cc:954] grpc_completion_queue_next(cq=0x3b152f0, deadline=gpr_timespec { tv_sec: -9223372036854775808, tv_nsec: 0, clock_type: 0 }, reserved=(nil))
I1018 12:09:55.714192200 12206 completion_queue.cc:1054] RETURN_EVENT[0x3b152f0]: QUEUE_TIMEOUT
I1018 12:09:55.785706000 12206 completion_queue.cc:954] grpc_completion_queue_next(cq=0x3b152f0, deadline=gpr_timespec { tv_sec: -9223372036854775808, tv_nsec: 0, clock_type: 0 }, reserved=(nil))
I1018 12:09:55.792353300 12206 completion_queue.cc:1054] RETURN_EVENT[0x3b152f0]: QUEUE_TIMEOUT
I1018 12:09:55.869137400 12206 completion_queue.cc:954] grpc_completion_queue_next(cq=0x3b152f0, deadline=gpr_timespec { tv_sec: -9223372036854775808, tv_nsec: 0, clock_type: 0 }, reserved=(nil))
I1018 12:09:55.875613500 12206 completion_queue.cc:1054] RETURN_EVENT[0x3b152f0]: QUEUE_TIMEOUT
I1018 12:09:55.952253600 12206 completion_queue.cc:954] grpc_completion_queue_next(cq=0x3b152f0, deadline=gpr_timespec { tv_sec: -9223372036854775808, tv_nsec: 0, clock_type: 0 }, reserved=(nil))
I1018 12:09:55.958769600 12206 completion_queue.cc:1054] RETURN_EVENT[0x3b152f0]: QUEUE_TIMEOUT
I1018 12:09:56.037989600 12206 completion_queue.cc:954] grpc_completion_queue_next(cq=0x3b152f0, deadline=gpr_timespec { tv_sec: -9223372036854775808, tv_nsec: 0, clock_type: 0 }, reserved=(nil))
I1018 12:09:56.045105600 12206 completion_queue.cc:1054] RETURN_EVENT[0x3b152f0]: QUEUE_TIMEOUT
I1018 12:09:56.114108900 12206 completion_queue.cc:954] grpc_completion_queue_next(cq=0x3b152f0, deadline=gpr_timespec { tv_sec: -9223372036854775808, tv_nsec: 0, clock_type: 0 }, reserved=(nil))
I1018 12:09:56.120438600 12206 completion_queue.cc:1054] RETURN_EVENT[0x3b152f0]: QUEUE_TIMEOUT
I1018 12:11:53.852811100 12206 chttp2_transport.cc:1822] perform_transport_op[t=0x3b2e980]: DISCONNECT:{"created":"@1539853913.852758200","description":"Did not receive HTTP/2 settings before handshake timeout","file":"../deps/grpc/src/core/ext/transport/chttp2/server/chttp2_server.cc","file_line":91}
I1018 12:11:53.854777100 12206 completion_queue.cc:954] grpc_completion_queue_next(cq=0x3b152f0, deadline=gpr_timespec { tv_sec: -9223372036854775808, tv_nsec: 0, clock_type: 0 }, reserved=(nil))
I1018 12:11:53.855295400 12206 completion_queue.cc:1054] RETURN_EVENT[0x3b152f0]: QUEUE_TIMEOUT
I1018 12:11:53.855814700 12206 completion_queue.cc:954] grpc_completion_queue_next(cq=0x3b152f0, deadline=gpr_timespec { tv_sec: -9223372036854775808, tv_nsec: 0, clock_type: 0 }, reserved=(nil))
I1018 12:11:53.856325700 12206 completion_queue.cc:1054] RETURN_EVENT[0x3b152f0]: QUEUE_TIMEOUT
sku...@gmail.com
Oct 18, 2018, 6:27:38 AM10/18/18
to grpc.io
EDIT: client does get 14 Unavailable error
Reply all
Reply to author
Forward
0 new messages