c/c++: connection refused after 1st msg successful

246 views
Skip to first unread message

Naveen Rawat

unread,
Mar 8, 2021, 2:35:43 AM3/8/21
to grpc.io
Hi All,

I have:
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:50051
I0307 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:50052
I0307 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:50052
D0307 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:50052
I0307 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:50052
I0307 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.

Thanks and Regards
Naveen Rawat
Reply all
Reply to author
Forward
0 new messages