gRPC server shutdown with ERROR: Endpoint read failed

[sku...@gmail.com]

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]

EDIT: client does get 14 Unavailable error