EDIT: client does get 14 Unavailable error On Thursday, October 18, 2018 at 12:18:22 PM UTC+3, [email protected] wrote: > > 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.&[email protected]><..[.: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 > > > > >
-- You received this message because you are subscribed to the Google Groups "grpc.io" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To post to this group, send email to [email protected]. Visit this group at https://groups.google.com/group/grpc-io. To view this discussion on the web visit https://groups.google.com/d/msgid/grpc-io/eed1db5e-49c4-4c95-9bfd-735ab605c981%40googlegroups.com. For more options, visit https://groups.google.com/d/optout.
