[c++] channel.WaitForConnected assertion failed while trying for mTLS connection
105 views
Skip to first unread message
Manish Khandelwal
Sep 13, 2022, 1:21:02 PM9/13/22
to grpc.io
Hi All,
Created a custom channel and populated SslCredentials with ca cert, client cert and client key. Below assertion is observed once channel.WaitForConnected is called.
I0913 17:07:25.303815824 17165 init.cc:165] grpc_init(void)
I0913 17:07:25.303940980 17165 init.cc:212] grpc_shutdown(void)
I0913 17:07:25.304056078 17165 init.cc:212] grpc_shutdown(void)
I0913 17:07:25.304331812 17165 init.cc:165] grpc_init(void)
I0913 17:07:25.304439088 17165 secure_channel_create.cc:201] grpc_secure_channel_create(creds=0x7fa6ec010d80, target=10.220.6.50:50058, args=0x7fa705760590, reserved=(nil))
I0913 17:07:25.304579888 17165 init.cc:165] grpc_init(void)
I0913 17:07:25.305033297 17165 ev_posix.cc:352] (polling-api) pollset_set_create(0x7fa6ec00fc70)
I0913 17:07:25.305103697 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 1 -> 2
I0913 17:07:25.305229970 17165 client_channel.cc:1402] chand=0x7fa6ec00fa08: creating client_channel for channel stack 0x7fa6ec00f958
I0913 17:07:25.305320485 17165 ev_posix.cc:304] (polling-api) pollset_init(0x7fa6ec011c70)
I0913 17:07:25.305436421 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:796 ref 1 -> 2 pollset
I0913 17:07:25.305555151 17165 timer_generic.cc:364] TIMER 0x7fa6ec00e4d0: SET 5003 now 3 call 0x7fa6ec00e508[0x7fa70b4823cd]
I0913 17:07:25.305665221 17165 timer_generic.cc:401] .. add to shard 0 with queue_deadline_cap=0 => is_first_timer=false
I0913 17:07:25.305775850 17165 ev_posix.cc:364] (polling-api) pollset_set_add_pollset(0x7fa6ec00fc70, 0x7fa6ec011c70)
I0913 17:07:25.305887875 17165 ev_epollex_linux.cc:1450] PSS:0x7fa6ec00fc70: add pollset 0x7fa6ec011c70
I0913 17:07:25.306001577 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1241 ref 2 -> 3 pollset_as_multipollable
I0913 17:07:25.306742453 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1244 unref 3 -> 2 pollset
I0913 17:07:25.306846936 17165 ev_epollex_linux.cc:569] (fd-trace) Pollable_create: created epfd: 16 (type: 0)
I0913 17:07:25.306956168 17165 ev_epollex_linux.cc:1249] PS:0x7fa6ec011c70 active pollable transition from empty to multi
I0913 17:07:25.307059253 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec011dc8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1280 ref 1 -> 2 pollset_set
I0913 17:07:25.307174631 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1281 unref 2 -> 1 pollset_as_multipollable
I0913 17:07:25.307288891 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec011dc8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1478 unref 2 -> 1 pollset_set
I0913 17:07:25.307496739 17165 init.cc:165] grpc_init(void)
I0913 17:07:25.334856920 17165 init.cc:212] grpc_shutdown(void)
I0913 17:07:25.335164222 17165 channel_connectivity.cc:43] grpc_channel_check_connectivity_state(channel=0x7fa6ec00f8c0, try_to_connect=1)
I0913 17:07:25.335212831 17165 connectivity_state.cc:174] ConnectivityStateTracker client_channel[0x7fa6ec00fac8]: get current state: IDLE
I0913 17:07:25.335308933 17165 ref_counted.h:133] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:88 ref 1 -> 2 TryToConnect
I0913 17:07:25.335442749 17165 work_serializer.cc:55] WorkSerializer::Run() 0x7fa6ec00bf80 Scheduling callback [/home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/client_channel.cc:1926]
I0913 17:07:25.335517898 17165 work_serializer.cc:65] Executing immediately
I0913 17:07:25.335660933 17165 ref_counted.h:133] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:88 ref 2 -> 3 ClientChannelControlHelper
I0913 17:07:25.335822965 17165 ev_posix.cc:352] (polling-api) pollset_set_create(0x7fa6ec0105f0)
I0913 17:07:25.335905657 17165 ref_counted.h:92] lb_policy_refcount:0x7fa6ec001688 ref 1 -> 2
I0913 17:07:25.336194241 17165 ev_posix.cc:352] (polling-api) pollset_set_create(0x7fa6ec010670)
I0913 17:07:25.336355155 17165 ev_posix.cc:377] (polling-api) pollset_set_add_pollset_set(0x7fa6ec010670, 0x7fa6ec0105f0)
I0913 17:07:25.336457682 17165 ev_epollex_linux.cc:1487] PSS: merge (0x7fa6ec010670, 0x7fa6ec0105f0)
I0913 17:07:25.307856561 17166 executor.cc:224] EXECUTOR (default-executor) [0]: step (sub_depth=0)
I0913 17:07:25.307920536 17167 executor.cc:224] EXECUTOR (resolver-executor) [0]: step (sub_depth=0)
I0913 17:07:25.336576133 17165 ev_epollex_linux.cc:1521] PSS: parent 0x7fa6ec010670 to 0x7fa6ec0105f0
I0913 17:07:25.337203867 17165 resolving_lb_policy.cc:163] resolving_lb=0x7fa6ec001680: starting name resolution
I0913 17:07:25.337258063 17165 ref_counted.h:92] lb_policy_refcount:0x7fa6ec001688 ref 2 -> 3
I0913 17:07:25.337429314 17165 client_channel.cc:1306] chand=0x7fa6ec00fa08: update: state=CONNECTING picker=0x7fa6ec0127e0
I0913 17:07:25.337497200 17165 connectivity_state.cc:152] ConnectivityStateTracker client_channel[0x7fa6ec00fac8]: IDLE -> CONNECTING (helper)
I0913 17:07:25.337667613 17165 ref_counted.h:103] resolver_refcount:0x7fa6ec0129d8 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc:434 ref 1 -> 2 dns-resolving
I0913 17:07:25.338277467 17165 grpc_ares_wrapper.cc:128] (c-ares resolver) request:0x7fa6ec012b80 c-ares address sorting: input[0]=10.220.6.50:50058
I0913 17:07:25.338486711 17165 grpc_ares_wrapper.cc:128] (c-ares resolver) request:0x7fa6ec012b80 c-ares address sorting: output[0]=10.220.6.50:50058
I0913 17:07:25.338643994 17165 ev_posix.cc:377] (polling-api) pollset_set_add_pollset_set(0x7fa6ec0105f0, 0x7fa6ec00fc70)
I0913 17:07:25.338706851 17165 ev_epollex_linux.cc:1487] PSS: merge (0x7fa6ec0105f0, 0x7fa6ec00fc70)
I0913 17:07:25.338813848 17165 ev_epollex_linux.cc:1521] PSS: parent 0x7fa6ec0105f0 to 0x7fa6ec00fc70
I0913 17:07:25.339155232 17165 client_channel.cc:1581] chand=0x7fa6ec00fa08: creat[4173222.493507] serial8250: too much work for irq4
ed resolving_lb_policy=0x7fa6ec001680
I0913 17:07:25.339274241 17165 ref_counted.h:199] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:105 unref 3 -> 2 TryToConnect
I0913 17:07:25.339380121 17165 work_serializer.cc:102] WorkSerializer::DrainQueue() 0x7fa6ec00bf80
I0913 17:07:25.339499410 17165 work_serializer.cc:117] Queue Drained
I0913 17:07:25.339617022 17165 work_serializer.cc:55] WorkSerializer::Run() 0x7fa6ec00bf80 Scheduling callback [/home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc:327]
I0913 17:07:25.339708934 17165 work_serializer.cc:65] Executing immediately
I0913 17:07:25.339876553 17165 resolving_lb_policy.cc:293] resolving_lb=0x7fa6ec001680: got resolver result
I0913 17:07:25.340316832 17165 ref_counted.h:92] lb_policy_refcount:0x7fa6ec001688 ref 3 -> 4
I0913 17:07:25.340460426 17165 ev_posix.cc:352] (polling-api) pollset_set_create(0x7fa6ec012e20)
I0913 17:07:25.340571334 17165 resolving_lb_policy.cc:258] resolving_lb=0x7fa6ec001680: created new LB policy 0x7fa6ec012b80
I0913 17:07:25.340654584 17165 ev_posix.cc:377] (polling-api) pollset_set_add_pollset_set(0x7fa6ec012e20, 0x7fa6ec0105f0)
I0913 17:07:25.380510767 17165 ev_epollex_linux.cc:1487] PSS: merge (0x7fa6ec012e20, 0x7fa6ec0105f0)
I0913 17:07:25.380744037 17165 ev_epollex_linux.cc:1521] PSS: parent 0x7fa6ec012e20 to 0x7fa6ec00fc70
I0913 17:07:25.380469980 17168 timer_generic.cc:716] TIMER CHECK BEGIN: now=78 next=9223372036854775807 tls_min=0 glob_min=0
I0913 17:07:25.385597447 17168 timer_generic.cc:611] .. shard[0]->min_deadline = 1
I0913 17:07:25.386931416 17168 timer_generic.cc:534] .. shard[0]: heap_empty=true
I0913 17:07:25.391432826 17168 timer_generic.cc:509] .. shard[0]->queue_deadline_cap --> 1078
I0913 17:07:25.391458807 17168 timer_generic.cc:574] .. shard[0] popped 0
I0913 17:07:25.392370096 17168 timer_generic.cc:629] .. result --> 1, shard[0]->min_deadline 1 --> 1079, now=78
I0913 17:07:25.393245905 17168 timer_generic.cc:534] .. shard[1]: heap_empty=true
I0913 17:07:25.394042375 17168 timer_generic.cc:509] .. shard[1]->queue_deadline_cap --> 1078
I0913 17:07:25.394793309 17168 timer_generic.cc:574] .. shard[1] popped 0
I0913 17:07:25.395162909 17168 timer_generic.cc:629] .. result --> 1, shard[1]->min_deadline 1 --> 1079, now=78
I0913 17:07:25.384528317 17165 resolving_lb_policy.cc:240] resolving_lb=0x7fa6ec001680: Updating child policy 0x7fa6ec012b80
I0913 17:07:25.396767303 17165 child_policy_handler.cc:211] [child_policy_handler 0x7fa6ec012b80] creating new child policy pick_first
I0913 17:07:25.397911862 17165 ref_counted.h:103] lb_policy_refcount:0x7fa6ec012b88 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/lb_policy/child_policy_handler.cc:258 ref 1 -> 2 Helper
I0913 17:07:25.397978351 17165 ev_posix.cc:352] (polling-api) pollset_set_create(0x7fa6ec0130c0)
I0913 17:07:25.398036179 17165 pick_first.cc:146] Pick First 0x7fa6ec010af0 created.
I0913 17:07:25.399215100 17165 child_policy_handler.cc:272] [child_policy_handler 0x7fa6ec012b80] created new LB policy "pick_first" (0x7fa6ec010af0)
I0913 17:07:25.399387189 17165 ev_posix.cc:377] (polling-api) pollset_set_add_pollset_set(0x7fa6ec0130c0, 0x7fa6ec012e20)
I0913 17:07:25.399397525 17165 ev_epollex_linux.cc:1487] PSS: merge (0x7fa6ec0130c0, 0x7fa6ec012e20)
I0913 17:07:25.399502008 17165 ev_epollex_linux.cc:1521] PSS: parent 0x7fa6ec0130c0 to 0x7fa6ec00fc70
I0913 17:07:25.399616268 17165 child_policy_handler.cc:230] [child_policy_handler 0x7fa6ec012b80] updating child policy 0x7fa6ec010af0
I0913 17:07:25.399732763 17165 pick_first.cc:265] Pick First 0x7fa6ec010af0 received update with 1 addresses
I0913 17:07:25.399861830 17165 subchannel_list.h:361] [pick_first 0x7fa6ec010af0] Creating subchannel list 0x7fa6ec00ed40 for 1 subchannels
I0913 17:07:25.400047329 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 2 -> 3
I0913 17:07:25.400099011 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 3 -> 4
I0913 17:07:25.407755012 17168 timer_generic.cc:534] .. shard[2]: heap_empty=true
I0913 17:07:25.407776244 17168 timer_generic.cc:509] .. shard[2]->queue_deadline_cap --> 1078
I0913 17:07:25.407922352 17168 timer_generic.cc:574] .. shard[2] popped 0
I0913 17:07:25.408062314 17168 timer_generic.cc:629] .. result --> 1, shard[2]->min_deadline 1 --> 1079, now=78
I0913 17:07:25.408211215 17168 timer_generic.cc:534] .. shard[3]: heap_empty=true
I0913 17:07:25.408946504 17168 timer_generic.cc:509] .. shard[3]->queue_deadline_cap --> 1078
I0913 17:07:25.409368625 17168 timer_generic.cc:574] .. shard[3] popped 0
I0913 17:07:25.409511939 17168 timer_generic.cc:629] .. result --> 1, shard[3]->min_deadline 1 --> 1079, now=78
I0913 17:07:25.409652739 17168 timer_generic.cc:739] TIMER CHECK END: r=1; next=1079
I0913 17:07:25.409791304 17168 timer_manager.cc:188] sleep for a 1001 milliseconds
I0913 17:07:25.410554530 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 4 -> 5
I0913 17:07:25.410646720 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 5 -> 6
I0913 17:07:25.410764054 17165 ref_counted.h:103] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:92 ref 1 -> 2 connector_arg_copy
I0913 17:07:25.410875800 17165 ref_counted.h:199] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/ext/transport/chttp2/client/secure/secure_channel_create.cc:144 unref 2 -> 1 lb_channel_create
I0913 17:07:25.410993133 17165 ref_counted.h:183] subchannel_pool:0x7fa6ec00b9c8 unref 6 -> 5
I0913 17:07:25.411102086 17165 ref_counted.h:183] subchannel_pool:0x7fa6ec00b9c8 unref 5 -> 4
I0913 17:07:25.411285908 17165 ref_counted.h:103] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:92 ref 1 -> 2 connector_arg_copy
I0913 17:07:25.411333959 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 4 -> 5
I0913 17:07:25.411511914 17165 ev_posix.cc:352] (polling-api) pollset_set_create(0x7fa6ec03d640)
I0913 17:07:25.411604943 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 5 -> 6
I0913 17:07:25.411669755 17165 ref_counted.h:103] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:92 ref 2 -> 3 connector_arg_copy
I0913 17:07:25.413236714 17165 ref_counted.h:103] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:92 ref 3 -> 4 connector_arg_copy
I0913 17:07:25.413338403 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 6 -> 7
I0913 17:07:25.413450429 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 7 -> 8
I0913 17:07:25.413561895 17165 ref_counted.h:183] subchannel_pool:0x7fa6ec00b9c8 unref 8 -> 7
I0913 17:07:25.413666937 17165 ref_counted.h:199] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:86 unref 4 -> 3 connector_arg_destroy
I0913 17:07:25.413773375 17165 ref_counted.h:183] subchannel_pool:0x7fa6ec00b9c8 unref 7 -> 6
I0913 17:07:25.414899775 17165 client_channel.cc:868] chand=0x7fa6ec00fa08: creating subchannel wrapper 0x7fa6ec03da30 for subchannel 0x7fa6ec033280
I0913 17:07:25.414985540 17165 ref_counted.h:133] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:88 ref 2 -> 3 SubchannelWrapper
I0913 17:07:25.415218810 17165 subchannel_list.h:404] [pick_first 0x7fa6ec010af0] subchannel list 0x7fa6ec00ed40 index 0: Created subchannel 0x7fa6ec03da30 for address uri ipv4:10.220.6.50:50058
I0913 17:07:25.415344245 17165 ref_counted.h:103] lb_policy_refcount:0x7fa6ec010af8 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc:93 ref 1 -> 2 subchannel_list
I0913 17:07:25.415441464 17165 subchannel_list.h:308] [pick_first 0x7fa6ec010af0] subchannel list 0x7fa6ec00ed40 index 0 of 1 (subchannel 0x7fa6ec03da30): starting watch (from IDLE)
I0913 17:07:25.415542035 17165 ref_counted.h:103] pick_first:0x7fa6ec00ed48 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/lb_policy/subchannel_list.h:317 ref 1 -> 2 Watcher
I0913 17:07:25.415705464 17165 ref_counted.h:103] client_channel_routing:0x7fa6ec03da38 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/client_channel.cc:921 ref 1 -> 2 WatcherWrapper
I0913 17:07:25.443438598 17165 ev_posix.cc:377] (polling-api) pollset_set_add_pollset_set(0x7fa6ec03d640, 0x7fa6ec0130c0)
I0913 17:07:25.443463740 17165 ev_epollex_linux.cc:1487] PSS: merge (0x7fa6ec03d640, 0x7fa6ec0130c0)
I0913 17:07:25.443569620 17165 ev_epollex_linux.cc:1521] PSS: parent 0x7fa6ec03d640 to 0x7fa6ec00fc70
I0913 17:07:25.443969391 17165 socket_utils_common_posix.cc:320] Enabling TCP_USER_TIMEOUT with a timeout of 10000 ms
I0913 17:07:25.445888071 17165 ev_posix.cc:254] (polling-api) fd_create(18, tcp-client:ipv4:10.220.6.50:50058, 1)
I0913 17:07:25.446187550 17165 ev_posix.cc:255] (fd-trace) fd_create(18, tcp-client:ipv4:10.220.6.50:50058, 1)
I0913 17:07:25.446316058 17165 ev_posix.cc:394] (polling-api) pollset_set_add_fd(0x7fa6ec03d640, 18)
I0913 17:07:25.446402382 17165 ev_epollex_linux.cc:1353] PSS:0x7fa6ec03d640: add fd 0x7fa6ec03e720 (18)
I0913 17:07:25.446514687 17165 ev_epollex_linux.cc:616] add fd 0x7fa6ec03e720 (18) to pollable 0x7fa6ec011dc0
I0913 17:07:25.446658560 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 6 -> 7
I0913 17:07:25.446745163 17165 ref_counted.h:103] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:92 ref 3 -> 4 connector_arg_copy
I0913 17:07:25.446854395 17165 tcp_client_posix.c[4173222.577355] serial8250: too much work for irq4
c:329] CLIENT_CONNECT: ipv4:10.220.6.50:50058: asynchronously connecting fd 0x7fa6ec03e720
I0913 17:07:25.446979271 17165 timer_generic.cc:364] TIMER 0x7fa6ec012c20: SET 20036 now 36 call 0x7fa6ec012c58[0x7fa70b61f33b]
I0913 17:07:25.447319258 17165 timer_generic.cc:401] .. add to shard 0 with queue_deadline_cap=1078 => is_first_timer=false
I0913 17:07:25.447601138 17165 ref_counted.h:199] resolver_refcount:0x7fa6ec0129d8 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc:396 unref 2 -> 1 dns-resolving
I0913 17:07:25.447646674 17165 work_serializer.cc:102] WorkSerializer::DrainQueue() 0x7fa6ec00bf80
I0913 17:07:25.447753112 17165 work_serializer.cc:117] Queue Drained
I0913 17:07:25.447868211 17165 client_channel.cc:1033] chand=0x7fa6ec00fa08: connectivity change for subchannel wrapper 0x7fa6ec03da30 subchannel 0x7fa6ec033280; hopping into work_serializer
I0913 17:07:25.447979119 17165 work_serializer.cc:55] WorkSerializer::Run() 0x7fa6ec00bf80 Scheduling callback [/home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/client_channel.cc:1044]
I0913 17:07:25.448078573 17165 work_serializer.cc:65] Executing immediately
I0913 17:07:25.448185570 17165 client_channel.cc:1066] chand=0x7fa6ec00fa08: processing connectivity change in work serializer for subchannel wrapper 0x7fa6ec03da30 subchannel 0x7fa6ec033280 watcher=0x7fa6ec03ba20
I0913 17:07:25.448334751 17165 subchannel_list.h:241] [pick_first 0x7fa6ec010af0] subchannel list 0x7fa6ec00ed40 index 0 of 1 (subchannel 0x7fa6ec03da30): connectivity changed: state=CONNECTING, shutting_down=0, pending_watcher=0x7fa6ec03ba20
I0913 17:07:25.448437557 17165 ref_counted.h:103] lb_policy_refcount:0x7fa6ec010af8 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc:410 ref 2 -> 3 QueuePicker
I0913 17:07:25.448549582 17165 client_channel.cc:1306] chand=0x7fa6ec00fa08: update: state=CONNECTING picker=0x7fa6ec013ac0
I0913 17:07:25.448671944 17165 ref_counted.h:199] lb_policy_refcount:0x7fa6ec001688 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/lb_policy.h:375 unref 4 -> 3 QueuePicker
I0913 17:07:25.448745697 17165 work_serializer.cc:102] WorkSerializer::DrainQueue() 0x7fa6ec00bf80
I0913 17:07:25.449227881 17165 work_serializer.cc:117] Queue Drained
I0913 17:07:25.449335436 17165 init.cc:165] grpc_init(void)
I0913 17:07:25.449470928 17165 completion_queue.cc:526] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
I0913 17:07:25.449589100 17165 ev_posix.cc:304] (polling-api) pollset_init(0x7fa6ec03f298)
I0913 17:07:25.449735767 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:796 ref 1 -> 2 pollset
I0913 17:07:25.480508672 17165 channel_connectivity.cc:232] grpc_channel_watch_connectivity_state(channel=0x7fa6ec00f8c0, last_observed_state=0, deadline=gpr_timespec { tv_sec: 1663089445, tv_nsec: 335137682, clock_type: 1 }, cq=0x7fa6ec03f190, tag=0x7fa6ec013a50)
I0913 17:07:25.480579072 17165 ref_counted.h:133] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:88 ref 3 -> 4 watch_channel_connectivity
I0913 17:07:25.480707859 17165 ev_posix.cc:364] (polling-api) pollset_set_add_pollset(0x7fa6ec00fc70, 0x7fa6ec03f298)
I0913 17:07:25.480900901 17165 ev_epollex_linux.cc:1450] PSS:0x7fa6ec00fc70: add pollset 0x7fa6ec03f298
I0913 17:07:25.481010971 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1241 ref 2 -> 3 pollset_as_multipollable
I0913 17:07:25.481119085 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1244 unref 3 -> 2 pollset
I0913 17:07:25.481230272 17165 ev_epollex_linux.cc:569] (fd-trace) Pollable_create: created epfd: 19 (type: 0)
I0913 17:07:25.481345650 17165 ev_epollex_linux.cc:1249] PS:0x7fa6ec03f298 active pollable transition from empty to multi
I0913 17:07:25.481428063 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec03f638 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1280 ref 1 -> 2 pollset_set
I0913 17:07:25.481534501 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1281 unref 2 -> 1 pollset_as_multipollable
I0913 17:07:25.481642056 17165 ev_epollex_linux.cc:616] add fd 0x7fa6ec03e720 (18) to pollable 0x7fa6ec03f630
I0913 17:07:25.481755758 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec03f638 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1478 unref 2 -> 1 pollset_set
I0913 17:07:25.481859402 17165 ref_counted.h:133] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:88 ref 4 -> 5 ExternalConnectivityWatcher
I0913 17:07:25.482000482 17165 work_serializer.cc:55] WorkSerializer::Run() 0x7fa6ec00bf80 Scheduling callback [/home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/client_channel.cc:1155]
I0913 17:07:25.482080380 17165 work_serializer.cc:65] Executing immediately
I0913 17:07:25.482211402 17165 timer_generic.cc:364] TIMER 0x7fa6ec03f418: SET 600034 now 180 call 0x7fa6ec03f388[0x7fa70b482e3b]
I0913 17:07:25.482299402 17165 timer_generic.cc:401] .. add to shard 0 with queue_deadline_cap=1078 => is_first_timer=false
I0913 17:07:25.482430983 17165 connectivity_state.cc:118] ConnectivityStateTracker client_channel[0x7fa6ec00fac8]: add watcher 0x7fa6ec03f130
I0913 17:07:25.482516190 17165 connectivity_state.cc:124] ConnectivityStateTracker client_channel[0x7fa6ec00fac8]: notifying watcher 0x7fa6ec03f130: IDLE -> CONNECTING
I0913 17:07:25.482647771 17165 work_serializer.cc:55] WorkSerializer::Run() 0x7fa6ec00bf80 Scheduling callback [/home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/client_channel.cc:1175]
I0913 17:07:25.482732139 17165 work_serializer.cc:76] Scheduling on queue : item 0x7fa6ec03ec80
I0913 17:07:25.482900317 17165 work_serializer.cc:102] WorkSerializer::DrainQueue() 0x7fa6ec00bf80
I0913 17:07:25.482950044 17165 work_serializer.cc:134] Running item 0x7fa6ec03ec80 : callback scheduled at [/home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/client_channel.cc:1175]
I0913 17:07:25.483054526 17165 connectivity_state.cc:141] ConnectivityStateTracker client_channel[0x7fa6ec00fac8]: remove watcher 0x7fa6ec03f130
I0913 17:07:25.483184711 17165 ev_posix.cc:371] (polling-api) pollset_set_del_pollset(0x7fa6ec00fc70, 0x7fa6ec03f298)
I0913 17:07:25.483269917 17165 ev_epollex_linux.cc:1398] PSS:0x7fa6ec00fc70: del pollset 0x7fa6ec03f298
I0913 17:07:25.483379707 17165 ev_epollex_linux.cc:664] PS:0x7fa6ec03f298 (pollable:0x7fa6ec03f630) maybe_finish_shutdown sc=(nil) (target:!NULL) rw=(nil) (target:NULL) cpsc=0 (target:0)
I0913 17:07:25.511424054 17165 ref_counted.h:199] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:105 unref 5 -> 4 ExternalConnectivityWatcher
I0913 17:07:25.511541387 17165 work_serializer.cc:102] WorkSerializer::DrainQueue() 0x7fa6ec00bf80
I0913 17:07:25.511615978 17165 work_serializer.cc:117] Queue Drained
I0913 17:07:25.511634695 17165 timer_generic.cc:467] TIMER 0x7fa6ec03f418: CANCEL pending=true
I0913 17:07:25.511748397 17165 completion_queue.cc:707] cq_end_op_for_next(cq=0x7fa6ec03f190, tag=0x7fa6ec013a50, error="No Error", done=0x7fa70b482a2e, done_arg=0x7fa6ec03f310, storage=0x7fa6ec03f460)
I0913 17:07:25.511850644 17165 ev_posix.cc:331] (polling-api) pollset_kick(0x7fa6ec03f298, (nil))
I0913 17:07:25.511959597 1[4173222.646290] serial8250: too much work for irq4
7165 ev_epollex_linux.cc:731] PS:0x7fa6ec03f298 kick (nil) tls_pollset=(nil) tls_worker=(nil) pollset.root_worker=(nil)
I0913 17:07:25.512064638 17165 ev_epollex_linux.cc:741] PS:0x7fa6ec03f298 kicked_any_without_poller
I0913 17:07:25.512201248 17165 completion_queue.cc:982] grpc_completion_queue_next(cq=0x7fa6ec03f190, deadline=gpr_timespec { tv_sec: 9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))
I0913 17:07:25.512371381 17165 ref_counted.h:199] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:105 unref 4 -> 3 watch_channel_connectivity
I0913 17:07:25.512474746 17165 completion_queue.cc:1083] RETURN_EVENT[0x7fa6ec03f190]: OP_COMPLETE: tag:0x7fa6ec013a50 OK
I0913 17:07:25.512537882 17165 completion_queue.cc:1425] grpc_completion_queue_destroy(cq=0x7fa6ec03f190)
I0913 17:07:25.512637895 17165 completion_queue.cc:1419] grpc_completion_queue_shutdown(cq=0x7fa6ec03f190)
I0913 17:07:25.512750200 17165 ev_posix.cc:309] (polling-api) pollset_shutdown(0x7fa6ec03f298)
I0913 17:07:25.512975648 17165 ev_epollex_linux.cc:664] PS:0x7fa6ec03f298 (pollable:0x7fa6ec03f630) maybe_finish_shutdown sc=0x7fa6ec03f1d0 (target:!NULL) rw=(nil) (target:NULL) cpsc=0 (target:0)
I0913 17:07:25.513091305 17165 ev_posix.cc:314] (polling-api) pollset_destroy(0x7fa6ec03f298)
I0913 17:07:25.513200816 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec03f638 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:927 unref 1 -> 0 pollset
I0913 17:07:25.513311165 17165 ev_epollex_linux.cc:149] (fd-trace) pollable_unref: Closing epfd: 19
I0913 17:07:25.513445540 17165 init.cc:212] grpc_shutdown(void)
I0913 17:07:25.513544994 17165 channel_connectivity.cc:43] grpc_channel_check_connectivity_state(channel=0x7fa6ec00f8c0, try_to_connect=1)
I0913 17:07:25.513658695 17165 connectivity_state.cc:174] ConnectivityStateTracker client_channel[0x7fa6ec00fac8]: get current state: CONNECTING
I0913 17:07:25.513767368 17165 init.cc:165] grpc_init(void)
I0913 17:07:25.513882746 17165 completion_queue.cc:526] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
I0913 17:07:25.513992257 17165 ev_posix.cc:304] (polling-api) pollset_init(0x7fa6ec03f738)
I0913 17:07:25.514111267 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:796 ref 1 -> 2 pollset
I0913 17:07:25.514229997 17165 channel_connectivity.cc:232] grpc_channel_watch_connectivity_state(channel=0x7fa6ec00f8c0, last_observed_state=1, deadline=gpr_timespec { tv_sec: 1663089445, tv_nsec: 335137682, clock_type: 1 }, cq=0x7fa6ec03f630, tag=0x7fa6ec013b20)
I0913 17:07:25.514340067 17165 ref_counted.h:133] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:88 ref 3 -> 4 watch_channel_connectivity
I0913 17:07:25.514452930 17165 ev_posix.cc:364] (polling-api) pollset_set_add_pollset(0x7fa6ec00fc70, 0x7fa6ec03f738)
I0913 17:07:25.514564397 17165 ev_epollex_linux.cc:1450] PSS:0x7fa6ec00fc70: add pollset 0x7fa6ec03f738
I0913 17:07:25.514675584 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1241 ref 2 -> 3 pollset_as_multipollable
I0913 17:07:25.542637797 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1244 unref 3 -> 2 pollset
I0913 17:07:25.542729429 17165 ev_epollex_linux.cc:569] (fd-trace) Pollable_create: created epfd: 19 (type: 0)
I0913 17:07:25.542869950 17165 ev_epollex_linux.cc:1249] PS:0x7fa6ec03f738 active pollable transition from empty to multi
I0913 17:07:25.542934483 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec03fdd8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1280 ref 1 -> 2 pollset_set
I0913 17:07:25.543148477 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1281 unref 2 -> 1 pollset_as_multipollable
I0913 17:07:25.543274750 17165 ev_epollex_linux.cc:616] add fd 0x7fa6ec03e720 (18) to pollable 0x7fa6ec03fdd0
I0913 17:07:25.543391245 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec03fdd8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1478 unref 2 -> 1 pollset_set
I0913 17:07:25.543491817 17165 ref_counted.h:133] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:88 ref 4 -> 5 ExternalConnectivityWatcher
I0913 17:07:25.543632617 17165 work_serializer.cc:55] WorkSerializer::Run() 0x7fa6ec00bf80 Scheduling callback [/home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/client_channel.cc:1155]
I0913 17:07:25.543722572 17165 work_serializer.cc:65] Executing immediately
I0913 17:07:25.543974280 17165 timer_generic.cc:364] TIMER 0x7fa6ec03f418: SET 600034 now 242 call 0x7fa6ec03f388[0x7fa70b482e3b]
I0913 17:07:25.544049988 17165 timer_generic.cc:401] .. add to shard 0 with queue_deadline_cap=1078 => is_first_timer=false
I0913 17:07:25.544172909 17165 connectivity_state.cc:118] ConnectivityStateTracker client_channel[0x7fa6ec00fac8]: add watcher 0x7fa6ec03f5d0
I0913 17:07:25.544299461 17165 work_serializer.cc:102] WorkSerializer::DrainQueue() 0x7fa6ec00bf80
I0913 17:07:25.544386902 17165 work_serializer.cc:117] Queue Drained
I0913 17:07:25.544504236 17165 completion_queue.cc:982] grpc_completion_queue_next(cq=0x7fa6ec03f630, deadline=gpr_timespec { tv_sec: 9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))
I0913 17:07:25.544651741 17165 ev_posix.cc:322] (polling-api) pollset_work(0x7fa6ec03f738, 9223372036854775807) begin
I0913 17:07:25.544765442 17165 ev_epollex_linux.cc:1120] PS:0x7fa6ec03f738 work hdl=(nil) worker=0x7fa7057602f0 now=243 deadline=9223372036854775807 kwp=0 pollable=0x7fa6ec03fdd0
I0913 17:07:25.544948147 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec03fdd8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1018 ref 1 -> 2 pollset_worker
I0913 17:07:25.545075537 17165 ev_epollex_linux.cc:938] POLLABLE:0x7fa6ec03fdd0[type=pollset epfd=19 wakeup=20] poll for -1ms
I0913 17:07:25.571483922 17165 ev_epollex_linux.cc:957] POLLABLE:0x7fa6ec03fdd0 got 1 events
I0913 17:07:25.571542309 17165 ev_epollex_linux.cc:905] PS:0x7fa6ec03f738 got fd 0x7fa6ec03e720: cancel=0 read=0 write=1
I0913 17:07:25.571681153 17165 tcp_client_posix.cc:142] CLIENT_CONNECT: ipv4:10.220.6.50:50058: on_writable: error="No Error"
I0913 17:07:25.571790944 17165 timer_generic.cc:467] TIMER 0x7fa6ec012c20: CANCEL pending=true
I0913 17:07:25.571914423 17165 ev_posix.cc:400] (polling-api) pollset_set_del_fd(0x7fa6ec03d640, 18)
I0913 17:07:25.572013319 17165 ev_epollex_linux.cc:1377] PSS:0x7fa6ec03d640: del fd 0x7fa6ec03e720
I0913 17:07:25.572390182 17165 combiner.cc:61] C:0x7fa6ec03f4f0 create
I0913 17:07:25.572544950 17165 ref_counted.h:103] tcp:0x7fa6ec0403d8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/tcp_posix.cc:1823 ref 1 -> 2 error-tracking
I0913 17:07:25.572643566 17165 tcp_client_posix.cc:105] CLIENT_CONNECT: ipv4:10.220.6.50:50058: on_alarm: error="Cancelled"
I0913 17:07:25.572758665 17165 ref_counted.h:183] subchannel_pool:0x7fa6ec00b9c8 unref 7 -> 6
I0913 17:07:25.572988862 17165 ref_counted.h:199] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:86 unref 4 -> 3 connector_arg_destroy
I0913 17:07:25.573173801 17165 handshaker.cc:99] handshake_manager 0x7fa6ec038720: adding handshaker http_connect [0x7fa6ec040f40] at index 0
I0913 17:07:25.573545916 17165 ssl_transport_security.cc:220] HANDSHAKE START - before SSL initialization - PINIT
I0913 17:07:25.573650398 17165 ssl_transport_security.cc:220] LOOP - before SSL initialization - PINIT
I0913 17:07:25.573789243 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS write client hello - TWCH
I0913 17:07:25.573852379 17165 ref_counted.h:103] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/transport/security_handshaker.cc:113 ref 3 -> 4 handshake
I0913 17:07:25.573949878 17165 handshaker.cc:99] handshake_manager 0x7fa6ec038720: adding handshaker security [0x7fa6ec05c6e0] at index 1
I0913 17:07:25.574059668 17165 ev_posix.cc:394] (polling-api) pollset_set_add_fd(0x7fa6ec03d640, 18)
I0913 17:07:25.574176722 17165 ev_epollex_linux.cc:1353] PSS:0x7fa6ec03d640: add fd 0x7fa6ec03e720 (18)
I0913 17:07:25.574290144 17165 ev_epollex_linux.cc:616] add fd 0x7fa6ec03e720 (18) to pollable 0x7fa6ec011dc0
I0913 17:07:25.574407198 17165 ev_epollex_linux.cc:616] add fd 0x7fa6ec03e720 (18) to pollable 0x7fa6ec03fdd0
I0913 17:07:25.574524252 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 6 -> 7
I0913 17:07:25.574623148 17165 ref_counted.h:103] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:92 ref 4 -> 5 connector_arg_copy
I0913 17:07:25.574756125 17165 timer_generic.cc:364] TIMER 0x7fa6ec0387d8: SET 20036 now 273 call 0x7fa6ec038810[0x7fa70b5f12d2]
I0913 17:07:25.574843287 17165 timer_generic.cc:401] .. add to shard 0 with queue_deadline_cap=1078 => is_first_timer=false
I0913 17:07:25.575114551 17165 handshaker.cc:129] handshake_manager 0x7fa6ec038720: error="No Error" shutdown=0 index=0, args={endpoint=0x7fa6ec0403b0, args=0x7fa6ec012830 {size=12: grpc.primary_user_agent=grpc-c++/1.30.0, grpc.keepalive_time_ms=10000, grpc.keepalive_timeout_ms=10000, grpc.ssl_target_name_override=Infinera.com, grpc.client_channel_factory=0x7fa6ec00e9f0, grpc.channel_credentials=0x7fa6ec010d80, grpc.server_uri=dns:///10.220.6.50:50058, grpc.default_authority=Infinera.com, grpc.subchannel_pool=0x7fa6ec00b9c0, grpc.http2_scheme=https, grpc.security_connector=0x7fa6ec013030, grpc.subchannel_address=ipv4:10.220.6.50:50058}, read_buffer=0x7fa6ec012bf0 (length=0), exit_early=0}
I0913 17:07:25.575178246 17165 handshaker.cc:176] handshake_manager 0x7fa6ec038720: calling handshaker http_connect [0x7fa6ec040f40] at index 0
I0913 17:07:25.575312900 17165 handshaker.cc:129] handshake_manager 0x7fa6ec038720: error="No Error" shutdown=0 index=1, args={endpoint=0x7fa6ec0403b0, args=0x7fa6ec012830 {size=12: grpc.primary_user_agent=grpc-c++/1.30.0, grpc.keepalive_time_ms=10000, grpc.keepalive_timeout_ms=10000, grpc.ssl_target_name_override=Infinera.com, grpc.client_channel_factory=0x7fa6ec00e9f0, grpc.channel_credentials=0x7fa6ec010d80, grpc.server_uri=dns:///10.220.6.50:50058, grpc.default_authority=Infinera.com, grpc.subchannel_pool=0x7fa6ec00b9c0, grpc.http2_scheme=https, grpc.security_connector=0x7fa6ec013030, grpc.subchannel_address=ipv4:10.220.6.50:50058}, read_buffer=0x7fa6ec012bf0 (length=0), exit_early=0}
I0913 17:07:25.603279024 17165 handshaker.cc:176] handshake_manager 0x7fa6ec038720: calling handshaker security [0x7fa6ec05c6e0] at index 1
I0913 17:07:25.603416192 17165 tcp_posix.cc:1566] WRITE 0x7fa6ec0403b0 (peer=ipv4:10.220.6.50:50058)
I0913 17:07:25.603619012 17165 tcp_posix.cc:1616] write: "No Error"
I0913 17:07:25.603753386 17165 ref_counted.h:103] tcp:0x7fa6ec0403d8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/tcp_posix.cc:908 ref 2 -> 3 read
I0913 17:07:25.604010961 17165 tcp_posix.cc:541] TCP:0x7fa6ec0403b0 notify_on_read
I0913 17:07:25.604401513 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec03fdd8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1085 unref 2 -> 1 pollset_worker
I0913 17:07:25.604615228 17165 ev_epollex_linux.cc:664] PS:0x7fa6ec03f738 (pollable:0x7fa6ec03fdd0) maybe_finish_shutdown sc=(nil) (target:!NULL) rw=(nil) (target:NULL) cpsc=1 (target:0)
I0913 17:07:25.604730047 17165 ev_posix.cc:325] (polling-api) pollset_work(0x7fa6ec03f738, 9223372036854775807) end
I0913 17:07:25.604973653 17165 ev_posix.cc:322] (polling-api) pollset_work(0x7fa6ec03f738, 9223372036854775807) begin
I0913 17:07:25.605089869 17165 ev_epollex_linux.cc:1120] PS:0x7fa6ec03f738 work hdl=(nil) worker=0x7fa7057602f0 now=273 deadline=9223372036854775807 kwp=0 pollable=0x7fa6ec03fdd0
I0913 17:07:25.605204967 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec03fdd8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1018 ref 1 -> 2 pollset_worker
I0913 17:07:25.605318669 17165 ev_epollex_linux.cc:938] POLLABLE:0x7fa6ec03fdd0[type=pollset epfd=19 wakeup=20] poll for -1ms
I0913 17:07:25.624281973 17165 ev_epollex_linux.cc:957] POLLABLE:0x7fa6ec03fdd0 got 1 events
I0913 17:07:25.625191306 17165 ev_epollex_linux.cc:905] PS:0x7fa6ec03f738 got fd 0x7fa6ec03e720: cancel=0 read=1 write=1
I0913 17:07:25.626231103 17165 tcp_posix.cc:887] TCP:0x7fa6ec0403b0 got_read: "No Error"
I0913 17:07:25.627087357 17165 tcp_posix.cc:869] TCP:0x7fa6ec0403b0 alloc_slices
I0913 17:07:25.627883827 17165 resource_quota.cc:890] RQ anonymous_pool_7fa6ec03f7b0 ipv4:10.220.6.50:50058: alloc 8192; free_pool -> -8192
I0913 17:07:25.629396031 17165 combiner.cc:135] C:0x7fa6ec03f4f0 grpc_combiner_execute c=0x7fa6ec040cf8 last=1
I0913 17:07:25.630779167 17165 combiner.cc:199] C:0x7fa6ec03f4f0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0913 17:07:25.633678419 17165 combiner.cc:222] C:0x7fa6ec03f4f0 maybe_finish_one n=0x7fa6ec040cf8
I0913 17:07:25.635280857 17165 combiner.cc:308] C:0x7fa6ec03f4f0 grpc_combiner_execute_finally c=0x7fa6ec03f820; ac=0x7fa6ec03f4f0
I0913 17:07:25.636448324 17165 combiner.cc:264] C:0x7fa6ec03f4f0 finish old_state=5
I0913 17:07:25.637369670 17165 combiner.cc:199] C:0x7fa6ec03f4f0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=1
I0913 17:07:25.638760349 17165 combiner.cc:246] C:0x7fa6ec03f4f0 execute_final[0] c=0x7fa6ec03f820
I0913 17:07:25.639790648 17165 resource_quota.cc:321] RQ: check allocation for user 0x7fa6ec040cf0 shutdown=0 free_pool=-8192
I0913 17:07:25.640919004 17165 resource_quota.cc:347] RQ anonymous_pool_7fa6ec03f7b0 ipv4:10.220.6.50:50058: grant alloc 8192 bytes; rq_free_pool -> 9223372036854767615
I0913 17:07:25.642398521 17165 combiner.cc:264] C:0x7fa6ec03f4f0 finish old_state=3
I0913 17:07:25.643722712 17165 tcp_posix.cc:850] TCP:0x7fa6ec0403b0 read_allocation_done: "No Error"
I0913 17:07:25.644955550 17165 tcp_posix.cc:680] TCP:0x7fa6ec0403b0 call_cb 0x7fa6ec05c8d8 0x7fa70b65e450:0x7fa6ec05c6e0
I0913 17:07:25.646910547 17165 tcp_posix.cc:683] READ 0x7fa6ec0403b0 (peer=ipv4:10.220.6.50:50058) error="No Error"
I0913 17:07:25.648767487 17165 ref_counted.h:199] tcp:0x7fa6ec0403d8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/tcp_posix.cc:844 unref 3 -> 2 read
I0913 17:07:25.650205100 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS write client hello - TWCH
I0913 17:07:25.652048630 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS read server hello - TRSH
I0913 17:07:25.653957812 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS read server certific - TRSC
I0913 17:07:25.655300999 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS read server key exch - TRSKE
I0913 17:07:25.656334650 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS read server done - TRSD
I0913 17:07:25.659340898 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS write client key exc - TWCKE
I0913 17:07:25.660446066 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS write change cipher - TWCCS
I0913 17:07:25.661612974 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS write finished - TWFIN
I0913 17:07:25.662694117 17165 tcp_posix.cc:1566] WRITE 0x7fa6ec0403b0 (peer=ipv4:10.220.6.50:50058)
I0913 17:07:25.664612238 17165 tcp_posix.cc:1616] write: "No Error"
I0913 17:07:25.665905140 17165 ref_counted.h:103] tcp:0x7fa6ec0403d8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/tcp_posix.cc:908 ref 2 -> 3 read
I0913 17:07:25.667535235 17165 tcp_posix.cc:887] TCP:0x7fa6ec0403b0 got_read: "No Error"
I0913 17:07:25.668567210 17165 tcp_posix.cc:879] TCP:0x7fa6ec0403b0 do_read
I0913 17:07:25.669521521 17165 tcp_posix.cc:680] TCP:0x7fa6ec0403b0 call_cb 0x7fa6ec05c8d8 0x7fa70b65e450:0x7fa6ec05c6e0
I0913 17:07:25.670683960 17165 tcp_posix.cc:683] READ 0x7fa6ec0403b0 (peer=ipv4:10.220.6.50:50058) error="No Error"
I0913 17:07:25.671891934 17165 ref_counted.h:199] tcp:0x7fa6ec0403d8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/tcp_posix.cc:844 unref 3 -> 2 read
I0913 17:07:25.673510017 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS write finished - TWFIN
I0913 17:07:25.674696760 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS read server session - TRST
I0913 17:07:25.675933230 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS read change cipher s - TRCCS
I0913 17:07:25.677194564 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS read finished - TRFIN
I0913 17:07:25.678290792 17165 ssl_transport_security.cc:220] HANDSHAKE DONE - SSL negotiation finished succe - SSLOK
E0913 17:07:25.680856761 17165 ssl_transport_security.cc:470] assertion failed: (int)peer->property_count == current_insert_index
signal 6[SIGABRT] caught by process [/opt/infinera/thanos/local/bin/tunnelclient]
#####DumpStacktrace ########
#0 /opt/infinera/thanos/local/lib/libBaseSystem.so unsigned long backward::details::unwind<backward::StackTraceImpl<backward::system_tag::linux_tag>::callback>(backward::StackTraceImpl<backward::system_tag::linux_tag>::callback, unsigned long) [0x7fa709dd4c72]
#1 /opt/infinera/thanos/local/lib/libBaseSystem.so backward::StackTraceImpl<backward::system_tag::linux_tag>::load_here(unsigned long) [0x7fa709dd4008]
#2 /opt/infinera/thanos/local/lib/libBaseSystem.so util::Backtrace::DumpStacktrace() [0x7fa709dd2c5e]
#3 /opt/infinera/thanos/local/lib/libBaseSystem.so OsProcess::MyFailureHandler(int) [0x7fa709db54e7]
#4 /lib/x86_64-linux-gnu/libc.so.6 [0x7fa70988683f]
#5 /lib/x86_64-linux-gnu/libc.so.6 gsignal [0x7fa7098867bb]
#6 /lib/x86_64-linux-gnu/libc.so.6 abort [0x7fa709871534]
#7 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b6a1dfd]
#8 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b6a3acf]
#9 /opt/infinera/thanos/local/lib/libgrpc.so.10 tsi_handshaker_result_extract_peer(tsi_handshaker_result const*, tsi_peer*) [0x7fa70b6a6db1]
#10 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b65df19]
#11 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b65e2b2]
#12 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b65e44b]
#13 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b65e5fe]
#14 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b6117ac]
#15 /opt/infinera/thanos/local/lib/libgrpc.so.10 grpc_core::ExecCtx::Flush() [0x7fa70b611cdc]
#16 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b6098b7]
#17 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b6110bd]
#18 /opt/infinera/thanos/local/lib/libgrpc.so.10 grpc_pollset_work(grpc_pollset*, grpc_pollset_worker**, long) [0x7fa70b61859f]
#19 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b674c8f]
#20 /opt/infinera/thanos/local/lib/libgrpc.so.10 grpc_completion_queue_next [0x7fa70b675154]
#21 /opt/infinera/thanos/local/lib/libgrpc++.so.1 grpc_impl::CompletionQueue::AsyncNextInternal(void**, bool*, gpr_timespec) [0x7fa70b09a675]
#22 /opt/infinera/thanos/local/lib/libgrpc++.so.1 grpc_impl::CompletionQueue::Next(void**, bool*) [0x7fa70b088ff6]
#23 /opt/infinera/thanos/local/lib/libgrpc++.so.1 grpc_impl::Channel::WaitForStateChangeImpl(grpc_connectivity_state, gpr_timespec) [0x7fa70b0883b4]
#24 /opt/infinera/thanos/local/bin/tunnelclient bool grpc::ChannelInterface::WaitForStateChange<gpr_timespec>(grpc_connectivity_state, gpr_timespec) [0x55d52d47a6e3]
#25 /opt/infinera/thanos/local/bin/tunnelclient bool grpc::ChannelInterface::WaitForConnected<gpr_timespec>(gpr_timespec) [0x55d52d4797fe]
#26 /opt/infinera/thanos/local/bin/tunnelclient ConnectionManager::createChannel(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::shared_ptr<grpc_impl::Channel>&) [0x55d52d472e6f]
#27 /opt/infinera/thanos/local/bin/tunnelclient ConnectionManager::connectToServer() [0x55d52d473b81]
#28 /opt/infinera/thanos/local/bin/tunnelclient boost::_mfi::mf0<void, ConnectionManager>::operator()(ConnectionManager*) const [0x55d52d47d4bc]
#29 /opt/infinera/thanos/local/bin/tunnelclient void boost::_bi::list1<boost::_bi::value<ConnectionManager*> >::operator()<boost::_mfi::mf0<void, ConnectionManager>, boost::_bi::list0>(boost::_bi::type<void>, boost::_mfi::mf0<void, ConnectionManager>&, boost::_bi::list0&, int) [0x55d52d47d41e]
#30 /opt/infinera/thanos/local/bin/tunnelclient boost::_bi::bind_t<void, boost::_mfi::mf0<void, ConnectionManager>, boost::_bi::list1<boost::_bi::value<ConnectionManager*> > >::operator()() [0x55d52d47d2cc]
#31 /opt/infinera/thanos/local/bin/tunnelclient boost::detail::thread_data<boost::_bi::bind_t<void, boost::_mfi::mf0<void, ConnectionManager>, boost::_bi::list1<boost::_bi::value<ConnectionManager*> > > >::run() [0x55d52d47d0f3]
#####End DumpStacktrace ########
I0913 17:07:25.303940980 17165 init.cc:212] grpc_shutdown(void)
I0913 17:07:25.304056078 17165 init.cc:212] grpc_shutdown(void)
I0913 17:07:25.304331812 17165 init.cc:165] grpc_init(void)
I0913 17:07:25.304439088 17165 secure_channel_create.cc:201] grpc_secure_channel_create(creds=0x7fa6ec010d80, target=10.220.6.50:50058, args=0x7fa705760590, reserved=(nil))
I0913 17:07:25.304579888 17165 init.cc:165] grpc_init(void)
I0913 17:07:25.305033297 17165 ev_posix.cc:352] (polling-api) pollset_set_create(0x7fa6ec00fc70)
I0913 17:07:25.305103697 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 1 -> 2
I0913 17:07:25.305229970 17165 client_channel.cc:1402] chand=0x7fa6ec00fa08: creating client_channel for channel stack 0x7fa6ec00f958
I0913 17:07:25.305320485 17165 ev_posix.cc:304] (polling-api) pollset_init(0x7fa6ec011c70)
I0913 17:07:25.305436421 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:796 ref 1 -> 2 pollset
I0913 17:07:25.305555151 17165 timer_generic.cc:364] TIMER 0x7fa6ec00e4d0: SET 5003 now 3 call 0x7fa6ec00e508[0x7fa70b4823cd]
I0913 17:07:25.305665221 17165 timer_generic.cc:401] .. add to shard 0 with queue_deadline_cap=0 => is_first_timer=false
I0913 17:07:25.305775850 17165 ev_posix.cc:364] (polling-api) pollset_set_add_pollset(0x7fa6ec00fc70, 0x7fa6ec011c70)
I0913 17:07:25.305887875 17165 ev_epollex_linux.cc:1450] PSS:0x7fa6ec00fc70: add pollset 0x7fa6ec011c70
I0913 17:07:25.306001577 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1241 ref 2 -> 3 pollset_as_multipollable
I0913 17:07:25.306742453 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1244 unref 3 -> 2 pollset
I0913 17:07:25.306846936 17165 ev_epollex_linux.cc:569] (fd-trace) Pollable_create: created epfd: 16 (type: 0)
I0913 17:07:25.306956168 17165 ev_epollex_linux.cc:1249] PS:0x7fa6ec011c70 active pollable transition from empty to multi
I0913 17:07:25.307059253 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec011dc8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1280 ref 1 -> 2 pollset_set
I0913 17:07:25.307174631 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1281 unref 2 -> 1 pollset_as_multipollable
I0913 17:07:25.307288891 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec011dc8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1478 unref 2 -> 1 pollset_set
I0913 17:07:25.307496739 17165 init.cc:165] grpc_init(void)
I0913 17:07:25.334856920 17165 init.cc:212] grpc_shutdown(void)
I0913 17:07:25.335164222 17165 channel_connectivity.cc:43] grpc_channel_check_connectivity_state(channel=0x7fa6ec00f8c0, try_to_connect=1)
I0913 17:07:25.335212831 17165 connectivity_state.cc:174] ConnectivityStateTracker client_channel[0x7fa6ec00fac8]: get current state: IDLE
I0913 17:07:25.335308933 17165 ref_counted.h:133] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:88 ref 1 -> 2 TryToConnect
I0913 17:07:25.335442749 17165 work_serializer.cc:55] WorkSerializer::Run() 0x7fa6ec00bf80 Scheduling callback [/home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/client_channel.cc:1926]
I0913 17:07:25.335517898 17165 work_serializer.cc:65] Executing immediately
I0913 17:07:25.335660933 17165 ref_counted.h:133] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:88 ref 2 -> 3 ClientChannelControlHelper
I0913 17:07:25.335822965 17165 ev_posix.cc:352] (polling-api) pollset_set_create(0x7fa6ec0105f0)
I0913 17:07:25.335905657 17165 ref_counted.h:92] lb_policy_refcount:0x7fa6ec001688 ref 1 -> 2
I0913 17:07:25.336194241 17165 ev_posix.cc:352] (polling-api) pollset_set_create(0x7fa6ec010670)
I0913 17:07:25.336355155 17165 ev_posix.cc:377] (polling-api) pollset_set_add_pollset_set(0x7fa6ec010670, 0x7fa6ec0105f0)
I0913 17:07:25.336457682 17165 ev_epollex_linux.cc:1487] PSS: merge (0x7fa6ec010670, 0x7fa6ec0105f0)
I0913 17:07:25.307856561 17166 executor.cc:224] EXECUTOR (default-executor) [0]: step (sub_depth=0)
I0913 17:07:25.307920536 17167 executor.cc:224] EXECUTOR (resolver-executor) [0]: step (sub_depth=0)
I0913 17:07:25.336576133 17165 ev_epollex_linux.cc:1521] PSS: parent 0x7fa6ec010670 to 0x7fa6ec0105f0
I0913 17:07:25.337203867 17165 resolving_lb_policy.cc:163] resolving_lb=0x7fa6ec001680: starting name resolution
I0913 17:07:25.337258063 17165 ref_counted.h:92] lb_policy_refcount:0x7fa6ec001688 ref 2 -> 3
I0913 17:07:25.337429314 17165 client_channel.cc:1306] chand=0x7fa6ec00fa08: update: state=CONNECTING picker=0x7fa6ec0127e0
I0913 17:07:25.337497200 17165 connectivity_state.cc:152] ConnectivityStateTracker client_channel[0x7fa6ec00fac8]: IDLE -> CONNECTING (helper)
I0913 17:07:25.337667613 17165 ref_counted.h:103] resolver_refcount:0x7fa6ec0129d8 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc:434 ref 1 -> 2 dns-resolving
I0913 17:07:25.338277467 17165 grpc_ares_wrapper.cc:128] (c-ares resolver) request:0x7fa6ec012b80 c-ares address sorting: input[0]=10.220.6.50:50058
I0913 17:07:25.338486711 17165 grpc_ares_wrapper.cc:128] (c-ares resolver) request:0x7fa6ec012b80 c-ares address sorting: output[0]=10.220.6.50:50058
I0913 17:07:25.338643994 17165 ev_posix.cc:377] (polling-api) pollset_set_add_pollset_set(0x7fa6ec0105f0, 0x7fa6ec00fc70)
I0913 17:07:25.338706851 17165 ev_epollex_linux.cc:1487] PSS: merge (0x7fa6ec0105f0, 0x7fa6ec00fc70)
I0913 17:07:25.338813848 17165 ev_epollex_linux.cc:1521] PSS: parent 0x7fa6ec0105f0 to 0x7fa6ec00fc70
I0913 17:07:25.339155232 17165 client_channel.cc:1581] chand=0x7fa6ec00fa08: creat[4173222.493507] serial8250: too much work for irq4
ed resolving_lb_policy=0x7fa6ec001680
I0913 17:07:25.339274241 17165 ref_counted.h:199] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:105 unref 3 -> 2 TryToConnect
I0913 17:07:25.339380121 17165 work_serializer.cc:102] WorkSerializer::DrainQueue() 0x7fa6ec00bf80
I0913 17:07:25.339499410 17165 work_serializer.cc:117] Queue Drained
I0913 17:07:25.339617022 17165 work_serializer.cc:55] WorkSerializer::Run() 0x7fa6ec00bf80 Scheduling callback [/home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc:327]
I0913 17:07:25.339708934 17165 work_serializer.cc:65] Executing immediately
I0913 17:07:25.339876553 17165 resolving_lb_policy.cc:293] resolving_lb=0x7fa6ec001680: got resolver result
I0913 17:07:25.340316832 17165 ref_counted.h:92] lb_policy_refcount:0x7fa6ec001688 ref 3 -> 4
I0913 17:07:25.340460426 17165 ev_posix.cc:352] (polling-api) pollset_set_create(0x7fa6ec012e20)
I0913 17:07:25.340571334 17165 resolving_lb_policy.cc:258] resolving_lb=0x7fa6ec001680: created new LB policy 0x7fa6ec012b80
I0913 17:07:25.340654584 17165 ev_posix.cc:377] (polling-api) pollset_set_add_pollset_set(0x7fa6ec012e20, 0x7fa6ec0105f0)
I0913 17:07:25.380510767 17165 ev_epollex_linux.cc:1487] PSS: merge (0x7fa6ec012e20, 0x7fa6ec0105f0)
I0913 17:07:25.380744037 17165 ev_epollex_linux.cc:1521] PSS: parent 0x7fa6ec012e20 to 0x7fa6ec00fc70
I0913 17:07:25.380469980 17168 timer_generic.cc:716] TIMER CHECK BEGIN: now=78 next=9223372036854775807 tls_min=0 glob_min=0
I0913 17:07:25.385597447 17168 timer_generic.cc:611] .. shard[0]->min_deadline = 1
I0913 17:07:25.386931416 17168 timer_generic.cc:534] .. shard[0]: heap_empty=true
I0913 17:07:25.391432826 17168 timer_generic.cc:509] .. shard[0]->queue_deadline_cap --> 1078
I0913 17:07:25.391458807 17168 timer_generic.cc:574] .. shard[0] popped 0
I0913 17:07:25.392370096 17168 timer_generic.cc:629] .. result --> 1, shard[0]->min_deadline 1 --> 1079, now=78
I0913 17:07:25.393245905 17168 timer_generic.cc:534] .. shard[1]: heap_empty=true
I0913 17:07:25.394042375 17168 timer_generic.cc:509] .. shard[1]->queue_deadline_cap --> 1078
I0913 17:07:25.394793309 17168 timer_generic.cc:574] .. shard[1] popped 0
I0913 17:07:25.395162909 17168 timer_generic.cc:629] .. result --> 1, shard[1]->min_deadline 1 --> 1079, now=78
I0913 17:07:25.384528317 17165 resolving_lb_policy.cc:240] resolving_lb=0x7fa6ec001680: Updating child policy 0x7fa6ec012b80
I0913 17:07:25.396767303 17165 child_policy_handler.cc:211] [child_policy_handler 0x7fa6ec012b80] creating new child policy pick_first
I0913 17:07:25.397911862 17165 ref_counted.h:103] lb_policy_refcount:0x7fa6ec012b88 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/lb_policy/child_policy_handler.cc:258 ref 1 -> 2 Helper
I0913 17:07:25.397978351 17165 ev_posix.cc:352] (polling-api) pollset_set_create(0x7fa6ec0130c0)
I0913 17:07:25.398036179 17165 pick_first.cc:146] Pick First 0x7fa6ec010af0 created.
I0913 17:07:25.399215100 17165 child_policy_handler.cc:272] [child_policy_handler 0x7fa6ec012b80] created new LB policy "pick_first" (0x7fa6ec010af0)
I0913 17:07:25.399387189 17165 ev_posix.cc:377] (polling-api) pollset_set_add_pollset_set(0x7fa6ec0130c0, 0x7fa6ec012e20)
I0913 17:07:25.399397525 17165 ev_epollex_linux.cc:1487] PSS: merge (0x7fa6ec0130c0, 0x7fa6ec012e20)
I0913 17:07:25.399502008 17165 ev_epollex_linux.cc:1521] PSS: parent 0x7fa6ec0130c0 to 0x7fa6ec00fc70
I0913 17:07:25.399616268 17165 child_policy_handler.cc:230] [child_policy_handler 0x7fa6ec012b80] updating child policy 0x7fa6ec010af0
I0913 17:07:25.399732763 17165 pick_first.cc:265] Pick First 0x7fa6ec010af0 received update with 1 addresses
I0913 17:07:25.399861830 17165 subchannel_list.h:361] [pick_first 0x7fa6ec010af0] Creating subchannel list 0x7fa6ec00ed40 for 1 subchannels
I0913 17:07:25.400047329 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 2 -> 3
I0913 17:07:25.400099011 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 3 -> 4
I0913 17:07:25.407755012 17168 timer_generic.cc:534] .. shard[2]: heap_empty=true
I0913 17:07:25.407776244 17168 timer_generic.cc:509] .. shard[2]->queue_deadline_cap --> 1078
I0913 17:07:25.407922352 17168 timer_generic.cc:574] .. shard[2] popped 0
I0913 17:07:25.408062314 17168 timer_generic.cc:629] .. result --> 1, shard[2]->min_deadline 1 --> 1079, now=78
I0913 17:07:25.408211215 17168 timer_generic.cc:534] .. shard[3]: heap_empty=true
I0913 17:07:25.408946504 17168 timer_generic.cc:509] .. shard[3]->queue_deadline_cap --> 1078
I0913 17:07:25.409368625 17168 timer_generic.cc:574] .. shard[3] popped 0
I0913 17:07:25.409511939 17168 timer_generic.cc:629] .. result --> 1, shard[3]->min_deadline 1 --> 1079, now=78
I0913 17:07:25.409652739 17168 timer_generic.cc:739] TIMER CHECK END: r=1; next=1079
I0913 17:07:25.409791304 17168 timer_manager.cc:188] sleep for a 1001 milliseconds
I0913 17:07:25.410554530 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 4 -> 5
I0913 17:07:25.410646720 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 5 -> 6
I0913 17:07:25.410764054 17165 ref_counted.h:103] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:92 ref 1 -> 2 connector_arg_copy
I0913 17:07:25.410875800 17165 ref_counted.h:199] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/ext/transport/chttp2/client/secure/secure_channel_create.cc:144 unref 2 -> 1 lb_channel_create
I0913 17:07:25.410993133 17165 ref_counted.h:183] subchannel_pool:0x7fa6ec00b9c8 unref 6 -> 5
I0913 17:07:25.411102086 17165 ref_counted.h:183] subchannel_pool:0x7fa6ec00b9c8 unref 5 -> 4
I0913 17:07:25.411285908 17165 ref_counted.h:103] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:92 ref 1 -> 2 connector_arg_copy
I0913 17:07:25.411333959 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 4 -> 5
I0913 17:07:25.411511914 17165 ev_posix.cc:352] (polling-api) pollset_set_create(0x7fa6ec03d640)
I0913 17:07:25.411604943 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 5 -> 6
I0913 17:07:25.411669755 17165 ref_counted.h:103] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:92 ref 2 -> 3 connector_arg_copy
I0913 17:07:25.413236714 17165 ref_counted.h:103] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:92 ref 3 -> 4 connector_arg_copy
I0913 17:07:25.413338403 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 6 -> 7
I0913 17:07:25.413450429 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 7 -> 8
I0913 17:07:25.413561895 17165 ref_counted.h:183] subchannel_pool:0x7fa6ec00b9c8 unref 8 -> 7
I0913 17:07:25.413666937 17165 ref_counted.h:199] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:86 unref 4 -> 3 connector_arg_destroy
I0913 17:07:25.413773375 17165 ref_counted.h:183] subchannel_pool:0x7fa6ec00b9c8 unref 7 -> 6
I0913 17:07:25.414899775 17165 client_channel.cc:868] chand=0x7fa6ec00fa08: creating subchannel wrapper 0x7fa6ec03da30 for subchannel 0x7fa6ec033280
I0913 17:07:25.414985540 17165 ref_counted.h:133] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:88 ref 2 -> 3 SubchannelWrapper
I0913 17:07:25.415218810 17165 subchannel_list.h:404] [pick_first 0x7fa6ec010af0] subchannel list 0x7fa6ec00ed40 index 0: Created subchannel 0x7fa6ec03da30 for address uri ipv4:10.220.6.50:50058
I0913 17:07:25.415344245 17165 ref_counted.h:103] lb_policy_refcount:0x7fa6ec010af8 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc:93 ref 1 -> 2 subchannel_list
I0913 17:07:25.415441464 17165 subchannel_list.h:308] [pick_first 0x7fa6ec010af0] subchannel list 0x7fa6ec00ed40 index 0 of 1 (subchannel 0x7fa6ec03da30): starting watch (from IDLE)
I0913 17:07:25.415542035 17165 ref_counted.h:103] pick_first:0x7fa6ec00ed48 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/lb_policy/subchannel_list.h:317 ref 1 -> 2 Watcher
I0913 17:07:25.415705464 17165 ref_counted.h:103] client_channel_routing:0x7fa6ec03da38 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/client_channel.cc:921 ref 1 -> 2 WatcherWrapper
I0913 17:07:25.443438598 17165 ev_posix.cc:377] (polling-api) pollset_set_add_pollset_set(0x7fa6ec03d640, 0x7fa6ec0130c0)
I0913 17:07:25.443463740 17165 ev_epollex_linux.cc:1487] PSS: merge (0x7fa6ec03d640, 0x7fa6ec0130c0)
I0913 17:07:25.443569620 17165 ev_epollex_linux.cc:1521] PSS: parent 0x7fa6ec03d640 to 0x7fa6ec00fc70
I0913 17:07:25.443969391 17165 socket_utils_common_posix.cc:320] Enabling TCP_USER_TIMEOUT with a timeout of 10000 ms
I0913 17:07:25.445888071 17165 ev_posix.cc:254] (polling-api) fd_create(18, tcp-client:ipv4:10.220.6.50:50058, 1)
I0913 17:07:25.446187550 17165 ev_posix.cc:255] (fd-trace) fd_create(18, tcp-client:ipv4:10.220.6.50:50058, 1)
I0913 17:07:25.446316058 17165 ev_posix.cc:394] (polling-api) pollset_set_add_fd(0x7fa6ec03d640, 18)
I0913 17:07:25.446402382 17165 ev_epollex_linux.cc:1353] PSS:0x7fa6ec03d640: add fd 0x7fa6ec03e720 (18)
I0913 17:07:25.446514687 17165 ev_epollex_linux.cc:616] add fd 0x7fa6ec03e720 (18) to pollable 0x7fa6ec011dc0
I0913 17:07:25.446658560 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 6 -> 7
I0913 17:07:25.446745163 17165 ref_counted.h:103] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:92 ref 3 -> 4 connector_arg_copy
I0913 17:07:25.446854395 17165 tcp_client_posix.c[4173222.577355] serial8250: too much work for irq4
c:329] CLIENT_CONNECT: ipv4:10.220.6.50:50058: asynchronously connecting fd 0x7fa6ec03e720
I0913 17:07:25.446979271 17165 timer_generic.cc:364] TIMER 0x7fa6ec012c20: SET 20036 now 36 call 0x7fa6ec012c58[0x7fa70b61f33b]
I0913 17:07:25.447319258 17165 timer_generic.cc:401] .. add to shard 0 with queue_deadline_cap=1078 => is_first_timer=false
I0913 17:07:25.447601138 17165 ref_counted.h:199] resolver_refcount:0x7fa6ec0129d8 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc:396 unref 2 -> 1 dns-resolving
I0913 17:07:25.447646674 17165 work_serializer.cc:102] WorkSerializer::DrainQueue() 0x7fa6ec00bf80
I0913 17:07:25.447753112 17165 work_serializer.cc:117] Queue Drained
I0913 17:07:25.447868211 17165 client_channel.cc:1033] chand=0x7fa6ec00fa08: connectivity change for subchannel wrapper 0x7fa6ec03da30 subchannel 0x7fa6ec033280; hopping into work_serializer
I0913 17:07:25.447979119 17165 work_serializer.cc:55] WorkSerializer::Run() 0x7fa6ec00bf80 Scheduling callback [/home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/client_channel.cc:1044]
I0913 17:07:25.448078573 17165 work_serializer.cc:65] Executing immediately
I0913 17:07:25.448185570 17165 client_channel.cc:1066] chand=0x7fa6ec00fa08: processing connectivity change in work serializer for subchannel wrapper 0x7fa6ec03da30 subchannel 0x7fa6ec033280 watcher=0x7fa6ec03ba20
I0913 17:07:25.448334751 17165 subchannel_list.h:241] [pick_first 0x7fa6ec010af0] subchannel list 0x7fa6ec00ed40 index 0 of 1 (subchannel 0x7fa6ec03da30): connectivity changed: state=CONNECTING, shutting_down=0, pending_watcher=0x7fa6ec03ba20
I0913 17:07:25.448437557 17165 ref_counted.h:103] lb_policy_refcount:0x7fa6ec010af8 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc:410 ref 2 -> 3 QueuePicker
I0913 17:07:25.448549582 17165 client_channel.cc:1306] chand=0x7fa6ec00fa08: update: state=CONNECTING picker=0x7fa6ec013ac0
I0913 17:07:25.448671944 17165 ref_counted.h:199] lb_policy_refcount:0x7fa6ec001688 /home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/lb_policy.h:375 unref 4 -> 3 QueuePicker
I0913 17:07:25.448745697 17165 work_serializer.cc:102] WorkSerializer::DrainQueue() 0x7fa6ec00bf80
I0913 17:07:25.449227881 17165 work_serializer.cc:117] Queue Drained
I0913 17:07:25.449335436 17165 init.cc:165] grpc_init(void)
I0913 17:07:25.449470928 17165 completion_queue.cc:526] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
I0913 17:07:25.449589100 17165 ev_posix.cc:304] (polling-api) pollset_init(0x7fa6ec03f298)
I0913 17:07:25.449735767 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:796 ref 1 -> 2 pollset
I0913 17:07:25.480508672 17165 channel_connectivity.cc:232] grpc_channel_watch_connectivity_state(channel=0x7fa6ec00f8c0, last_observed_state=0, deadline=gpr_timespec { tv_sec: 1663089445, tv_nsec: 335137682, clock_type: 1 }, cq=0x7fa6ec03f190, tag=0x7fa6ec013a50)
I0913 17:07:25.480579072 17165 ref_counted.h:133] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:88 ref 3 -> 4 watch_channel_connectivity
I0913 17:07:25.480707859 17165 ev_posix.cc:364] (polling-api) pollset_set_add_pollset(0x7fa6ec00fc70, 0x7fa6ec03f298)
I0913 17:07:25.480900901 17165 ev_epollex_linux.cc:1450] PSS:0x7fa6ec00fc70: add pollset 0x7fa6ec03f298
I0913 17:07:25.481010971 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1241 ref 2 -> 3 pollset_as_multipollable
I0913 17:07:25.481119085 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1244 unref 3 -> 2 pollset
I0913 17:07:25.481230272 17165 ev_epollex_linux.cc:569] (fd-trace) Pollable_create: created epfd: 19 (type: 0)
I0913 17:07:25.481345650 17165 ev_epollex_linux.cc:1249] PS:0x7fa6ec03f298 active pollable transition from empty to multi
I0913 17:07:25.481428063 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec03f638 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1280 ref 1 -> 2 pollset_set
I0913 17:07:25.481534501 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1281 unref 2 -> 1 pollset_as_multipollable
I0913 17:07:25.481642056 17165 ev_epollex_linux.cc:616] add fd 0x7fa6ec03e720 (18) to pollable 0x7fa6ec03f630
I0913 17:07:25.481755758 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec03f638 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1478 unref 2 -> 1 pollset_set
I0913 17:07:25.481859402 17165 ref_counted.h:133] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:88 ref 4 -> 5 ExternalConnectivityWatcher
I0913 17:07:25.482000482 17165 work_serializer.cc:55] WorkSerializer::Run() 0x7fa6ec00bf80 Scheduling callback [/home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/client_channel.cc:1155]
I0913 17:07:25.482080380 17165 work_serializer.cc:65] Executing immediately
I0913 17:07:25.482211402 17165 timer_generic.cc:364] TIMER 0x7fa6ec03f418: SET 600034 now 180 call 0x7fa6ec03f388[0x7fa70b482e3b]
I0913 17:07:25.482299402 17165 timer_generic.cc:401] .. add to shard 0 with queue_deadline_cap=1078 => is_first_timer=false
I0913 17:07:25.482430983 17165 connectivity_state.cc:118] ConnectivityStateTracker client_channel[0x7fa6ec00fac8]: add watcher 0x7fa6ec03f130
I0913 17:07:25.482516190 17165 connectivity_state.cc:124] ConnectivityStateTracker client_channel[0x7fa6ec00fac8]: notifying watcher 0x7fa6ec03f130: IDLE -> CONNECTING
I0913 17:07:25.482647771 17165 work_serializer.cc:55] WorkSerializer::Run() 0x7fa6ec00bf80 Scheduling callback [/home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/client_channel.cc:1175]
I0913 17:07:25.482732139 17165 work_serializer.cc:76] Scheduling on queue : item 0x7fa6ec03ec80
I0913 17:07:25.482900317 17165 work_serializer.cc:102] WorkSerializer::DrainQueue() 0x7fa6ec00bf80
I0913 17:07:25.482950044 17165 work_serializer.cc:134] Running item 0x7fa6ec03ec80 : callback scheduled at [/home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/client_channel.cc:1175]
I0913 17:07:25.483054526 17165 connectivity_state.cc:141] ConnectivityStateTracker client_channel[0x7fa6ec00fac8]: remove watcher 0x7fa6ec03f130
I0913 17:07:25.483184711 17165 ev_posix.cc:371] (polling-api) pollset_set_del_pollset(0x7fa6ec00fc70, 0x7fa6ec03f298)
I0913 17:07:25.483269917 17165 ev_epollex_linux.cc:1398] PSS:0x7fa6ec00fc70: del pollset 0x7fa6ec03f298
I0913 17:07:25.483379707 17165 ev_epollex_linux.cc:664] PS:0x7fa6ec03f298 (pollable:0x7fa6ec03f630) maybe_finish_shutdown sc=(nil) (target:!NULL) rw=(nil) (target:NULL) cpsc=0 (target:0)
I0913 17:07:25.511424054 17165 ref_counted.h:199] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:105 unref 5 -> 4 ExternalConnectivityWatcher
I0913 17:07:25.511541387 17165 work_serializer.cc:102] WorkSerializer::DrainQueue() 0x7fa6ec00bf80
I0913 17:07:25.511615978 17165 work_serializer.cc:117] Queue Drained
I0913 17:07:25.511634695 17165 timer_generic.cc:467] TIMER 0x7fa6ec03f418: CANCEL pending=true
I0913 17:07:25.511748397 17165 completion_queue.cc:707] cq_end_op_for_next(cq=0x7fa6ec03f190, tag=0x7fa6ec013a50, error="No Error", done=0x7fa70b482a2e, done_arg=0x7fa6ec03f310, storage=0x7fa6ec03f460)
I0913 17:07:25.511850644 17165 ev_posix.cc:331] (polling-api) pollset_kick(0x7fa6ec03f298, (nil))
I0913 17:07:25.511959597 1[4173222.646290] serial8250: too much work for irq4
7165 ev_epollex_linux.cc:731] PS:0x7fa6ec03f298 kick (nil) tls_pollset=(nil) tls_worker=(nil) pollset.root_worker=(nil)
I0913 17:07:25.512064638 17165 ev_epollex_linux.cc:741] PS:0x7fa6ec03f298 kicked_any_without_poller
I0913 17:07:25.512201248 17165 completion_queue.cc:982] grpc_completion_queue_next(cq=0x7fa6ec03f190, deadline=gpr_timespec { tv_sec: 9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))
I0913 17:07:25.512371381 17165 ref_counted.h:199] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:105 unref 4 -> 3 watch_channel_connectivity
I0913 17:07:25.512474746 17165 completion_queue.cc:1083] RETURN_EVENT[0x7fa6ec03f190]: OP_COMPLETE: tag:0x7fa6ec013a50 OK
I0913 17:07:25.512537882 17165 completion_queue.cc:1425] grpc_completion_queue_destroy(cq=0x7fa6ec03f190)
I0913 17:07:25.512637895 17165 completion_queue.cc:1419] grpc_completion_queue_shutdown(cq=0x7fa6ec03f190)
I0913 17:07:25.512750200 17165 ev_posix.cc:309] (polling-api) pollset_shutdown(0x7fa6ec03f298)
I0913 17:07:25.512975648 17165 ev_epollex_linux.cc:664] PS:0x7fa6ec03f298 (pollable:0x7fa6ec03f630) maybe_finish_shutdown sc=0x7fa6ec03f1d0 (target:!NULL) rw=(nil) (target:NULL) cpsc=0 (target:0)
I0913 17:07:25.513091305 17165 ev_posix.cc:314] (polling-api) pollset_destroy(0x7fa6ec03f298)
I0913 17:07:25.513200816 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec03f638 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:927 unref 1 -> 0 pollset
I0913 17:07:25.513311165 17165 ev_epollex_linux.cc:149] (fd-trace) pollable_unref: Closing epfd: 19
I0913 17:07:25.513445540 17165 init.cc:212] grpc_shutdown(void)
I0913 17:07:25.513544994 17165 channel_connectivity.cc:43] grpc_channel_check_connectivity_state(channel=0x7fa6ec00f8c0, try_to_connect=1)
I0913 17:07:25.513658695 17165 connectivity_state.cc:174] ConnectivityStateTracker client_channel[0x7fa6ec00fac8]: get current state: CONNECTING
I0913 17:07:25.513767368 17165 init.cc:165] grpc_init(void)
I0913 17:07:25.513882746 17165 completion_queue.cc:526] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
I0913 17:07:25.513992257 17165 ev_posix.cc:304] (polling-api) pollset_init(0x7fa6ec03f738)
I0913 17:07:25.514111267 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:796 ref 1 -> 2 pollset
I0913 17:07:25.514229997 17165 channel_connectivity.cc:232] grpc_channel_watch_connectivity_state(channel=0x7fa6ec00f8c0, last_observed_state=1, deadline=gpr_timespec { tv_sec: 1663089445, tv_nsec: 335137682, clock_type: 1 }, cq=0x7fa6ec03f630, tag=0x7fa6ec013b20)
I0913 17:07:25.514340067 17165 ref_counted.h:133] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:88 ref 3 -> 4 watch_channel_connectivity
I0913 17:07:25.514452930 17165 ev_posix.cc:364] (polling-api) pollset_set_add_pollset(0x7fa6ec00fc70, 0x7fa6ec03f738)
I0913 17:07:25.514564397 17165 ev_epollex_linux.cc:1450] PSS:0x7fa6ec00fc70: add pollset 0x7fa6ec03f738
I0913 17:07:25.514675584 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1241 ref 2 -> 3 pollset_as_multipollable
I0913 17:07:25.542637797 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1244 unref 3 -> 2 pollset
I0913 17:07:25.542729429 17165 ev_epollex_linux.cc:569] (fd-trace) Pollable_create: created epfd: 19 (type: 0)
I0913 17:07:25.542869950 17165 ev_epollex_linux.cc:1249] PS:0x7fa6ec03f738 active pollable transition from empty to multi
I0913 17:07:25.542934483 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec03fdd8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1280 ref 1 -> 2 pollset_set
I0913 17:07:25.543148477 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec00ac08 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1281 unref 2 -> 1 pollset_as_multipollable
I0913 17:07:25.543274750 17165 ev_epollex_linux.cc:616] add fd 0x7fa6ec03e720 (18) to pollable 0x7fa6ec03fdd0
I0913 17:07:25.543391245 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec03fdd8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1478 unref 2 -> 1 pollset_set
I0913 17:07:25.543491817 17165 ref_counted.h:133] stream_refcount:0x7fa6ec00f958 /home/rcheppudira/new_grpc/grpc/src/core/lib/transport/transport.h:88 ref 4 -> 5 ExternalConnectivityWatcher
I0913 17:07:25.543632617 17165 work_serializer.cc:55] WorkSerializer::Run() 0x7fa6ec00bf80 Scheduling callback [/home/rcheppudira/new_grpc/grpc/src/core/ext/filters/client_channel/client_channel.cc:1155]
I0913 17:07:25.543722572 17165 work_serializer.cc:65] Executing immediately
I0913 17:07:25.543974280 17165 timer_generic.cc:364] TIMER 0x7fa6ec03f418: SET 600034 now 242 call 0x7fa6ec03f388[0x7fa70b482e3b]
I0913 17:07:25.544049988 17165 timer_generic.cc:401] .. add to shard 0 with queue_deadline_cap=1078 => is_first_timer=false
I0913 17:07:25.544172909 17165 connectivity_state.cc:118] ConnectivityStateTracker client_channel[0x7fa6ec00fac8]: add watcher 0x7fa6ec03f5d0
I0913 17:07:25.544299461 17165 work_serializer.cc:102] WorkSerializer::DrainQueue() 0x7fa6ec00bf80
I0913 17:07:25.544386902 17165 work_serializer.cc:117] Queue Drained
I0913 17:07:25.544504236 17165 completion_queue.cc:982] grpc_completion_queue_next(cq=0x7fa6ec03f630, deadline=gpr_timespec { tv_sec: 9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))
I0913 17:07:25.544651741 17165 ev_posix.cc:322] (polling-api) pollset_work(0x7fa6ec03f738, 9223372036854775807) begin
I0913 17:07:25.544765442 17165 ev_epollex_linux.cc:1120] PS:0x7fa6ec03f738 work hdl=(nil) worker=0x7fa7057602f0 now=243 deadline=9223372036854775807 kwp=0 pollable=0x7fa6ec03fdd0
I0913 17:07:25.544948147 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec03fdd8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1018 ref 1 -> 2 pollset_worker
I0913 17:07:25.545075537 17165 ev_epollex_linux.cc:938] POLLABLE:0x7fa6ec03fdd0[type=pollset epfd=19 wakeup=20] poll for -1ms
I0913 17:07:25.571483922 17165 ev_epollex_linux.cc:957] POLLABLE:0x7fa6ec03fdd0 got 1 events
I0913 17:07:25.571542309 17165 ev_epollex_linux.cc:905] PS:0x7fa6ec03f738 got fd 0x7fa6ec03e720: cancel=0 read=0 write=1
I0913 17:07:25.571681153 17165 tcp_client_posix.cc:142] CLIENT_CONNECT: ipv4:10.220.6.50:50058: on_writable: error="No Error"
I0913 17:07:25.571790944 17165 timer_generic.cc:467] TIMER 0x7fa6ec012c20: CANCEL pending=true
I0913 17:07:25.571914423 17165 ev_posix.cc:400] (polling-api) pollset_set_del_fd(0x7fa6ec03d640, 18)
I0913 17:07:25.572013319 17165 ev_epollex_linux.cc:1377] PSS:0x7fa6ec03d640: del fd 0x7fa6ec03e720
I0913 17:07:25.572390182 17165 combiner.cc:61] C:0x7fa6ec03f4f0 create
I0913 17:07:25.572544950 17165 ref_counted.h:103] tcp:0x7fa6ec0403d8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/tcp_posix.cc:1823 ref 1 -> 2 error-tracking
I0913 17:07:25.572643566 17165 tcp_client_posix.cc:105] CLIENT_CONNECT: ipv4:10.220.6.50:50058: on_alarm: error="Cancelled"
I0913 17:07:25.572758665 17165 ref_counted.h:183] subchannel_pool:0x7fa6ec00b9c8 unref 7 -> 6
I0913 17:07:25.572988862 17165 ref_counted.h:199] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:86 unref 4 -> 3 connector_arg_destroy
I0913 17:07:25.573173801 17165 handshaker.cc:99] handshake_manager 0x7fa6ec038720: adding handshaker http_connect [0x7fa6ec040f40] at index 0
I0913 17:07:25.573545916 17165 ssl_transport_security.cc:220] HANDSHAKE START - before SSL initialization - PINIT
I0913 17:07:25.573650398 17165 ssl_transport_security.cc:220] LOOP - before SSL initialization - PINIT
I0913 17:07:25.573789243 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS write client hello - TWCH
I0913 17:07:25.573852379 17165 ref_counted.h:103] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/transport/security_handshaker.cc:113 ref 3 -> 4 handshake
I0913 17:07:25.573949878 17165 handshaker.cc:99] handshake_manager 0x7fa6ec038720: adding handshaker security [0x7fa6ec05c6e0] at index 1
I0913 17:07:25.574059668 17165 ev_posix.cc:394] (polling-api) pollset_set_add_fd(0x7fa6ec03d640, 18)
I0913 17:07:25.574176722 17165 ev_epollex_linux.cc:1353] PSS:0x7fa6ec03d640: add fd 0x7fa6ec03e720 (18)
I0913 17:07:25.574290144 17165 ev_epollex_linux.cc:616] add fd 0x7fa6ec03e720 (18) to pollable 0x7fa6ec011dc0
I0913 17:07:25.574407198 17165 ev_epollex_linux.cc:616] add fd 0x7fa6ec03e720 (18) to pollable 0x7fa6ec03fdd0
I0913 17:07:25.574524252 17165 ref_counted.h:92] subchannel_pool:0x7fa6ec00b9c8 ref 6 -> 7
I0913 17:07:25.574623148 17165 ref_counted.h:103] security_connector_refcount:0x7fa6ec013038 /home/rcheppudira/new_grpc/grpc/src/core/lib/security/security_connector/security_connector.cc:92 ref 4 -> 5 connector_arg_copy
I0913 17:07:25.574756125 17165 timer_generic.cc:364] TIMER 0x7fa6ec0387d8: SET 20036 now 273 call 0x7fa6ec038810[0x7fa70b5f12d2]
I0913 17:07:25.574843287 17165 timer_generic.cc:401] .. add to shard 0 with queue_deadline_cap=1078 => is_first_timer=false
I0913 17:07:25.575114551 17165 handshaker.cc:129] handshake_manager 0x7fa6ec038720: error="No Error" shutdown=0 index=0, args={endpoint=0x7fa6ec0403b0, args=0x7fa6ec012830 {size=12: grpc.primary_user_agent=grpc-c++/1.30.0, grpc.keepalive_time_ms=10000, grpc.keepalive_timeout_ms=10000, grpc.ssl_target_name_override=Infinera.com, grpc.client_channel_factory=0x7fa6ec00e9f0, grpc.channel_credentials=0x7fa6ec010d80, grpc.server_uri=dns:///10.220.6.50:50058, grpc.default_authority=Infinera.com, grpc.subchannel_pool=0x7fa6ec00b9c0, grpc.http2_scheme=https, grpc.security_connector=0x7fa6ec013030, grpc.subchannel_address=ipv4:10.220.6.50:50058}, read_buffer=0x7fa6ec012bf0 (length=0), exit_early=0}
I0913 17:07:25.575178246 17165 handshaker.cc:176] handshake_manager 0x7fa6ec038720: calling handshaker http_connect [0x7fa6ec040f40] at index 0
I0913 17:07:25.575312900 17165 handshaker.cc:129] handshake_manager 0x7fa6ec038720: error="No Error" shutdown=0 index=1, args={endpoint=0x7fa6ec0403b0, args=0x7fa6ec012830 {size=12: grpc.primary_user_agent=grpc-c++/1.30.0, grpc.keepalive_time_ms=10000, grpc.keepalive_timeout_ms=10000, grpc.ssl_target_name_override=Infinera.com, grpc.client_channel_factory=0x7fa6ec00e9f0, grpc.channel_credentials=0x7fa6ec010d80, grpc.server_uri=dns:///10.220.6.50:50058, grpc.default_authority=Infinera.com, grpc.subchannel_pool=0x7fa6ec00b9c0, grpc.http2_scheme=https, grpc.security_connector=0x7fa6ec013030, grpc.subchannel_address=ipv4:10.220.6.50:50058}, read_buffer=0x7fa6ec012bf0 (length=0), exit_early=0}
I0913 17:07:25.603279024 17165 handshaker.cc:176] handshake_manager 0x7fa6ec038720: calling handshaker security [0x7fa6ec05c6e0] at index 1
I0913 17:07:25.603416192 17165 tcp_posix.cc:1566] WRITE 0x7fa6ec0403b0 (peer=ipv4:10.220.6.50:50058)
I0913 17:07:25.603619012 17165 tcp_posix.cc:1616] write: "No Error"
I0913 17:07:25.603753386 17165 ref_counted.h:103] tcp:0x7fa6ec0403d8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/tcp_posix.cc:908 ref 2 -> 3 read
I0913 17:07:25.604010961 17165 tcp_posix.cc:541] TCP:0x7fa6ec0403b0 notify_on_read
I0913 17:07:25.604401513 17165 ref_counted.h:199] pollable_refcount:0x7fa6ec03fdd8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1085 unref 2 -> 1 pollset_worker
I0913 17:07:25.604615228 17165 ev_epollex_linux.cc:664] PS:0x7fa6ec03f738 (pollable:0x7fa6ec03fdd0) maybe_finish_shutdown sc=(nil) (target:!NULL) rw=(nil) (target:NULL) cpsc=1 (target:0)
I0913 17:07:25.604730047 17165 ev_posix.cc:325] (polling-api) pollset_work(0x7fa6ec03f738, 9223372036854775807) end
I0913 17:07:25.604973653 17165 ev_posix.cc:322] (polling-api) pollset_work(0x7fa6ec03f738, 9223372036854775807) begin
I0913 17:07:25.605089869 17165 ev_epollex_linux.cc:1120] PS:0x7fa6ec03f738 work hdl=(nil) worker=0x7fa7057602f0 now=273 deadline=9223372036854775807 kwp=0 pollable=0x7fa6ec03fdd0
I0913 17:07:25.605204967 17165 ref_counted.h:103] pollable_refcount:0x7fa6ec03fdd8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/ev_epollex_linux.cc:1018 ref 1 -> 2 pollset_worker
I0913 17:07:25.605318669 17165 ev_epollex_linux.cc:938] POLLABLE:0x7fa6ec03fdd0[type=pollset epfd=19 wakeup=20] poll for -1ms
I0913 17:07:25.624281973 17165 ev_epollex_linux.cc:957] POLLABLE:0x7fa6ec03fdd0 got 1 events
I0913 17:07:25.625191306 17165 ev_epollex_linux.cc:905] PS:0x7fa6ec03f738 got fd 0x7fa6ec03e720: cancel=0 read=1 write=1
I0913 17:07:25.626231103 17165 tcp_posix.cc:887] TCP:0x7fa6ec0403b0 got_read: "No Error"
I0913 17:07:25.627087357 17165 tcp_posix.cc:869] TCP:0x7fa6ec0403b0 alloc_slices
I0913 17:07:25.627883827 17165 resource_quota.cc:890] RQ anonymous_pool_7fa6ec03f7b0 ipv4:10.220.6.50:50058: alloc 8192; free_pool -> -8192
I0913 17:07:25.629396031 17165 combiner.cc:135] C:0x7fa6ec03f4f0 grpc_combiner_execute c=0x7fa6ec040cf8 last=1
I0913 17:07:25.630779167 17165 combiner.cc:199] C:0x7fa6ec03f4f0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0
I0913 17:07:25.633678419 17165 combiner.cc:222] C:0x7fa6ec03f4f0 maybe_finish_one n=0x7fa6ec040cf8
I0913 17:07:25.635280857 17165 combiner.cc:308] C:0x7fa6ec03f4f0 grpc_combiner_execute_finally c=0x7fa6ec03f820; ac=0x7fa6ec03f4f0
I0913 17:07:25.636448324 17165 combiner.cc:264] C:0x7fa6ec03f4f0 finish old_state=5
I0913 17:07:25.637369670 17165 combiner.cc:199] C:0x7fa6ec03f4f0 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=1
I0913 17:07:25.638760349 17165 combiner.cc:246] C:0x7fa6ec03f4f0 execute_final[0] c=0x7fa6ec03f820
I0913 17:07:25.639790648 17165 resource_quota.cc:321] RQ: check allocation for user 0x7fa6ec040cf0 shutdown=0 free_pool=-8192
I0913 17:07:25.640919004 17165 resource_quota.cc:347] RQ anonymous_pool_7fa6ec03f7b0 ipv4:10.220.6.50:50058: grant alloc 8192 bytes; rq_free_pool -> 9223372036854767615
I0913 17:07:25.642398521 17165 combiner.cc:264] C:0x7fa6ec03f4f0 finish old_state=3
I0913 17:07:25.643722712 17165 tcp_posix.cc:850] TCP:0x7fa6ec0403b0 read_allocation_done: "No Error"
I0913 17:07:25.644955550 17165 tcp_posix.cc:680] TCP:0x7fa6ec0403b0 call_cb 0x7fa6ec05c8d8 0x7fa70b65e450:0x7fa6ec05c6e0
I0913 17:07:25.646910547 17165 tcp_posix.cc:683] READ 0x7fa6ec0403b0 (peer=ipv4:10.220.6.50:50058) error="No Error"
I0913 17:07:25.648767487 17165 ref_counted.h:199] tcp:0x7fa6ec0403d8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/tcp_posix.cc:844 unref 3 -> 2 read
I0913 17:07:25.650205100 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS write client hello - TWCH
I0913 17:07:25.652048630 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS read server hello - TRSH
I0913 17:07:25.653957812 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS read server certific - TRSC
I0913 17:07:25.655300999 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS read server key exch - TRSKE
I0913 17:07:25.656334650 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS read server done - TRSD
I0913 17:07:25.659340898 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS write client key exc - TWCKE
I0913 17:07:25.660446066 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS write change cipher - TWCCS
I0913 17:07:25.661612974 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS write finished - TWFIN
I0913 17:07:25.662694117 17165 tcp_posix.cc:1566] WRITE 0x7fa6ec0403b0 (peer=ipv4:10.220.6.50:50058)
I0913 17:07:25.664612238 17165 tcp_posix.cc:1616] write: "No Error"
I0913 17:07:25.665905140 17165 ref_counted.h:103] tcp:0x7fa6ec0403d8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/tcp_posix.cc:908 ref 2 -> 3 read
I0913 17:07:25.667535235 17165 tcp_posix.cc:887] TCP:0x7fa6ec0403b0 got_read: "No Error"
I0913 17:07:25.668567210 17165 tcp_posix.cc:879] TCP:0x7fa6ec0403b0 do_read
I0913 17:07:25.669521521 17165 tcp_posix.cc:680] TCP:0x7fa6ec0403b0 call_cb 0x7fa6ec05c8d8 0x7fa70b65e450:0x7fa6ec05c6e0
I0913 17:07:25.670683960 17165 tcp_posix.cc:683] READ 0x7fa6ec0403b0 (peer=ipv4:10.220.6.50:50058) error="No Error"
I0913 17:07:25.671891934 17165 ref_counted.h:199] tcp:0x7fa6ec0403d8 /home/rcheppudira/new_grpc/grpc/src/core/lib/iomgr/tcp_posix.cc:844 unref 3 -> 2 read
I0913 17:07:25.673510017 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS write finished - TWFIN
I0913 17:07:25.674696760 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS read server session - TRST
I0913 17:07:25.675933230 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS read change cipher s - TRCCS
I0913 17:07:25.677194564 17165 ssl_transport_security.cc:220] LOOP - SSLv3/TLS read finished - TRFIN
I0913 17:07:25.678290792 17165 ssl_transport_security.cc:220] HANDSHAKE DONE - SSL negotiation finished succe - SSLOK
E0913 17:07:25.680856761 17165 ssl_transport_security.cc:470] assertion failed: (int)peer->property_count == current_insert_index
signal 6[SIGABRT] caught by process [/opt/infinera/thanos/local/bin/tunnelclient]
#####DumpStacktrace ########
#0 /opt/infinera/thanos/local/lib/libBaseSystem.so unsigned long backward::details::unwind<backward::StackTraceImpl<backward::system_tag::linux_tag>::callback>(backward::StackTraceImpl<backward::system_tag::linux_tag>::callback, unsigned long) [0x7fa709dd4c72]
#1 /opt/infinera/thanos/local/lib/libBaseSystem.so backward::StackTraceImpl<backward::system_tag::linux_tag>::load_here(unsigned long) [0x7fa709dd4008]
#2 /opt/infinera/thanos/local/lib/libBaseSystem.so util::Backtrace::DumpStacktrace() [0x7fa709dd2c5e]
#3 /opt/infinera/thanos/local/lib/libBaseSystem.so OsProcess::MyFailureHandler(int) [0x7fa709db54e7]
#4 /lib/x86_64-linux-gnu/libc.so.6 [0x7fa70988683f]
#5 /lib/x86_64-linux-gnu/libc.so.6 gsignal [0x7fa7098867bb]
#6 /lib/x86_64-linux-gnu/libc.so.6 abort [0x7fa709871534]
#7 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b6a1dfd]
#8 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b6a3acf]
#9 /opt/infinera/thanos/local/lib/libgrpc.so.10 tsi_handshaker_result_extract_peer(tsi_handshaker_result const*, tsi_peer*) [0x7fa70b6a6db1]
#10 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b65df19]
#11 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b65e2b2]
#12 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b65e44b]
#13 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b65e5fe]
#14 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b6117ac]
#15 /opt/infinera/thanos/local/lib/libgrpc.so.10 grpc_core::ExecCtx::Flush() [0x7fa70b611cdc]
#16 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b6098b7]
#17 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b6110bd]
#18 /opt/infinera/thanos/local/lib/libgrpc.so.10 grpc_pollset_work(grpc_pollset*, grpc_pollset_worker**, long) [0x7fa70b61859f]
#19 /opt/infinera/thanos/local/lib/libgrpc.so.10 [0x7fa70b674c8f]
#20 /opt/infinera/thanos/local/lib/libgrpc.so.10 grpc_completion_queue_next [0x7fa70b675154]
#21 /opt/infinera/thanos/local/lib/libgrpc++.so.1 grpc_impl::CompletionQueue::AsyncNextInternal(void**, bool*, gpr_timespec) [0x7fa70b09a675]
#22 /opt/infinera/thanos/local/lib/libgrpc++.so.1 grpc_impl::CompletionQueue::Next(void**, bool*) [0x7fa70b088ff6]
#23 /opt/infinera/thanos/local/lib/libgrpc++.so.1 grpc_impl::Channel::WaitForStateChangeImpl(grpc_connectivity_state, gpr_timespec) [0x7fa70b0883b4]
#24 /opt/infinera/thanos/local/bin/tunnelclient bool grpc::ChannelInterface::WaitForStateChange<gpr_timespec>(grpc_connectivity_state, gpr_timespec) [0x55d52d47a6e3]
#25 /opt/infinera/thanos/local/bin/tunnelclient bool grpc::ChannelInterface::WaitForConnected<gpr_timespec>(gpr_timespec) [0x55d52d4797fe]
#26 /opt/infinera/thanos/local/bin/tunnelclient ConnectionManager::createChannel(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::shared_ptr<grpc_impl::Channel>&) [0x55d52d472e6f]
#27 /opt/infinera/thanos/local/bin/tunnelclient ConnectionManager::connectToServer() [0x55d52d473b81]
#28 /opt/infinera/thanos/local/bin/tunnelclient boost::_mfi::mf0<void, ConnectionManager>::operator()(ConnectionManager*) const [0x55d52d47d4bc]
#29 /opt/infinera/thanos/local/bin/tunnelclient void boost::_bi::list1<boost::_bi::value<ConnectionManager*> >::operator()<boost::_mfi::mf0<void, ConnectionManager>, boost::_bi::list0>(boost::_bi::type<void>, boost::_mfi::mf0<void, ConnectionManager>&, boost::_bi::list0&, int) [0x55d52d47d41e]
#30 /opt/infinera/thanos/local/bin/tunnelclient boost::_bi::bind_t<void, boost::_mfi::mf0<void, ConnectionManager>, boost::_bi::list1<boost::_bi::value<ConnectionManager*> > >::operator()() [0x55d52d47d2cc]
#31 /opt/infinera/thanos/local/bin/tunnelclient boost::detail::thread_data<boost::_bi::bind_t<void, boost::_mfi::mf0<void, ConnectionManager>, boost::_bi::list1<boost::_bi::value<ConnectionManager*> > > >::run() [0x55d52d47d0f3]
#####End DumpStacktrace ########
Please help me out in fixing the same. Is there any fix already available?
Thanks
Manish Khandelwal
Easwar Swaminathan
Sep 14, 2022, 2:01:16 PM9/14/22
to grpc.io
Could you also provide some code snippets from what you are trying to do. Thanks.
Manish Khandelwal
Sep 21, 2022, 9:15:12 PM9/21/22
to grpc.io
Hi Easwar,
Below is the code snippets.
std::shared_ptr<grpc::ChannelCredentials> ConnectionManager::createChannelCredentials()
{
grpc::SslCredentialsOptions sslCredOptions;
std::string rootCertPath("/var/security/x509/trustedCerts/RSA_2048_SHA_512_root.crt");
std::string clientKeyPath("/var/security/x509/keys/RSA_2048_SHA_512_client.key");
std::string clientCertPath("/var/security/x509/certs/RSA_2048_SHA_512_client.crt");
//Here caCert, clientCert, ClientKey is of type string
getFileData(rootCertPath, caCert);//getFileData() will read and populate cert/key from the provided loc
sslCredOptions.pem_root_certs = caCert;
getFileData(clientKeyPath, clientKey);
sslCredOptions.pem_private_key = clientKey;
getFileData(clientCertPath, clientCert);
sslCredOptions.pem_cert_chain = clientCert;
return grpc::SslCredentials(sslCredOptions);
}
//Here server
std::shared_ptr<grpc::Channel> ConnectionManager::createChannel(const std::string &serverAddress, std::shared_ptr<grpc::Channel>& channel_)
{
std::shared_ptr<grpc::ChannelCredentials> channelCreds = ::grpc::InsecureChannelCredentials();
channelCreds = createChannelCredentials();
ChannelArguments channelArg;
std::string san("<CertSANName>");
channelArg.SetInt(GRPC_ARG_KEEPALIVE_TIME_MS, keepAliveTime_);
channelArg.SetInt(GRPC_ARG_KEEPALIVE_TIMEOUT_MS, keepAliveTime_);
channelArg.SetSslTargetNameOverride(san);
channel_ = grpc::CreateCustomChannel(serverAddress_, channelCreds, channelArg);
std::chrono::time_point<std::chrono::system_clock> deadline = std::chrono::system_clock::now() + std::chrono::seconds(10);
//if(!channel_->WaitForConnected(gpr_time_add(gpr_now(GPR_CLOCK_REALTIME), gpr_time_from_seconds(600, GPR_TIMESPAN))) || channel_->GetState(false) != grpc_connectivity_state::GRPC_CHANNEL_READY)
if(!channel_->WaitForConnected(deadline) || channel_->GetState(false) != grpc_connectivity_state::GRPC_CHANNEL_READY)//It is crashing here
{
//notify and start some backoff logic
}
else
{
//Secure connection established
....
....
....
}
return channel_;
}
{
grpc::SslCredentialsOptions sslCredOptions;
std::string rootCertPath("/var/security/x509/trustedCerts/RSA_2048_SHA_512_root.crt");
std::string clientKeyPath("/var/security/x509/keys/RSA_2048_SHA_512_client.key");
std::string clientCertPath("/var/security/x509/certs/RSA_2048_SHA_512_client.crt");
//Here caCert, clientCert, ClientKey is of type string
getFileData(rootCertPath, caCert);//getFileData() will read and populate cert/key from the provided loc
sslCredOptions.pem_root_certs = caCert;
getFileData(clientKeyPath, clientKey);
sslCredOptions.pem_private_key = clientKey;
getFileData(clientCertPath, clientCert);
sslCredOptions.pem_cert_chain = clientCert;
return grpc::SslCredentials(sslCredOptions);
}
//Here server
std::shared_ptr<grpc::Channel> ConnectionManager::createChannel(const std::string &serverAddress, std::shared_ptr<grpc::Channel>& channel_)
{
std::shared_ptr<grpc::ChannelCredentials> channelCreds = ::grpc::InsecureChannelCredentials();
channelCreds = createChannelCredentials();
ChannelArguments channelArg;
std::string san("<CertSANName>");
channelArg.SetInt(GRPC_ARG_KEEPALIVE_TIME_MS, keepAliveTime_);
channelArg.SetInt(GRPC_ARG_KEEPALIVE_TIMEOUT_MS, keepAliveTime_);
channelArg.SetSslTargetNameOverride(san);
channel_ = grpc::CreateCustomChannel(serverAddress_, channelCreds, channelArg);
std::chrono::time_point<std::chrono::system_clock> deadline = std::chrono::system_clock::now() + std::chrono::seconds(10);
//if(!channel_->WaitForConnected(gpr_time_add(gpr_now(GPR_CLOCK_REALTIME), gpr_time_from_seconds(600, GPR_TIMESPAN))) || channel_->GetState(false) != grpc_connectivity_state::GRPC_CHANNEL_READY)
if(!channel_->WaitForConnected(deadline) || channel_->GetState(false) != grpc_connectivity_state::GRPC_CHANNEL_READY)//It is crashing here
{
//notify and start some backoff logic
}
else
{
//Secure connection established
....
....
....
}
return channel_;
}
Tested the same with below openssl utility and I can see in the pcap that handshake is happening successfully.
"sudo openssl s_client -connect <ip>:<port>-cert /var/security/x509/certs/RSA_2048_SHA_512_client.crt -key /var/security/x509/keys/RSA_2048_SHA_512_client.key -CAfile /var/security/x509/trusted_certs/RSA_2048_SHA_512_root.crt -state -debug"
Thanks
Manish Khandelwal
Manish Khandelwal
Sep 25, 2022, 9:43:15 PM9/25/22
to grpc.io
Hi Google Team,
Please hep me in understanding what is going wrong here and how I can fix this.
Is this a known issue please share some details.
Thanks
Manish Khandelwal
Zhen Lian
Oct 24, 2022, 6:36:24 PM10/24/22
to grpc.io
It seems the server is using `grpc::InsecureChannelCredentials` while the client is using `SslCredentials`. Theoretically speaking they should both use SSL credentials if you want TLS functionality. You can try switch `grpc::InsecureChannelCredentials` to `SslCredentials` and see if the error still persists.
Reply all
Reply to author
Forward
0 new messages