I think more logs are needed here. From the logs that you did post, it
seems like the connection was established but I don't see any details of
the RPC itself. Your code doesn't show the RPC either.
On Thursday, November 11, 2021 at 5:21:39 PM UTC-8 kiranku...@gmail.com
wrote:
> GRPC Client is written in GoLang runs over Ubuntu VM 16.04. This is
> running on a bare metal server.
>
> GRPC Client in GoLang
>
> ======================
>
> var opts []grpc.DialOption
>
> opts = append(opts, grpc.WithInsecure())
>
> opts = append(opts, grpc.WithBlock())
>
> serverAddr := serverIp + ":" + serverPort
>
> conn, err := grpc.Dial(serverAddr, opts...)
>
> if err != nil {
>
> common.Logger().Errorf("fail to dial: %v", err)
>
> return nil
>
> }
>
> //defer conn.Close()
>
> client := xxx_pb.xxxClient(conn)
>
> return client
>
>
>
> My GRPC Servers runs in an EC2 instance (AWS)
>
> GRPC Server in Python
>
> ====================
>
> def serve():
>
> print("GRPC Server Starting")
>
> server = grpc.server(futures.ThreadPoolExecutor(max_workers=10))
>
>
> xxx_grpc_pb2_grpc.add_xxxServicer_to_server( xxxFwServicer(),
> server)
>
> server.add_insecure_port('[::]:50051')
>
> server.start()
>
> server.wait_for_termination()
>
>
>
> if __name__ == '__main__':
>
> serve()
>
> The connection is successful between GRPC client/server. However, when the
> client code does a GET using one of the predefined GRPC API, GRPC server
> responds with the below error.
>
> *rpc error: code = Internal desc = stream terminated by RST_STREAM with
> error code: NO_ERROR*
>
> When the same GRPC server is run on ubuntu VM on another bare metal server
> instead of EC2 AWS instance, then I don't see this error. Everything works
> fine.
>
> On AWS Front, I enabled the security groups and other permissions for port
> 50051. I assume this is good enough as GRPC Client/Server connection is
> established successfully.
>
> GRPC Client and Server communicate over Public Network (Internet) here.
>
> From the process logs that I added, Server RPC API is not even getting
> called. The log message present in the RPC API code on server side doesn't
> even get printed.
>
> Enabled GRPC logs on the server and they are as below during Client GRPC
> request. I can't make out much though.
>
> I1111 23:21:45.544276213 21932 timer_generic.cc:512] ..
> shard[19]->queue_deadline_cap --> 13015
>
> I1111 23:21:45.544278865 21932 timer_generic.cc:577] ..
> shard[19] popped 0
>
> I1111 23:21:45.544286851 21932 timer_generic.cc:632] .. result
> --> 1, shard[19]->min_deadline 12015 --> 13016, now=12015
>
> I1111 23:21:45.544290422 21932 timer_generic.cc:741] TIMER CHECK
> END: r=1; next=13012
>
> I1111 23:21:45.544297936 21932 timer_manager.cc:188] sleep for a
> 997 milliseconds
>
> I1111 23:21:45.552848998 21933
> completion_queue.cc:1078] RETURN_EVENT[0x196d9f5321d0]: QUEUE_TIMEOUT
>
> I1111 23:21:45.552879498 21933
> completion_queue.cc:969] grpc_completion_queue_next(cq=0x196d9f5321d0,
> deadline=gpr_timespec { tv_sec: 1636672905, tv_nsec: 752877317, clock_type:
> 1 }, reserved=(nil))
>
> I1111 23:21:45.754174520 21933
> completion_queue.cc:1078] RETURN_EVENT[0x196d9f5321d0]: QUEUE_TIMEOUT
>
> I1111 23:21:45.754204954 21933
> completion_queue.cc:969] grpc_completion_queue_next(cq=0x196d9f5321d0,
> deadline=gpr_timespec { tv_sec: 1636672905, tv_nsec: 954198396, clock_type:
> 1 }, reserved=(nil))
>
> I1111 23:21:45.955498820 21933
> completion_queue.cc:1078] RETURN_EVENT[0x196d9f5321d0]: QUEUE_TIMEOUT
>
> I1111 23:21:45.955651038 21933
> completion_queue.cc:969] grpc_completion_queue_next(cq=0x196d9f5321d0,
> deadline=gpr_timespec { tv_sec: 1636672906, tv_nsec: 155648812, clock_type:
> 1 }, reserved=(nil))
>
> I1111 23:21:46.156859185 21933
> completion_queue.cc:1078] RETURN_EVENT[0x196d9f5321d0]: QUEUE_TIMEOUT
>
> I1111 23:21:46.156955462 21933
> completion_queue.cc:969] grpc_completion_queue_next(cq=0x196d9f5321d0,
> deadline=gpr_timespec { tv_sec: 1636672906, tv_nsec: 356953290, clock_type:
> 1 }, reserved=(nil))
>
> I1111 23:21:46.358278383 21933
> completion_queue.cc:1078] RETURN_EVENT[0x196d9f5321d0]: QUEUE_TIMEOUT
>
> I1111 23:21:46.358295443 21933
> completion_queue.cc:969] grpc_completion_queue_next(cq=0x196d9f5321d0,
> deadline=gpr_timespec { tv_sec: 1636672906, tv_nsec: 552873984, clock_type:
> 1 }, reserved=(nil))
>
> I1111 23:21:46.541256973 21932 timer_manager.cc:204] wait ended:
> was_timed:1 kicked:0
>
> I1111 23:21:46.541274502 21932 timer_generic.cc:719] TIMER CHECK
> BEGIN: now=13012 next=9223372036854775807 tls_min=12015 glob_min=13012
>
> I1111 23:21:46.541279016 21932 timer_generic.cc:614] ..
> shard[31]->min_deadline = 13012
>
> I1111 23:21:46.541282578 21932 timer_generic.cc:537] ..
> shard[31]: heap_empty=true
>
> I1111 23:21:46.541285883 21932 timer_generic.cc:512] ..
> shard[31]->queue_deadline_cap --> 14011
>
> I1111 23:21:46.541288850 21932 timer_generic.cc:577] ..
> shard[31] popped 0
>
> I1111 23:21:46.545322680 21932 timer_generic.cc:577] .. shard[3]
> popped 0
>
> I1111 23:21:46.545325545 21932 timer_generic.cc:632] .. result
> --> 1, shard[3]->min_deadline 13016 --> 14017, now=13016
>
> I1111 23:21:46.545334606 21932 timer_generic.cc:741] TIMER CHECK
> END: r=1; next=14012
>
> I1111 23:21:46.545341069 21932 timer_manager.cc:188] sleep for a
> 996 milliseconds
>
> I1111 23:21:46.553617211 21933
> completion_queue.cc:1078] RETURN_EVENT[0x196d9f5321d0]: QUEUE_TIMEOUT
>
> I1111 23:21:46.553643502 21933
> completion_queue.cc:969] grpc_completion_queue_next(cq=0x196d9f5321d0,
> deadline=gpr_timespec { tv_sec: 1636672906, tv_nsec: 753641584, clock_type:
> 1 }, reserved=(nil))
>
> I1111 23:21:46.754965487 21933
> completion_queue.cc:1078] RETURN_EVENT[0x196d9f5321d0]: QUEUE_TIMEOUT
>
> I1111 23:21:46.754995057 21933
> completion_queue.cc:969] grpc_completion_queue_next(cq=0x196d9f5321d0,
> deadline=gpr_timespec { tv_sec: 1636672906, tv_nsec: 954988879, clock_type:
> 1 }, reserved=(nil))
>
> I1111 23:21:46.776727789 21933
> tcp_server_posix.cc:243] SERVER_CONNECT: incoming connection: ipv4:
> 66.170.99.2:29734
>
> I1111 23:21:46.776762659 21933 timer_generic.cc:367] TIMER
> 0x737c6c002608: SET 133247 now 13247 call 0x737c6c002638[0x737c7d3819e0]
>
> I1111 23:21:46.776773077 21933 timer_generic.cc:404] .. add to
> shard 19 with queue_deadline_cap=14016 => is_first_timer=false
>
> I1111 23:21:46.776783737 21933
> handshaker.cc:129] handshake_manager 0x737c6c0025a0: error="No
> Error" shutdown=0 index=0, args={endpoint=0x737c6c007d60,
> args=0x737c6c007500 {size=0: }, read_buffer=0x737c6c002820 (length=0),
> exit_early=0}
>
> I1111 23:21:46.776793254 21933
> handshaker.cc:162] handshake_manager 0x737c6c0025a0: handshaking
> complete -- scheduling on_handshake_done with error="No Error"
>
> I1111 23:21:46.776899489 21933 timer_generic.cc:470] TIMER
> 0x737c6c002608: CANCEL pending=true
>
> I1111 23:21:46.776919469 21933 timer_generic.cc:367] TIMER
> 0x737c6c009ab8: SET 7213247 now 13247 call 0x737c6c009a38[0x737c7d315b20]
>
> I1111 23:21:46.776923335 21933 timer_generic.cc:404] .. add to
> shard 4 with queue_deadline_cap=14011 => is_first_timer=false
>
> I1111 23:21:46.776929541 21933
> chttp2_transport.cc:789] W:0x737c6c0087b0 SERVER [ipv4:
> 66.170.99.2:29734] state IDLE -> WRITING [TRANSPORT_FLOW_CONTROL]
>
> I1111 23:21:46.776933463 21933
> chttp2_transport.cc:789] W:0x737c6c0087b0 SERVER [ipv4:
> 66.170.99.2:29734] state WRITING -> WRITING+MORE [INITIAL_WRITE]
>
> I1111 23:21:46.776937899 21933
> init.cc:168] grpc_init(void)
>
> I1111 23:21:46.776957552 21933
> chttp2_transport.cc:1814] perform_transport_op[t=0x737c6c0087b0]:
> START_CONNECTIVITY_WATCH:watcher=0x737c6c0012e0:from=IDLE
> SET_ACCEPT_STREAM:0x737c7d3fc420(0x737c6c00a2e8,...)
>
> I1111 23:21:46.776967068 21933 timer_generic.cc:367] TIMER
> 0x737c6c002700: SET 133247 now 13247 call 0x737c6c002730[0x737c7d312910]
>
> I1111 23:21:46.776971608 21933 timer_generic.cc:404] .. add to
> shard 3 with queue_deadline_cap=14016 => is_first_timer=false
>
> I1111 23:21:46.776980639 21933
> connectivity_state.cc:121] ConnectivityStateTracker
> server_transport[0x737c6c008a38]: add watcher 0x737c6c0012e0
>
> I1111 23:21:46.777048480 21933
> connectivity_state.cc:127] ConnectivityStateTracker
> server_transport[0x737c6c008a38]: notifying watcher 0x737c6c0012e0: IDLE ->
> READY
>
> I1111 23:21:46.777053479 21933 connectivity_state.cc:79] watcher
> 0x737c6c0012e0: delivering async notification for READY (OK)
>
> I1111 23:21:46.777061564 21933 timer_generic.cc:470] TIMER
> 0x737c6c009ab8: CANCEL pending=true
>
> I1111 23:21:46.777066479 21933
> tcp_posix.cc:545] TCP:0x737c6c007d60 notify_on_read
>
> I1111 23:21:46.777074313 21933 timer_generic.cc:367] TIMER
> 0x737c6c009ab8: SET 7213247 now 13247 call 0x737c6c009a38[0x737c7d315b20]
>
> I1111 23:21:46.777078859 21933 timer_generic.cc:404] .. add to
> shard 4 with queue_deadline_cap=14011 => is_first_timer=false
>
> D1111 23:21:46.777090664 21933
> flow_control.cc:115] 0x737c6c009820[0][svr] | t updt sent |
> trw: 65535, tlw: 4194304,
> taw: 65535 -> 4194304, srw: ,
> slw: , saw:
>
> I1111 23:21:46.777096183 21933
> chttp2_transport.cc:789] W:0x737c6c0087b0 SERVER [ipv4:
> 66.170.99.2:29734] state WRITING+MORE -> WRITING [begin write in current
> thread]
>
> I1111 23:21:46.777099698 21933 tcp_posix.cc:1569] WRITE
> 0x737c6c007d60 (peer=ipv4:66.170.99.2:29734)
>
> D1111 23:21:46.777103913 21933 tcp_posix.cc:1573] DATA: 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 '............@.....@...... .þ.....'
>
> I1111 23:21:46.777107042 21933 tcp_posix.cc:1569] WRITE
> 0x737c6c007d60 (peer=ipv4:66.170.99.2:29734)
>
> D1111 23:21:46.777110254 21933 tcp_posix.cc:1573] DATA: 00 00
> 04 08 00 00 00 00 00 00 3f 00 01 '..........?..'
>
> I1111 23:21:46.777134291 21933 tcp_posix.cc:1619] write: "No
> Error"
>
> I1111 23:21:46.777143819 21933
> chttp2_transport.cc:789] W:0x737c6c0087b0 SERVER [ipv4:
> 66.170.99.2:29734] state WRITING -> IDLE [finish writing]
>
> I1111 23:21:46.777150598 21933
> tcp_posix.cc:890] TCP:0x737c6c007d60 got_read: "No Error"
>
> I1111 23:21:46.777153564 21933
> tcp_posix.cc:872] TCP:0x737c6c007d60 alloc_slices
>
> I1111 23:21:46.777156840 21933 resource_quota.cc:892] RQ
> anonymous_pool_126978225082368 ipv4:66.170.99.2:29734: alloc 8192;
> free_pool -> -8192:q!
>
> I1111 23:21:46.777160608 21933 resource_quota.cc:324] RQ: check
> allocation for user 0x737c6c007940 shutdown=0 free_pool=-8192
> outstanding_allocations=8192
>
> I1111 23:21:46.777168902 21933 resource_quota.cc:352] RQ
> anonymous_pool_126978225082368 ipv4:66.170.99.2:29734: grant alloc 8192
> bytes; rq_free_pool -> 9223372036854767615
>
> I1111 23:21:46.777185523 21933
> tcp_posix.cc:853] TCP:0x737c6c007d60 read_allocation_done: "No
> Error"
>
> I1111 23:21:46.777202888 21933
> tcp_posix.cc:682] TCP:0x737c6c007d60 call_cb 0x737c6c0088d8
> 0x737c7d315d60:0x737c6c0087b0
>
> I1111 23:21:46.777314092 21933 tcp_posix.cc:685] READ
> 0x737c6c007d60 (peer=ipv4:66.170.99.2:29734) error="No Error"
>
> D1111 23:21:46.777319644 21933 tcp_posix.cc:692] DATA: 50 52
> 49 20 2a 20 48 54 54 50 2f 32 2e 30 0d 0a 0d 0a 53 4d 0d 0a 0d 0a 00 00 1e
> 04 00 00 00 00 00 00 01 00 00 10 00 00 02 00 00 00 01 00 03 00 00 00 64 00
> 05 00 00 40 00 00 06 00 00 ff ff 00 00 04 08 00 00 00 00 00 7f ff 00 00
> 'PRI *
> HTTP/2.0....SM..............................d....@.....ÿÿ..........ÿ..'
>
> I1111 23:21:46.777325357 21933
> frame_settings.cc:230] CHTTP2:SVR:ipv4:66.170.99.2:29734: got
> setting HEADER_TABLE_SIZE = 4096
>
> I1111 23:21:46.777328806 21933
> frame_settings.cc:230] CHTTP2:SVR:ipv4:66.170.99.2:29734: got
> setting ENABLE_PUSH = 1
>
> I1111 23:21:46.777331703 21933
> frame_settings.cc:230] CHTTP2:SVR:ipv4:66.170.99.2:29734: got
> setting MAX_CONCURRENT_STREAMS = 100
>
> I1111 23:21:46.777334716 21933
> frame_settings.cc:230] CHTTP2:SVR:ipv4:66.170.99.2:29734: got
> setting MAX_FRAME_SIZE = 16384
>
> I1111 23:21:46.777341404 21933
> frame_settings.cc:230] CHTTP2:SVR:ipv4:66.170.99.2:29734: got
> setting MAX_HEADER_LIST_SIZE = 65535
>
> D1111 23:21:46.777348531 21933
> flow_control.cc:115] 0x737c6c009820[0][svr] | t updt recv |
> trw: 65535 -> 2147483647, tlw: 4194304,
> taw: 4194304, srw: ,
> slw: , saw:
>
> I1111 23:21:46.777357504 21933 timer_generic.cc:470] TIMER
> 0x737c6c009ab8: CANCEL pending=true
>
> I1111 23:21:46.777361416 21933
> tcp_posix.cc:545] TCP:0x737c6c007d60 notify_on_read
>
> I1111 23:21:46.777370130 21933 timer_generic.cc:470] TIMER
> 0x737c6c002700: CANCEL pending=true
>
> I1111 23:21:46.777374739 21933 timer_generic.cc:367] TIMER
> 0x737c6c009ab8: SET 7213248 now 13248 call 0x737c6c009a38[0x737c7d315b20]
>
> I1111 23:21:46.777377885 21933 timer_generic.cc:404] .. add to
> shard 4 with queue_deadline_cap=14011 => is_first_timer=false
>
> I1111 23:21:46.803679721 21933
> tcp_posix.cc:890] TCP:0x737c6c007d60 got_read: "No Error"
>
> I1111 23:21:46.803701534 21933
> tcp_posix.cc:882] TCP:0x737c6c007d60 do_read
>
> I1111 23:21:46.803720072 21933
> tcp_posix.cc:682] TCP:0x737c6c007d60 call_cb 0x737c6c0088d8
> 0x737c7d315d60:0x737c6c0087b0
>
> I1111 23:21:46.803725366 21933 tcp_posix.cc:685] READ
> 0x737c6c007d60 (peer=ipv4:66.170.99.2:29734) error="No Error"
>
> D1111 23:21:46.803729032 21933 tcp_posix.cc:692] DATA: 00 00
> 00 04 01 00 00 00 00 '.........'
>
> I1111 23:21:46.803734042 21933 timer_generic.cc:470] TIMER
> 0x737c6c009ab8: CANCEL pending=true
>
> I1111 23:21:46.803742800 21933
> tcp_posix.cc:545] TCP:0x737c6c007d60 notify_on_read
>
> I1111 23:21:46.803747316 21933 timer_generic.cc:367] TIMER
> 0x737c6c009ab8: SET 7213274 now 13274 call 0x737c6c009a38[0x737c7d315b20]
>
> I1111 23:21:46.803755887 21933 timer_generic.cc:404] .. add to
> shard 4 with queue_deadline_cap=14011 => is_first_timer=false
>
> I1111 23:21:46.804594289 21933
> tcp_posix.cc:890] TCP:0x737c6c007d60 got_read: "No Error"
>
> I1111 23:21:46.804602809 21933
> tcp_posix.cc:882] TCP:0x737c6c007d60 do_read
>
> I1111 23:21:46.804608189 21933
> tcp_posix.cc:682] TCP:0x737c6c007d60 call_cb 0x737c6c0088d8
> 0x737c7d315d60:0x737c6c0087b0
>
> I1111 23:21:46.804611274 21933 tcp_posix.cc:685] READ
> 0x737c6c007d60 (peer=ipv4:66.170.99.2:29734) error="No Error"
>
> D1111 23:21:46.804618296 21933 tcp_posix.cc:692] DATA: 00 00
> 04 03 00 00 00 00 01 00 00 00 00 '.............'
>
> I1111 23:21:46.804622419 21933 timer_generic.cc:470] TIMER
> 0x737c6c009ab8: CANCEL pending=true
>
> I1111 23:21:46.804625465 21933
> tcp_posix.cc:545] TCP:0x737c6c007d60 notify_on_read
>
> I1111 23:21:46.804629089 21933 timer_generic.cc:367] TIMER
> 0x737c6c009ab8: SET 7213275 now 13275 call 0x737c6c009a38[0x737c7d315b20]
>
> I1111 23:21:46.804632047 21933 timer_generic.cc:404] .. add to
> shard 4 with queue_deadline_cap=14011 => is_first_timer=false
>
> I1111 23:21:46.955876216 21933
> completion_queue.cc:1078] RETURN_EVENT[0x196d9f5321d0]: QUEUE_TIMEOUT
>
> I1111 23:21:46.955901757 21933
> completion_queue.cc:969] grpc_completion_queue_next(cq=0x196d9f5321d0,
> deadline=gpr_timespec { tv_sec: 1636672907, tv_nsec: 155899496, clock_type:
> 1 }, reserved=(nil))
>
> I1111 23:21:47.157228522 21933
> completion_queue.cc:1078] RETURN_EVENT[0x196d9f5321d0]: QUEUE_TIMEOUT
>
> I1111 23:21:47.157245516 21933
> completion_queue.cc:969] grpc_completion_queue_next(cq=0x196d9f5321d0,
> deadline=gpr_timespec { tv_sec: 1636672907, tv_nsec: 357243618, clock_type:
> 1 }, reserved=(nil))
>
> I1111 23:21:47.358536911 21933
> completion_queue.cc:1078] RETURN_EVENT[0x196d9f5321d0]: QUEUE_TIMEOUT
>
> I1111 23:21:47.358567608 21933
> completion_queue.cc:969] grpc_completion_queue_next(cq=0x196d9f5321d0,
> deadline=gpr_timespec { tv_sec: 1636672907, tv_nsec: 553638656, clock_type:
> 1 }, reserved=(nil))
>
> I1111 23:21:47.541266827 21932 timer_manager.cc:204] wait ended:
> was_timed:1 kicked:0
>
> I1111 23:21:47.541284766 21932 timer_generic.cc:719] TIMER CHECK
> BEGIN: now=14012 next=9223372036854775807 tls_min=13016 glob_min=14012
>
> I1111 23:21:47.541289173 21932 timer_generic.cc:614] ..
> shard[0]->min_deadline = 14012
>
> I1111 23:21:47.541292337 21932 timer_generic.cc:537] ..
> shard[0]: heap_empty=true
>
> I1111 23:21:47.541295125 21932 timer_generic.cc:512] ..
> shard[0]->queue_deadline_cap --> 15012
>
> I1111 23:21:47.541298018 21932 timer_generic.cc:577] .. shard[0]
> popped 0
>
> Any help on how to proceed ? Google/Stackoverflow/GRPC documentation
> didn't get me much on this issue.
>
>
>
>
>
--
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 grpc-io+unsubscr...@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/grpc-io/feddeffe-6145-499c-8506-9ddc6999cdc1n%40googlegroups.com.
