Why GRPC server running on EC2/AWS returns RST_STREAM error for a GET Call?
Kiran Kumar
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.
