StatusCode.INTERNAL, Did not read entire message
92 views
Skip to first unread message
kurr...@gmail.com
Nov 8, 2017, 12:58:12 AM11/8/17
to grpc.io
Hello
I am trying to call a grpc service from python.
I have generated python code using protoc 3.4.1. And I have tried with grpc 1.6.6 and grpc 1.6.1
I have also generated java code, and can successfully call the same service method from java.
When I try to run the python code I get the following error:
File "my_client.py", line 107, in <module>
run()
File "my_client.py", line 87, in run
response = stub.ChartRequest(request)
File "/home/anton/git/pi/rm/venv/lib/python3.6/site-packages/grpc/_channel.py", line 492, in __call__
return _end_unary_response_blocking(state, call, False, deadline)
File "/home/anton/git/pi/rm/venv/lib/python3.6/site-packages/grpc/_channel.py", line 440, in _end_unary_response_blocking
raise _Rendezvous(state, None, None, deadline)
grpc._channel._Rendezvous: <_Rendezvous of RPC that terminated with (StatusCode.INTERNAL, Did not read entire message)>
My python code is:
import grpc
# import sys
import time
import datetime
import os
#os.environ["GRPC_TRACE"] = "all"
os.environ["GRPC_VERBOSITY"] = "DEBUG"
host = "10.5.0.5"
port = 50051
def run():
channel = grpc.insecure_channel(host + ':' + str(port))
# cridentials?
stub = ChartService_pb2_grpc.ChartServiceStub(channel)
crrm = ChartRequestMessage_pb2
request = crrm.Info__pb2.ChartInfo(symbol='HELLO', period=Period_pb2.PERIOD_M1, timesign=1)
response = stub.ChartRequest(request)
print("printing results")
for ri in response.rate_info:
print(ri)
if __name__ == '__main__':
run()Does anyone know what the problem might be?
kurr...@gmail.com
Nov 8, 2017, 4:16:05 AM11/8/17
to grpc.io
This is the full trace output:
D1108 21:47:57.847244577 12183 ev_posix.c:111] Using polling engine: pollD1108 21:47:57.847309517 12183 dns_resolver.c:301] Using native dns resolverD1108 21:47:57.847330925 12183 timer_manager.c:82] Spawn timer threadI1108 21:47:57.847367743 12183 init.c:168] grpc_init(void)I1108 21:47:57.847377872 12183 metadata_array.c:27] grpc_metadata_array_init(array=0x7f2dc0054c18)I1108 21:47:57.852191165 12183 init.c:168] grpc_init(void)I1108 21:47:57.852229745 12183 init.c:168] grpc_init(void)I1108 21:47:57.852240445 12183 channel_create.c:88] grpc_insecure_channel_create(target=10.5.0.5:50051, args=0x7f2dc0058458, reserved=(nil))D1108 21:47:57.852278636 12183 combiner.c:84] C:0x183fec0 createI1108 21:47:57.852319259 12183 init.c:168] grpc_init(void)I1108 21:47:57.852330685 12183 completion_queue.c:417] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)I1108 21:47:57.852673327 12187 channel_connectivity.c:38] grpc_channel_check_connectivity_state(channel=0x183fcd0, try_to_connect=0)D1108 21:47:57.852695891 12187 connectivity_state.c:84] CONWATCH: 0x183fe08 client_channel: get IDLEI1108 21:47:57.852972693 12183 init.c:168] grpc_init(void)I1108 21:47:57.852989918 12183 init.c:168] grpc_init(void)I1108 21:47:57.853001246 12183 init.c:168] grpc_init(void)I1108 21:47:57.853019105 12183 init.c:168] grpc_init(void)I1108 21:47:57.853029394 12183 init.c:168] grpc_init(void)I1108 21:47:57.853039027 12183 init.c:168] grpc_init(void)I1108 21:47:57.853046376 12183 metadata_array.c:27] grpc_metadata_array_init(array=0x7f2dc007b378)I1108 21:47:57.853057364 12183 init.c:168] grpc_init(void)I1108 21:47:57.853065705 12183 init.c:168] grpc_init(void)I1108 21:47:57.853074815 12183 init.c:168] grpc_init(void)I1108 21:47:57.853082896 12183 init.c:168] grpc_init(void)I1108 21:47:57.853089653 12183 metadata_array.c:27] grpc_metadata_array_init(array=0x7f2dc007b3a8)I1108 21:47:57.853101029 12183 init.c:168] grpc_init(void)I1108 21:47:57.853109511 12183 completion_queue.c:417] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)I1108 21:47:57.853124892 12183 init.c:168] grpc_init(void)I1108 21:47:57.853146414 12183 init.c:168] grpc_init(void)I1108 21:47:57.853160323 12183 init.c:168] grpc_init(void)I1108 21:47:57.853190129 12183 call.c:1780] grpc_call_start_batch(call=0x1842f18, ops=0x1843c00, nops=6, tag=0x7f2dbf021320, reserved=(nil))I1108 21:47:57.853201671 12183 call.c:1426] ops[0]: SEND_INITIAL_METADATA(nil)I1108 21:47:57.853209408 12183 call.c:1426] ops[1]: SEND_MESSAGE ptr=0x1594880I1108 21:47:57.853216269 12183 call.c:1426] ops[2]: SEND_CLOSE_FROM_CLIENTI1108 21:47:57.853223440 12183 call.c:1426] ops[3]: RECV_INITIAL_METADATA ptr=0x7f2dc007b378I1108 21:47:57.853230737 12183 call.c:1426] ops[4]: RECV_MESSAGE ptr=0x7f2dc46b7d90I1108 21:47:57.853374426 12183 call.c:1426] ops[5]: RECV_STATUS_ON_CLIENT metadata=0x7f2dc007b3a8 status=0x7f2dc00578a0 details=0x7f2dc00578a8I1108 21:47:57.853436256 12183 client_channel.c:1383] OP[client-channel:0x18435d0]: SEND_INITIAL_METADATA{key=3a 70 61 74 68 ':path' value=2f 69 6f 2e 70 72 69 63 65 69 6e 73 69 67 68 74 2e 6d 74 34 6d 61 6e 61 67 65 72 2e 4e 65 77 43 68 61 72 74 42 61 73 65 73 53 65 72 76 69 63 65 2f 43 68 61 72 74 52 65 71 75 65 73 74 '/io.priceinsight.mt4manager.NewChartBasesService/ChartRequest', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=31 30 2e 35 2e 30 2e 35 3a 35 30 30 35 31 '10.5.0.5:50051'} SEND_MESSAGE:flags=0x00000000:len=10 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATAD1108 21:47:57.853472613 12183 client_channel.c:1421] chand=0x183fd90 calld=0x18435f0: entering combinerD1108 21:47:57.853499965 12183 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x18438a0 last=1D1108 21:47:57.853544005 12183 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=1 time_to_execute_final_list=0D1108 21:47:57.853572154 12183 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x18438a0I1108 21:47:57.853582598 12187 init.c:168] grpc_init(void)D1108 21:47:57.853601302 12183 client_channel.c:298] chand=0x183fd90: starting name resolutionI1108 21:47:57.853610840 12187 completion_queue.c:417] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)D1108 21:47:57.853651552 12185 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x182a6f0 last=3I1108 21:47:57.853659849 12187 channel_connectivity.c:209] grpc_channel_watch_connectivity_state(channel=0x183fcd0, last_observed_state=0, deadline=gpr_timespec { tv_sec: 1510130878, tv_nsec: 53640842, clock_type: 1 }, cq=0x7f2db0002400, tag=0x7f2dbf021250)D1108 21:47:57.853715088 12187 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x7f2db0001990 last=5I1108 21:47:57.853734116 12187 completion_queue.c:833] grpc_completion_queue_next(cq=0x7f2db0002400, deadline=gpr_timespec { tv_sec: 1510130878, tv_nsec: 53730217, clock_type: 1 }, reserved=(nil))D1108 21:47:57.853696737 12183 client_channel.c:1108] chand=0x183fd90 calld=0x18435f0: deferring pick pending resolver resultD1108 21:47:57.853780663 12183 combiner.c:284] C:0x183fec0 finish old_state=7D1108 21:47:57.853797376 12183 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=1 exec_ctx_ready_to_finish=1 time_to_execute_final_list=0D1108 21:47:57.853811051 12183 combiner.c:199] C:0x183fec0 queue_offloadI1108 21:47:57.853823639 12183 init.c:173] grpc_shutdown(void)D1108 21:47:57.853826069 12185 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=1 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.853853248 12185 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x182a6f0I1108 21:47:57.853853187 12183 completion_queue.c:833] grpc_completion_queue_next(cq=0x1842480, deadline=gpr_timespec { tv_sec: 1510130878, tv_nsec: 53849583, clock_type: 1 }, reserved=(nil))D1108 21:47:57.853876808 12185 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x183fde0 last=5D1108 21:47:57.853891122 12185 combiner.c:284] C:0x183fec0 finish old_state=7D1108 21:47:57.853903455 12185 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=1 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.853911824 12185 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x7f2db0001990D1108 21:47:57.853922405 12185 timer_generic.c:248] TIMER 0x7f2db0002618: SET 4722.653135544 [207] now 4722.453413112 [6] call 0x7f2db00025c8[0x7f2dc2c02980]D1108 21:47:57.853930860 12185 timer_generic.c:281] .. add to shard 18 with queue_deadline_cap=0 => is_first_timer=falseD1108 21:47:57.853939067 12185 connectivity_state.c:121] CONWATCH: 0x183fe08 client_channel: from IDLE [cur=IDLE] notify=0x7f2db0001990D1108 21:47:57.853946313 12185 combiner.c:284] C:0x183fec0 finish old_state=5D1108 21:47:57.853953277 12185 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=1 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.853961518 12185 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x183fde0D1108 21:47:57.853968691 12185 client_channel.c:370] chand=0x183fd90: got resolver result: error="No Error"D1108 21:47:57.853977583 12185 pick_first.c:687] Pick First 0x7f2db80014d0 created.I1108 21:47:57.853985003 12185 pick_first.c:335] Pick First 0x7f2db80014d0 received update with 1 addressesI1108 21:47:57.854026367 12185 pick_first.c:416] Pick First 0x7f2db80014d0 created subchannel 0x7f2db8001ab0 for address uri ipv4:10.5.0.5:50051D1108 21:47:57.854038167 12185 client_channel.c:477] chand=0x183fd90: resolver result: lb_policy_name="pick_first" (changed), service_config="(null)"D1108 21:47:57.854048151 12185 client_channel.c:559] chand=0x183fd90: initializing new LB policyD1108 21:47:57.854056074 12185 connectivity_state.c:96] CONWATCH: 0x7f2db8001570 (null): get IDLED1108 21:47:57.854064006 12185 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x183fa20 last=3D1108 21:47:57.854071725 12185 connectivity_state.c:121] CONWATCH: 0x7f2db8001570 (null): from IDLE [cur=IDLE] notify=0x7f2db80015a8D1108 21:47:57.854078601 12185 client_channel.c:248] chand=0x183fd90: setting connectivity state to IDLED1108 21:47:57.854086297 12185 connectivity_state.c:171] SET: 0x183fe08 client_channel: IDLE --> IDLE [new_lb+resolver] error=(nil) "No Error"D1108 21:47:57.854093605 12185 combiner.c:284] C:0x183fec0 finish old_state=5D1108 21:47:57.854100830 12185 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=1 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.854108116 12185 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x183fa20D1108 21:47:57.854122963 12185 client_channel.c:1092] chand=0x183fd90 calld=0x18435f0: resolver returned, doing pickD1108 21:47:57.854131766 12185 client_channel.c:940] chand=0x183fd90 calld=0x18435f0: applying service config to callD1108 21:47:57.854139169 12185 client_channel.c:1178] chand=0x183fd90 calld=0x18435f0: starting pick on lb_policy=0x7f2db80014d0D1108 21:47:57.854147736 12185 connectivity_state.c:121] CONWATCH: 0x7f2db8001b80 subchannel: from IDLE [cur=IDLE] notify=0x1844288D1108 21:47:57.854156266 12185 connectivity_state.c:171] SET: 0x7f2db8001b80 subchannel: IDLE --> CONNECTING [state_change] error=(nil) "No Error"D1108 21:47:57.854163556 12185 connectivity_state.c:198] NOTIFY: 0x7f2db8001b80 subchannel: 0x1844288D1108 21:47:57.854440253 12185 tcp_client_posix.c:321] CLIENT_CONNECT: ipv4:10.5.0.5:50051: asynchronously connecting fd 0x7f2db8002530D1108 21:47:57.854455183 12185 timer_generic.c:248] TIMER 0x7f2db8002690: SET 4742.453648846 [20007] now 4722.453946904 [7] call 0x7f2db80026b8[0x7f2dc2ba87f0]D1108 21:47:57.854678491 12185 timer_generic.c:281] .. add to shard 26 with queue_deadline_cap=0 => is_first_timer=falseD1108 21:47:57.854699257 12185 combiner.c:284] C:0x183fec0 finish old_state=3D1108 21:47:57.854708625 12185 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x7f2db8001510 last=1D1108 21:47:57.854722598 12185 tcp_client_posix.c:142] CLIENT_CONNECT: ipv4:10.5.0.5:50051: on_writable: error="No Error"D1108 21:47:57.854735166 12185 timer_generic.c:332] TIMER 0x7f2db8002690: CANCEL pending=trueD1108 21:47:57.854750703 12185 combiner.c:84] C:0x7f2db80029b0 createD1108 21:47:57.854763194 12185 tcp_client_posix.c:104] CLIENT_CONNECT: ipv4:10.5.0.5:50051: on_alarm: error="Cancelled"D1108 21:47:57.854786277 12185 timer_generic.c:248] TIMER 0x7f2db8002ef0: SET 4742.453648846 [20007] now 4722.454277226 [7] call 0x7f2db8002f18[0x7f2dc2b95a40]D1108 21:47:57.854795786 12185 timer_generic.c:281] .. add to shard 24 with queue_deadline_cap=0 => is_first_timer=falseD1108 21:47:57.854805263 12185 timer_generic.c:332] TIMER 0x7f2db8002ef0: CANCEL pending=trueD1108 21:47:57.854829482 12185 combiner.c:84] C:0x7f2db8007810 createD1108 21:47:57.854867308 12185 chttp2_transport.c:841] W:0x7f2db8004290 CLIENT state IDLE -> WRITING [initial_write]D1108 21:47:57.854875520 12185 combiner.c:332] C:0x7f2db8007810 grpc_combiner_execute_finally c=0x7f2db8004340; ac=0x183fec0D1108 21:47:57.854882761 12185 combiner.c:161] C:0x7f2db8007810 grpc_combiner_execute c=0x7f2db8002330 last=1D1108 21:47:57.854894482 12185 chttp2_transport.c:841] W:0x7f2db8004290 CLIENT state WRITING -> WRITING+MORE [init]D1108 21:47:57.854901703 12185 combiner.c:161] C:0x7f2db80029b0 grpc_combiner_execute c=0x7f2db8002da0 last=1D1108 21:47:57.854909296 12185 combiner.c:161] C:0x7f2db8007810 grpc_combiner_execute c=0x7f2db80043b8 last=3D1108 21:47:57.854936261 12185 combiner.c:161] C:0x7f2db8007810 grpc_combiner_execute c=0x7f2db8003350 last=5D1108 21:47:57.854945524 12185 connectivity_state.c:171] SET: 0x7f2db8001b80 subchannel: CONNECTING --> READY [connected] error=(nil) "No Error"D1108 21:47:57.854954334 12185 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.854962817 12185 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x7f2db8001510D1108 21:47:57.854971476 12185 pick_first.c:469] Pick First 0x7f2db80014d0 connectivity changed. Updating selected: 0; Updating subchannels: 0; Checking 0 index (1 total); State: 1; D1108 21:47:57.854981289 12185 connectivity_state.c:171] SET: 0x7f2db8001570 (null): IDLE --> CONNECTING [connecting_changed] error=(nil) "No Error"D1108 21:47:57.854988863 12185 connectivity_state.c:198] NOTIFY: 0x7f2db8001570 (null): 0x7f2db80015a8D1108 21:47:57.854996525 12185 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x7f2db80015a8 last=3D1108 21:47:57.855004608 12185 connectivity_state.c:121] CONWATCH: 0x7f2db8001b80 subchannel: from CONNECTING [cur=READY] notify=0x1844288D1108 21:47:57.855012188 12185 combiner.c:284] C:0x183fec0 finish old_state=5D1108 21:47:57.855019443 12185 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x7f2db8001510 last=3D1108 21:47:57.855027174 12185 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.855034549 12185 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x7f2db80015a8D1108 21:47:57.855041623 12185 client_channel.c:262] chand=0x183fd90: lb_policy=0x7f2db80014d0 state changed to CONNECTINGD1108 21:47:57.855049193 12185 client_channel.c:248] chand=0x183fd90: setting connectivity state to CONNECTINGD1108 21:47:57.855056940 12185 connectivity_state.c:171] SET: 0x183fe08 client_channel: IDLE --> CONNECTING [lb_changed] error=(nil) "No Error"D1108 21:47:57.855064036 12185 connectivity_state.c:198] NOTIFY: 0x183fe08 client_channel: 0x7f2db0001990D1108 21:47:57.855071723 12185 connectivity_state.c:121] CONWATCH: 0x7f2db8001570 (null): from CONNECTING [cur=CONNECTING] notify=0x7f2db8007e08D1108 21:47:57.855079203 12185 combiner.c:284] C:0x183fec0 finish old_state=5D1108 21:47:57.855087391 12185 timer_generic.c:332] TIMER 0x7f2db0002618: CANCEL pending=trueD1108 21:47:57.855096355 12185 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x7f2db80036e0 last=3I1108 21:47:57.855104692 12185 completion_queue.c:620] cq_end_op_for_next(exec_ctx=0x7f2dc0048e70, cq=0x7f2db0002400, tag=0x7f2dbf021250, error="No Error", done=0x7f2dc2c02b30, done_arg=0x7f2db0002570, storage=0x7f2db0002650)D1108 21:47:57.855116936 12185 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.855124680 12185 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x7f2db8001510I1108 21:47:57.855128110 12187 completion_queue.c:937] RETURN_EVENT[0x7f2db0002400]: OP_COMPLETE: tag:0x7f2dbf021250 OKD1108 21:47:57.855132167 12185 pick_first.c:469] Pick First 0x7f2db80014d0 connectivity changed. Updating selected: 0; Updating subchannels: 0; Checking 0 index (1 total); State: 2; D1108 21:47:57.855155647 12185 connectivity_state.c:171] SET: 0x7f2db8001570 (null): CONNECTING --> READY [connecting_ready] error=(nil) "No Error"D1108 21:47:57.855165682 12185 connectivity_state.c:198] NOTIFY: 0x7f2db8001570 (null): 0x7f2db8007e08I1108 21:47:57.855165724 12187 channel_connectivity.c:38] grpc_channel_check_connectivity_state(channel=0x183fcd0, try_to_connect=0)D1108 21:47:57.855176047 12185 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x7f2db8007e08 last=5D1108 21:47:57.855184237 12187 connectivity_state.c:84] CONWATCH: 0x183fe08 client_channel: get CONNECTINGI1108 21:47:57.855189562 12185 pick_first.c:573] Pick First 0x7f2db80014d0 selected subchannel 0x7f2db8001ab0 (connected 0x7f2db80031d0)I1108 21:47:57.855203676 12185 pick_first.c:586] Servicing pending pick with selected subchannel 0x7f2db80031d0D1108 21:47:57.855211915 12185 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x18436e0 last=7D1108 21:47:57.855221727 12185 combiner.c:161] C:0x7f2db8007810 grpc_combiner_execute c=0x7f2db8002f00 last=7D1108 21:47:57.855229600 12185 combiner.c:284] C:0x183fec0 finish old_state=9D1108 21:47:57.855236983 12185 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.855244189 12185 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x7f2db80036e0D1108 21:47:57.855251659 12185 combiner.c:284] C:0x183fec0 finish old_state=7D1108 21:47:57.855259166 12185 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.855266937 12185 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x7f2db8007e08D1108 21:47:57.855274483 12185 client_channel.c:262] chand=0x183fd90: lb_policy=0x7f2db80014d0 state changed to READYD1108 21:47:57.855281828 12185 client_channel.c:248] chand=0x183fd90: setting connectivity state to READYD1108 21:47:57.855289422 12185 connectivity_state.c:171] SET: 0x183fe08 client_channel: CONNECTING --> READY [lb_changed] error=(nil) "No Error"D1108 21:47:57.855297133 12185 connectivity_state.c:121] CONWATCH: 0x7f2db8001570 (null): from READY [cur=READY] notify=0x7f2db8004228D1108 21:47:57.855304526 12185 combiner.c:284] C:0x183fec0 finish old_state=5D1108 21:47:57.855312055 12185 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.855319158 12185 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x18436e0D1108 21:47:57.855325929 12185 client_channel.c:1160] chand=0x183fd90 calld=0x18435f0: pick completed asynchronouslyD1108 21:47:57.855355967 12185 client_channel.c:983] chand=0x183fd90 calld=0x18435f0: create subchannel_call=0x7f2db8008948: error="No Error"D1108 21:47:57.855366385 12185 client_channel.c:921] chand=0x183fd90 calld=0x18435f0: sending 1 pending batches to subchannel_call=0x7f2db8008948I1108 21:47:57.855381311 12185 http_client_filter.c:305] OP[http-client:0x7f2db80089c0]: SEND_INITIAL_METADATA{key=3a 70 61 74 68 ':path' value=2f 69 6f 2e 70 72 69 63 65 69 6e 73 69 67 68 74 2e 6d 74 34 6d 61 6e 61 67 65 72 2e 4e 65 77 43 68 61 72 74 42 61 73 65 73 53 65 72 76 69 63 65 2f 43 68 61 72 74 52 65 71 75 65 73 74 '/io.priceinsight.mt4manager.NewChartBasesService/ChartRequest', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=31 30 2e 35 2e 30 2e 35 3a 35 30 30 35 31 '10.5.0.5:50051'} SEND_MESSAGE:flags=0x00000000:len=10 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATAI1108 21:47:57.855413158 12185 connected_channel.c:55] OP[connected:0x7f2db80089f0]: SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 69 6f 2e 70 72 69 63 65 69 6e 73 69 67 68 74 2e 6d 74 34 6d 61 6e 61 67 65 72 2e 4e 65 77 43 68 61 72 74 42 61 73 65 73 53 65 72 76 69 63 65 2f 43 68 61 72 74 52 65 71 75 65 73 74 '/io.priceinsight.mt4manager.NewChartBasesService/ChartRequest', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=31 30 2e 35 2e 30 2e 35 3a 35 30 30 35 31 '10.5.0.5:50051', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 70 79 74 68 6f 6e 2f 31 2e 36 2e 30 20 67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6d 61 6e 79 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 61 72 63 69 61 29 'grpc-python/1.6.0 grpc-c/4.0.0 (manylinux; chttp2; garcia)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip'} SEND_MESSAGE:flags=0x00000000:len=10 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATAD1108 21:47:57.855451126 12185 chttp2_transport.c:1524] perform_stream_op[s=0x7f2db8008ec0]: SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 69 6f 2e 70 72 69 63 65 69 6e 73 69 67 68 74 2e 6d 74 34 6d 61 6e 61 67 65 72 2e 4e 65 77 43 68 61 72 74 42 61 73 65 73 53 65 72 76 69 63 65 2f 43 68 61 72 74 52 65 71 75 65 73 74 '/io.priceinsight.mt4manager.NewChartBasesService/ChartRequest', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=31 30 2e 35 2e 30 2e 35 3a 35 30 30 35 31 '10.5.0.5:50051', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 70 79 74 68 6f 6e 2f 31 2e 36 2e 30 20 67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6d 61 6e 79 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 61 72 63 69 61 29 'grpc-python/1.6.0 grpc-c/4.0.0 (manylinux; chttp2; garcia)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip'} SEND_MESSAGE:flags=0x00000000:len=10 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATAI1108 21:47:57.855459427 12187 channel_connectivity.c:209] grpc_channel_watch_connectivity_state(channel=0x183fcd0, last_observed_state=1, deadline=gpr_timespec { tv_sec: 1510130878, tv_nsec: 55443048, clock_type: 1 }, cq=0x7f2db0002400, tag=0x7f2dbf0212b8)D1108 21:47:57.855473429 12185 combiner.c:161] C:0x7f2db8007810 grpc_combiner_execute c=0x18438a0 last=9D1108 21:47:57.855484309 12187 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x7f2db0001860 last=3D1108 21:47:57.855488362 12185 combiner.c:284] C:0x183fec0 finish old_state=5D1108 21:47:57.855501364 12185 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=1 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0I1108 21:47:57.855501167 12187 completion_queue.c:833] grpc_completion_queue_next(cq=0x7f2db0002400, deadline=gpr_timespec { tv_sec: 1510130878, tv_nsec: 55497667, clock_type: 1 }, reserved=(nil))D1108 21:47:57.855528875 12185 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x7f2db0001860D1108 21:47:57.855545468 12185 timer_generic.c:248] TIMER 0x7f2db0002618: SET 4722.654937714 [209] now 4722.455036244 [8] call 0x7f2db00025c8[0x7f2dc2c02980]D1108 21:47:57.855552884 12185 timer_generic.c:281] .. add to shard 18 with queue_deadline_cap=0 => is_first_timer=falseD1108 21:47:57.855558252 12185 connectivity_state.c:121] CONWATCH: 0x183fe08 client_channel: from CONNECTING [cur=READY] notify=0x7f2db0001860D1108 21:47:57.855563256 12185 combiner.c:284] C:0x183fec0 finish old_state=3D1108 21:47:57.855568154 12185 timer_generic.c:332] TIMER 0x7f2db0002618: CANCEL pending=trueD1108 21:47:57.855574244 12185 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x7f2db8003f80 last=1I1108 21:47:57.855579867 12185 completion_queue.c:620] cq_end_op_for_next(exec_ctx=0x7f2dc0048e70, cq=0x7f2db0002400, tag=0x7f2dbf0212b8, error="No Error", done=0x7f2dc2c02b30, done_arg=0x7f2db0002570, storage=0x7f2db0002650)D1108 21:47:57.855590445 12185 combiner.c:221] C:0x7f2db8007810 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0I1108 21:47:57.855596521 12187 completion_queue.c:937] RETURN_EVENT[0x7f2db0002400]: OP_COMPLETE: tag:0x7f2dbf0212b8 OKD1108 21:47:57.855598709 12185 combiner.c:239] C:0x7f2db8007810 maybe_finish_one n=0x7f2db8002330D1108 21:47:57.855612227 12185 combiner.c:332] C:0x7f2db8007810 grpc_combiner_execute_finally c=0x7f2db8004340; ac=0x7f2db8007810I1108 21:47:57.855617825 12187 channel_connectivity.c:38] grpc_channel_check_connectivity_state(channel=0x183fcd0, try_to_connect=0)D1108 21:47:57.855620788 12185 combiner.c:284] C:0x7f2db8007810 finish old_state=13D1108 21:47:57.855629653 12187 connectivity_state.c:84] CONWATCH: 0x183fe08 client_channel: get READYD1108 21:47:57.855634917 12185 combiner.c:221] C:0x7f2db8007810 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.855643380 12185 combiner.c:239] C:0x7f2db8007810 maybe_finish_one n=0x7f2db80043b8D1108 21:47:57.855665169 12185 bdp_estimator.c:67] bdp[ipv4:10.5.0.5:50051]:sched acc=0 est=65536D1108 21:47:57.855675673 12185 combiner.c:284] C:0x7f2db8007810 finish old_state=11D1108 21:47:57.855685346 12185 resource_quota.c:776] RQ anonymous_pool_7f2db80028e0 ipv4:10.5.0.5:50051: alloc 8192; free_pool -> -8192D1108 21:47:57.855694547 12185 combiner.c:161] C:0x7f2db80029b0 grpc_combiner_execute c=0x7f2db8002cd8 last=3D1108 21:47:57.855703797 12185 combiner.c:221] C:0x7f2db8007810 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.855712014 12185 combiner.c:239] C:0x7f2db8007810 maybe_finish_one n=0x7f2db8003350D1108 21:47:57.855723301 12185 connectivity_state.c:121] CONWATCH: 0x7f2db80044e0 client_transport: from READY [cur=READY] notify=0x7f2db8002190D1108 21:47:57.855733220 12185 combiner.c:284] C:0x7f2db8007810 finish old_state=9D1108 21:47:57.855740436 12185 combiner.c:221] C:0x7f2db8007810 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.855745796 12185 combiner.c:239] C:0x7f2db8007810 maybe_finish_one n=0x7f2db8002f00D1108 21:47:57.855751706 12185 connectivity_state.c:121] CONWATCH: 0x7f2db80044e0 client_transport: from READY [cur=READY] notify=0x7f2db8001510D1108 21:47:57.855756849 12185 combiner.c:284] C:0x7f2db8007810 finish old_state=7D1108 21:47:57.855762293 12185 combiner.c:221] C:0x7f2db8007810 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.855767210 12185 combiner.c:239] C:0x7f2db8007810 maybe_finish_one n=0x18438a0D1108 21:47:57.855796423 12185 chttp2_transport.c:1263] perform_stream_op_locked: SEND_INITIAL_METADATA{key=3a 73 63 68 65 6d 65 ':scheme' value=68 74 74 70 'http', key=3a 6d 65 74 68 6f 64 ':method' value=50 4f 53 54 'POST', key=3a 70 61 74 68 ':path' value=2f 69 6f 2e 70 72 69 63 65 69 6e 73 69 67 68 74 2e 6d 74 34 6d 61 6e 61 67 65 72 2e 4e 65 77 43 68 61 72 74 42 61 73 65 73 53 65 72 76 69 63 65 2f 43 68 61 72 74 52 65 71 75 65 73 74 '/io.priceinsight.mt4manager.NewChartBasesService/ChartRequest', key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=31 30 2e 35 2e 30 2e 35 3a 35 30 30 35 31 '10.5.0.5:50051', key=74 65 'te' value=74 72 61 69 6c 65 72 73 'trailers', key=63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type' value=61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc', key=75 73 65 72 2d 61 67 65 6e 74 'user-agent' value=67 72 70 63 2d 70 79 74 68 6f 6e 2f 31 2e 36 2e 30 20 67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6d 61 6e 79 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 61 72 63 69 61 29 'grpc-python/1.6.0 grpc-c/4.0.0 (manylinux; chttp2; garcia)', key=67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding' value=69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip'} SEND_MESSAGE:flags=0x00000000:len=10 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA; on_complete = 0x7f2db8008b50I1108 21:47:57.855816069 12185 chttp2_transport.c:1245] HTTP:0:HDR:CLI: :scheme: httpI1108 21:47:57.855825999 12185 chttp2_transport.c:1245] HTTP:0:HDR:CLI: :method: POSTI1108 21:47:57.855824909 12187 channel_connectivity.c:209] grpc_channel_watch_connectivity_state(channel=0x183fcd0, last_observed_state=2, deadline=gpr_timespec { tv_sec: 1510130878, tv_nsec: 55813312, clock_type: 1 }, cq=0x7f2db0002400, tag=0x7f2dbf021250)I1108 21:47:57.855836371 12185 chttp2_transport.c:1245] HTTP:0:HDR:CLI: :path: /io.priceinsight.mt4manager.NewChartBasesService/ChartRequestD1108 21:47:57.855848088 12187 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x7f2db0001940 last=3I1108 21:47:57.855851646 12185 chttp2_transport.c:1245] HTTP:0:HDR:CLI: :authority: 10.5.0.5:50051I1108 21:47:57.855864013 12187 completion_queue.c:833] grpc_completion_queue_next(cq=0x7f2db0002400, deadline=gpr_timespec { tv_sec: 1510130878, tv_nsec: 55860706, clock_type: 1 }, reserved=(nil))I1108 21:47:57.855865155 12185 chttp2_transport.c:1245] HTTP:0:HDR:CLI: te: trailersI1108 21:47:57.855887388 12185 chttp2_transport.c:1245] HTTP:0:HDR:CLI: content-type: application/grpcI1108 21:47:57.855894660 12185 chttp2_transport.c:1245] HTTP:0:HDR:CLI: user-agent: grpc-python/1.6.0 grpc-c/4.0.0 (manylinux; chttp2; garcia)I1108 21:47:57.855901726 12185 chttp2_transport.c:1245] HTTP:0:HDR:CLI: grpc-accept-encoding: identity,deflate,gzipD1108 21:47:57.855910832 12185 chttp2_transport.c:1047] HTTP:CLI: Allocating new grpc_chttp2_stream 0x7f2db8008ec0 to id 1D1108 21:47:57.855917790 12185 combiner.c:161] C:0x7f2db80029b0 grpc_combiner_execute c=0x7f2db8002dc8 last=5D1108 21:47:57.855929873 12185 chttp2_transport.c:1113] complete_closure_step: 0x7f2db8008b50 refs=4 flags=0x0003 desc=op->on_complete err="No Error"D1108 21:47:57.855936151 12185 combiner.c:284] C:0x7f2db8007810 finish old_state=5D1108 21:47:57.855943420 12185 combiner.c:221] C:0x7f2db8007810 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=1D1108 21:47:57.855951557 12185 combiner.c:265] C:0x7f2db8007810 execute_final[0] c=0x7f2db8004340D1108 21:47:57.855961433 12185 writing.c:226] W:0x7f2db8004290 CLIENT[1] im-(sent,send)=(0,1) announce=5D1108 21:47:57.855973921 12185 hpack_encoder.c:417] Encode: ':path: /io.priceinsight.mt4manager.NewChartBasesService/ChartRequest', elem_interned=0 [2], k_interned=1, v_interned=0D1108 21:47:57.855989832 12185 chttp2_transport.c:841] W:0x7f2db8004290 CLIENT state WRITING+MORE -> WRITING [begin writing]D1108 21:47:57.855996678 12185 combiner.c:284] C:0x7f2db8007810 finish old_state=3D1108 21:47:57.856006312 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 50 52 49 20 2a 20 48 54 54 50 2f 32 2e 30 0d 0a 0d 0a 53 4d 0d 0a 0d 0a 'PRI * HTTP/2.0....SM....'D1108 21:47:57.856533654 12186 timer_generic.c:538] TIMER CHECK BEGIN: now=4722.456020264 [9] next=9223372036854775807.000000000 [9223372036854775807] tls_min=0 glob_min=0D1108 21:47:57.858187933 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 00 00 24 04 00 00 00 00 00 00 02 00 00 00 00 00 03 00 00 00 00 00 04 00 00 ff ff 00 05 00 01 00 49 00 06 00 00 20 00 fe 03 00 00 00 01 '..$.............................I.... .......'D1108 21:47:57.858199443 12186 timer_generic.c:452] .. shard[0]->min_deadline = 1D1108 21:47:57.858206389 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 00 01 1b 01 04 00 00 00 01 40 07 '.........@.'D1108 21:47:57.858215768 12186 timer_generic.c:393] .. shard[0]: heap_empty=trueD1108 21:47:57.858227910 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 3a 73 63 68 65 6d 65 ':scheme'D1108 21:47:57.858239595 12186 timer_generic.c:368] .. shard[0]->queue_deadline_cap --> 1009D1108 21:47:57.858250071 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 04 '.'D1108 21:47:57.858260380 12186 timer_generic.c:470] .. result --> 1, shard[0]->min_deadline 1 --> 1010, now=9D1108 21:47:57.858269687 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 68 74 74 70 'http'D1108 21:47:57.858280080 12186 timer_generic.c:393] .. shard[1]: heap_empty=trueD1108 21:47:57.858288942 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 40 07 '@.'D1108 21:47:57.858298478 12186 timer_generic.c:368] .. shard[1]->queue_deadline_cap --> 1009D1108 21:47:57.858308854 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 3a 6d 65 74 68 6f 64 ':method'D1108 21:47:57.858318189 12186 timer_generic.c:470] .. result --> 1, shard[1]->min_deadline 1 --> 1010, now=9D1108 21:47:57.858327562 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 04 '.'D1108 21:47:57.858337420 12186 timer_generic.c:393] .. shard[2]: heap_empty=trueD1108 21:47:57.858347326 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 50 4f 53 54 'POST'D1108 21:47:57.858361260 12186 timer_generic.c:368] .. shard[2]->queue_deadline_cap --> 1009D1108 21:47:57.858371138 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 00 05 '..'D1108 21:47:57.858381096 12186 timer_generic.c:470] .. result --> 1, shard[2]->min_deadline 1 --> 1010, now=9D1108 21:47:57.858390959 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 3a 70 61 74 68 ':path'D1108 21:47:57.858401485 12186 timer_generic.c:393] .. shard[3]: heap_empty=trueD1108 21:47:57.858410805 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 3d '='D1108 21:47:57.858419708 12186 timer_generic.c:368] .. shard[3]->queue_deadline_cap --> 1009D1108 21:47:57.858431513 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 2f 69 6f 2e 70 72 69 63 65 69 6e 73 69 67 68 74 2e 6d 74 34 6d 61 6e 61 67 65 72 2e 4e 65 77 43 68 61 72 74 42 61 73 65 73 53 65 72 76 69 63 65 2f 43 68 61 72 74 52 65 71 75 65 73 74 '/io.priceinsight.mt4manager.NewChartBasesService/ChartRequest'D1108 21:47:57.858441655 12186 timer_generic.c:470] .. result --> 1, shard[3]->min_deadline 1 --> 1010, now=9D1108 21:47:57.858451675 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 40 0a '@.'D1108 21:47:57.858462538 12186 timer_generic.c:393] .. shard[4]: heap_empty=trueD1108 21:47:57.858469012 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 3a 61 75 74 68 6f 72 69 74 79 ':authority'D1108 21:47:57.858486022 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 0e '.'D1108 21:47:57.858494519 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 31 30 2e 35 2e 30 2e 35 3a 35 30 30 35 31 '10.5.0.5:50051'D1108 21:47:57.858501468 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 40 02 '@.'D1108 21:47:57.858523811 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 74 65 'te'D1108 21:47:57.858532310 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 08 '.'D1108 21:47:57.858539945 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 74 72 61 69 6c 65 72 73 'trailers'D1108 21:47:57.858546185 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 40 0c '@.'D1108 21:47:57.858553025 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type'D1108 21:47:57.858559395 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 10 '.'D1108 21:47:57.858566420 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'D1108 21:47:57.858573316 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 40 0a '@.'D1108 21:47:57.858580766 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 75 73 65 72 2d 61 67 65 6e 74 'user-agent'D1108 21:47:57.858587577 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 3a ':'D1108 21:47:57.858595090 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 67 72 70 63 2d 70 79 74 68 6f 6e 2f 31 2e 36 2e 30 20 67 72 70 63 2d 63 2f 34 2e 30 2e 30 20 28 6d 61 6e 79 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 3b 20 67 61 72 63 69 61 29 'grpc-python/1.6.0 grpc-c/4.0.0 (manylinux; chttp2; garcia)'D1108 21:47:57.858477503 12186 timer_generic.c:368] .. shard[4]->queue_deadline_cap --> 1009D1108 21:47:57.875658112 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 40 14 '@.'D1108 21:47:57.875696002 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding'D1108 21:47:57.875712010 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 15 '.'D1108 21:47:57.875722479 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip'D1108 21:47:57.875731842 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 00 00 04 08 00 00 00 00 01 00 00 00 05 00 00 '...............'D1108 21:47:57.875742533 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 0f 00 01 00 00 00 01 00 00 00 00 0a 0a 06 45 '..............E'D1108 21:47:57.875751086 12185 tcp_posix.c:491] WRITE 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 55 52 55 53 44 28 01 'URUSD(.'D1108 21:47:57.875912277 12185 tcp_posix.c:523] write: "No Error"D1108 21:47:57.875928473 12185 combiner.c:161] C:0x7f2db8007810 grpc_combiner_execute c=0x7f2db8004390 last=1D1108 21:47:57.875936744 12185 combiner.c:221] C:0x7f2db80029b0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.875944794 12185 combiner.c:239] C:0x7f2db80029b0 maybe_finish_one n=0x7f2db8002da0D1108 21:47:57.875951429 12185 combiner.c:284] C:0x7f2db80029b0 finish old_state=7D1108 21:47:57.875957515 12185 combiner.c:221] C:0x7f2db80029b0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.875964031 12185 combiner.c:239] C:0x7f2db80029b0 maybe_finish_one n=0x7f2db8002cd8D1108 21:47:57.875971520 12185 combiner.c:332] C:0x7f2db80029b0 grpc_combiner_execute_finally c=0x7f2db8002918; ac=0x7f2db80029b0D1108 21:47:57.875978291 12185 combiner.c:284] C:0x7f2db80029b0 finish old_state=7D1108 21:47:57.875984222 12185 combiner.c:221] C:0x7f2db80029b0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.875990889 12185 combiner.c:239] C:0x7f2db80029b0 maybe_finish_one n=0x7f2db8002dc8D1108 21:47:57.875997670 12185 combiner.c:284] C:0x7f2db80029b0 finish old_state=5D1108 21:47:57.876003451 12185 combiner.c:221] C:0x7f2db80029b0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=1D1108 21:47:57.876010155 12185 combiner.c:265] C:0x7f2db80029b0 execute_final[0] c=0x7f2db8002918D1108 21:47:57.876018173 12185 resource_quota.c:297] RQ anonymous_pool_7f2db80028e0 ipv4:10.5.0.5:50051: grant alloc 8192 bytes; rq_free_pool -> 9223372036854767615D1108 21:47:57.876026266 12185 combiner.c:284] C:0x7f2db80029b0 finish old_state=3D1108 21:47:57.876047613 12185 tcp_posix.c:219] read: error="No Error"D1108 21:47:57.876057706 12185 tcp_posix.c:224] READ 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 00 00 18 04 00 00 00 00 00 00 04 00 00 ff ff 00 05 00 01 00 06 00 06 00 00 20 00 fe 03 00 00 00 01 '......................... .......'D1108 21:47:57.876310145 12185 combiner.c:161] C:0x7f2db8007810 grpc_combiner_execute c=0x7f2db80043b8 last=3D1108 21:47:57.876320634 12185 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=1 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.876332079 12185 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x7f2db8003f80D1108 21:47:57.876346214 12185 combiner.c:284] C:0x183fec0 finish old_state=5D1108 21:47:57.876355898 12185 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=1 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.876366075 12185 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x7f2db0001940D1108 21:47:57.876380600 12185 timer_generic.c:248] TIMER 0x7f2db0002618: SET 4722.655308219 [209] now 4722.475870155 [29] call 0x7f2db00025c8[0x7f2dc2c02980]D1108 21:47:57.876390696 12185 timer_generic.c:281] .. add to shard 18 with queue_deadline_cap=0 => is_first_timer=falseD1108 21:47:57.876401712 12185 connectivity_state.c:121] CONWATCH: 0x183fe08 client_channel: from READY [cur=READY] notify=0x7f2db0001940D1108 21:47:57.876412453 12185 combiner.c:284] C:0x183fec0 finish old_state=3D1108 21:47:57.876422578 12185 combiner.c:221] C:0x7f2db8007810 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.876433070 12185 combiner.c:239] C:0x7f2db8007810 maybe_finish_one n=0x7f2db8004390D1108 21:47:57.876444528 12185 chttp2_transport.c:841] W:0x7f2db8004290 CLIENT state WRITING -> IDLE [finish writing]D1108 21:47:57.876457923 12185 chttp2_transport.c:1113] complete_closure_step: 0x7f2db8008b50 refs=3 flags=0x0003 desc=send_initial_metadata_finished err="No Error"D1108 21:47:57.876468677 12185 chttp2_transport.c:1113] complete_closure_step: 0x7f2db8008b50 refs=2 flags=0x0003 desc=finish_write_cb err="No Error"D1108 21:47:57.876480023 12185 chttp2_transport.c:1113] complete_closure_step: 0x7f2db8008b50 refs=1 flags=0x0003 desc=send_trailing_metadata_finished err="No Error"D1108 21:47:57.876495267 12185 combiner.c:284] C:0x7f2db8007810 finish old_state=5D1108 21:47:57.876636315 12185 combiner.c:221] C:0x7f2db8007810 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.876653543 12185 combiner.c:239] C:0x7f2db8007810 maybe_finish_one n=0x7f2db80043b8D1108 21:47:57.876668226 12185 frame_settings.c:215] CHTTP2:CLI:ipv4:10.5.0.5:50051: got setting INITIAL_WINDOW_SIZE = 65535D1108 21:47:57.876679485 12185 frame_settings.c:215] CHTTP2:CLI:ipv4:10.5.0.5:50051: got setting MAX_FRAME_SIZE = 65542D1108 21:47:57.876688210 12185 frame_settings.c:215] CHTTP2:CLI:ipv4:10.5.0.5:50051: got setting MAX_HEADER_LIST_SIZE = 8192D1108 21:47:57.876697741 12185 frame_settings.c:215] CHTTP2:CLI:ipv4:10.5.0.5:50051: got setting GRPC_ALLOW_TRUE_BINARY_METADATA = 1D1108 21:47:57.876717196 12185 combiner.c:284] C:0x7f2db8007810 finish old_state=3D1108 21:47:57.876728632 12185 resource_quota.c:776] RQ anonymous_pool_7f2db80028e0 ipv4:10.5.0.5:50051: alloc 8192; free_pool -> -8192D1108 21:47:57.876738961 12185 combiner.c:161] C:0x7f2db80029b0 grpc_combiner_execute c=0x7f2db8002cd8 last=1D1108 21:47:57.876749115 12185 combiner.c:221] C:0x7f2db80029b0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.876758904 12185 combiner.c:239] C:0x7f2db80029b0 maybe_finish_one n=0x7f2db8002cd8D1108 21:47:57.876768989 12185 combiner.c:332] C:0x7f2db80029b0 grpc_combiner_execute_finally c=0x7f2db8002918; ac=0x7f2db80029b0D1108 21:47:57.876778205 12185 combiner.c:284] C:0x7f2db80029b0 finish old_state=5D1108 21:47:57.876788188 12185 combiner.c:221] C:0x7f2db80029b0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=1D1108 21:47:57.876798744 12185 combiner.c:265] C:0x7f2db80029b0 execute_final[0] c=0x7f2db8002918D1108 21:47:57.876809655 12185 resource_quota.c:297] RQ anonymous_pool_7f2db80028e0 ipv4:10.5.0.5:50051: grant alloc 8192 bytes; rq_free_pool -> 9223372036854759423D1108 21:47:57.876819695 12185 combiner.c:284] C:0x7f2db80029b0 finish old_state=3D1108 21:47:57.876843566 12185 tcp_posix.c:219] read: error="No Error"D1108 21:47:57.876857973 12185 tcp_posix.c:224] READ 0x7f2db8002a80 (peer=ipv4:10.5.0.5:50051): 00 00 00 04 01 00 00 00 00 00 00 66 01 05 00 00 00 01 40 07 3a 73 74 61 74 75 73 03 32 30 30 40 0c 63 6f 6e 74 65 6e 74 2d 74 79 70 65 10 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 00 0b 67 72 70 63 2d 73 74 61 74 75 73 02 31 33 00 0c 67 72 70 63 2d 6d 65 73 73 61 67 65 1b 44 69 64 20 6e 6f 74 20 72 65 61 64 20 65 6e 74 69 72 65 20 6d 65 73 73 61 67 65 '...........f......@.:status.200@.content-type.application/grpc..grpc-status.13..grpc-message.Did not read entire message'D1108 21:47:57.876871011 12185 combiner.c:161] C:0x7f2db8007810 grpc_combiner_execute c=0x7f2db80043b8 last=1D1108 21:47:57.876881916 12185 combiner.c:221] C:0x7f2db8007810 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:57.876892959 12185 combiner.c:239] C:0x7f2db8007810 maybe_finish_one n=0x7f2db80043b8I1108 21:47:57.876904443 12185 parsing.c:621] parsing Trailers-OnlyI1108 21:47:57.876922798 12185 parsing.c:496] HTTP:1:TRL:CLI: :status: 32 30 30 '200'I1108 21:47:57.876937821 12185 parsing.c:496] HTTP:1:TRL:CLI: content-type: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'D1108 21:47:57.876951367 12185 hpack_parser.c:656] Decode: 'grpc-status: 13', elem_interned=0 [2], k_interned=1, v_interned=0I1108 21:47:57.876961612 12185 parsing.c:496] HTTP:1:TRL:CLI: grpc-status: 31 33 '13'D1108 21:47:57.876972250 12185 hpack_parser.c:656] Decode: 'grpc-message: Did not read entire message', elem_interned=0 [2], k_interned=1, v_interned=0I1108 21:47:57.876983370 12185 parsing.c:496] HTTP:1:TRL:CLI: grpc-message: 44 69 64 20 6e 6f 74 20 72 65 61 64 20 65 6e 74 69 72 65 20 6d 65 73 73 61 67 65 'Did not read entire message'D1108 21:47:57.877002634 12185 chttp2_transport.c:1113] complete_closure_step: 0x7f2db8008b50 refs=0 flags=0x0003 desc=recv_trailing_metadata_finished err="No Error"D1108 21:47:57.877021773 12185 call.c:695] get_final_status CLID1108 21:47:57.877045290 12185 call.c:698] 1: {"created":"@1510130877.877019272","description":"Error received from peer","file":"src/core/lib/surface/call.c","file_line":989,"grpc_message":"Did not read entire message","grpc_status":13}I1108 21:47:57.877060143 12185 completion_queue.c:620] cq_end_op_for_next(exec_ctx=0x7f2dc0048e70, cq=0x1842480, tag=0x7f2dbf021320, error="No Error", done=0x7f2dc2bb9c90, done_arg=0x18437f8, storage=0x1843800)I1108 21:47:57.877110934 12183 completion_queue.c:937] RETURN_EVENT[0x1842480]: OP_COMPLETE: tag:0x7f2dbf021320 OKI1108 21:47:57.877133519 12183 metadata_array.c:27] grpc_metadata_array_init(array=0x7ffdaf458830)I1108 21:47:57.877147056 12183 metadata_array.c:32] grpc_metadata_array_destroy(array=0x7f2dc007b378)I1108 21:47:57.877158665 12183 metadata_array.c:27] grpc_metadata_array_init(array=0x7ffdaf458830)I1108 21:47:57.877171079 12183 metadata_array.c:32] grpc_metadata_array_destroy(array=0x7f2dc007b3a8)I1108 21:47:57.877274400 12183 init.c:173] grpc_shutdown(void)I1108 21:47:57.877294434 12183 init.c:173] grpc_shutdown(void)I1108 21:47:57.877307327 12183 init.c:173] grpc_shutdown(void)I1108 21:47:57.877318495 12183 init.c:173] grpc_shutdown(void)I1108 21:47:57.877330187 12183 init.c:173] grpc_shutdown(void)I1108 21:47:57.877340554 12183 init.c:173] grpc_shutdown(void)I1108 21:47:57.877351280 12183 init.c:173] grpc_shutdown(void)I1108 21:47:57.877361672 12183 init.c:173] grpc_shutdown(void)I1108 21:47:57.877372600 12183 init.c:173] grpc_shutdown(void)D1108 21:47:57.877843494 12185 combiner.c:284] C:0x7f2db8007810 finish old_state=3D1108 21:47:57.875663371 12186 timer_generic.c:470] .. result --> 1, shard[4]->min_deadline 1 --> 1010, now=9D1108 21:47:57.877903053 12186 timer_generic.c:393] .. shard[5]: heap_empty=trueD1108 21:47:57.877914621 12186 timer_generic.c:368] .. shard[5]->queue_deadline_cap --> 1009D1108 21:47:57.877925631 12186 timer_generic.c:470] .. result --> 1, shard[5]->min_deadline 1 --> 1010, now=9D1108 21:47:57.877936652 12186 timer_generic.c:393] .. shard[6]: heap_empty=trueD1108 21:47:57.877945347 12186 timer_generic.c:368] .. shard[6]->queue_deadline_cap --> 1009D1108 21:47:57.877953027 12186 timer_generic.c:470] .. result --> 1, shard[6]->min_deadline 1 --> 1010, now=9D1108 21:47:57.877960030 12186 timer_generic.c:393] .. shard[7]: heap_empty=trueD1108 21:47:57.877965991 12186 timer_generic.c:368] .. shard[7]->queue_deadline_cap --> 1009D1108 21:47:57.877972327 12186 timer_generic.c:470] .. result --> 1, shard[7]->min_deadline 1 --> 1010, now=9D1108 21:47:57.877979163 12186 timer_generic.c:393] .. shard[8]: heap_empty=trueD1108 21:47:57.877984978 12186 timer_generic.c:368] .. shard[8]->queue_deadline_cap --> 1009D1108 21:47:57.877992517 12186 timer_generic.c:470] .. result --> 1, shard[8]->min_deadline 1 --> 1010, now=9D1108 21:47:57.880908877 12186 timer_generic.c:393] .. shard[9]: heap_empty=trueD1108 21:47:57.880952937 12186 timer_generic.c:368] .. shard[9]->queue_deadline_cap --> 1009D1108 21:47:57.880964620 12186 timer_generic.c:470] .. result --> 1, shard[9]->min_deadline 1 --> 1010, now=9D1108 21:47:57.880976381 12186 timer_generic.c:393] .. shard[10]: heap_empty=trueD1108 21:47:57.880985344 12186 timer_generic.c:368] .. shard[10]->queue_deadline_cap --> 1009D1108 21:47:57.880994373 12186 timer_generic.c:470] .. result --> 1, shard[10]->min_deadline 1 --> 1010, now=9D1108 21:47:57.881002772 12186 timer_generic.c:393] .. shard[11]: heap_empty=trueD1108 21:47:57.881013203 12186 timer_generic.c:368] .. shard[11]->queue_deadline_cap --> 1009D1108 21:47:57.881019776 12186 timer_generic.c:470] .. result --> 1, shard[11]->min_deadline 1 --> 1010, now=9D1108 21:47:57.881026681 12186 timer_generic.c:393] .. shard[12]: heap_empty=trueD1108 21:47:57.881032693 12186 timer_generic.c:368] .. shard[12]->queue_deadline_cap --> 1009D1108 21:47:57.881039353 12186 timer_generic.c:470] .. result --> 1, shard[12]->min_deadline 1 --> 1010, now=9D1108 21:47:57.881045939 12186 timer_generic.c:393] .. shard[13]: heap_empty=trueD1108 21:47:57.881052166 12186 timer_generic.c:368] .. shard[13]->queue_deadline_cap --> 1009D1108 21:47:57.881059616 12186 timer_generic.c:470] .. result --> 1, shard[13]->min_deadline 1 --> 1010, now=9D1108 21:47:57.881065943 12186 timer_generic.c:393] .. shard[14]: heap_empty=trueD1108 21:47:57.881072680 12186 timer_generic.c:368] .. shard[14]->queue_deadline_cap --> 1009D1108 21:47:57.881080059 12186 timer_generic.c:470] .. result --> 1, shard[14]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882062758 12186 timer_generic.c:393] .. shard[15]: heap_empty=trueD1108 21:47:57.882110835 12186 timer_generic.c:368] .. shard[15]->queue_deadline_cap --> 1009D1108 21:47:57.882122819 12186 timer_generic.c:470] .. result --> 1, shard[15]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882133288 12186 timer_generic.c:393] .. shard[16]: heap_empty=trueD1108 21:47:57.882141250 12186 timer_generic.c:368] .. shard[16]->queue_deadline_cap --> 1009D1108 21:47:57.882150842 12186 timer_generic.c:470] .. result --> 1, shard[16]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882159304 12186 timer_generic.c:393] .. shard[17]: heap_empty=trueD1108 21:47:57.882166753 12186 timer_generic.c:368] .. shard[17]->queue_deadline_cap --> 1009D1108 21:47:57.882175084 12186 timer_generic.c:470] .. result --> 1, shard[17]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882183824 12186 timer_generic.c:393] .. shard[18]: heap_empty=trueD1108 21:47:57.882192793 12186 timer_generic.c:368] .. shard[18]->queue_deadline_cap --> 102D1108 21:47:57.882202320 12186 timer_generic.c:470] .. result --> 1, shard[18]->min_deadline 1 --> 103, now=9D1108 21:47:57.882210553 12186 timer_generic.c:393] .. shard[19]: heap_empty=trueD1108 21:47:57.882219032 12186 timer_generic.c:368] .. shard[19]->queue_deadline_cap --> 1009D1108 21:47:57.882227276 12186 timer_generic.c:470] .. result --> 1, shard[19]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882235696 12186 timer_generic.c:393] .. shard[20]: heap_empty=trueD1108 21:47:57.882244072 12186 timer_generic.c:368] .. shard[20]->queue_deadline_cap --> 1009D1108 21:47:57.882253119 12186 timer_generic.c:470] .. result --> 1, shard[20]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882261073 12186 timer_generic.c:393] .. shard[21]: heap_empty=trueD1108 21:47:57.882269331 12186 timer_generic.c:368] .. shard[21]->queue_deadline_cap --> 1009D1108 21:47:57.882277698 12186 timer_generic.c:470] .. result --> 1, shard[21]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882286412 12186 timer_generic.c:393] .. shard[22]: heap_empty=trueD1108 21:47:57.882295174 12186 timer_generic.c:368] .. shard[22]->queue_deadline_cap --> 1009D1108 21:47:57.882303865 12186 timer_generic.c:470] .. result --> 1, shard[22]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882311890 12186 timer_generic.c:393] .. shard[23]: heap_empty=trueD1108 21:47:57.882320548 12186 timer_generic.c:368] .. shard[23]->queue_deadline_cap --> 1009D1108 21:47:57.882329195 12186 timer_generic.c:470] .. result --> 1, shard[23]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882337831 12186 timer_generic.c:393] .. shard[24]: heap_empty=trueD1108 21:47:57.882346286 12186 timer_generic.c:368] .. shard[24]->queue_deadline_cap --> 1009D1108 21:47:57.882355704 12186 timer_generic.c:470] .. result --> 1, shard[24]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882363709 12186 timer_generic.c:393] .. shard[25]: heap_empty=trueD1108 21:47:57.882372211 12186 timer_generic.c:368] .. shard[25]->queue_deadline_cap --> 1009D1108 21:47:57.882381799 12186 timer_generic.c:470] .. result --> 1, shard[25]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882388730 12186 timer_generic.c:393] .. shard[26]: heap_empty=trueD1108 21:47:57.882394891 12186 timer_generic.c:368] .. shard[26]->queue_deadline_cap --> 1009D1108 21:47:57.882401050 12186 timer_generic.c:470] .. result --> 1, shard[26]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882407568 12186 timer_generic.c:393] .. shard[27]: heap_empty=trueD1108 21:47:57.882414449 12186 timer_generic.c:368] .. shard[27]->queue_deadline_cap --> 1009D1108 21:47:57.882420492 12186 timer_generic.c:470] .. result --> 1, shard[27]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882426758 12186 timer_generic.c:393] .. shard[28]: heap_empty=trueD1108 21:47:57.882432797 12186 timer_generic.c:368] .. shard[28]->queue_deadline_cap --> 1009D1108 21:47:57.882439643 12186 timer_generic.c:470] .. result --> 1, shard[28]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882445965 12186 timer_generic.c:393] .. shard[29]: heap_empty=trueD1108 21:47:57.882452939 12186 timer_generic.c:368] .. shard[29]->queue_deadline_cap --> 1009D1108 21:47:57.882459535 12186 timer_generic.c:470] .. result --> 1, shard[29]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882466080 12186 timer_generic.c:393] .. shard[30]: heap_empty=trueD1108 21:47:57.882472120 12186 timer_generic.c:368] .. shard[30]->queue_deadline_cap --> 1009D1108 21:47:57.882478321 12186 timer_generic.c:470] .. result --> 1, shard[30]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882484533 12186 timer_generic.c:393] .. shard[31]: heap_empty=trueD1108 21:47:57.882490598 12186 timer_generic.c:368] .. shard[31]->queue_deadline_cap --> 1009D1108 21:47:57.882496611 12186 timer_generic.c:470] .. result --> 1, shard[31]->min_deadline 1 --> 1010, now=9D1108 21:47:57.882504832 12186 timer_generic.c:564] TIMER CHECK END: r=1; next=4722.549691371 [103]D1108 21:47:57.882540361 12186 timer_manager.c:181] sleep for a 0.067658977 secondsD1108 21:47:57.950284337 12186 timer_manager.c:197] wait ended: was_timed:1 kicked:0D1108 21:47:57.950344774 12186 timer_generic.c:538] TIMER CHECK BEGIN: now=4722.549832785 [103] next=9223372036854775807.000000000 [9223372036854775807] tls_min=0 glob_min=103D1108 21:47:57.950358957 12186 timer_generic.c:452] .. shard[18]->min_deadline = 103D1108 21:47:57.950369397 12186 timer_generic.c:393] .. shard[18]: heap_empty=trueD1108 21:47:57.950379507 12186 timer_generic.c:368] .. shard[18]->queue_deadline_cap --> 251D1108 21:47:57.950388842 12186 timer_generic.c:376] .. add timer with deadline 209 to heapD1108 21:47:57.950399089 12186 timer_generic.c:403] .. check top timer deadline=209 now=103D1108 21:47:57.950409806 12186 timer_generic.c:470] .. result --> 1, shard[18]->min_deadline 103 --> 209, now=103D1108 21:47:57.950421093 12186 timer_generic.c:564] TIMER CHECK END: r=1; next=4722.655691371 [209]D1108 21:47:57.950432276 12186 timer_manager.c:181] sleep for a 0.105765953 secondsTraceback (most recent call last): File "mt4_client.py", line 107, in <module> run() File "mt4_client.py", line 87, in run response = stub.ChartRequest(request) File "/usr/local/lib/python3.6/dist-packages/grpc/_channel.py", line 492, in __call__ return _end_unary_response_blocking(state, call, False, deadline) File "/usr/local/lib/python3.6/dist-packages/grpc/_channel.py", line 440, in _end_unary_response_blocking raise _Rendezvous(state, None, None, deadline)grpc._channel._Rendezvous: <_Rendezvous of RPC that terminated with (StatusCode.INTERNAL, Did not read entire message)>I1108 21:47:58.056124983 12187 completion_queue.c:937] RETURN_EVENT[0x7f2db0002400]: QUEUE_TIMEOUTI1108 21:47:58.056181261 12187 completion_queue.c:833] grpc_completion_queue_next(cq=0x7f2db0002400, deadline=gpr_timespec { tv_sec: 1510130878, tv_nsec: 256174759, clock_type: 1 }, reserved=(nil))D1108 21:47:58.056317506 12186 timer_manager.c:197] wait ended: was_timed:1 kicked:0D1108 21:47:58.056345303 12186 timer_generic.c:538] TIMER CHECK BEGIN: now=4722.655833459 [209] next=9223372036854775807.000000000 [9223372036854775807] tls_min=103 glob_min=209D1108 21:47:58.056357822 12186 timer_generic.c:452] .. shard[18]->min_deadline = 209D1108 21:47:58.056367025 12186 timer_generic.c:393] .. shard[18]: heap_empty=falseD1108 21:47:58.056376197 12186 timer_generic.c:403] .. check top timer deadline=209 now=209D1108 21:47:58.056384529 12186 timer_generic.c:409] TIMER 0x7f2db0002618: FIRE 0ms lateD1108 21:47:58.056393835 12186 timer_generic.c:393] .. shard[18]: heap_empty=trueD1108 21:47:58.056403045 12186 timer_generic.c:470] .. result --> 2, shard[18]->min_deadline 209 --> 252, now=209D1108 21:47:58.056415237 12186 timer_generic.c:564] TIMER CHECK END: r=2; next=4722.698691371 [252]D1108 21:47:58.056422429 12186 timer_manager.c:82] Spawn timer threadD1108 21:47:58.056488012 12186 combiner.c:161] C:0x183fec0 grpc_combiner_execute c=0x7f2db4002bd0 last=1D1108 21:47:58.056525169 12186 combiner.c:221] C:0x183fec0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0D1108 21:47:58.056540497 12186 combiner.c:239] C:0x183fec0 maybe_finish_one n=0x7f2db4002bd0D1108 21:47:58.056552186 12186 connectivity_state.c:118] CONWATCH: 0x183fe08 client_channel: unsubscribe notify=0x7f2db0001940D1108 21:47:58.056564250 12186 combiner.c:284] C:0x183fec0 finish old_state=3D1108 21:47:58.056575335 12186 timer_generic.c:332] TIMER 0x7f2db0002618: CANCEL pending=falseE1108 21:47:58.056603670 12186 channel_connectivity.c:124] watch_completion_error: "Cancelled"I1108 21:47:58.056657204 12186 completion_queue.c:620] cq_end_op_for_next(exec_ctx=0x7f2dbf847e70, cq=0x7f2db0002400, tag=0x7f2dbf021250, error={"created":"@1510130878.056505077","description":"Timed out waiting for connection state change","file":"src/core/ext/filters/client_channel/channel_connectivity.c","file_line":131}, done=0x7f2dc2c02b30, done_arg=0x7f2db0002570, storage=0x7f2db0002650)E1108 21:47:58.056679778 12186 completion_queue.c:623] Operation failed: tag=0x7f2dbf021250, error={"created":"@1510130878.056505077","description":"Timed out waiting for connection state change","file":"src/core/ext/filters/client_channel/channel_connectivity.c","file_line":131}D1108 21:47:58.056711834 12186 timer_generic.c:538] TIMER CHECK BEGIN: now=4722.656200486 [209] next=9223372036854775807.000000000 [9223372036854775807] tls_min=209 glob_min=252D1108 21:47:58.056731095 12186 timer_generic.c:564] TIMER CHECK END: r=1; next=4722.698691371 [252]D1108 21:47:58.056755298 12186 timer_manager.c:181] sleep for a 0.042443856 secondsI1108 21:47:58.056736474 12187 completion_queue.c:937] RETURN_EVENT[0x7f2db0002400]: OP_COMPLETE: tag:0x7f2dbf021250 ERRORI1108 21:47:58.056860844 12187 completion_queue.c:1227] grpc_completion_queue_shutdown(cq=0x7f2db0002400)I1108 21:47:58.056887326 12187 completion_queue.c:833] grpc_completion_queue_next(cq=0x7f2db0002400, deadline=gpr_timespec { tv_sec: 9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))I1108 21:47:58.056905389 12187 completion_queue.c:937] RETURN_EVENT[0x7f2db0002400]: QUEUE_SHUT
Nathaniel Manista
Nov 8, 2017, 6:27:40 PM11/8/17
to kurr...@gmail.com, grpc.io
This is surprising and I don't think I have an answer immediately available. Has this problem persisted? How many times, and over what period of time, have you observed and and been able to reproduce it?
-Nathaniel
Anton
Nov 8, 2017, 6:30:40 PM11/8/17
to Nathaniel Manista, grpc.io
Hi Nathaniel
My apologies for wasting your time. It is due to a change in the proto file.
kurr...@gmail.com
Nov 9, 2017, 10:47:47 PM11/9/17
to grpc.io
Actually, I was mistaken.
On the client, which is vaguely more insightful, but not much more, is:
Both server and client are using the same protos.
I have checked again and again, and even checked using Beyond Compare - and yes the protos are definitely the same. I have regenerated both c++ and python. But I cannot solve this problem.
I turned on tracing on the server, and I see the following, which doesnt really give any insight.
myserver_1 | E1110 03:29:44.440736118 45 lockfree_event.c:86] lfev_notify_on[read]: 0x7e3d4510 curr=(nil) closure=0x7e3d46acmyserver_1 | E1110 03:29:50.048372285 47 lockfree_event.c:202] lfev_set_ready[read]: 0x7e3d4510 curr=0x7e3d46acmyserver_1 | E1110 03:29:50.048576913 47 lockfree_event.c:86] lfev_notify_on[read]: 0x7e3d4510 curr=(nil) closure=0x7e3d46acmyserver_1 | E1110 03:29:50.048854967 47 lockfree_event.c:86] lfev_notify_on[read]: 0x7bf007b0 curr=(nil) closure=0x7bf00960myserver_1 | E1110 03:29:50.049348128 47 lockfree_event.c:202] lfev_set_ready[write]: 0x7bf007b4 curr=(nil)myserver_1 | E1110 03:29:50.049500737 47 lockfree_event.c:202] lfev_set_ready[read]: 0x7bf007b0 curr=0x7bf00960myserver_1 | E1110 03:29:50.049521129 47 lockfree_event.c:202] lfev_set_ready[write]: 0x7bf007b4 curr=0x2myserver_1 | E1110 03:29:50.049655975 47 lockfree_event.c:86] lfev_notify_on[read]: 0x7bf007b0 curr=(nil) closure=0x7bf00960myserver_1 | E1110 03:29:50.049876094 47 lockfree_event.c:202] lfev_set_ready[read]: 0x7bf007b0 curr=0x7bf00960myserver_1 | E1110 03:29:50.049898436 47 lockfree_event.c:202] lfev_set_ready[write]: 0x7bf007b4 curr=0x2myserver_1 | E1110 03:29:50.050109911 47 lockfree_event.c:86] lfev_notify_on[read]: 0x7bf007b0 curr=(nil) closure=0x7bf00960myserver_1 | E1110 03:29:50.272122346 47 lockfree_event.c:202] lfev_set_ready[read]: 0x7bf007b0 curr=0x7bf00960myserver_1 | E1110 03:29:50.272167534 47 lockfree_event.c:202] lfev_set_ready[write]: 0x7bf007b4 curr=0x2myserver_1 | E1110 03:29:50.272284180 47 lockfree_event.c:152] lfev_set_shutdown: 0x7bf007b0 curr=(nil) err={"created":"@1510284590.272251275","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":2320,"grpc_status":14,"occurred_during_write":0,"referenced_errors":[{"created":"@1510284590.272214992","description":"Socket closed","fd":15,"file":"src/core/lib/iomgr/tcp_posix.c","file_line":285,"target_address":"ipv4:10.5.0.1:44206"}]}myserver_1 | E1110 03:29:50.272395493 47 lockfree_event.c:152] lfev_set_shutdown: 0x7bf007b4 curr=0x2 err={"created":"@1510284590.272251275","description":"Endpoint read failed","file":"src/core/ext/transport/chttp2/transport/chttp2_transport.c","file_line":2320,"grpc_status":14,"occurred_during_write":0,"referenced_errors":[{"created":"@1510284590.272214992","description":"Socket closed","fd":15,"file":"src/core/lib/iomgr/tcp_posix.c","file_line":285,"target_address":"ipv4:10.5.0.1:44206"}]}myserver_1 |
On the client, which is vaguely more insightful, but not much more, is:
I1110 16:38:27.564608732 21622 parsing.c:496] HTTP:1:TRL:CLI: :status: 32 30 30 '200'I1110 16:38:27.564625831 21622 parsing.c:496] HTTP:1:TRL:CLI: content-type: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'D1110 16:38:27.564640069 21622 hpack_parser.c:656] Decode: 'grpc-status: 13', elem_interned=0 [2], k_interned=1, v_interned=0I1110 16:38:27.564650384 21622 parsing.c:496] HTTP:1:TRL:CLI: grpc-status: 31 33 '13'D1110 16:38:27.564662356 21622 hpack_parser.c:656] Decode: 'grpc-message: Did not read entire message', elem_interned=0 [2], k_interned=1, v_interned=0I1110 16:38:27.564673985 21622 parsing.c:496] HTTP:1:TRL:CLI: grpc-message: 44 69 64 20 6e 6f 74 20 72 65 61 64 20 65 6e 74 69 72 65 20 6d 65 73 73 61 67 65 'Did not read entire message'D1110 16:38:27.564732205 21622 chttp2_transport.c:1113] complete_closure_step: 0x2aa1040 refs=0 flags=0x0003 desc=recv_trailing_metadata_finished err="No Error"D1110 16:38:27.564755512 21622 call.c:695] get_final_status CLID1110 16:38:27.564780355 21622 call.c:698] 1: {"created":"@1510285107.564752594","description":"Error received from peer","file":"src/core/lib/surface/call.c","file_line":989,"grpc_message":"Did not read entire message","grpc_status":13}I1110 16:38:27.564796452 21622 completion_queue.c:620] cq_end_op_for_next(exec_ctx=0x7ffd25e94350, cq=0x2a972d0, tag=0x7fbb362c32b8, error="No Error", done=0x7fbb39e26c90, done_arg=0x2a98648, storage=0x2a98650)D1110 16:38:27.596187511 21622 combiner.c:284] C:0x2a9def0 finish old_state=3I1110 16:38:27.596231238 21622 completion_queue.c:937] RETURN_EVENT[0x2a972d0]: OP_COMPLETE: tag:0x7fbb362c32b8 OKI1110 16:38:27.596247961 21622 metadata_array.c:27] grpc_metadata_array_init(array=0x7ffd25e94260)I1110 16:38:27.596255930 21622 metadata_array.c:32] grpc_metadata_array_destroy(array=0x7fbb3731d348)I1110 16:38:27.596262829 21622 metadata_array.c:27] grpc_metadata_array_init(array=0x7ffd25e94260)I1110 16:38:27.596267641 21622 metadata_array.c:32] grpc_metadata_array_destroy(array=0x7fbb3731d378)
Nathaniel Manista
Nov 10, 2017, 6:26:28 PM11/10/17
to kurr...@gmail.com, grpc.io
This conversation is probably now worth moving to the issue tracker.
On what platform are you working (hardware and operating system, with versions)? Are you able to reproduce the problem with sample code that you could share with us?
-Nathaniel
Anton
Nov 12, 2017, 11:20:44 PM11/12/17
to Nathaniel Manista, grpc.io
Thanks Nathaniel
I've posted details on https://github.com/grpc/grpc/issues/13305
Reply all
Reply to author
Forward
0 new messages