1) two applications talking to each other over grpc, both having a client and server threads each.
2) a lab machine, which we switch between two networks: (10.4.10.x) and (192.168.100.x)
3) when lab machine is in 1st network, i have no issues.
4) when lab machine is 2nd network (i also make sure to change ip address in grpc APIs and finally tried localhost ip), after single message communication i am getting: connection refused error and cannot establish any further communication.
I am not deeply familiar grpc and googling so far have not helped much. following is log snippet, can add more but not sure how as attachment seems is not allowed.
Server listening on
127.0.0.1:50051I0307 23:05:25.438279214 142527 init.cc:166] grpc_init(void)
I0307 23:05:25.438286505 142527 init.cc:166] grpc_init(void)
I0307 23:05:25.438294248 142527 channel_create.cc:96] grpc_insecure_channel_create(target=
127.0.0.1:50052, args=0x7ffc4c754020, reserved=(nil))
I0307 23:05:25.438318308 142527 init.cc:166] grpc_init(void)
I0307 23:05:25.438369590 142527 ev_posix.cc:354] (polling-api) pollset_set_create(0xe63df30)
I0307 23:05:25.438376639 142527 ref_counted.h:92] subchannel_pool:0xe6688a8 ref 1 -> 2
I0307 23:05:25.438400013 142527 client_channel.cc:1633] chand=0xe67cea8: creating client_channel for channel stack 0xe67cdf8
I0307 23:05:25.438406865 142527 ev_posix.cc:306] (polling-api) pollset_init(0xe63c830)
I0307 23:05:25.438411966 142527 ref_counted.h:103] pollable_refcount:0xe669788 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:793 ref 3 -> 4 pollset
I0307 23:05:25.438417364 142527 timer_generic.cc:367] TIMER 0xe640c80: SET 5001 now 1 call 0xe640cb8[0xa58a57]
I0307 23:05:25.438424077 142527 timer_generic.cc:404] .. add to shard 30 with queue_deadline_cap=0 => is_first_timer=false
I0307 23:05:25.438428604 142527 ev_posix.cc:366] (polling-api) pollset_set_add_pollset(0xe63df30, 0xe63c830)
I0307 23:05:25.438433374 142527 ev_epollex_linux.cc:1444] PSS:0xe63df30: add pollset 0xe63c830
I0307 23:05:25.438438434 142527 ref_counted.h:103] pollable_refcount:0xe669788 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1235 ref 4 -> 5 pollset_as_multipollable
I0307 23:05:25.438443430 142527 ref_counted.h:199] pollable_refcount:0xe669788 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1238 unref 5 -> 4 pollset
I0307 23:05:25.438449635 142527 ev_epollex_linux.cc:566] (fd-trace) Pollable_create: created epfd: 127 (type: 0)
I0307 23:05:25.438482451 142558 completion_queue.cc:1197] grpc_completion_queue_next(cq=0xe645d40, deadline=gpr_timespec { tv_sec: 9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))
D0307 23:05:25.438500085 142558 completion_queue.cc:1176] PENDING TAGS: 0xe67a150 0xe6414b0 0xe6403b0
I0307 23:05:25.438527364 142557 timer_generic.cc:719] TIMER CHECK BEGIN: now=1 next=9223372036854775807 tls_min=0 glob_min=0
I0307 23:05:25.438542439 142557 timer_generic.cc:614] .. shard[0]->min_deadline = 1
I0307 23:05:25.438547478 142557 timer_generic.cc:537] .. shard[0]: heap_empty=true
I0307 23:05:25.438552008 142557 timer_generic.cc:512] .. shard[0]->queue_deadline_cap --> 1001
I0307 23:05:25.438556391 142557 timer_generic.cc:577] .. shard[0] popped 0
I0307 23:05:25.438560737 142557 timer_generic.cc:632] .. result --> 1, shard[0]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438565735 142557 timer_generic.cc:537] .. shard[1]: heap_empty=true
I0307 23:05:25.438569936 142557 timer_generic.cc:512] .. shard[1]->queue_deadline_cap --> 1001
I0307 23:05:25.438580733 142557 timer_generic.cc:577] .. shard[1] popped 0
I0307 23:05:25.438585243 142557 timer_generic.cc:632] .. result --> 1, shard[1]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438590064 142557 timer_generic.cc:537] .. shard[2]: heap_empty=true
I0307 23:05:25.438594282 142557 timer_generic.cc:512] .. shard[2]->queue_deadline_cap --> 1001
I0307 23:05:25.438598393 142557 timer_generic.cc:577] .. shard[2] popped 0
I0307 23:05:25.438602766 142557 timer_generic.cc:632] .. result --> 1, shard[2]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438607485 142557 timer_generic.cc:537] .. shard[3]: heap_empty=true
I0307 23:05:25.438611657 142557 timer_generic.cc:512] .. shard[3]->queue_deadline_cap --> 1001
I0307 23:05:25.438620520 142557 timer_generic.cc:577] .. shard[3] popped 0
I0307 23:05:25.438624833 142557 timer_generic.cc:632] .. result --> 1, shard[3]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438629618 142557 timer_generic.cc:537] .. shard[4]: heap_empty=true
I0307 23:05:25.438633930 142557 timer_generic.cc:512] .. shard[4]->queue_deadline_cap --> 1001
I0307 23:05:25.438642622 142557 timer_generic.cc:577] .. shard[4] popped 0
I0307 23:05:25.438646983 142557 timer_generic.cc:632] .. result --> 1, shard[4]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438651430 142557 timer_generic.cc:537] .. shard[5]: heap_empty=true
I0307 23:05:25.438655541 142557 timer_generic.cc:512] .. shard[5]->queue_deadline_cap --> 1001
I0307 23:05:25.438659865 142557 timer_generic.cc:577] .. shard[5] popped 0
I0307 23:05:25.438664038 142557 timer_generic.cc:632] .. result --> 1, shard[5]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438669906 142557 timer_generic.cc:537] .. shard[6]: heap_empty=true
I0307 23:05:25.438674478 142557 timer_generic.cc:512] .. shard[6]->queue_deadline_cap --> 1001
I0307 23:05:25.438678517 142557 timer_generic.cc:577] .. shard[6] popped 0
I0307 23:05:25.438682588 142557 timer_generic.cc:632] .. result --> 1, shard[6]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438692463 142557 timer_generic.cc:537] .. shard[7]: heap_empty=true
I0307 23:05:25.438696738 142557 timer_generic.cc:512] .. shard[7]->queue_deadline_cap --> 1001
I0307 23:05:25.438700891 142557 timer_generic.cc:577] .. shard[7] popped 0
I0307 23:05:25.438707030 142557 timer_generic.cc:632] .. result --> 1, shard[7]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438715600 142557 timer_generic.cc:537] .. shard[8]: heap_empty=true
I0307 23:05:25.438719859 142557 timer_generic.cc:512] .. shard[8]->queue_deadline_cap --> 1001
I0307 23:05:25.438724024 142557 timer_generic.cc:577] .. shard[8] popped 0
I0307 23:05:25.438728106 142557 timer_generic.cc:632] .. result --> 1, shard[8]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438736845 142557 timer_generic.cc:537] .. shard[9]: heap_empty=true
I0307 23:05:25.438741122 142557 timer_generic.cc:512] .. shard[9]->queue_deadline_cap --> 1001
I0307 23:05:25.438745334 142557 timer_generic.cc:577] .. shard[9] popped 0
I0307 23:05:25.438754063 142557 timer_generic.cc:632] .. result --> 1, shard[9]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438758768 142557 timer_generic.cc:537] .. shard[10]: heap_empty=true
I0307 23:05:25.438763059 142557 timer_generic.cc:512] .. shard[10]->queue_deadline_cap --> 1001
I0307 23:05:25.438767325 142557 timer_generic.cc:577] .. shard[10] popped 0
I0307 23:05:25.438771635 142557 timer_generic.cc:632] .. result --> 1, shard[10]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438776337 142557 timer_generic.cc:537] .. shard[11]: heap_empty=true
I0307 23:05:25.438780686 142557 timer_generic.cc:512] .. shard[11]->queue_deadline_cap --> 1001
I0307 23:05:25.438784728 142557 timer_generic.cc:577] .. shard[11] popped 0
I0307 23:05:25.438788992 142557 timer_generic.cc:632] .. result --> 1, shard[11]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438793371 142557 timer_generic.cc:537] .. shard[12]: heap_empty=true
I0307 23:05:25.438797742 142557 timer_generic.cc:512] .. shard[12]->queue_deadline_cap --> 1001
I0307 23:05:25.438801834 142557 timer_generic.cc:577] .. shard[12] popped 0
I0307 23:05:25.438806067 142557 timer_generic.cc:632] .. result --> 1, shard[12]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438813135 142557 timer_generic.cc:537] .. shard[13]: heap_empty=true
I0307 23:05:25.438817449 142557 timer_generic.cc:512] .. shard[13]->queue_deadline_cap --> 1001
I0307 23:05:25.438821561 142557 timer_generic.cc:577] .. shard[13] popped 0
I0307 23:05:25.438825673 142557 timer_generic.cc:632] .. result --> 1, shard[13]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438830259 142557 timer_generic.cc:537] .. shard[14]: heap_empty=true
I0307 23:05:25.438836660 142557 timer_generic.cc:512] .. shard[14]->queue_deadline_cap --> 1001
I0307 23:05:25.438846682 142557 timer_generic.cc:577] .. shard[14] popped 0
I0307 23:05:25.438851104 142557 timer_generic.cc:632] .. result --> 1, shard[14]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438855573 142557 timer_generic.cc:537] .. shard[15]: heap_empty=true
I0307 23:05:25.438859836 142557 timer_generic.cc:512] .. shard[15]->queue_deadline_cap --> 1001
I0307 23:05:25.438864027 142557 timer_generic.cc:577] .. shard[15] popped 0
I0307 23:05:25.438868209 142557 timer_generic.cc:632] .. result --> 1, shard[15]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438872655 142557 timer_generic.cc:537] .. shard[16]: heap_empty=true
I0307 23:05:25.438881600 142557 timer_generic.cc:512] .. shard[16]->queue_deadline_cap --> 1001
I0307 23:05:25.438885991 142557 timer_generic.cc:577] .. shard[16] popped 0
I0307 23:05:25.438890062 142557 timer_generic.cc:632] .. result --> 1, shard[16]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438899120 142557 timer_generic.cc:537] .. shard[17]: heap_empty=true
I0307 23:05:25.438903431 142557 timer_generic.cc:512] .. shard[17]->queue_deadline_cap --> 1001
I0307 23:05:25.438907603 142557 timer_generic.cc:577] .. shard[17] popped 0
I0307 23:05:25.438911886 142557 timer_generic.cc:632] .. result --> 1, shard[17]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438916190 142557 timer_generic.cc:537] .. shard[18]: heap_empty=true
I0307 23:05:25.438920459 142557 timer_generic.cc:512] .. shard[18]->queue_deadline_cap --> 1001
I0307 23:05:25.438924557 142557 timer_generic.cc:577] .. shard[18] popped 0
I0307 23:05:25.438928742 142557 timer_generic.cc:632] .. result --> 1, shard[18]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438938723 142557 timer_generic.cc:537] .. shard[19]: heap_empty=true
I0307 23:05:25.438943012 142557 timer_generic.cc:512] .. shard[19]->queue_deadline_cap --> 1001
I0307 23:05:25.438947045 142557 timer_generic.cc:577] .. shard[19] popped 0
I0307 23:05:25.438955592 142557 timer_generic.cc:632] .. result --> 1, shard[19]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438959840 142557 timer_generic.cc:537] .. shard[20]: heap_empty=true
I0307 23:05:25.438963872 142557 timer_generic.cc:512] .. shard[20]->queue_deadline_cap --> 1001
I0307 23:05:25.438972147 142557 timer_generic.cc:577] .. shard[20] popped 0
I0307 23:05:25.438976420 142557 timer_generic.cc:632] .. result --> 1, shard[20]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438980775 142557 timer_generic.cc:537] .. shard[21]: heap_empty=true
I0307 23:05:25.438985088 142557 timer_generic.cc:512] .. shard[21]->queue_deadline_cap --> 1001
I0307 23:05:25.438989308 142557 timer_generic.cc:577] .. shard[21] popped 0
I0307 23:05:25.438993537 142557 timer_generic.cc:632] .. result --> 1, shard[21]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.438997800 142557 timer_generic.cc:537] .. shard[22]: heap_empty=true
I0307 23:05:25.439001804 142557 timer_generic.cc:512] .. shard[22]->queue_deadline_cap --> 1001
I0307 23:05:25.439005828 142557 timer_generic.cc:577] .. shard[22] popped 0
I0307 23:05:25.439009829 142557 timer_generic.cc:632] .. result --> 1, shard[22]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.439013948 142557 timer_generic.cc:537] .. shard[23]: heap_empty=true
I0307 23:05:25.439017925 142557 timer_generic.cc:512] .. shard[23]->queue_deadline_cap --> 1001
I0307 23:05:25.439021870 142557 timer_generic.cc:577] .. shard[23] popped 0
I0307 23:05:25.439025942 142557 timer_generic.cc:632] .. result --> 1, shard[23]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.439030213 142557 timer_generic.cc:537] .. shard[24]: heap_empty=true
I0307 23:05:25.439034329 142557 timer_generic.cc:512] .. shard[24]->queue_deadline_cap --> 1001
I0307 23:05:25.439038412 142557 timer_generic.cc:577] .. shard[24] popped 0
I0307 23:05:25.439042674 142557 timer_generic.cc:632] .. result --> 1, shard[24]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.439051319 142557 timer_generic.cc:537] .. shard[25]: heap_empty=true
I0307 23:05:25.439055482 142557 timer_generic.cc:512] .. shard[25]->queue_deadline_cap --> 1001
I0307 23:05:25.439059686 142557 timer_generic.cc:577] .. shard[25] popped 0
I0307 23:05:25.439063985 142557 timer_generic.cc:632] .. result --> 1, shard[25]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.439068375 142557 timer_generic.cc:537] .. shard[26]: heap_empty=true
I0307 23:05:25.439072588 142557 timer_generic.cc:512] .. shard[26]->queue_deadline_cap --> 1001
I0307 23:05:25.439076669 142557 timer_generic.cc:577] .. shard[26] popped 0
I0307 23:05:25.439080852 142557 timer_generic.cc:632] .. result --> 1, shard[26]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.439085187 142557 timer_generic.cc:537] .. shard[27]: heap_empty=true
I0307 23:05:25.439089159 142557 timer_generic.cc:512] .. shard[27]->queue_deadline_cap --> 1001
I0307 23:05:25.439093169 142557 timer_generic.cc:577] .. shard[27] popped 0
I0307 23:05:25.439097282 142557 timer_generic.cc:632] .. result --> 1, shard[27]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.439101354 142557 timer_generic.cc:537] .. shard[28]: heap_empty=true
I0307 23:05:25.439105632 142557 timer_generic.cc:512] .. shard[28]->queue_deadline_cap --> 1001
I0307 23:05:25.439109687 142557 timer_generic.cc:577] .. shard[28] popped 0
I0307 23:05:25.439113843 142557 timer_generic.cc:632] .. result --> 1, shard[28]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.439118010 142557 timer_generic.cc:537] .. shard[29]: heap_empty=true
I0307 23:05:25.439122191 142557 timer_generic.cc:512] .. shard[29]->queue_deadline_cap --> 1001
I0307 23:05:25.439126365 142557 timer_generic.cc:577] .. shard[29] popped 0
I0307 23:05:25.439130527 142557 timer_generic.cc:632] .. result --> 1, shard[29]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.439134789 142557 timer_generic.cc:537] .. shard[30]: heap_empty=true
I0307 23:05:25.439138948 142557 timer_generic.cc:512] .. shard[30]->queue_deadline_cap --> 1001
I0307 23:05:25.439143211 142557 timer_generic.cc:577] .. shard[30] popped 0
I0307 23:05:25.439147422 142557 timer_generic.cc:632] .. result --> 1, shard[30]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.439151651 142557 timer_generic.cc:537] .. shard[31]: heap_empty=true
I0307 23:05:25.439155618 142557 timer_generic.cc:512] .. shard[31]->queue_deadline_cap --> 1001
I0307 23:05:25.439159696 142557 timer_generic.cc:577] .. shard[31] popped 0
I0307 23:05:25.439163933 142557 timer_generic.cc:632] .. result --> 1, shard[31]->min_deadline 1 --> 1002, now=1
I0307 23:05:25.439168754 142557 timer_generic.cc:741] TIMER CHECK END: r=1; next=1002
I0307 23:05:25.439173109 142557 timer_manager.cc:188] sleep for a 1001 milliseconds
I0307 23:05:25.439205801 142560 server.cc:1720] grpc_server_request_registered_call(server=0xe641e40, rmp=0xe667290, call=0x7f24b00010f0, deadline=0x7f24b0000938, initial_metadata=0x7f24b0000978, optional_payload=0x7f24b0001230, cq_bound_to_call=0xe644eb0, cq_for_notification=0xe644eb0, tag=0x7f24b00010b0)
I0307 23:05:25.439221540 142560 server.cc:1720] grpc_server_request_registered_call(server=0xe641e40, rmp=0xe6408e0, call=0x7f24b0001b50, deadline=0x7f24b00013e8, initial_metadata=0x7f24b0001428, optional_payload=0x7f24b0001c90, cq_bound_to_call=0xe644eb0, cq_for_notification=0xe644eb0, tag=0x7f24b0001b10)
I0307 23:05:25.439238950 142559 completion_queue.cc:1197] grpc_completion_queue_next(cq=0xe63f2f0, deadline=gpr_timespec { tv_sec: 219158, tv_nsec: 870386063, clock_type: 0 }, reserved=(nil))
D0307 23:05:25.439254146 142559 completion_queue.cc:1176] PENDING TAGS: 0xe645ba0 0xe6412a0
I0307 23:05:25.449401956 142527 ev_epollex_linux.cc:1243] PS:0xe63c830 active pollable transition from empty to multi
I0307 23:05:25.449409504 142527 ref_counted.h:103] pollable_refcount:0xe67d128 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1274 ref 1 -> 2 pollset_set
I0307 23:05:25.449415040 142527 ref_counted.h:199] pollable_refcount:0xe669788 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1275 unref 4 -> 3 pollset_as_multipollable
I0307 23:05:25.449420432 142527 ref_counted.h:199] pollable_refcount:0xe67d128 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1472 unref 2 -> 1 pollset_set
I0307 23:05:25.449443223 142527 init.cc:166] grpc_init(void)
I0307 23:05:25.449450057 142527 init.cc:214] grpc_shutdown(void)
I0307 23:05:25.449456551 142527 channel.cc:453] grpc_channel_register_call(channel=0xe67cd60, method=/ric.CPCC/TerminateTestApp, host=(null), reserved=(nil))
D0307 23:05:25.449466681 142527 metadata.cc:161] mdelem ALLOC_MD_NOREF_KEY_VAL:0xe6417b0:1: ':path' = '/ric.CPCC/TerminateTestApp'
D0307 23:05:25.449473754 142527 channel.cc:431] mdelem REF:0xe6417b0:1->2: ':path' = '/ric.CPCC/TerminateTestApp'
D0307 23:05:25.449479383 142527 channel.cc:443] mdelem UNREF:0xe6417b0:2->1: ':path' = '/ric.CPCC/TerminateTestApp'
I0307 23:05:25.449484721 142527 channel.cc:453] grpc_channel_register_call(channel=0xe67cd60, method=/ric.CPCC/SendE2SmMsg, host=(null), reserved=(nil))
D0307 23:05:25.449490002 142527 metadata.cc:161] mdelem ALLOC_MD_NOREF_KEY_VAL:0xe6405c0:1: ':path' = '/ric.CPCC/SendE2SmMsg'
D0307 23:05:25.449494968 142527 channel.cc:431] mdelem REF:0xe6405c0:1->2: ':path' = '/ric.CPCC/SendE2SmMsg'
D0307 23:05:25.449499840 142527 channel.cc:443] mdelem UNREF:0xe6405c0:2->1: ':path' = '/ric.CPCC/SendE2SmMsg'
I0307 23:05:25.449506432 142527 init.cc:214] grpc_shutdown(void)
I0307 23:05:25.449608533 142560 completion_queue.cc:1197] grpc_completion_queue_next(cq=0xe644eb0, deadline=gpr_timespec { tv_sec: 9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))
D0307 23:05:25.449660459 142560 completion_queue.cc:1176] PENDING TAGS: 0xe679540 0x7f24b00010b0 0x7f24b0001b10
I0307 23:05:25.449678808 142560 ev_posix.cc:324] (polling-api) pollset_work(0xe644fc0, 9223372036854775807) begin
I0307 23:05:25.449688938 142560 ev_epollex_linux.cc:1114] PS:0xe644fc0 work hdl=(nil) worker=0x7f24c71ae760 now=13 deadline=9223372036854775807 kwp=0 pollable=0xe678fd0
I0307 23:05:25.449697082 142560 ref_counted.h:103] pollable_refcount:0xe678fd8 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1012 ref 2 -> 3 pollset_worker
I0307 23:05:25.449708855 142560 ev_epollex_linux.cc:932] POLLABLE:0xe678fd0[type=fd epfd=125 wakeup=126] poll for -1ms
I0307 23:05:25.450657769 142561 init.cc:166] grpc_init(void)
I0307 23:05:25.450690014 142561 completion_queue.cc:669] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
I0307 23:05:25.450702492 142561 ev_posix.cc:306] (polling-api) pollset_init(0x7f24b4000b10)
I0307 23:05:25.450712054 142561 ref_counted.h:103] pollable_refcount:0xe669788 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:793 ref 3 -> 4 pollset
I0307 23:05:25.450724919 142561 channel.cc:486] grpc_channel_create_registered_call(channel=0xe67cd60, parent_call=(nil), propagation_mask=ffff, completion_queue=0x7f24b4000a00, registered_call_handle=0xe6410f0, deadline=gpr_timespec { tv_sec: 9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))
D0307 23:05:25.467184896 142561 channel.cc:492] mdelem REF:0xe6405c0:1->2: ':path' = '/ric.CPCC/SendE2SmMsg'
D0307 23:05:25.467236475 142561 transport.h:85] CLIENT_CHANNEL 0xe67cdf8:0xe67cd60 REF call
I0307 23:05:25.467256305 142561 ref_counted.h:133] stream_refcount:0xe67cdf8 /home/user/grpc/src/core/lib/transport/transport.h:88 ref 1 -> 2 call
I0307 23:05:25.467311052 142561 grpc_context.cc:28] grpc_census_call_set_context(call=0x7f24b4000de0, census_context=(nil))
I0307 23:05:25.467368646 142561 call.cc:1965] grpc_call_start_batch(call=0x7f24b4000de0, ops=0x7f24c69ad4d0, nops=6, tag=0x7f24b4001e68, reserved=(nil))
I0307 23:05:25.467384847 142561 call.cc:1561] ops[0]: SEND_INITIAL_METADATA(nil)
I0307 23:05:25.467395640 142561 call.cc:1561] ops[1]: SEND_MESSAGE ptr=0x7f24b4000b80
I0307 23:05:25.467401378 142561 call.cc:1561] ops[2]: SEND_CLOSE_FROM_CLIENT
I0307 23:05:25.467407651 142561 call.cc:1561] ops[3]: RECV_INITIAL_METADATA ptr=0x7f24c69ad908
I0307 23:05:25.467413646 142561 call.cc:1561] ops[4]: RECV_MESSAGE ptr=0x7f24b4001f00
I0307 23:05:25.467420889 142561 call.cc:1561] ops[5]: RECV_STATUS_ON_CLIENT metadata=0x7f24c69ad958 status=0x7f24b4001f38 details=0x7f24b4001f40
D0307 23:05:25.467436001 142561 transport.h:85] CALL_STACK 0x7f24b40017c0:0x7f24b4000de0 REF completion
I0307 23:05:25.467444039 142561 ref_counted.h:133] stream_refcount:0x7f24b40017c0 /home/user/grpc/src/core/lib/transport/transport.h:88 ref 1 -> 2 completion
I0307 23:05:25.467452203 142561 call_combiner.cc:116] ==> CallCombiner::Start() [0x7f24b4000df8] closure=0x7f24b4002320 [/home/user/grpc/src/core/lib/surface/call.cc:646: executing batch] error="No Error"
I0307 23:05:25.467457700 142561 call_combiner.cc:124] size: 0 -> 1
I0307 23:05:25.467462367 142561 call_combiner.cc:132] EXECUTING IMMEDIATELY
D0307 23:05:25.467468335 142561 exec_ctx.cc:34] running closure 0x7f24b4002320: created [/home/user/grpc/src/core/lib/surface/call.cc:644]: scheduled [/home/user/grpc/src/core/lib/iomgr/call_combiner.cc:98]
I0307 23:05:25.467495650 142561 call.cc:633] OP[client-channel:0x7f24b4001850]: SEND_INITIAL_METADATA{key=3a 70 61 74 68 ':path' value=2f 72 69 63 2e 43 50 43 43 2f 53 65 6e 64 45 32 53 6d 4d 73 67 '/ric.CPCC/SendE2SmMsg'} SEND_MESSAGE:flags=0x00000000:len=94 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA
I0307 23:05:25.467504507 142561 client_channel.cc:2410] chand=0xe67cea8 calld=0x7f24b4001870: adding pending batch at index 0
I0307 23:05:25.467510193 142561 client_channel.cc:2215] chand=0xe67cea8 calld=0x7f24b4001870: grabbing data plane mutex to perform pick
D0307 23:05:25.467518562 142561 transport.h:85] CLIENT_CHANNEL 0xe67cdf8:0xe67cd60 REF PickSubchannelLocked
I0307 23:05:25.467523949 142561 ref_counted.h:133] stream_refcount:0xe67cdf8 /home/user/grpc/src/core/lib/transport/transport.h:88 ref 2 -> 3 PickSubchannelLocked
I0307 23:05:25.467529224 142561 client_channel.cc:3862] chand=0xe67cea8 calld=0x7f24b4001870: adding to queued picks list
I0307 23:05:25.467534398 142561 ev_posix.cc:366] (polling-api) pollset_set_add_pollset(0xe63df30, 0x7f24b4000b10)
I0307 23:05:25.467539571 142561 ev_epollex_linux.cc:1444] PSS:0xe63df30: add pollset 0x7f24b4000b10
I0307 23:05:25.467551618 142561 ref_counted.h:103] pollable_refcount:0xe669788 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1235 ref 4 -> 5 pollset_as_multipollable
I0307 23:05:25.467561290 142561 ref_counted.h:199] pollable_refcount:0xe669788 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1238 unref 5 -> 4 pollset
I0307 23:05:25.467570528 142561 ev_epollex_linux.cc:566] (fd-trace) Pollable_create: created epfd: 129 (type: 0)
I0307 23:05:25.467581579 142561 ev_epollex_linux.cc:1243] PS:0x7f24b4000b10 active pollable transition from empty to multi
I0307 23:05:25.467587087 142561 ref_counted.h:103] pollable_refcount:0x7f24b4002b98 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1274 ref 1 -> 2 pollset_set
I0307 23:05:25.467592455 142561 ref_counted.h:199] pollable_refcount:0xe669788 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1275 unref 4 -> 3 pollset_as_multipollable
I0307 23:05:25.467613886 142561 ref_counted.h:199] pollable_refcount:0x7f24b4002b98 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1472 unref 2 -> 1 pollset_set
D0307 23:05:25.467623515 142561 transport.h:85] CALL_STACK 0x7f24b40017c0:0x7f24b4000de0 REF QueuedPickCanceller
I0307 23:05:25.467629287 142561 ref_counted.h:133] stream_refcount:0x7f24b40017c0 /home/user/grpc/src/core/lib/transport/transport.h:88 ref 2 -> 3 QueuedPickCanceller
I0307 23:05:25.467634687 142561 call_combiner.cc:208] call_combiner=0x7f24b4000df8: setting notify_on_cancel=0x7f24b4003108
D0307 23:05:25.467641710 142561 exec_ctx.cc:43] closure 0x7f24b4002320 finished
D0307 23:05:25.467649313 142561 exec_ctx.cc:34] running closure 0x7f24b4000960: created [/home/user/grpc/src/core/ext/filters/client_channel/client_channel.cc:3999]: scheduled [/home/user/grpc/src/core/ext/filters/client_channel/client_channel.cc:3987]
I0307 23:05:25.467657242 142561 work_serializer.cc:55] WorkSerializer::Run() 0xe63e4b0 Scheduling callback [/home/user/grpc/src/core/ext/filters/client_channel/client_channel.cc:3999]
I0307 23:05:25.467668185 142561 work_serializer.cc:65] Executing immediately
I0307 23:05:25.467678062 142561 connectivity_state.cc:174] ConnectivityStateTracker client_channel[0xe67cf88]: get current state: IDLE
D0307 23:05:25.467683149 142561 transport.h:85] CLIENT_CHANNEL 0xe67cdf8:0xe67cd60 REF TryToConnect
I0307 23:05:25.467688262 142561 ref_counted.h:133] stream_refcount:0xe67cdf8 /home/user/grpc/src/core/lib/transport/transport.h:88 ref 3 -> 4 TryToConnect
I0307 23:05:25.467694130 142561 work_serializer.cc:55] WorkSerializer::Run() 0xe63e4b0 Scheduling callback [/home/user/grpc/src/core/ext/filters/client_channel/client_channel.cc:2036]
I0307 23:05:25.467699185 142561 work_serializer.cc:76] Scheduling on queue : item 0x7f24b4000950
D0307 23:05:25.467704174 142561 transport.h:102] CLIENT_CHANNEL 0xe67cdf8:0xe67cd60 UNREF PickSubchannelLocked
I0307 23:05:25.467709349 142561 ref_counted.h:199] stream_refcount:0xe67cdf8 /home/user/grpc/src/core/lib/transport/transport.h:105 unref 4 -> 3 PickSubchannelLocked
I0307 23:05:25.467714264 142561 work_serializer.cc:102] WorkSerializer::DrainQueue() 0xe63e4b0
I0307 23:05:25.467719345 142561 work_serializer.cc:134] Running item 0x7f24b4000950 : callback scheduled at [/home/user/grpc/src/core/ext/filters/client_channel/client_channel.cc:2036]
D0307 23:05:25.467737261 142561 transport.h:85] CLIENT_CHANNEL 0xe67cdf8:0xe67cd60 REF ClientChannelControlHelper
I0307 23:05:25.467744379 142561 ref_counted.h:133] stream_refcount:0xe67cdf8 /home/user/grpc/src/core/lib/transport/transport.h:88 ref 3 -> 4 ClientChannelControlHelper
I0307 23:05:25.467755889 142561 ev_posix.cc:354] (polling-api) pollset_set_create(0x7f24b40032a0)
I0307 23:05:25.467765661 142561 ref_counted.h:92] lb_policy_refcount:0x7f24b40033e8 ref 1 -> 2
I0307 23:05:25.467792998 142561 ev_posix.cc:354] (polling-api) pollset_set_create(0x7f24b4003940)
I0307 23:05:25.467799697 142561 ev_posix.cc:379] (polling-api) pollset_set_add_pollset_set(0x7f24b4003940, 0x7f24b40032a0)
I0307 23:05:25.467804505 142561 ev_epollex_linux.cc:1481] PSS: merge (0x7f24b4003940, 0x7f24b40032a0)
I0307 23:05:25.467818854 142561 ev_epollex_linux.cc:1515] PSS: parent 0x7f24b4003940 to 0x7f24b40032a0
I0307 23:05:25.467830255 142561 resolving_lb_policy.cc:161] resolving_lb=0x7f24b40033e0: starting name resolution
I0307 23:05:25.467837040 142561 ref_counted.h:92] lb_policy_refcount:0x7f24b40033e8 ref 2 -> 3
I0307 23:05:25.467843256 142561 client_channel.cc:1362] chand=0xe67cea8: update: state=CONNECTING picker=0x7f24b40009b0
I0307 23:05:25.467849761 142561 connectivity_state.cc:152] ConnectivityStateTracker client_channel[0xe67cf88]: IDLE -> CONNECTING (helper)
D0307 23:05:25.467871415 142561 dns_resolver_ares.cc:185] (c-ares resolver) resolver:0x7f24b4003460 AresDnsResolver::StartLocked() is called.
I0307 23:05:25.467885006 142561 ref_counted.h:103] resolver_refcount:0x7f24b4003468 /home/user/grpc/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc:437 ref 1 -> 2 dns-resolving
D0307 23:05:25.467893047 142561 grpc_ares_wrapper.cc:648] (c-ares resolver) request:0x7f24b4003230 c-ares grpc_dns_lookup_ares_locked_impl name=
127.0.0.1:50052, default_port=https
I0307 23:05:25.467938686 142561 grpc_ares_wrapper.cc:130] (c-ares resolver) request:0x7f24b4003230 c-ares address sorting: input[0]=
127.0.0.1:50052I0307 23:05:25.467976805 142561 grpc_ares_wrapper.cc:130] (c-ares resolver) request:0x7f24b4003230 c-ares address sorting: output[0]=
127.0.0.1:50052D0307 23:05:25.467984574 142561 dns_resolver_ares.cc:449] (c-ares resolver) resolver:0x7f24b4003460 Started resolving. pending_request_:0x7f24b4003230
I0307 23:05:25.467989854 142561 ev_posix.cc:379] (polling-api) pollset_set_add_pollset_set(0x7f24b40032a0, 0xe63df30)
I0307 23:05:25.467994742 142561 ev_epollex_linux.cc:1481] PSS: merge (0x7f24b40032a0, 0xe63df30)
I0307 23:05:25.467999424 142561 ev_epollex_linux.cc:1515] PSS: parent 0x7f24b40032a0 to 0xe63df30
I0307 23:05:25.468004624 142561 client_channel.cc:1865] chand=0xe67cea8: created resolving_lb_policy=0x7f24b40033e0
D0307 23:05:25.468009538 142561 transport.h:102] CLIENT_CHANNEL 0xe67cdf8:0xe67cd60 UNREF TryToConnect
I0307 23:05:25.468014507 142561 ref_counted.h:199] stream_refcount:0xe67cdf8 /home/user/grpc/src/core/lib/transport/transport.h:105 unref 4 -> 3 TryToConnect
I0307 23:05:25.468019356 142561 work_serializer.cc:102] WorkSerializer::DrainQueue() 0xe63e4b0
I0307 23:05:25.468023507 142561 work_serializer.cc:117] Queue Drained
D0307 23:05:25.468028331 142561 exec_ctx.cc:43] closure 0x7f24b4000960 finished
D0307 23:05:25.468033573 142561 exec_ctx.cc:34] running closure 0x7f24b4003500: created [/home/user/grpc/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc:140]: scheduled [/home/user/grpc/src/core/ext/filters/client_channel/resolver/dns/c_ares/grpc_ares_wrapper.cc:192]
I0307 23:05:25.468040222 142561 work_serializer.cc:55] WorkSerializer::Run() 0xe63e4b0 Scheduling callback [/home/user/grpc/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc:328]
I0307 23:05:25.468045387 142561 work_serializer.cc:65] Executing immediately
I0307 23:05:25.468059326 142561 resolving_lb_policy.cc:292] resolving_lb=0x7f24b40033e0: got resolver result
I0307 23:05:25.468086374 142561 ref_counted.h:92] lb_policy_refcount:0x7f24b40033e8 ref 3 -> 4
I0307 23:05:25.468094967 142561 ev_posix.cc:354] (polling-api) pollset_set_create(0x7f24b4003d50)
I0307 23:05:25.468100656 142561 resolving_lb_policy.cc:257] resolving_lb=0x7f24b40033e0: created new LB policy 0x7f24b4003230
I0307 23:05:25.468105467 142561 ev_posix.cc:379] (polling-api) pollset_set_add_pollset_set(0x7f24b4003d50, 0x7f24b40032a0)
I0307 23:05:25.468110259 142561 ev_epollex_linux.cc:1481] PSS: merge (0x7f24b4003d50, 0x7f24b40032a0)
I0307 23:05:25.468123283 142561 ev_epollex_linux.cc:1515] PSS: parent 0x7f24b4003d50 to 0xe63df30
I0307 23:05:25.468128697 142561 resolving_lb_policy.cc:239] resolving_lb=0x7f24b40033e0: Updating child policy 0x7f24b4003230
I0307 23:05:25.468138721 142561 child_policy_handler.cc:211] [child_policy_handler 0x7f24b4003230] creating new child policy pick_first
I0307 23:05:25.468149446 142561 ref_counted.h:103] lb_policy_refcount:0x7f24b4003238 /home/user/grpc/src/core/ext/filters/client_channel/lb_policy/child_policy_handler.cc:258 ref 1 -> 2 Helper
I0307 23:05:25.468160317 142561 ev_posix.cc:354] (polling-api) pollset_set_create(0x7f24b4003ee0)
I0307 23:05:25.468167136 142561 pick_first.cc:146] Pick First 0x7f24b4003dd0 created.
I0307 23:05:25.468174058 142561 child_policy_handler.cc:272] [child_policy_handler 0x7f24b4003230] created new LB policy "pick_first" (0x7f24b4003dd0)
I0307 23:05:25.468181508 142561 ev_posix.cc:379] (polling-api) pollset_set_add_pollset_set(0x7f24b4003ee0, 0x7f24b4003d50)
I0307 23:05:25.468189387 142561 ev_epollex_linux.cc:1481] PSS: merge (0x7f24b4003ee0, 0x7f24b4003d50)
I0307 23:05:25.468194043 142561 ev_epollex_linux.cc:1515] PSS: parent 0x7f24b4003ee0 to 0xe63df30
I0307 23:05:25.468199179 142561 child_policy_handler.cc:230] [child_policy_handler 0x7f24b4003230] updating child policy 0x7f24b4003dd0
I0307 23:05:25.468204915 142561 pick_first.cc:265] Pick First 0x7f24b4003dd0 received update with 1 addresses
I0307 23:05:25.468216833 142561 subchannel_list.h:361] [pick_first 0x7f24b4003dd0] Creating subchannel list 0x7f24b40043f0 for 1 subchannels
I0307 23:05:25.468239396 142561 ref_counted.h:92] subchannel_pool:0xe6688a8 ref 2 -> 3
I0307 23:05:25.468253494 142561 ref_counted.h:92] subchannel_pool:0xe6688a8 ref 3 -> 4
I0307 23:05:25.468269239 142561 ref_counted.h:92] subchannel_pool:0xe6688a8 ref 4 -> 5
I0307 23:05:25.468287745 142561 ev_posix.cc:354] (polling-api) pollset_set_create(0x7f24b4005540)
I0307 23:05:25.468303829 142561 ref_counted.h:92] subchannel_pool:0xe6688a8 ref 5 -> 6
D0307 23:05:25.468338566 142561 global_subchannel_pool.cc:104] SUBCHANNEL: 0x7f24b4005330 WEAK_REF 0x10000 -> 0x10001 [subchannel_register+new]
I0307 23:05:25.468347615 142561 ref_counted.h:92] subchannel_pool:0xe6688a8 ref 6 -> 7
I0307 23:05:25.468353266 142561 ref_counted.h:92] subchannel_pool:0xe6688a8 ref 7 -> 8
I0307 23:05:25.468358699 142561 ref_counted.h:183] subchannel_pool:0xe6688a8 unref 8 -> 7
I0307 23:05:25.468363978 142561 ref_counted.h:183] subchannel_pool:0xe6688a8 unref 7 -> 6
I0307 23:05:25.468370616 142561 client_channel.cc:896] chand=0xe67cea8: creating subchannel wrapper 0x7f24b4004730 for subchannel 0x7f24b4005330
D0307 23:05:25.468375761 142561 transport.h:85] CLIENT_CHANNEL 0xe67cdf8:0xe67cd60 REF SubchannelWrapper
I0307 23:05:25.468381365 142561 ref_counted.h:133] stream_refcount:0xe67cdf8 /home/user/grpc/src/core/lib/transport/transport.h:88 ref 3 -> 4 SubchannelWrapper
I0307 23:05:25.468398433 142561 subchannel_list.h:402] [pick_first 0x7f24b4003dd0] subchannel list 0x7f24b40043f0 index 0: Created subchannel 0x7f24b4004730 for address uri ipv4:
127.0.0.1:50052I0307 23:05:25.468409144 142561 ref_counted.h:103] lb_policy_refcount:0x7f24b4003dd8 /home/user/grpc/src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc:93 ref 1 -> 2 subchannel_list
I0307 23:05:25.468419787 142561 subchannel_list.h:308] [pick_first 0x7f24b4003dd0] subchannel list 0x7f24b40043f0 index 0 of 1 (subchannel 0x7f24b4004730): starting watch (from IDLE)
I0307 23:05:25.468425737 142561 ref_counted.h:103] pick_first:0x7f24b40043f8 /home/user/grpc/src/core/ext/filters/client_channel/lb_policy/subchannel_list.h:317 ref 1 -> 2 Watcher
I0307 23:05:25.468442492 142561 ref_counted.h:103] client_channel_routing:0x7f24b4004738 /home/user/grpc/src/core/ext/filters/client_channel/client_channel.cc:949 ref 1 -> 2 WatcherWrapper
I0307 23:05:25.468453616 142561 ev_posix.cc:379] (polling-api) pollset_set_add_pollset_set(0x7f24b4005540, 0x7f24b4003ee0)
I0307 23:05:25.468458563 142561 ev_epollex_linux.cc:1481] PSS: merge (0x7f24b4005540, 0x7f24b4003ee0)
I0307 23:05:25.468463282 142561 ev_epollex_linux.cc:1515] PSS: parent 0x7f24b4005540 to 0xe63df30
D0307 23:05:25.468470403 142561 subchannel.cc:960] SUBCHANNEL: 0x7f24b4005330 WEAK_REF 0x10001 -> 0x10002 [connecting]
I0307 23:05:25.468502039 142561 socket_utils_common_posix.cc:360] Enabling TCP_USER_TIMEOUT with a timeout of 1000 ms
I0307 23:05:25.468570720 142561 ev_posix.cc:256] (polling-api) fd_create(131, tcp-client:ipv4:
127.0.0.1:50052, 1)
I0307 23:05:25.468578307 142561 ev_posix.cc:257] (fd-trace) fd_create(131, tcp-client:ipv4:
127.0.0.1:50052, 1)
D0307 23:05:25.468589658 142561 ev_epollex_linux.cc:176] FD 131 0x7f24b4006e60 create tcp-client:ipv4:
127.0.0.1:50052 fd=131
I0307 23:05:25.468600504 142561 ev_posix.cc:396] (polling-api) pollset_set_add_fd(0x7f24b4005540, 131)
I0307 23:05:25.468605429 142561 ev_epollex_linux.cc:1347] PSS:0x7f24b4005540: add fd 0x7f24b4006e60 (131)
I0307 23:05:25.468610350 142561 ev_epollex_linux.cc:613] add fd 0x7f24b4006e60 (131) to pollable 0xe67d120
I0307 23:05:25.468616954 142561 ev_epollex_linux.cc:613] add fd 0x7f24b4006e60 (131) to pollable 0x7f24b4002b90
D0307 23:05:25.468628431 142561 ev_epollex_linux.cc:353] FD 131 0x7f24b4006e60 ref 2 1 -> 3 [pollset_set; /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1361]
I0307 23:05:25.468637772 142561 ref_counted.h:92] subchannel_pool:0xe6688a8 ref 6 -> 7
I0307 23:05:25.468643226 142561 tcp_client_posix.cc:320] CLIENT_CONNECT: ipv4:
127.0.0.1:50052: asynchronously connecting fd 0x7f24b4006e60
I0307 23:05:25.468648894 142561 timer_generic.cc:367] TIMER 0x7f24b4004ca0: SET 20031 now 31 call 0x7f24b4004cd8[0xa0e509]
I0307 23:05:25.468657573 142561 timer_generic.cc:404] .. add to shard 13 with queue_deadline_cap=1001 => is_first_timer=false
D0307 23:05:25.468664394 142561 lockfree_event.cc:99] LockfreeEvent::NotifyOn: 0x7f24b4006ee8 curr=(nil) closure=0x7f24b4004d28
I0307 23:05:25.468672247 142561 client_channel.cc:3876] chand=0xe67cea8 calld=0x7f24b4001870: applying service config to call
I0307 23:05:25.468678270 142561 ref_counted.h:92] lb_policy_refcount:0x7f24b40033e8 ref 4 -> 5
I0307 23:05:25.468686973 142561 client_channel.cc:4060] chand=0xe67cea8 calld=0x7f24b4001870: LB pick returned QUEUE (subchannel=(nil), error="No Error")
I0307 23:05:25.468703257 142561 ref_counted.h:199] resolver_refcount:0x7f24b4003468 /home/user/grpc/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc:399 unref 2 -> 1 dns-resolving
I0307 23:05:25.468710711 142561 work_serializer.cc:102] WorkSerializer::DrainQueue() 0xe63e4b0
I0307 23:05:25.468715761 142561 work_serializer.cc:117] Queue Drained
D0307 23:05:25.468720897 142561 exec_ctx.cc:43] closure 0x7f24b4003500 finished
D0307 23:05:25.468726161 142561 exec_ctx.cc:34] running closure 0x7f24b4004608: created [/home/user/grpc/src/core/ext/filters/client_channel/subchannel.cc:388]: scheduled [/home/user/grpc/src/core/ext/filters/client_channel/subchannel.cc:380]
I0307 23:05:25.468731897 142561 client_channel.cc:1061] chand=0xe67cea8: connectivity change for subchannel wrapper 0x7f24b4004730 subchannel 0x7f24b4005330; hopping into work_serializer
I0307 23:05:25.468738415 142561 work_serializer.cc:55] WorkSerializer::Run() 0xe63e4b0 Scheduling callback [/home/user/grpc/src/core/ext/filters/client_channel/client_channel.cc:1072]
I0307 23:05:25.468743085 142561 work_serializer.cc:65] Executing immediately
I0307 23:05:25.468748395 142561 client_channel.cc:1094] chand=0xe67cea8: processing connectivity change in work serializer for subchannel wrapper 0x7f24b4004730 subchannel 0x7f24b4005330 watcher=0x7f24b40008f0
I0307 23:05:25.468755607 142561 subchannel_list.h:241] [pick_first 0x7f24b4003dd0] subchannel list 0x7f24b40043f0 index 0 of 1 (subchannel 0x7f24b4004730): connectivity changed: state=CONNECTING, shutting_down=0, pending_watcher=0x7f24b40008f0
I0307 23:05:25.468762464 142561 ref_counted.h:103] lb_policy_refcount:0x7f24b4003dd8 /home/user/grpc/src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc:410 ref 2 -> 3 QueuePicker
I0307 23:05:25.468768969 142561 client_channel.cc:1362] chand=0xe67cea8: update: state=CONNECTING picker=0x7f24b40046d0
I0307 23:05:25.468775779 142561 ref_counted.h:92] lb_policy_refcount:0x7f24b4003dd8 ref 3 -> 4
I0307 23:05:25.468790653 142561 client_channel.cc:4060] chand=0xe67cea8 calld=0x7f24b4001870: LB pick returned QUEUE (subchannel=(nil), error="No Error")
I0307 23:05:25.468797290 142561 ref_counted.h:199] lb_policy_refcount:0x7f24b40033e8 /home/user/grpc/src/core/ext/filters/client_channel/lb_policy.h:377 unref 5 -> 4 QueuePicker
I0307 23:05:25.468805811 142561 work_serializer.cc:102] WorkSerializer::DrainQueue() 0xe63e4b0
I0307 23:05:25.468809964 142561 work_serializer.cc:117] Queue Drained
D0307 23:05:25.468814831 142561 exec_ctx.cc:43] closure 0x7f24b4004608 finished
D0307 23:05:25.468820075 142561 exec_ctx.cc:34] running closure 0x7f24b4006d80: created [/home/user/grpc/src/core/ext/filters/client_channel/lb_policy.cc:118]: scheduled [/home/user/grpc/src/core/ext/filters/client_channel/lb_policy.cc:107]
I0307 23:05:25.468825884 142561 work_serializer.cc:55] WorkSerializer::Run() 0xe63e4b0 Scheduling callback [/home/user/grpc/src/core/ext/filters/client_channel/lb_policy.cc:118]
I0307 23:05:25.468830674 142561 work_serializer.cc:65] Executing immediately
I0307 23:05:25.468836062 142561 ref_counted.h:183] lb_policy_refcount:0x7f24b40033e8 unref 4 -> 3
I0307 23:05:25.468840925 142561 work_serializer.cc:102] WorkSerializer::DrainQueue() 0xe63e4b0
I0307 23:05:25.468845108 142561 work_serializer.cc:117] Queue Drained
D0307 23:05:25.468853207 142561 exec_ctx.cc:43] closure 0x7f24b4006d80 finished
D0307 23:05:25.468858426 142561 exec_ctx.cc:34] running closure 0x7f24b4003a10: created [/home/user/grpc/src/core/ext/filters/client_channel/lb_policy.cc:118]: scheduled [/home/user/grpc/src/core/ext/filters/client_channel/lb_policy.cc:107]
I0307 23:05:25.468872884 142561 work_serializer.cc:55] WorkSerializer::Run() 0xe63e4b0 Scheduling callback [/home/user/grpc/src/core/ext/filters/client_channel/lb_policy.cc:118]
I0307 23:05:25.468877704 142561 work_serializer.cc:65] Executing immediately
I0307 23:05:25.468882317 142561 ref_counted.h:183] lb_policy_refcount:0x7f24b4003dd8 unref 4 -> 3
I0307 23:05:25.468886914 142561 work_serializer.cc:102] WorkSerializer::DrainQueue() 0xe63e4b0
I0307 23:05:25.468890987 142561 work_serializer.cc:117] Queue Drained
D0307 23:05:25.468895684 142561 exec_ctx.cc:43] closure 0x7f24b4003a10 finished
I0307 23:05:25.468902441 142561 completion_queue.cc:1197] grpc_completion_queue_next(cq=0x7f24b4000a00, deadline=gpr_timespec { tv_sec: 9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))
D0307 23:05:25.468912034 142561 completion_queue.cc:1176] PENDING TAGS: 0x7f24b4001e68
I0307 23:05:25.468920553 142561 ev_posix.cc:324] (polling-api) pollset_work(0x7f24b4000b10, 9223372036854775807) begin
I0307 23:05:25.468927510 142561 ev_epollex_linux.cc:1114] PS:0x7f24b4000b10 work hdl=(nil) worker=0x7f24c69ad490 now=32 deadline=9223372036854775807 kwp=0 pollable=0x7f24b4002b90
I0307 23:05:25.468933445 142561 ref_counted.h:103] pollable_refcount:0x7f24b4002b98 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1012 ref 1 -> 2 pollset_worker
I0307 23:05:25.468940260 142561 ev_epollex_linux.cc:932] POLLABLE:0x7f24b4002b90[type=pollset epfd=129 wakeup=130] poll for -1ms
I0307 23:05:25.468946217 142561 ev_epollex_linux.cc:951] POLLABLE:0x7f24b4002b90 got 1 events
I0307 23:05:25.468951157 142561 ev_epollex_linux.cc:900] PS:0x7f24b4000b10 got fd 0x7f24b4006e60: cancel=0 read=0 write=1
D0307 23:05:25.468955993 142561 lockfree_event.cc:214] LockfreeEvent::SetReady: 0x7f24b4006ee8 curr=0x7f24b4004d28
D0307 23:05:25.468961357 142561 exec_ctx.cc:34] running closure 0x7f24b4004d28: created [/home/user/grpc/src/core/lib/iomgr/tcp_client_posix.cc:316]: scheduled [/home/user/grpc/src/core/lib/iomgr/lockfree_event.cc:243]
I0307 23:05:25.468966454 142561 tcp_client_posix.cc:143] CLIENT_CONNECT: ipv4:
127.0.0.1:50052: on_writable: error="No Error"
I0307 23:05:25.468971289 142561 timer_generic.cc:470] TIMER 0x7f24b4004ca0: CANCEL pending=true
I0307 23:05:25.468976979 142561 ev_posix.cc:402] (polling-api) pollset_set_del_fd(0x7f24b4005540, 131)
I0307 23:05:25.468981478 142561 ev_epollex_linux.cc:1371] PSS:0x7f24b4005540: del fd 0x7f24b4006e60
D0307 23:05:25.468987148 142561 ev_epollex_linux.cc:390] FD 131 0x7f24b4006e60 unref 2 3 -> 1 [pollset_set; /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1377]
I0307 23:05:25.468995314 142561 combiner.cc:61] C:0x7f24b4006f30 create
D0307 23:05:25.469014542 142561 tcp_posix.cc:1812] cannot set inq fd=131 errno=92
D0307 23:05:25.469021678 142561 exec_ctx.cc:43] closure 0x7f24b4004d28 finished
D0307 23:05:25.469026883 142561 exec_ctx.cc:34] running closure 0x7f24b4004cd8: created [/home/user/grpc/src/core/lib/iomgr/tcp_client_posix.cc:325]: scheduled [/home/user/grpc/src/core/lib/iomgr/timer_generic.cc:477]
I0307 23:05:25.469031814 142561 tcp_client_posix.cc:107] CLIENT_CONNECT: ipv4:
127.0.0.1:50052: on_alarm: error="Cancelled"
I0307 23:05:25.469038442 142561 ref_counted.h:183] subchannel_pool:0xe6688a8 unref 7 -> 6
D0307 23:05:25.469043362 142561 exec_ctx.cc:43] closure 0x7f24b4004cd8 finished
D0307 23:05:25.469048805 142561 exec_ctx.cc:34] running closure 0x7f24b4004eb8: created [/home/user/grpc/src/core/ext/transport/chttp2/client/chttp2_connector.cc:44]: scheduled [/home/user/grpc/src/core/lib/iomgr/tcp_client_posix.cc:242]
I0307 23:05:25.469069480 142561 handshaker.cc:99] handshake_manager 0x7f24b4007ef0: adding handshaker http_connect [0x7f24b40080b0] at index 0
I0307 23:05:25.469081439 142561 ev_posix.cc:396] (polling-api) pollset_set_add_fd(0x7f24b4005540, 131)
I0307 23:05:25.469086333 142561 ev_epollex_linux.cc:1347] PSS:0x7f24b4005540: add fd 0x7f24b4006e60 (131)
I0307 23:05:25.469091270 142561 ev_epollex_linux.cc:613] add fd 0x7f24b4006e60 (131) to pollable 0xe67d120
I0307 23:05:25.469097061 142561 ev_epollex_linux.cc:613] add fd 0x7f24b4006e60 (131) to pollable 0x7f24b4002b90
D0307 23:05:25.469103146 142561 ev_epollex_linux.cc:353] FD 131 0x7f24b4006e60 ref 2 1 -> 3 [pollset_set; /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1361]
I0307 23:05:25.469109590 142561 ref_counted.h:92] subchannel_pool:0xe6688a8 ref 6 -> 7
I0307 23:05:25.469115409 142561 timer_generic.cc:367] TIMER 0x7f24b4007fa8: SET 20031 now 32 call 0x7f24b4007fe0[0xb5ab74]
I0307 23:05:25.469124532 142561 timer_generic.cc:404] .. add to shard 4 with queue_deadline_cap=1001 => is_first_timer=false
I0307 23:05:25.469161268 142561 handshaker.cc:129] handshake_manager 0x7f24b4007ef0: error="No Error" shutdown=0 index=0, args={endpoint=0x7f24b4007220, args=0x7f24b4000910 {size=11: grpc.primary_user_agent=grpc-c++/1.31.0, grpc.keepalive_time_ms=1000, grpc.keepalive_timeout_ms=1000, grpc.keepalive_permit_without_calls=1, grpc.http2.max_pings_without_data=0, grpc.http2.max_ping_strikes=5, grpc.client_channel_factory=0xe6686f0, grpc.server_uri=dns:///
127.0.0.1:50052, grpc.subchannel_pool=0xe6688a0, grpc.default_authority=
127.0.0.1:50052, grpc.subchannel_address=ipv4:
127.0.0.1:50052}, read_buffer=0x7f24b4007db0 (length=0), exit_early=0}
I0307 23:05:25.469170045 142561 handshaker.cc:176] handshake_manager 0x7f24b4007ef0: calling handshaker http_connect [0x7f24b40080b0] at index 0
D0307 23:05:25.469175632 142561 exec_ctx.cc:43] closure 0x7f24b4004eb8 finished
D0307 23:05:25.469180925 142561 exec_ctx.cc:34] running closure 0x7f24b4007f58: created [/home/user/grpc/src/core/lib/channel/handshaker.cc:237]: scheduled [/home/user/grpc/src/core/ext/filters/client_channel/http_connect_handshaker.cc:294]
I0307 23:05:25.469203658 142561 handshaker.cc:129] handshake_manager 0x7f24b4007ef0: error="No Error" shutdown=0 index=1, args={endpoint=0x7f24b4007220, args=0x7f24b4000910 {size=11: grpc.primary_user_agent=grpc-c++/1.31.0, grpc.keepalive_time_ms=1000, grpc.keepalive_timeout_ms=1000, grpc.keepalive_permit_without_calls=1, grpc.http2.max_pings_without_data=0, grpc.http2.max_ping_strikes=5, grpc.client_channel_factory=0xe6686f0, grpc.server_uri=dns:///
127.0.0.1:50052, grpc.subchannel_pool=0xe6688a0, grpc.default_authority=
127.0.0.1:50052, grpc.subchannel_address=ipv4:
127.0.0.1:50052}, read_buffer=0x7f24b4007db0 (length=0), exit_early=0}
I0307 23:05:25.469211354 142561 handshaker.cc:162] handshake_manager 0x7f24b4007ef0: handshaking complete -- scheduling on_handshake_done with error="No Error"
I0307 23:05:25.469216162 142561 timer_generic.cc:470] TIMER 0x7f24b4007fa8: CANCEL pending=true
D0307 23:05:25.469220770 142561 exec_ctx.cc:43] closure 0x7f24b4007f58 finished
D0307 23:05:25.469225899 142561 exec_ctx.cc:34] running closure 0x7f24b4007fe0: created [/home/user/grpc/src/core/lib/channel/handshaker.cc:243]: scheduled [/home/user/grpc/src/core/lib/iomgr/timer_generic.cc:477]
D0307 23:05:25.469230573 142561 exec_ctx.cc:43] closure 0x7f24b4007fe0 finished
D0307 23:05:25.469235369 142561 exec_ctx.cc:34] running closure 0x7f24b4008028: created [/home/user/grpc/src/core/lib/channel/handshaker.cc:239]: scheduled [/home/user/grpc/src/core/lib/channel/handshaker.cc:170]
I0307 23:05:25.469242079 142561 ev_posix.cc:402] (polling-api) pollset_set_del_fd(0x7f24b4005540, 131)
I0307 23:05:25.469246865 142561 ev_epollex_linux.cc:1371] PSS:0x7f24b4005540: del fd 0x7f24b4006e60
D0307 23:05:25.469252159 142561 ev_epollex_linux.cc:390] FD 131 0x7f24b4006e60 unref 2 3 -> 1 [pollset_set; /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1377]
I0307 23:05:25.469263382 142561 combiner.cc:61] C:0x7f24b4004860 create
I0307 23:05:25.469305706 142561 ref_counted.h:103] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:425 ref 1 -> 2 init keepalive ping
I0307 23:05:25.469313446 142561 timer_generic.cc:367] TIMER 0x7f24b400a878: SET 1032 now 32 call 0x7f24b400a758[0xb432de]
I0307 23:05:25.469327042 142561 timer_generic.cc:404] .. add to shard 17 with queue_deadline_cap=1001 => is_first_timer=false
I0307 23:05:25.469334018 142561 ref_counted.h:103] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:517 ref 2 -> 3 bdp_ping
I0307 23:05:25.469342236 142561 bdp_estimator.h:53] bdp[ipv4:127.0.0.1:50052]:sched acc=0 est=65536
I0307 23:05:25.469368171 142561 chttp2_transport.cc:798] W:0x7f24b4009330 CLIENT [ipv4:
127.0.0.1:50052] state IDLE -> WRITING [TRANSPORT_FLOW_CONTROL]
I0307 23:05:25.469375667 142561 ref_counted.h:103] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:891 ref 3 -> 4 writing
I0307 23:05:25.469381619 142561 combiner.cc:308] C:0x7f24b4004860 grpc_combiner_execute_finally c=0x7f24b4009400; ac=(nil)
I0307 23:05:25.469386636 142561 combiner.cc:135] C:0x7f24b4004860 grpc_combiner_execute c=0x7f24b4003c70 last=1
I0307 23:05:25.469392302 142561 chttp2_transport.cc:798] W:0x7f24b4009330 CLIENT [ipv4:
127.0.0.1:50052] state WRITING -> WRITING+MORE [INITIAL_WRITE]
I0307 23:05:25.469399704 142561 ref_counted.h:103] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:3170 ref 4 -> 5 benign_reclaimer
I0307 23:05:25.469417586 142561 combiner.cc:135] C:0x7f24b4006f30 grpc_combiner_execute c=0x7f24b4007c88 last=1
I0307 23:05:25.469423629 142561 ref_counted.h:103] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:3352 ref 5 -> 6 reading_action
I0307 23:05:25.469438303 142561 combiner.cc:135] C:0x7f24b4004860 grpc_combiner_execute c=0x7f24b40094d8 last=3
D0307 23:05:25.469446906 142561 exec_ctx.cc:43] closure 0x7f24b4008028 finished
D0307 23:05:25.469452323 142561 exec_ctx.cc:34] running closure 0x7f24b40053a0: created [/home/user/grpc/src/core/ext/filters/client_channel/subchannel.cc:674]: scheduled [/home/user/grpc/src/core/ext/transport/chttp2/client/chttp2_connector.cc:200]
D0307 23:05:25.469457770 142561 subchannel.cc:1023] SUBCHANNEL: 0x7f24b4005330 WEAK_REF 0x10002 -> 0x10003 [on_connecting_finished]
I0307 23:05:25.469464867 142561 ref_counted.h:92] subchannel_pool:0xe6688a8 ref 7 -> 8
D0307 23:05:25.469487205 142561 metadata.cc:161] mdelem INTERNED_MD_NOREF_KEY:0x7f24b4008720:1: ':authority' = '
127.0.0.1:50052'
D0307 23:05:25.469510340 142561 metadata.cc:161] mdelem INTERNED_MD_NOREF_KEY:0x7f24b4008900:1: 'user-agent' = 'grpc-c++/1.31.0 grpc-c/11.0.0 (linux; chttp2)'
I0307 23:05:25.469527771 142561 ref_counted.h:183] subchannel_pool:0xe6688a8 unref 8 -> 7
I0307 23:05:25.469536325 142561 ref_counted.h:92] subchannel_pool:0xe6688a8 ref 7 -> 8
I0307 23:05:25.469541526 142561 subchannel.cc:1085] New connected subchannel at 0x7f24b4004e00 for subchannel 0x7f24b4005330
D0307 23:05:25.469547301 142561 subchannel.cc:319] SUBCHANNEL: 0x7f24b4005330 WEAK_REF 0x10003 -> 0x10004 [state_watcher]
D0307 23:05:25.469552294 142561 subchannel.cc:320] SUBCHANNEL: 0x7f24b4005330 WEAK_UNREF 0x10004 -> 0x10003 [connecting]
I0307 23:05:25.469563298 142561 chttp2_transport.cc:1855] perform_transport_op[t=0x7f24b4009330]: START_CONNECTIVITY_WATCH:watcher=0x7f24b4008810:from=READY BIND_POLLSET_SET
I0307 23:05:25.469570963 142561 ref_counted.h:103] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:1859 ref 6 -> 7 transport_op
I0307 23:05:25.469576185 142561 combiner.cc:135] C:0x7f24b4004860 grpc_combiner_execute c=0x7f24b4008a68 last=5
I0307 23:05:25.469582685 142561 ref_counted.h:92] subchannel_refcount:0x7f24b4004e08 ref 1 -> 2
D0307 23:05:25.469588658 142561 subchannel.cc:1038] SUBCHANNEL: 0x7f24b4005330 WEAK_UNREF 0x10003 -> 0x10002 [on_connecting_finished]
I0307 23:05:25.469593982 142561 ref_counted.h:183] subchannel_pool:0xe6688a8 unref 8 -> 7
D0307 23:05:25.469598942 142561 exec_ctx.cc:43] closure 0x7f24b40053a0 finished
D0307 23:05:25.469604219 142561 exec_ctx.cc:34] running closure 0x7f24b4007e28: created [/home/user/grpc/src/core/ext/filters/client_channel/subchannel.cc:388]: scheduled [/home/user/grpc/src/core/ext/filters/client_channel/subchannel.cc:380]
I0307 23:05:25.469609573 142561 client_channel.cc:1061] chand=0xe67cea8: connectivity change for subchannel wrapper 0x7f24b4004730 subchannel 0x7f24b4005330; hopping into work_serializer
I0307 23:05:25.469615287 142561 work_serializer.cc:55] WorkSerializer::Run() 0xe63e4b0 Scheduling callback [/home/user/grpc/src/core/ext/filters/client_channel/client_channel.cc:1072]
I0307 23:05:25.469619753 142561 work_serializer.cc:65] Executing immediately
I0307 23:05:25.469624621 142561 client_channel.cc:1094] chand=0xe67cea8: processing connectivity change in work serializer for subchannel wrapper 0x7f24b4004730 subchannel 0x7f24b4005330 watcher=0x7f24b40008f0
I0307 23:05:25.469638317 142561 ref_counted.h:92] subchannel_refcount:0x7f24b4004e08 ref 2 -> 3
I0307 23:05:25.469643315 142561 ref_counted.h:183] subchannel_refcount:0x7f24b4004e08 unref 3 -> 2
I0307 23:05:25.469648928 142561 ref_counted.h:103] client_channel_routing:0x7f24b4004738 /home/user/grpc/src/core/ext/filters/client_channel/client_channel.cc:1136 ref 2 -> 3 ConnectedSubchannelUpdate
I0307 23:05:25.469658931 142561 ref_counted.h:92] subchannel_refcount:0x7f24b4004e08 ref 2 -> 3
I0307 23:05:25.469665427 142561 subchannel_list.h:241] [pick_first 0x7f24b4003dd0] subchannel list 0x7f24b40043f0 index 0 of 1 (subchannel 0x7f24b4004730): connectivity changed: state=READY, shutting_down=0, pending_watcher=0x7f24b40008f0
I0307 23:05:25.469670834 142561 pick_first.cc:445] Pick First 0x7f24b4003dd0 selected subchannel 0x7f24b4004730
I0307 23:05:25.469675774 142561 ref_counted.h:92] client_channel_routing:0x7f24b4004738 ref 3 -> 4
I0307 23:05:25.469681791 142561 client_channel.cc:1362] chand=0xe67cea8: update: state=READY picker=0x7f24b4004ab0
I0307 23:05:25.469687495 142561 connectivity_state.cc:152] ConnectivityStateTracker client_channel[0xe67cf88]: CONNECTING -> READY (helper)
I0307 23:05:25.469693809 142561 client_channel.cc:1743] chand=0xe67cea8: updating subchannel wrapper 0x7f24b4004730 data plane connected_subchannel to 0x7f24b4004e00
I0307 23:05:25.469699802 142561 ref_counted.h:92] client_channel_routing:0x7f24b4004738 ref 4 -> 5
I0307 23:05:25.469708086 142561 client_channel.cc:4060] chand=0xe67cea8 calld=0x7f24b4001870: LB pick returned COMPLETE (subchannel=0x7f24b4004730, error="No Error")
I0307 23:05:25.469712883 142561 client_channel.cc:3849] chand=0xe67cea8 calld=0x7f24b4001870: removing from queued picks list
I0307 23:05:25.469717793 142561 ev_posix.cc:373] (polling-api) pollset_set_del_pollset(0xe63df30, 0x7f24b4000b10)
I0307 23:05:25.469722613 142561 ev_epollex_linux.cc:1392] PSS:0xe63df30: del pollset 0x7f24b4000b10
I0307 23:05:25.469735509 142561 ev_epollex_linux.cc:661] PS:0x7f24b4000b10 (pollable:0x7f24b4002b90) maybe_finish_shutdown sc=(nil) (target:!NULL) rw=0x7f24c69ad490 (target:NULL) cpsc=0 (target:0)
I0307 23:05:25.469740788 142561 ref_counted.h:92] subchannel_refcount:0x7f24b4004e08 ref 3 -> 4
I0307 23:05:25.469745863 142561 ref_counted.h:183] client_channel_routing:0x7f24b4004738 unref 5 -> 4
I0307 23:05:25.469751399 142561 ref_counted.h:183] client_channel_routing:0x7f24b4004738 unref 4 -> 3
I0307 23:05:25.469757294 142561 ref_counted.h:199] lb_policy_refcount:0x7f24b4003dd8 /home/user/grpc/src/core/ext/filters/client_channel/lb_policy.h:377 unref 3 -> 2 QueuePicker
I0307 23:05:25.469765529 142561 work_serializer.cc:102] WorkSerializer::DrainQueue() 0xe63e4b0
I0307 23:05:25.469770337 142561 work_serializer.cc:117] Queue Drained
D0307 23:05:25.469775161 142561 exec_ctx.cc:43] closure 0x7f24b4007e28 finished
D0307 23:05:25.469788010 142561 exec_ctx.cc:34] running closure 0x7f24b4001a78: created [/home/user/grpc/src/core/ext/filters/client_channel/client_channel.cc:3785]: scheduled [/home/user/grpc/src/core/ext/filters/client_channel/client_channel.cc:3786]
D0307 23:05:25.469802385 142561 transport.h:85] CALL_STACK 0x7f24b400ae70:0x7f24b400ae00 REF chttp2
I0307 23:05:25.469809783 142561 ref_counted.h:133] stream_refcount:0x7f24b400ae70 /home/user/grpc/src/core/lib/transport/transport.h:88 ref 1 -> 2 chttp2
I0307 23:05:25.469815132 142561 ref_counted.h:103] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:623 ref 7 -> 8 stream
I0307 23:05:25.469823068 142561 ev_posix.cc:339] (polling-api) pollset_add_fd(0x7f24b4000b10, 131)
I0307 23:05:25.469829476 142561 ref_counted.h:103] pollable_refcount:0x7f24b4002b98 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1198 ref 2 -> 3 pollset_add_fd
I0307 23:05:25.469836935 142561 ev_epollex_linux.cc:613] add fd 0x7f24b4006e60 (131) to pollable 0x7f24b4002b90
I0307 23:05:25.469843720 142561 ref_counted.h:199] pollable_refcount:0x7f24b4002b98 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1226 unref 3 -> 2 pollset_add_fd
I0307 23:05:25.469853984 142561 client_channel.cc:3770] chand=0xe67cea8 calld=0x7f24b4001870: create subchannel_call=0x7f24b400ae00: error="No Error"
I0307 23:05:25.469864751 142561 client_channel.cc:2573] chand=0xe67cea8 calld=0x7f24b4001870: starting 1 pending batches on subchannel_call=0x7f24b400ae00
I0307 23:05:25.469872784 142561 call_combiner.h:175] CallCombinerClosureList executing closure while already holding call_combiner 0x7f24b4000df8: closure=0x7f24b4002268 error="No Error" reason=PendingBatchesResume
D0307 23:05:25.469880174 142561 exec_ctx.cc:43] closure 0x7f24b4001a78 finished
D0307 23:05:25.469885545 142561 exec_ctx.cc:34] running closure 0x7f24b4002268: created [/home/user/grpc/src/core/ext/filters/client_channel/client_channel.cc:2589]: scheduled [/home/user/grpc/src/core/lib/iomgr/call_combiner.h:182]
I0307 23:05:25.469903001 142561 subchannel.cc:181] OP[authority:0x7f24b400af00]: SEND_INITIAL_METADATA{key=3a 70 61 74 68 ':path' value=2f 72 69 63 2e 43 50 43 43 2f 53 65 6e 64 45 32 53 6d 4d 73 67 '/ric.CPCC/SendE2SmMsg'} SEND_MESSAGE:flags=0x00000000:len=94 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA
D0307 23:05:25.469909378 142561 client_authority_filter.cc:63] mdelem REF:0x7f24b4008720:1->2: ':authority' = '
127.0.0.1:50052'
I0307 23:05:25.469928698 142561 channel_stack.cc:226] OP[message_size:0x7f24b400af18]: SEND_INITIAL_METADATA{key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=31 32 37 2e 30 2e 30 2e 31 3a 35 30 30 35 32 '
127.0.0.1:50052', key=3a 70 61 74 68 ':path' value=2f 72 69 63 2e 43 50 43 43 2f 53 65 6e 64 45 32 53 6d 4d 73 67 '/ric.CPCC/SendE2SmMsg'} SEND_MESSAGE:flags=0x00000000:len=94 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA
I0307 23:05:25.469945548 142561 channel_stack.cc:226] OP[http-client:0x7f24b400af30]: SEND_INITIAL_METADATA{key=3a 61 75 74 68 6f 72 69 74 79 ':authority' value=31 32 37 2e 30 2e 30 2e 31 3a 35 30 30 35 32 '
127.0.0.1:50052', key=3a 70 61 74 68 ':path' value=2f 72 69 63 2e 43 50 43 43 2f 53 65 6e 64 45 32 53 6d 4d 73 67 '/ric.CPCC/SendE2SmMsg'} SEND_MESSAGE:flags=0x00000000:len=94 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA
D0307 23:05:25.469953793 142561 http_client_filter.cc:463] mdelem REF:0x7f24b4008900:1->2: 'user-agent' = 'grpc-c++/1.31.0 grpc-c/11.0.0 (linux; chttp2)'
I0307 23:05:25.469991228 142561 channel_stack.cc:226] OP[message_decompress:0x7f24b400af48]: 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 61 75 74 68 6f 72 69 74 79 ':authority' value=31 32 37 2e 30 2e 30 2e 31 3a 35 30 30 35 32 '
127.0.0.1:50052', key=3a 70 61 74 68 ':path' value=2f 72 69 63 2e 43 50 43 43 2f 53 65 6e 64 45 32 53 6d 4d 73 67 '/ric.CPCC/SendE2SmMsg', 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 63 2b 2b 2f 31 2e 33 31 2e 30 20 67 72 70 63 2d 63 2f 31 31 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 29 'grpc-c++/1.31.0 grpc-c/11.0.0 (linux; chttp2)'} SEND_MESSAGE:flags=0x00000000:len=94 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA
I0307 23:05:25.470024646 142561 channel_stack.cc:226] OP[message_compress:0x7f24b400af60]: 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 61 75 74 68 6f 72 69 74 79 ':authority' value=31 32 37 2e 30 2e 30 2e 31 3a 35 30 30 35 32 '
127.0.0.1:50052', key=3a 70 61 74 68 ':path' value=2f 72 69 63 2e 43 50 43 43 2f 53 65 6e 64 45 32 53 6d 4d 73 67 '/ric.CPCC/SendE2SmMsg', 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 63 2b 2b 2f 31 2e 33 31 2e 30 20 67 72 70 63 2d 63 2f 31 31 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 29 'grpc-c++/1.31.0 grpc-c/11.0.0 (linux; chttp2)'} SEND_MESSAGE:flags=0x00000000:len=94 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA
I0307 23:05:25.470064556 142561 channel_stack.cc:226] OP[connected:0x7f24b400af78]: 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 61 75 74 68 6f 72 69 74 79 ':authority' value=31 32 37 2e 30 2e 30 2e 31 3a 35 30 30 35 32 '
127.0.0.1:50052', key=3a 70 61 74 68 ':path' value=2f 72 69 63 2e 43 50 43 43 2f 53 65 6e 64 45 32 53 6d 4d 73 67 '/ric.CPCC/SendE2SmMsg', 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 63 2b 2b 2f 31 2e 33 31 2e 30 20 67 72 70 63 2d 63 2f 31 31 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 29 'grpc-c++/1.31.0 grpc-c/11.0.0 (linux; chttp2)', 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', key=61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'accept-encoding' value=69 64 65 6e 74 69 74 79 2c 67 7a 69 70 'identity,gzip'} SEND_MESSAGE:flags=0x00000000:len=94 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA
I0307 23:05:25.470103869 142561 chttp2_transport.cc:1656] perform_stream_op[s=0x7f24b400bf70]: 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 61 75 74 68 6f 72 69 74 79 ':authority' value=31 32 37 2e 30 2e 30 2e 31 3a 35 30 30 35 32 '
127.0.0.1:50052', key=3a 70 61 74 68 ':path' value=2f 72 69 63 2e 43 50 43 43 2f 53 65 6e 64 45 32 53 6d 4d 73 67 '/ric.CPCC/SendE2SmMsg', 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 63 2b 2b 2f 31 2e 33 31 2e 30 20 67 72 70 63 2d 63 2f 31 31 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 29 'grpc-c++/1.31.0 grpc-c/11.0.0 (linux; chttp2)', 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', key=61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'accept-encoding' value=69 64 65 6e 74 69 74 79 2c 67 7a 69 70 'identity,gzip'} SEND_MESSAGE:flags=0x00000000:len=94 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA
D0307 23:05:25.470111178 142561 transport.h:85] CALL_STACK 0x7f24b400ae70:0x7f24b400ae00 REF perform_stream_op
I0307 23:05:25.470116447 142561 ref_counted.h:133] stream_refcount:0x7f24b400ae70 /home/user/grpc/src/core/lib/transport/transport.h:88 ref 2 -> 3 perform_stream_op
I0307 23:05:25.470121359 142561 combiner.cc:135] C:0x7f24b4004860 grpc_combiner_execute c=0x7f24b4002268 last=7
I0307 23:05:25.470127123 142561 call_combiner.cc:150] ==> CallCombiner::Stop() [0x7f24b4000df8] [/home/user/grpc/src/core/lib/channel/connected_channel.cc:139: passed batch to transport]
I0307 23:05:25.470131831 142561 call_combiner.cc:156] size: 1 -> 0
I0307 23:05:25.470136007 142561 call_combiner.cc:184] queue empty
D0307 23:05:25.470140463 142561 exec_ctx.cc:43] closure 0x7f24b4002268 finished
I0307 23:05:25.470145505 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0307 23:05:25.470149874 142561 combiner.cc:222] C:0x7f24b4004860 maybe_finish_one n=0x7f24b4003c70
I0307 23:05:25.470154557 142561 combiner.cc:308] C:0x7f24b4004860 grpc_combiner_execute_finally c=0x7f24b4009400; ac=0x7f24b4004860
I0307 23:05:25.470159155 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=11
I0307 23:05:25.470163877 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0307 23:05:25.470168608 142561 combiner.cc:222] C:0x7f24b4004860 maybe_finish_one n=0x7f24b40094d8
I0307 23:05:25.470173387 142561 timer_generic.cc:470] TIMER 0x7f24b400a878: CANCEL pending=true
I0307 23:05:25.470180810 142561 ref_counted.h:103] tcp:0x7f24b4007248 /home/user/grpc/src/core/lib/iomgr/tcp_posix.cc:908 ref 1 -> 2 read
I0307 23:05:25.470185466 142561 tcp_posix.cc:541] TCP:0x7f24b4007220 notify_on_read
D0307 23:05:25.470190322 142561 lockfree_event.cc:99] LockfreeEvent::NotifyOn: 0x7f24b4006ee0 curr=(nil) closure=0x7f24b40073d0
I0307 23:05:25.470195247 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=9
D0307 23:05:25.470200398 142561 exec_ctx.cc:34] running closure 0x7f24b400a758: created [/home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:427]: scheduled [/home/user/grpc/src/core/lib/iomgr/timer_generic.cc:477]
I0307 23:05:25.470205132 142561 combiner.cc:135] C:0x7f24b4004860 grpc_combiner_execute c=0x7f24b400a758 last=7
D0307 23:05:25.470209312 142561 exec_ctx.cc:43] closure 0x7f24b400a758 finished
I0307 23:05:25.470213852 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0307 23:05:25.470217991 142561 combiner.cc:222] C:0x7f24b4004860 maybe_finish_one n=0x7f24b4008a68
I0307 23:05:25.470222691 142561 ev_posix.cc:396] (polling-api) pollset_set_add_fd(0x7f24b4005540, 131)
I0307 23:05:25.470227121 142561 ev_epollex_linux.cc:1347] PSS:0x7f24b4005540: add fd 0x7f24b4006e60 (131)
I0307 23:05:25.470231474 142561 ev_epollex_linux.cc:613] add fd 0x7f24b4006e60 (131) to pollable 0xe67d120
D0307 23:05:25.470237452 142561 ev_epollex_linux.cc:353] FD 131 0x7f24b4006e60 ref 2 1 -> 3 [pollset_set; /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1361]
I0307 23:05:25.470242360 142561 connectivity_state.cc:118] ConnectivityStateTracker client_transport[0x7f24b4009660]: add watcher 0x7f24b4008810
I0307 23:05:25.470249044 142561 ref_counted.h:199] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:1849 unref 8 -> 7 transport_op
I0307 23:05:25.470253532 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=9
D0307 23:05:25.470258392 142561 exec_ctx.cc:34] running closure 0x7f24b40089a0: created [/home/user/grpc/src/core/lib/transport/transport.cc:230]: scheduled [/home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:1847]
D0307 23:05:25.470262809 142561 exec_ctx.cc:43] closure 0x7f24b40089a0 finished
I0307 23:05:25.470267291 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0307 23:05:25.470271461 142561 combiner.cc:222] C:0x7f24b4004860 maybe_finish_one n=0x7f24b4002268
I0307 23:05:25.470309625 142561 chttp2_transport.cc:1358] 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 61 75 74 68 6f 72 69 74 79 ':authority' value=31 32 37 2e 30 2e 30 2e 31 3a 35 30 30 35 32 '
127.0.0.1:50052', key=3a 70 61 74 68 ':path' value=2f 72 69 63 2e 43 50 43 43 2f 53 65 6e 64 45 32 53 6d 4d 73 67 '/ric.CPCC/SendE2SmMsg', 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 63 2b 2b 2f 31 2e 33 31 2e 30 20 67 72 70 63 2d 63 2f 31 31 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 29 'grpc-c++/1.31.0 grpc-c/11.0.0 (linux; chttp2)', 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', key=61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'accept-encoding' value=69 64 65 6e 74 69 74 79 2c 67 7a 69 70 'identity,gzip'} SEND_MESSAGE:flags=0x00000000:len=94 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA; on_complete = 0x7f24b400bc08
I0307 23:05:25.470318080 142561 chttp2_transport.cc:1335] HTTP:0:HDR:CLI: :scheme: http
I0307 23:05:25.470322923 142561 chttp2_transport.cc:1335] HTTP:0:HDR:CLI: :method: POST
I0307 23:05:25.470327774 142561 chttp2_transport.cc:1335] HTTP:0:HDR:CLI: :authority:
127.0.0.1:50052I0307 23:05:25.470332451 142561 chttp2_transport.cc:1335] HTTP:0:HDR:CLI: :path: /ric.CPCC/SendE2SmMsg
I0307 23:05:25.470337183 142561 chttp2_transport.cc:1335] HTTP:0:HDR:CLI: te: trailers
I0307 23:05:25.470341575 142561 chttp2_transport.cc:1335] HTTP:0:HDR:CLI: content-type: application/grpc
I0307 23:05:25.470345960 142561 chttp2_transport.cc:1335] HTTP:0:HDR:CLI: user-agent: grpc-c++/1.31.0 grpc-c/11.0.0 (linux; chttp2)
I0307 23:05:25.470350458 142561 chttp2_transport.cc:1335] HTTP:0:HDR:CLI: grpc-accept-encoding: identity,deflate,gzip
I0307 23:05:25.470355003 142561 chttp2_transport.cc:1335] HTTP:0:HDR:CLI: accept-encoding: identity,gzip
I0307 23:05:25.470364763 142561 stream_lists.cc:125] 0x7f24b4009330[0][cli]: add to waiting_for_concurrency
I0307 23:05:25.470371964 142561 stream_lists.cc:71] 0x7f24b4009330[0][cli]: pop from waiting_for_concurrency
I0307 23:05:25.470376658 142561 chttp2_transport.cc:1137] HTTP:CLI: Transport 0x7f24b4009330 allocating new grpc_chttp2_stream 0x7f24b400bf70 to id 1
I0307 23:05:25.470382358 142561 ref_counted.h:103] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:3181 ref 7 -> 8 destructive_reclaimer
I0307 23:05:25.470386899 142561 combiner.cc:135] C:0x7f24b4006f30 grpc_combiner_execute c=0x7f24b4007cd0 last=3
I0307 23:05:25.470391777 142561 stream_lists.cc:125] 0x7f24b4009330[1][cli]: add to writable
D0307 23:05:25.470396374 142561 transport.h:85] CALL_STACK 0x7f24b400ae70:0x7f24b400ae00 REF chttp2_writing:become
I0307 23:05:25.470401343 142561 ref_counted.h:133] stream_refcount:0x7f24b400ae70 /home/user/grpc/src/core/lib/transport/transport.h:88 ref 3 -> 4 chttp2_writing:become
D0307 23:05:25.470427731 142561 flow_control.cc:112] 0x7f24b400a478[1][cli] | app st recv | trw: 65535, tlw: 4194304, taw: 65535, srw: 65535, slw: 65535 -> 65540, saw: 65535
I0307 23:05:25.470443572 142561 chttp2_transport.cc:1198] complete_closure_step: t=0x7f24b4009330 0x7f24b400bc08 refs=3 flags=0x0001 desc=op->on_complete err="No Error" write_state=WRITING+MORE
D0307 23:05:25.470448571 142561 transport.h:102] CALL_STACK 0x7f24b400ae70:0x7f24b400ae00 UNREF perform_stream_op
I0307 23:05:25.470453589 142561 ref_counted.h:199] stream_refcount:0x7f24b400ae70 /home/user/grpc/src/core/lib/transport/transport.h:105 unref 4 -> 3 perform_stream_op
I0307 23:05:25.470458517 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=7
I0307 23:05:25.470463143 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0307 23:05:25.470467737 142561 combiner.cc:222] C:0x7f24b4004860 maybe_finish_one n=0x7f24b400a758
I0307 23:05:25.470472831 142561 ref_counted.h:103] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:2808 ref 8 -> 9 init keepalive ping
I0307 23:05:25.470477801 142561 timer_generic.cc:367] TIMER 0x7f24b400a878: SET 1032 now 32 call 0x7f24b400a758[0xb432de]
I0307 23:05:25.470482588 142561 timer_generic.cc:404] .. add to shard 17 with queue_deadline_cap=1001 => is_first_timer=false
I0307 23:05:25.470487659 142561 ref_counted.h:199] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:2815 unref 9 -> 8 init keepalive ping
I0307 23:05:25.470492099 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=5
I0307 23:05:25.470496602 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=1
I0307 23:05:25.470500935 142561 combiner.cc:246] C:0x7f24b4004860 execute_final[0] c=0x7f24b4009400
I0307 23:05:25.470512203 142561 stream_lists.cc:71] 0x7f24b4009330[1][cli]: pop from writable
I0307 23:05:25.470517652 142561 writing.cc:436] W:0x7f24b4009330 CLIENT[1] im-(sent,send)=(0,1) announce=5
I0307 23:05:25.470530377 142561 hpack_encoder.cc:617] Encode: ':authority:
127.0.0.1:50052', elem_interned=1 [3], k_interned=1, v_interned=1
D0307 23:05:25.470540366 142561 hpack_encoder.cc:114] mdelem REF:0x7f24b4008720:2->3: ':authority' = '
127.0.0.1:50052'
I0307 23:05:25.470545810 142561 hpack_encoder.cc:617] Encode: ':path: /ric.CPCC/SendE2SmMsg', elem_interned=0 [2], k_interned=1, v_interned=0
I0307 23:05:25.470552060 142561 hpack_encoder.cc:617] Encode: 'te: trailers', elem_interned=1 [1], k_interned=1, v_interned=1
I0307 23:05:25.470557753 142561 hpack_encoder.cc:617] Encode: 'content-type: application/grpc', elem_interned=1 [1], k_interned=1, v_interned=1
I0307 23:05:25.470563392 142561 hpack_encoder.cc:617] Encode: 'user-agent: grpc-c++/1.31.0 grpc-c/11.0.0 (linux; chttp2)', elem_interned=1 [3], k_interned=1, v_interned=1
D0307 23:05:25.470568857 142561 hpack_encoder.cc:114] mdelem REF:0x7f24b4008900:2->3: 'user-agent' = 'grpc-c++/1.31.0 grpc-c/11.0.0 (linux; chttp2)'
I0307 23:05:25.470574170 142561 hpack_encoder.cc:617] Encode: 'grpc-accept-encoding: identity,deflate,gzip', elem_interned=1 [1], k_interned=1, v_interned=1
I0307 23:05:25.470579651 142561 hpack_encoder.cc:617] Encode: 'accept-encoding: identity,gzip', elem_interned=1 [1], k_interned=1, v_interned=1
I0307 23:05:25.470586084 142561 chttp2_transport.cc:1198] complete_closure_step: t=0x7f24b4009330 0x7f24b400bc08 refs=2 flags=0x0001 desc=send_initial_metadata_finished err="No Error" write_state=WRITING+MORE
D0307 23:05:25.470597111 142561 flow_control.cc:112] 0x7f24b400a478[1][cli] | s updt sent | trw: 65535, tlw: 4194304 -> 4194309, taw: 65535, srw: 65535, slw: 4194309, saw: 4194304 -> 4194309
D0307 23:05:25.470610549 142561 flow_control.cc:112] 0x7f24b400a478[1][cli] | data sent | trw: 65535 -> 65436, tlw: 4194309, taw: 65535, srw: 65535 -> 65436, slw: 4194309, saw: 4194309
I0307 23:05:25.470617344 142561 chttp2_transport.cc:1198] complete_closure_step: t=0x7f24b4009330 0x7f24b400bc08 refs=1 flags=0x0001 desc=send_trailing_metadata_finished err="No Error" write_state=WRITING+MORE
I0307 23:05:25.470623996 142561 chttp2_transport.cc:1198] complete_closure_step: t=0x7f24b4009330 0x7f24b400bc08 refs=0 flags=0x0001 desc=on_write_finished_cb err="No Error" write_state=WRITING+MORE
I0307 23:05:25.470629406 142561 stream_lists.cc:125] 0x7f24b4009330[1][cli]: add to writing
D0307 23:05:25.470637340 142561 flow_control.cc:112] 0x7f24b400a478[0][cli] | t updt sent | trw: 65436, tlw: 4194309, taw: 65535 -> 4194309, srw: , slw: , saw:
I0307 23:05:25.470643332 142561 writing.cc:127] CLIENT: Ping sent [ipv4:
127.0.0.1:50052]: 0/0
I0307 23:05:25.470649051 142561 chttp2_transport.cc:798] W:0x7f24b4009330 CLIENT [ipv4:
127.0.0.1:50052] state WRITING+MORE -> WRITING [begin write in current thread]
I0307 23:05:25.470653933 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470659830 142561 tcp_posix.cc:1570] 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 'PRI * HTTP/2.0....SM....'
I0307 23:05:25.470664216 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470670621 142561 tcp_posix.cc:1570] DATA: 00 00 24 04 00 00 00 00 00 00 02 00 00 00 00 00 03 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 '..$.....................@.....@...... .......'
I0307 23:05:25.470675107 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470679969 142561 tcp_posix.cc:1570] DATA: 00 00 ec 01 04 00 00 00 01 86 83 40 0a '...........@.'
I0307 23:05:25.470684179 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470688808 142561 tcp_posix.cc:1570] DATA: 3a 61 75 74 68 6f 72 69 74 79 ':authority'
I0307 23:05:25.470692779 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470696825 142561 tcp_posix.cc:1570] DATA: 0f '.'
I0307 23:05:25.470700781 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470705451 142561 tcp_posix.cc:1570] DATA: 31 32 37 2e 30 2e 30 2e 31 3a 35 30 30 35 32 '
127.0.0.1:50052'
I0307 23:05:25.470709647 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470714049 142561 tcp_posix.cc:1570] DATA: 40 05 '@.'
I0307 23:05:25.470718173 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470722641 142561 tcp_posix.cc:1570] DATA: 3a 70 61 74 68 ':path'
I0307 23:05:25.470726799 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470730942 142561 tcp_posix.cc:1570] DATA: 15 '.'
I0307 23:05:25.470734939 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470739912 142561 tcp_posix.cc:1570] DATA: 2f 72 69 63 2e 43 50 43 43 2f 53 65 6e 64 45 32 53 6d 4d 73 67 '/ric.CPCC/SendE2SmMsg'
I0307 23:05:25.470744016 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470748273 142561 tcp_posix.cc:1570] DATA: 40 02 '@.'
I0307 23:05:25.470752331 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470756606 142561 tcp_posix.cc:1570] DATA: 74 65 'te'
I0307 23:05:25.470760721 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470764694 142561 tcp_posix.cc:1570] DATA: 08 '.'
I0307 23:05:25.470768709 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470773763 142561 tcp_posix.cc:1570] DATA: 74 72 61 69 6c 65 72 73 'trailers'
I0307 23:05:25.470778005 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470782181 142561 tcp_posix.cc:1570] DATA: 40 0c '@.'
I0307 23:05:25.470786278 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470791047 142561 tcp_posix.cc:1570] DATA: 63 6f 6e 74 65 6e 74 2d 74 79 70 65 'content-type'
I0307 23:05:25.470795572 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470799632 142561 tcp_posix.cc:1570] DATA: 10 '.'
I0307 23:05:25.470803652 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470808675 142561 tcp_posix.cc:1570] DATA: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
I0307 23:05:25.470812783 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470816840 142561 tcp_posix.cc:1570] DATA: 40 0a '@.'
I0307 23:05:25.470820814 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470825466 142561 tcp_posix.cc:1570] DATA: 75 73 65 72 2d 61 67 65 6e 74 'user-agent'
I0307 23:05:25.470829512 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470833590 142561 tcp_posix.cc:1570] DATA: 2d '-'
I0307 23:05:25.470837502 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470843406 142561 tcp_posix.cc:1570] DATA: 67 72 70 63 2d 63 2b 2b 2f 31 2e 33 31 2e 30 20 67 72 70 63 2d 63 2f 31 31 2e 30 2e 30 20 28 6c 69 6e 75 78 3b 20 63 68 74 74 70 32 29 'grpc-c++/1.31.0 grpc-c/11.0.0 (linux; chttp2)'
I0307 23:05:25.470847690 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470851707 142561 tcp_posix.cc:1570] DATA: 40 14 '@.'
I0307 23:05:25.470855704 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470860608 142561 tcp_posix.cc:1570] DATA: 67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'grpc-accept-encoding'
I0307 23:05:25.470864738 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470868923 142561 tcp_posix.cc:1570] DATA: 15 '.'
I0307 23:05:25.470873116 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470878167 142561 tcp_posix.cc:1570] DATA: 69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip'
I0307 23:05:25.470882307 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470886459 142561 tcp_posix.cc:1570] DATA: 40 0f '@.'
I0307 23:05:25.470890600 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470895339 142561 tcp_posix.cc:1570] DATA: 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 'accept-encoding'
I0307 23:05:25.470899435 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470903364 142561 tcp_posix.cc:1570] DATA: 0d '.'
I0307 23:05:25.470907291 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470911913 142561 tcp_posix.cc:1570] DATA: 69 64 65 6e 74 69 74 79 2c 67 7a 69 70 'identity,gzip'
I0307 23:05:25.470916124 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470921036 142561 tcp_posix.cc:1570] DATA: 00 00 04 08 00 00 00 00 01 00 00 00 05 00 00 63 00 01 00 00 00 01 00 '...............c.......'
I0307 23:05:25.470925454 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470930406 142561 tcp_posix.cc:1570] DATA: 00 00 00 5e '...^'
I0307 23:05:25.470934732 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470943204 142561 tcp_posix.cc:1570] DATA: 08 03 10 58 1a 58 11 01 00 00 30 00 01 0d 11 6f 69 64 10 00 00 00 10 00 00 00 10 00 00 00 10 00 00 00 10 00 00 00 10 00 00 00 10 00 00 00 10 00 00 00 10 00 00 00 10 00 00 00 10 00 00 00 10 00 00 00 10 00 00 00 10 00 00 00 10 00 00 00 10 00 00 00 10 00 00 00 65 61 64 6c 69 6e 65 3d '...X.X....0....oid....................................................................eadline='
I0307 23:05:25.470948426 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470953846 142561 tcp_posix.cc:1570] DATA: 00 00 04 08 00 00 00 00 00 00 3f 00 06 00 00 08 06 00 00 00 00 00 00 '..........?............'
I0307 23:05:25.470958045 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.470962499 142561 tcp_posix.cc:1570] DATA: 00 00 00 00 00 00 00 '.......'
I0307 23:05:25.470991255 142561 tcp_posix.cc:1616] write: "No Error"
D0307 23:05:25.470996927 142561 closure.h:238] running closure 0x7f24b4009490: created [/home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:985]: run [/home/user/grpc/src/core/lib/iomgr/tcp_posix.cc:1618]
I0307 23:05:25.471001662 142561 combiner.cc:135] C:0x7f24b4004860 grpc_combiner_execute c=0x7f24b4009490 last=3
D0307 23:05:25.471006122 142561 closure.h:247] closure 0x7f24b4009490 finished
I0307 23:05:25.471010415 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=5
D0307 23:05:25.471015709 142561 exec_ctx.cc:34] running closure 0x7f24b400a5d8: created [/home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:2626]: scheduled [/home/user/grpc/src/core/ext/transport/chttp2/transport/writing.cc:116]
I0307 23:05:25.471020380 142561 combiner.cc:135] C:0x7f24b4004860 grpc_combiner_execute c=0x7f24b400a5d8 last=3
D0307 23:05:25.471024896 142561 exec_ctx.cc:43] closure 0x7f24b400a5d8 finished
I0307 23:05:25.471029567 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0307 23:05:25.471033998 142561 combiner.cc:222] C:0x7f24b4004860 maybe_finish_one n=0x7f24b4009490
I0307 23:05:25.471038765 142561 chttp2_transport.cc:798] W:0x7f24b4009330 CLIENT [ipv4:
127.0.0.1:50052] state WRITING -> IDLE [finish writing]
I0307 23:05:25.471043992 142561 stream_lists.cc:71] 0x7f24b4009330[1][cli]: pop from writing
D0307 23:05:25.471048722 142561 transport.h:102] CALL_STACK 0x7f24b400ae70:0x7f24b400ae00 UNREF chttp2_writing:end
I0307 23:05:25.471053803 142561 ref_counted.h:199] stream_refcount:0x7f24b400ae70 /home/user/grpc/src/core/lib/transport/transport.h:105 unref 3 -> 2 chttp2_writing:end
I0307 23:05:25.471059032 142561 ref_counted.h:199] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:1044 unref 8 -> 7 writing
I0307 23:05:25.471063357 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=5
D0307 23:05:25.471068230 142561 exec_ctx.cc:34] running closure 0x7f24b400bc08: created [/home/user/grpc/src/core/lib/channel/connected_channel.cc:76]: scheduled [/home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:807]
I0307 23:05:25.471073685 142561 call_combiner.cc:116] ==> CallCombiner::Start() [0x7f24b4000df8] closure=0x7f24b4002368 [/home/user/grpc/src/core/lib/channel/connected_channel.cc:59: on_complete] error="No Error"
I0307 23:05:25.471078077 142561 call_combiner.cc:124] size: 0 -> 1
I0307 23:05:25.471082020 142561 call_combiner.cc:132] EXECUTING IMMEDIATELY
D0307 23:05:25.471086545 142561 exec_ctx.cc:43] closure 0x7f24b400bc08 finished
D0307 23:05:25.471091400 142561 exec_ctx.cc:34] running closure 0x7f24b4002368: created [/home/user/grpc/src/core/lib/surface/call.cc:1922]: scheduled [/home/user/grpc/src/core/lib/iomgr/call_combiner.cc:98]
I0307 23:05:25.471096549 142561 call_combiner.cc:150] ==> CallCombiner::Stop() [0x7f24b4000df8] [/home/user/grpc/src/core/lib/surface/call.cc:1531: on_complete]
I0307 23:05:25.471100804 142561 call_combiner.cc:156] size: 1 -> 0
I0307 23:05:25.471104650 142561 call_combiner.cc:184] queue empty
D0307 23:05:25.471111986 142561 exec_ctx.cc:43] closure 0x7f24b4002368 finished
I0307 23:05:25.471116639 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0307 23:05:25.471120980 142561 combiner.cc:222] C:0x7f24b4004860 maybe_finish_one n=0x7f24b400a5d8
I0307 23:05:25.471125441 142561 chttp2_transport.cc:2641] ipv4:
127.0.0.1:50052: Start BDP ping err="No Error"
I0307 23:05:25.471129919 142561 timer_generic.cc:470] TIMER 0x7f24b400a878: CANCEL pending=true
I0307 23:05:25.471134749 142561 bdp_estimator.h:66] bdp[ipv4:127.0.0.1:50052]:start acc=0 est=65536
I0307 23:05:25.471138991 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=3
D0307 23:05:25.471143823 142561 exec_ctx.cc:34] running closure 0x7f24b400a758: created [/home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:2810]: scheduled [/home/user/grpc/src/core/lib/iomgr/timer_generic.cc:477]
I0307 23:05:25.471148258 142561 combiner.cc:135] C:0x7f24b4004860 grpc_combiner_execute c=0x7f24b400a758 last=1
D0307 23:05:25.471152463 142561 exec_ctx.cc:43] closure 0x7f24b400a758 finished
I0307 23:05:25.471156997 142561 combiner.cc:199] C:0x7f24b4006f30 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0307 23:05:25.471161322 142561 combiner.cc:222] C:0x7f24b4006f30 maybe_finish_one n=0x7f24b4007c88
I0307 23:05:25.471168344 142561 combiner.cc:264] C:0x7f24b4006f30 finish old_state=5
I0307 23:05:25.471172990 142561 combiner.cc:199] C:0x7f24b4006f30 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0307 23:05:25.471177371 142561 combiner.cc:222] C:0x7f24b4006f30 maybe_finish_one n=0x7f24b4007cd0
I0307 23:05:25.471181668 142561 combiner.cc:264] C:0x7f24b4006f30 finish old_state=3
I0307 23:05:25.471185959 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0307 23:05:25.471190186 142561 combiner.cc:222] C:0x7f24b4004860 maybe_finish_one n=0x7f24b400a758
I0307 23:05:25.471195155 142561 ref_counted.h:103] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:2808 ref 7 -> 8 init keepalive ping
I0307 23:05:25.471199933 142561 timer_generic.cc:367] TIMER 0x7f24b400a878: SET 1032 now 32 call 0x7f24b400a758[0xb432de]
I0307 23:05:25.471204563 142561 timer_generic.cc:404] .. add to shard 17 with queue_deadline_cap=1001 => is_first_timer=false
I0307 23:05:25.471209372 142561 ref_counted.h:199] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:2815 unref 8 -> 7 init keepalive ping
I0307 23:05:25.471213820 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=3
I0307 23:05:25.471219064 142561 ref_counted.h:199] pollable_refcount:0x7f24b4002b98 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1079 unref 2 -> 1 pollset_worker
I0307 23:05:25.471224235 142561 ev_epollex_linux.cc:661] PS:0x7f24b4000b10 (pollable:0x7f24b4002b90) maybe_finish_shutdown sc=(nil) (target:!NULL) rw=(nil) (target:NULL) cpsc=0 (target:0)
I0307 23:05:25.471229399 142561 ev_posix.cc:327] (polling-api) pollset_work(0x7f24b4000b10, 9223372036854775807) end
I0307 23:05:25.471234538 142561 ev_posix.cc:324] (polling-api) pollset_work(0x7f24b4000b10, 9223372036854775807) begin
I0307 23:05:25.471240549 142561 ev_epollex_linux.cc:1114] PS:0x7f24b4000b10 work hdl=(nil) worker=0x7f24c69ad490 now=32 deadline=9223372036854775807 kwp=0 pollable=0x7f24b4002b90
I0307 23:05:25.471245704 142561 ref_counted.h:103] pollable_refcount:0x7f24b4002b98 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1012 ref 1 -> 2 pollset_worker
I0307 23:05:25.471251868 142561 ev_epollex_linux.cc:932] POLLABLE:0x7f24b4002b90[type=pollset epfd=129 wakeup=130] poll for -1ms
I0307 23:05:25.471257715 142561 ev_epollex_linux.cc:951] POLLABLE:0x7f24b4002b90 got 1 events
I0307 23:05:25.471262306 142561 ev_epollex_linux.cc:900] PS:0x7f24b4000b10 got fd 0x7f24b4006e60: cancel=0 read=1 write=1
D0307 23:05:25.471267134 142561 lockfree_event.cc:214] LockfreeEvent::SetReady: 0x7f24b4006ee0 curr=0x7f24b40073d0
D0307 23:05:25.471271447 142561 lockfree_event.cc:214] LockfreeEvent::SetReady: 0x7f24b4006ee8 curr=(nil)
D0307 23:05:25.471276558 142561 exec_ctx.cc:34] running closure 0x7f24b40073d0: created [/home/user/grpc/src/core/lib/iomgr/tcp_posix.cc:1794]: scheduled [/home/user/grpc/src/core/lib/iomgr/lockfree_event.cc:243]
I0307 23:05:25.471281100 142561 tcp_posix.cc:887] TCP:0x7f24b4007220 got_read: "No Error"
I0307 23:05:25.471285868 142561 tcp_posix.cc:869] TCP:0x7f24b4007220 alloc_slices
I0307 23:05:25.471290753 142561 resource_quota.cc:892] RQ anonymous_pool_139795615477984 ipv4:
127.0.0.1:50052: alloc 8192; free_pool -> -8192
I0307 23:05:25.471295223 142561 combiner.cc:135] C:0x7f24b4006f30 grpc_combiner_execute c=0x7f24b4007b68 last=1
D0307 23:05:25.471299644 142561 exec_ctx.cc:43] closure 0x7f24b40073d0 finished
I0307 23:05:25.471304496 142561 combiner.cc:199] C:0x7f24b4006f30 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0307 23:05:25.471308892 142561 combiner.cc:222] C:0x7f24b4006f30 maybe_finish_one n=0x7f24b4007b68
I0307 23:05:25.471313546 142561 combiner.cc:308] C:0x7f24b4006f30 grpc_combiner_execute_finally c=0x7f24b4007150; ac=0x7f24b4006f30
I0307 23:05:25.471318005 142561 combiner.cc:264] C:0x7f24b4006f30 finish old_state=5
I0307 23:05:25.471322633 142561 combiner.cc:199] C:0x7f24b4006f30 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=1
I0307 23:05:25.471326882 142561 combiner.cc:246] C:0x7f24b4006f30 execute_final[0] c=0x7f24b4007150
I0307 23:05:25.471331711 142561 resource_quota.cc:324] RQ: check allocation for user 0x7f24b4007b60 shutdown=0 free_pool=-8192 outstanding_allocations=8192
I0307 23:05:25.471337522 142561 resource_quota.cc:352] RQ anonymous_pool_139795615477984 ipv4:
127.0.0.1:50052: grant alloc 8192 bytes; rq_free_pool -> 9223372036854767615
I0307 23:05:25.471342382 142561 combiner.cc:264] C:0x7f24b4006f30 finish old_state=3
D0307 23:05:25.471347346 142561 exec_ctx.cc:34] running closure 0x7f24b40074b8: created [/home/user/grpc/src/core/lib/iomgr/resource_quota.cc:992]: scheduled [/home/user/grpc/src/core/lib/iomgr/resource_quota.cc:366]
D0307 23:05:25.471356330 142561 closure.h:238] running closure 0x7f24b4007500: created [/home/user/grpc/src/core/lib/iomgr/resource_quota.cc:994]: run [/home/user/grpc/src/core/lib/iomgr/resource_quota.cc:608]
I0307 23:05:25.471361208 142561 tcp_posix.cc:850] TCP:0x7f24b4007220 read_allocation_done: "No Error"
I0307 23:05:25.471375686 142561 tcp_posix.cc:680] TCP:0x7f24b4007220 call_cb 0x7f24b40094d8 0xb42229:0x7f24b4009330
I0307 23:05:25.471381332 142561 tcp_posix.cc:683] READ 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052) error="No Error"
D0307 23:05:25.471398078 142561 tcp_posix.cc:689] 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 00 00 04 08 00 00 00 00 00 00 3f 00 01 00 00 08 06 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 08 06 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 04 01 00 00 00 00 00 00 04 08 00 00 00 00 00 00 00 00 63 00 00 6b 01 04 00 00 00 01 88 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 40 14 67 72 70 63 2d 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 15 69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 40 0f 61 63 63 65 70 74 2d 65 6e 63 6f 64 69 6e 67 0d 69 64 65 6e 74 69 74 79 2c 67 7a 69 70 00 00 05 00 00 00 00 00 01 00 00 00 00 00 00 00 0f 01 05 00 00 00 01 40 0b 67 72 70 63 2d 73 74 61 74 75 73 01 30 '............@.....@...... .................?.........................................................c..k.......@.content-type.application/grpc@.grpc-accept-encoding.identity,deflate,gzip@.accept-encoding.identity,gzip.......................@.grpc-status.0'
D0307 23:05:25.471404888 142561 closure.h:238] running closure 0x7f24b40094d8: created [/home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:2614]: run [/home/user/grpc/src/core/lib/iomgr/tcp_posix.cc:697]
I0307 23:05:25.471409543 142561 combiner.cc:135] C:0x7f24b4004860 grpc_combiner_execute c=0x7f24b40094d8 last=1
D0307 23:05:25.471414017 142561 closure.h:247] closure 0x7f24b40094d8 finished
I0307 23:05:25.471418776 142561 ref_counted.h:199] tcp:0x7f24b4007248 /home/user/grpc/src/core/lib/iomgr/tcp_posix.cc:844 unref 2 -> 1 read
D0307 23:05:25.471423004 142561 closure.h:247] closure 0x7f24b4007500 finished
D0307 23:05:25.471427052 142561 exec_ctx.cc:43] closure 0x7f24b40074b8 finished
I0307 23:05:25.471434910 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0307 23:05:25.471439331 142561 combiner.cc:222] C:0x7f24b4004860 maybe_finish_one n=0x7f24b40094d8
I0307 23:05:25.471451667 142561 frame_settings.cc:223] 0x7f24b4009330[cli] adding 4128769 for initial_window change
I0307 23:05:25.471456568 142561 frame_settings.cc:230] CHTTP2:CLI:ipv4:
127.0.0.1:50052: got setting INITIAL_WINDOW_SIZE = 4194304
I0307 23:05:25.471461086 142561 frame_settings.cc:230] CHTTP2:CLI:ipv4:
127.0.0.1:50052: got setting MAX_FRAME_SIZE = 4194304
I0307 23:05:25.471465535 142561 frame_settings.cc:230] CHTTP2:CLI:ipv4:
127.0.0.1:50052: got setting MAX_HEADER_LIST_SIZE = 8192
I0307 23:05:25.471470036 142561 frame_settings.cc:230] CHTTP2:CLI:ipv4:
127.0.0.1:50052: got setting GRPC_ALLOW_TRUE_BINARY_METADATA = 1
D0307 23:05:25.471479311 142561 flow_control.cc:112] 0x7f24b400a478[0][cli] | t updt recv | trw: 65436 -> 4194205, tlw: 4194309, taw: 4194309, srw: , slw: , saw:
I0307 23:05:25.471485612 142561 chttp2_transport.cc:798] W:0x7f24b4009330 CLIENT [ipv4:
127.0.0.1:50052] state IDLE -> WRITING [PING_RESPONSE]
I0307 23:05:25.471490751 142561 ref_counted.h:103] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:891 ref 7 -> 8 writing
I0307 23:05:25.471495324 142561 combiner.cc:308] C:0x7f24b4004860 grpc_combiner_execute_finally c=0x7f24b4009400; ac=0x7f24b4004860
D0307 23:05:25.471504567 142561 flow_control.cc:112] 0x7f24b400a478[0][cli] | t updt recv | trw: 4194205 -> 4194304, tlw: 4194309, taw: 4194309, srw: , slw: , saw:
I0307 23:05:25.471510478 142561 parsing.cc:671] parsing initial_metadata
I0307 23:05:25.471520356 142561 hpack_parser.cc:639] Decode: ':status: 200', elem_interned=1 [1], k_interned=1, v_interned=1
I0307 23:05:25.471526220 142561 parsing.cc:420] HTTP:1:HDR:CLI: :status: 32 30 30 '200'
I0307 23:05:25.471537172 142561 hpack_parser.cc:639] Decode: 'content-type: application/grpc', elem_interned=1 [1], k_interned=1, v_interned=1
I0307 23:05:25.471543374 142561 parsing.cc:420] HTTP:1:HDR:CLI: content-type: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 67 72 70 63 'application/grpc'
I0307 23:05:25.471550282 142561 hpack_parser.cc:639] Decode: 'grpc-accept-encoding: identity,deflate,gzip', elem_interned=1 [1], k_interned=1, v_interned=1
I0307 23:05:25.471556373 142561 parsing.cc:420] HTTP:1:HDR:CLI: grpc-accept-encoding: 69 64 65 6e 74 69 74 79 2c 64 65 66 6c 61 74 65 2c 67 7a 69 70 'identity,deflate,gzip'
I0307 23:05:25.471562661 142561 hpack_parser.cc:639] Decode: 'accept-encoding: identity,gzip', elem_interned=1 [1], k_interned=1, v_interned=1
I0307 23:05:25.471568275 142561 parsing.cc:420] HTTP:1:HDR:CLI: accept-encoding: 69 64 65 6e 74 69 74 79 2c 67 7a 69 70 'identity,gzip'
D0307 23:05:25.471581229 142561 flow_control.cc:112] 0x7f24b400a478[1][cli] | data recv | trw: 4194304, tlw: 4194309 -> 4194304, taw: 4194309 -> 4194304, srw: 4194205, slw: 4194309 -> 4194304, saw: 4194309 -> 4194304
I0307 23:05:25.471588668 142561 parsing.cc:676] parsing trailing_metadata
I0307 23:05:25.471594969 142561 hpack_parser.cc:639] Decode: 'grpc-status: 0', elem_interned=1 [1], k_interned=1, v_interned=1
I0307 23:05:25.471599890 142561 parsing.cc:531] HTTP:1:TRL:CLI: grpc-status: 30 '0'
D0307 23:05:25.471605651 142561 transport.h:102] CALL_STACK 0x7f24b400ae70:0x7f24b400ae00 UNREF chttp2
I0307 23:05:25.471610768 142561 ref_counted.h:199] stream_refcount:0x7f24b400ae70 /home/user/grpc/src/core/lib/transport/transport.h:105 unref 2 -> 1 chttp2
I0307 23:05:25.471615616 142561 timer_generic.cc:470] TIMER 0x7f24b400a878: CANCEL pending=true
I0307 23:05:25.471620859 142561 ref_counted.h:103] tcp:0x7f24b4007248 /home/user/grpc/src/core/lib/iomgr/tcp_posix.cc:908 ref 1 -> 2 read
D0307 23:05:25.471625827 142561 closure.h:238] running closure 0x7f24b40073d0: created [/home/user/grpc/src/core/lib/iomgr/tcp_posix.cc:1794]: run [/home/user/grpc/src/core/lib/iomgr/tcp_posix.cc:925]
I0307 23:05:25.471630501 142561 tcp_posix.cc:887] TCP:0x7f24b4007220 got_read: "No Error"
I0307 23:05:25.471634789 142561 tcp_posix.cc:879] TCP:0x7f24b4007220 do_read
I0307 23:05:25.471640344 142561 tcp_posix.cc:541] TCP:0x7f24b4007220 notify_on_read
D0307 23:05:25.471644625 142561 lockfree_event.cc:99] LockfreeEvent::NotifyOn: 0x7f24b4006ee0 curr=(nil) closure=0x7f24b40073d0
D0307 23:05:25.471648982 142561 closure.h:247] closure 0x7f24b40073d0 finished
I0307 23:05:25.471653493 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=5
D0307 23:05:25.471658456 142561 exec_ctx.cc:34] running closure 0x7f24b400a620: created [/home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:2628]: scheduled [/home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:1760]
I0307 23:05:25.471663063 142561 combiner.cc:135] C:0x7f24b4004860 grpc_combiner_execute c=0x7f24b400a620 last=3
D0307 23:05:25.471667467 142561 exec_ctx.cc:43] closure 0x7f24b400a620 finished
D0307 23:05:25.471672418 142561 exec_ctx.cc:34] running closure 0x7f24b400be48: created [/home/user/grpc/src/core/lib/channel/connected_channel.cc:76]: scheduled [/home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:1181]
I0307 23:05:25.471678391 142561 call_combiner.cc:116] ==> CallCombiner::Start() [0x7f24b4000df8] closure=0x7f24b400b440 [/home/user/grpc/src/core/lib/channel/connected_channel.cc:59: recv_initial_metadata_ready] error="No Error"
I0307 23:05:25.471683062 142561 call_combiner.cc:124] size: 0 -> 1
I0307 23:05:25.471687081 142561 call_combiner.cc:132] EXECUTING IMMEDIATELY
D0307 23:05:25.471691113 142561 exec_ctx.cc:43] closure 0x7f24b400be48 finished
D0307 23:05:25.471695930 142561 exec_ctx.cc:34] running closure 0x7f24b400bea8: created [/home/user/grpc/src/core/lib/channel/connected_channel.cc:76]: scheduled [/home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:1181]
I0307 23:05:25.471701770 142561 call_combiner.cc:116] ==> CallCombiner::Start() [0x7f24b4000df8] closure=0x7f24b400b4a8 [/home/user/grpc/src/core/lib/channel/connected_channel.cc:59: recv_message_ready] error="No Error"
I0307 23:05:25.471706357 142561 call_combiner.cc:124] size: 1 -> 2
I0307 23:05:25.471710443 142561 call_combiner.cc:138] QUEUING
D0307 23:05:25.471714593 142561 exec_ctx.cc:43] closure 0x7f24b400bea8 finished
D0307 23:05:25.471719505 142561 exec_ctx.cc:34] running closure 0x7f24b400a758: created [/home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:2810]: scheduled [/home/user/grpc/src/core/lib/iomgr/timer_generic.cc:477]
I0307 23:05:25.471723823 142561 combiner.cc:135] C:0x7f24b4004860 grpc_combiner_execute c=0x7f24b400a758 last=5
D0307 23:05:25.471727962 142561 exec_ctx.cc:43] closure 0x7f24b400a758 finished
D0307 23:05:25.471732795 142561 exec_ctx.cc:34] running closure 0x7f24b400b440: created [/home/user/grpc/src/core/ext/filters/http/message_compress/message_decompress_filter.cc:66]: scheduled [/home/user/grpc/src/core/lib/iomgr/call_combiner.cc:98]
D0307 23:05:25.471738056 142561 closure.h:238] running closure 0x7f24b400b170: created [/home/user/grpc/src/core/ext/filters/http/client/http_client_filter.cc:62]: run [/home/user/grpc/src/core/ext/filters/http/message_compress/message_decompress_filter.cc:165]
D0307 23:05:25.471744322 142561 closure.h:238] running closure 0x7f24b40016a8: created [/home/user/grpc/src/core/lib/surface/call.cc:1811]: run [/home/user/grpc/src/core/ext/filters/http/client/http_client_filter.cc:201]
I0307 23:05:25.471750181 142561 call_combiner.cc:150] ==> CallCombiner::Stop() [0x7f24b4000df8] [/home/user/grpc/src/core/lib/surface/call.cc:1463: recv_initial_metadata_ready]
I0307 23:05:25.471754657 142561 call_combiner.cc:156] size: 2 -> 1
I0307 23:05:25.471758824 142561 call_combiner.cc:163] checking queue
I0307 23:05:25.471763222 142561 call_combiner.cc:177] EXECUTING FROM QUEUE: closure=0x7f24b400b4a8 error="No Error"
D0307 23:05:25.471769042 142561 closure.h:247] closure 0x7f24b40016a8 finished
D0307 23:05:25.471773305 142561 closure.h:247] closure 0x7f24b400b170 finished
D0307 23:05:25.471777258 142561 exec_ctx.cc:43] closure 0x7f24b400b440 finished
D0307 23:05:25.471781980 142561 exec_ctx.cc:34] running closure 0x7f24b400b4a8: created [/home/user/grpc/src/core/ext/filters/http/message_compress/message_decompress_filter.cc:72]: scheduled [/home/user/grpc/src/core/lib/iomgr/call_combiner.cc:98]
D0307 23:05:25.471787408 142561 closure.h:238] running closure 0x7f24b400afd0: created [/home/user/grpc/src/core/ext/filters/message_size/message_size_filter.cc:147]: run [/home/user/grpc/src/core/ext/filters/http/message_compress/message_decompress_filter.cc:291]
D0307 23:05:25.471792554 142561 closure.h:238] running closure 0x7f24b4001660: created [/home/user/grpc/src/core/lib/surface/call.cc:1840]: run [/home/user/grpc/src/core/ext/filters/message_size/message_size_filter.cc:230]
I0307 23:05:25.471799845 142561 call_combiner.cc:150] ==> CallCombiner::Stop() [0x7f24b4000df8] [/home/user/grpc/src/core/lib/surface/call.cc:1369: recv_message_ready]
I0307 23:05:25.471804354 142561 call_combiner.cc:156] size: 1 -> 0
I0307 23:05:25.471808420 142561 call_combiner.cc:184] queue empty
I0307 23:05:25.471813600 142561 combiner.cc:135] C:0x7f24b4004860 grpc_combiner_execute c=0x7f24b4008d30 last=7
D0307 23:05:25.471818093 142561 closure.h:247] closure 0x7f24b4001660 finished
D0307 23:05:25.471822159 142561 closure.h:247] closure 0x7f24b400afd0 finished
D0307 23:05:25.471826195 142561 exec_ctx.cc:43] closure 0x7f24b400b4a8 finished
I0307 23:05:25.471831284 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=1
I0307 23:05:25.471836004 142561 combiner.cc:222] C:0x7f24b4004860 maybe_finish_one n=0x7f24b400a620
I0307 23:05:25.471840456 142561 chttp2_transport.cc:2665] ipv4:
127.0.0.1:50052: Complete BDP ping err="No Error"
I0307 23:05:25.471856272 142561 bdp_estimator.cc:50] bdp[ipv4:127.0.0.1:50052]:complete acc=256 est=65536 dt=0.000706 bw=2.900788Mbs bw_est=0.000000Mbs
I0307 23:05:25.471862413 142561 timer_generic.cc:367] TIMER 0x7f24b400a720: SET 134 now 34 call 0x7f24b400a590[0xb42d8a]
I0307 23:05:25.471869120 142561 timer_generic.cc:404] .. add to shard 3 with queue_deadline_cap=1001 => is_first_timer=true
I0307 23:05:25.471873547 142561 timer_generic.cc:426] .. old shard min_deadline=1002
I0307 23:05:25.471884361 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=9
I0307 23:05:25.471889185 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0307 23:05:25.471893402 142561 combiner.cc:222] C:0x7f24b4004860 maybe_finish_one n=0x7f24b400a758
I0307 23:05:25.471898510 142561 ref_counted.h:103] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:2808 ref 8 -> 9 init keepalive ping
I0307 23:05:25.471903543 142561 timer_generic.cc:367] TIMER 0x7f24b400a878: SET 1034 now 34 call 0x7f24b400a758[0xb432de]
I0307 23:05:25.471908281 142561 timer_generic.cc:404] .. add to shard 17 with queue_deadline_cap=1001 => is_first_timer=false
I0307 23:05:25.471913037 142561 ref_counted.h:199] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:2815 unref 9 -> 8 init keepalive ping
I0307 23:05:25.471917927 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=7
I0307 23:05:25.471922422 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0307 23:05:25.471926595 142561 combiner.cc:222] C:0x7f24b4004860 maybe_finish_one n=0x7f24b4008d30
I0307 23:05:25.471908100 142557 timer_manager.cc:204] wait ended: was_timed:0 kicked:1
I0307 23:05:25.471933158 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=5
D0307 23:05:25.471939502 142561 exec_ctx.cc:34] running closure 0x7f24b400bf08: created [/home/user/grpc/src/core/lib/channel/connected_channel.cc:76]: scheduled [/home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:1181]
I0307 23:05:25.471944496 142561 call_combiner.cc:116] ==> CallCombiner::Start() [0x7f24b4000df8] closure=0x7f24b400b7b8 [/home/user/grpc/src/core/lib/channel/connected_channel.cc:59: recv_trailing_metadata_ready] error="No Error"
I0307 23:05:25.471954503 142561 call_combiner.cc:124] size: 0 -> 1
I0307 23:05:25.471958966 142561 call_combiner.cc:132] EXECUTING IMMEDIATELY
D0307 23:05:25.471963096 142561 exec_ctx.cc:43] closure 0x7f24b400bf08 finished
D0307 23:05:25.471967915 142561 exec_ctx.cc:34] running closure 0x7f24b400b7b8: created [/home/user/grpc/src/core/ext/filters/http/message_compress/message_decompress_filter.cc:76]: scheduled [/home/user/grpc/src/core/lib/iomgr/call_combiner.cc:98]
I0307 23:05:25.471943936 142557 timer_generic.cc:719] TIMER CHECK BEGIN: now=35 next=9223372036854775807 tls_min=0 glob_min=134
D0307 23:05:25.471977010 142561 closure.h:238] running closure 0x7f24b400b1c8: created [/home/user/grpc/src/core/ext/filters/http/client/http_client_filter.cc:65]: run [/home/user/grpc/src/core/ext/filters/http/message_compress/message_decompress_filter.cc:320]
I0307 23:05:25.471978804 142557 timer_generic.cc:741] TIMER CHECK END: r=1; next=134
D0307 23:05:25.471983807 142561 closure.h:238] running closure 0x7f24b400b018: created [/home/user/grpc/src/core/ext/filters/message_size/message_size_filter.cc:150]: run [/home/user/grpc/src/core/ext/filters/http/client/http_client_filter.cc:222]
I0307 23:05:25.471987850 142557 timer_manager.cc:188] sleep for a 99 milliseconds
D0307 23:05:25.471990534 142561 closure.h:238] running closure 0x7f24b400ae10: created [/home/user/grpc/src/core/ext/filters/client_channel/subchannel.cc:251]: run [/home/user/grpc/src/core/ext/filters/message_size/message_size_filter.cc:249]
D0307 23:05:25.471997627 142561 closure.h:238] running closure 0x7f24b4001908: created [/home/user/grpc/src/core/ext/filters/deadline/deadline_filter.cc:148]: run [/home/user/grpc/src/core/ext/filters/client_channel/subchannel.cc:296]
D0307 23:05:25.472003203 142561 closure.h:238] running closure 0x7f24b40016f0: created [/home/user/grpc/src/core/lib/surface/call.cc:1875]: run [/home/user/grpc/src/core/ext/filters/deadline/deadline_filter.cc:136]
I0307 23:05:25.472008491 142561 call_combiner.cc:150] ==> CallCombiner::Stop() [0x7f24b4000df8] [/home/user/grpc/src/core/lib/surface/call.cc:1521: recv_trailing_metadata_ready]
I0307 23:05:25.472012742 142561 call_combiner.cc:156] size: 1 -> 0
I0307 23:05:25.472016712 142561 call_combiner.cc:184] queue empty
D0307 23:05:25.472021064 142561 call.cc:739] set_final_status CLI
D0307 23:05:25.472025162 142561 call.cc:740] "No Error"
D0307 23:05:25.472031249 142561 metadata_batch.cc:90] mdelem UNREF:0x7f24b4008720:3->2: ':authority' = '
127.0.0.1:50052'
D0307 23:05:25.472036751 142561 metadata_batch.cc:90] mdelem UNREF:0xe6405c0:2->1: ':path' = '/ric.CPCC/SendE2SmMsg'
D0307 23:05:25.472041536 142561 metadata_batch.cc:90] mdelem UNREF:0x7f24b4008900:3->2: 'user-agent' = 'grpc-c++/1.31.0 grpc-c/11.0.0 (linux; chttp2)'
I0307 23:05:25.472047313 142561 completion_queue.cc:882] cq_end_op_for_next(cq=0x7f24b4000a00, tag=0x7f24b4001e68, error="No Error", done=0xa29ffb, done_arg=0x7f24b4002240, storage=0x7f24b40022b0)
I0307 23:05:25.472052464 142561 ev_posix.cc:333] (polling-api) pollset_kick(0x7f24b4000b10, (nil))
I0307 23:05:25.472057623 142561 ev_epollex_linux.cc:728] PS:0x7f24b4000b10 kick (nil) tls_pollset=0x7f24b4000b10 tls_worker=0x7f24c69ad490 pollset.root_worker=0x7f24c69ad490
I0307 23:05:25.472061991 142561 ev_epollex_linux.cc:764] PS:0x7f24b4000b10 kicked_any_but_awake
D0307 23:05:25.472066181 142561 closure.h:247] closure 0x7f24b40016f0 finished
D0307 23:05:25.472070253 142561 closure.h:247] closure 0x7f24b4001908 finished
D0307 23:05:25.472074227 142561 closure.h:247] closure 0x7f24b400ae10 finished
D0307 23:05:25.472078206 142561 closure.h:247] closure 0x7f24b400b018 finished
D0307 23:05:25.472082129 142561 closure.h:247] closure 0x7f24b400b1c8 finished
D0307 23:05:25.472086149 142561 exec_ctx.cc:43] closure 0x7f24b400b7b8 finished
I0307 23:05:25.472091430 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=1 time_to_execute_final_list=1
I0307 23:05:25.472095988 142561 combiner.cc:246] C:0x7f24b4004860 execute_final[0] c=0x7f24b4009400
D0307 23:05:25.472104319 142561 flow_control.cc:112] 0x7f24b400a478[0][cli] | t updt sent | trw: 4194304, tlw: 4194304, taw: 4194304, srw: , slw: , saw:
I0307 23:05:25.472110182 142561 chttp2_transport.cc:798] W:0x7f24b4009330 CLIENT [ipv4:
127.0.0.1:50052] state WRITING -> WRITING [begin write in current thread]
I0307 23:05:25.472114716 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.472120156 142561 tcp_posix.cc:1570] DATA: 00 00 08 06 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 04 01 00 '.......................'
I0307 23:05:25.472124700 142561 tcp_posix.cc:1566] WRITE 0x7f24b4007220 (peer=ipv4:
127.0.0.1:50052)
D0307 23:05:25.472129031 142561 tcp_posix.cc:1570] DATA: 00 00 00 '...'
I0307 23:05:25.472159527 142561 tcp_posix.cc:1616] write: "No Error"
D0307 23:05:25.472165269 142561 closure.h:238] running closure 0x7f24b4009490: created [/home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:985]: run [/home/user/grpc/src/core/lib/iomgr/tcp_posix.cc:1618]
I0307 23:05:25.472170000 142561 combiner.cc:135] C:0x7f24b4004860 grpc_combiner_execute c=0x7f24b4009490 last=3
D0307 23:05:25.472174288 142561 closure.h:247] closure 0x7f24b4009490 finished
I0307 23:05:25.472178659 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=5
I0307 23:05:25.472183229 142561 combiner.cc:199] C:0x7f24b4004860 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=1 time_to_execute_final_list=0
I0307 23:05:25.472187598 142561 combiner.cc:222] C:0x7f24b4004860 maybe_finish_one n=0x7f24b4009490
I0307 23:05:25.472192280 142561 chttp2_transport.cc:798] W:0x7f24b4009330 CLIENT [ipv4:
127.0.0.1:50052] state WRITING -> IDLE [finish writing]
I0307 23:05:25.472197741 142561 ref_counted.h:199] chttp2_refcount:0x7f24b4009338 /home/user/grpc/src/core/ext/transport/chttp2/transport/chttp2_transport.cc:1044 unref 8 -> 7 writing
I0307 23:05:25.472202283 142561 combiner.cc:264] C:0x7f24b4004860 finish old_state=3
I0307 23:05:25.472207402 142561 ref_counted.h:199] pollable_refcount:0x7f24b4002b98 /home/user/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1079 unref 2 -> 1 pollset_worker
I0307 23:05:25.472212481 142561 ev_epollex_linux.cc:661] PS:0x7f24b4000b10 (pollable:0x7f24b4002b90) maybe_finish_shutdown sc=(nil) (target:!NULL) rw=(nil) (target:NULL) cpsc=0 (target:0)
I0307 23:05:25.472216955 142561 ev_posix.cc:327] (polling-api) pollset_work(0x7f24b4000b10, 9223372036854775807) end
D0307 23:05:25.472221601 142561 transport.h:102] CALL_STACK 0x7f24b40017c0:0x7f24b4000de0 UNREF completion
I0307 23:05:25.472226463 142561 ref_counted.h:199] stream_refcount:0x7f24b40017c0 /home/user/grpc/src/core/lib/transport/transport.h:105 unref 3 -> 2 completion
I0307 23:05:25.472237192 142561 completion_queue.cc:1298] RETURN_EVENT[0x7f24b4000a00]: OP_COMPLETE: tag:0x7f24b4001e68 OK
I0307 23:05:25.472253017 142561 completion_queue.cc:1682] grpc_completion_queue_destroy(cq=0x7f24b4000a00)
I0307 23:05:25.472257776 142561 completion_queue.cc:1676] grpc_completion_queue_shutdown(cq=0x7f24b4000a00)
I0307 23:05:25.472262684 142561 ev_posix.cc:311] (polling-api) pollset_shutdown(0x7f24b4000b10)
connect: Connection refused
Please help.