TLS Handshake failures due to epollex delays

[ioanna del]

Hello,

I am using a c++ gRPC client in version v1.39.1 which runs in Red Hat Enterprise Linux release 8.4 (version 4.18.0-305.12.1.el8_4.x86_64). The version of gcc used is 8.0.1. Also 8.2.1 has been used. The gRPC client communicates with a java gRPC server. The communication is over TLS and TLS handshake can be completed successfully. Thus, the certificates, keys and cipher suites seems to be proper. However, there are several failed TLS handshakes until a successful one.

We have noticed big delays in the c++ grpc client side. These delays can affect the TLS handshake outcome. A number of TLS handshakes seems to be failed because the whole handshake cannot be completed within 10 seconds as required. This TLS timer of 10 seconds seems to expire either in gRPC client or in gRPC server. Then the TLS handshake fails and the client's socket is closed. Afterwards a new attempt begins through a new socket. There might be more that one failed attempts. Finally, at some point, the TLS handshake will be completed successfully at exact 10 seconds. 

I have enabled the grpc client logs and pcap has been captured in client's node. In the attached screeshot from the pcap,  the first handshake begin with a Client Hello at 16:38:44 and the Server Hello arrives immediately at the same time. However, according to the grpc client logs, the Server Hello is read after 5 seconds at 18:38:49!

Such delays of 5 seconds are always happening in the grpc client for all the received messages. During this time frame the grpc client seems to wait for an epoll wakeup signal which is extermely delayed! Please note that epollex should be available for my kernel (4.18 which is higher than 4.5). Could you please explain why there are these delays and epoll is not working properly? How this problem could be resolved?

`D1020 16:38:39.753959775 3644097 ev_posix.cc:173]            Using polling engine: epollex

D1020 16:38:39.754780035 3644097 lb_policy_registry.cc:42]   registering LB policy factory for "grpclb"

D1020 16:38:39.754827531 3644097 lb_policy_registry.cc:42]   registering LB policy factory for "priority_experimental"

D1020 16:38:39.754841439 3644097 lb_policy_registry.cc:42]   registering LB policy factory for "weighted_target_experimental"

D1020 16:38:39.754851012 3644097 lb_policy_registry.cc:42]   registering LB policy factory for "pick_first"

D1020 16:38:39.754859649 3644097 lb_policy_registry.cc:42]   registering LB policy factory for "round_robin"

D1020 16:38:39.754875408 3644097 lb_policy_registry.cc:42]   registering LB policy factory for "ring_hash_experimental"

D1020 16:38:39.754889653 3644097 dns_resolver_ares.cc:497]   Using ares dns resolver

D1020 16:38:39.755538877 3644097 certificate_provider_registry.cc:33] registering certificate provider factory for "file_watcher"

D1020 16:38:39.755588913 3644097 lb_policy_registry.cc:42]   registering LB policy factory for "cds_experimental"

D1020 16:38:39.755605378 3644097 lb_policy_registry.cc:42]   registering LB policy factory for "xds_cluster_impl_experimental"

D1020 16:38:39.755615676 3644097 lb_policy_registry.cc:42]   registering LB policy factory for "xds_cluster_resolver_experimental"

D1020 16:38:39.755625453 3644097 lb_policy_registry.cc:42]   registering LB policy factory for "xds_cluster_manager_experimental"

I1020 16:38:39.755676093 3644097 timer_manager.cc:88]        Spawn timer thread

I1020 16:38:39.755738013 3644097 init.cc:167]                grpc_init(void)

I1020 16:38:39.755832650 3644097 ssl_credentials.cc:140]     grpc_ssl_credentials_create(pem_root_certs=-----BEGIN CERTIFICATE-----

MIIDezCCAmOgAwIBAgIEWiEfnDANBgkqhkiG9w0BAQsFADBnMRowGAYDVQQDExFk

Y2FlLXNpbXVsYXRvci1jYTENMAsGA1UECxMETUFOTzEOMAwGA1UEChMFTm9raWEx

EDAOBgNVBAcTB1dyb2NsYXcxCzAJBgNVBAgTAkRMMQswCQYDVQQGEwJQTDAeFw0y

MTEwMTkxNTAwMTlaFw0yMzEwMTkxNTAwMTlaMGcxGjAYBgNVBAMTEWRjYWUtc2lt

dWxhdG9yLWNhMQ0wCwYDVQQLEwRNQU5PMQ4wDAYDVQQKEwVOb2tpYTEQMA4GA1UE

BxMHV3JvY2xhdzELMAkGA1UECBMCREwxCzAJBgNVBAYTAlBMMIIBIjANBgkqhkiG

9w0BAQEFAAOCAQ8AMIIBCgKCAQEAnSVyGx2m5oXViAwg/6YUSuLnv3TpNYxV0yMw

8awrGCmcE7LlkvJuDEf/LVinI+XPqjdjI9C8AFnzBQr98sSkzF0Y7VrJV+Rg8C9c

xz8H+vRn89rTVv9L15Lag8DabQ3QKaiR3JvC/D6acLVfaWazTNYsKAnI9G1mYvp2

5impewES/Io1rxvgQxulMUFPgpwGyvkfJI5pfl7pi17Ib2weTlZgPqPXDfm2d/Bp

oxUs2mzavmg11zliYg8BKAtxqTQo+TR092ekHUOwm6c73ubVw70Cgod3r+RKMY37

fhiOzaf0ZJQ7PfCBL/wtRyZsV6ZJR+Rwd836JWjYyChffU/2IQIDAQABoy8wLTAM

BgNVHRMEBTADAQH/MB0GA1UdDgQWBBTSBH9RX6eu5Aa92sizWCSL4EqLezANBgkq

hkiG9w0BAQsFAAOCAQEAK6zx/yCx3kT07IxLqWI46WUtlEoBMHj0k42OtCxol5IF

5qD1czoIBCuJUuMAnuNAYw5QuMGwv2gVgo8eAi2fZ2OFnN8GPVcYPPwtpGV0ImGF

tZQVcHyZ8bM89iDLkQF2Sbul5+YtfwtE9sBskmuORFmnz3xpwzo6gn43rc28rLSk

XMHicz4bY9or5ucPG7QesYmAraF9VuDUbCyH5nsZZLSJGfkEeY5/Y+G6HpEqo4T6

Sx6nIWWh+9cvmdeN5UT7hytRz47x1nlD58jl42drPPybSg8vsmg8aPbRI1eaouUn

0nOwZrbH4AI1SkVhaMbfhw6KJomuyDQgYy/ROUtV5w==

-----END CERTIFICATE-----

, pem_key_cert_pair=0x7ffc3282eac0, verify_options=(nil), reserved=(nil))

I1020 16:38:39.755880558 3644097 init.cc:167]                grpc_init(void)

I1020 16:38:39.755909976 3644097 init.cc:213]                grpc_shutdown(void)

I1020 16:38:39.755997262 3644097 init.cc:167]                grpc_init(void)

I1020 16:38:39.756042850 3644097 secure_channel_create.cc:181] grpc_secure_channel_create(creds=0x15b7600, target=10.84.2.178:8085, args=0x7ffc3282e990, reserved=(nil))

I1020 16:38:39.756345268 3644097 init.cc:167]                grpc_init(void)

I1020 16:38:39.756343786 3644569 timer_generic.cc:719]       TIMER CHECK BEGIN: now=2 next=9223372036854775807 tls_min=0 glob_min=0

I1020 16:38:39.756495984 3644569 timer_generic.cc:614]         .. shard[0]->min_deadline = 1

I1020 16:38:39.756523567 3644569 timer_generic.cc:537]         .. shard[0]: heap_empty=true

I1020 16:38:39.756539695 3644569 timer_generic.cc:512]         .. shard[0]->queue_deadline_cap --> 1002

I1020 16:38:39.756554676 3644569 timer_generic.cc:578]         .. shard[0] popped 0

I1020 16:38:39.756568296 3644569 timer_generic.cc:632]         .. result --> 1, shard[0]->min_deadline 1 --> 1003, now=2

I1020 16:38:39.756584465 3644569 timer_generic.cc:537]         .. shard[1]: heap_empty=true

I1020 16:38:39.756596299 3644569 timer_generic.cc:512]         .. shard[1]->queue_deadline_cap --> 1002

I1020 16:38:39.756608463 3644569 timer_generic.cc:578]         .. shard[1] popped 0

I1020 16:38:39.756620600 3644569 timer_generic.cc:632]         .. result --> 1, shard[1]->min_deadline 1 --> 1003, now=2

I1020 16:38:39.756635985 3644569 timer_generic.cc:537]         .. shard[2]: heap_empty=true

I1020 16:38:39.756633959 3644097 ev_posix.cc:353]            (polling-api) pollset_set_create(0x15fd4d0)

I1020 16:38:39.756831676 3644097 client_channel.cc:1099]     chand=0x15fd278: creating client_channel for channel stack 0x15fd1c8

I1020 16:38:39.756856862 3644097 ev_posix.cc:304]            (polling-api) pollset_init(0x15f9ee0)

I1020 16:38:39.756870192 3644097 timer_generic.cc:367]       TIMER 0x15fd5d0: SET 5002 now 2 call 0x15fd608[0x7fc0746d0679]

I1020 16:38:39.756906778 3644097 timer_generic.cc:404]         .. add to shard 0 with queue_deadline_cap=1002 => is_first_timer=false

I1020 16:38:39.756917460 3644097 ev_posix.cc:365]            (polling-api) pollset_set_add_pollset(0x15fd4d0, 0x15f9ee0)

I1020 16:38:39.756923031 3644097 ev_epollex_linux.cc:1455]   PSS:0x15fd4d0: add pollset 0x15f9ee0

I1020 16:38:39.756939170 3644097 ev_epollex_linux.cc:566]    (fd-trace) Pollable_create: created epfd: 11 (type: 0)

I1020 16:38:39.756956407 3644097 ev_epollex_linux.cc:1253]   PS:0x15f9ee0 active pollable transition from empty to multi

I1020 16:38:39.756966674 3644097 ref_counted.h:86]           pollable_refcount:0x15fd858 /code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/ev_epollex_linux.cc:1284 ref 1 -> 2 pollset_set

I1020 16:38:39.756978430 3644097 ref_counted.h:182]          pollable_refcount:0x15fd858 /code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/ev_epollex_linux.cc:1483 unref 2 -> 1 pollset_set

I1020 16:38:39.757380242 3644097 init.cc:167]                grpc_init(void)

I1020 16:38:39.757429722 3644097 init.cc:213]                grpc_shutdown(void)

I1020 16:38:39.757441822 3644097 init.cc:213]                grpc_shutdown(void)

I1020 16:38:39.757612302 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:39.757646710 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: IDLE

D1020 16:38:39.757655357 3644570 transport.h:85]             CLIENT_CHANNEL 0x15fd1c8:0x15fd150 REF TryToConnect

I1020 16:38:39.757663811 3644570 ref_counted.h:115]          stream_refcount:0x15fd1c8 /code/grpc-rpms/grpc-1.39.1/src/core/lib/transport/transport.h:88 ref 1 -> 2 TryToConnect

I1020 16:38:39.757701227 3644570 work_serializer.cc:55]      WorkSerializer::Run() 0x15face0 Scheduling callback [/code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/client_channecc:1844]

I1020 16:38:39.757708792 3644570 work_serializer.cc:65]        Executing immediately

I1020 16:38:39.757735775 3644570 client_channel.cc:1565]     chand=0x15fd278: starting name resolution

D1020 16:38:39.757745199 3644570 transport.h:85]             CLIENT_CHANNEL 0x15fd1c8:0x15fd150 REF ResolverResultHandler

I1020 16:38:39.757750776 3644570 ref_counted.h:115]          stream_refcount:0x15fd1c8 /code/grpc-rpms/grpc-1.39.1/src/core/lib/transport/transport.h:88 ref 2 -> 3 ResolverResultHandler

I1020 16:38:39.757941961 3644570 connectivity_state.cc:156]  ConnectivityStateTracker client_channel[0x15fd338]: IDLE -> CONNECTING (started resolving, OK)

D1020 16:38:39.758025530 3644570 dns_resolver_ares.cc:167]   (c-ares resolver) resolver:0x7fc054000fd0 AresDnsResolver::StartLocked() is called.

I1020 16:38:39.758038782 3644570 ref_counted.h:86]           Resolver:0x7fc054000fd8 /code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc:4 ref 1 -> 2 dns-resolving

D1020 16:38:39.758048599 3644570 grpc_ares_wrapper.cc:1079]  (c-ares resolver) request:0x7fc054001670 c-ares grpc_dns_lookup_ares_locked_impl name=10.84.2.178:8085, default_port=https

I1020 16:38:39.756654587 3644569 timer_generic.cc:512]         .. shard[2]->queue_deadline_cap --> 1002

I1020 16:38:39.758180252 3644570 grpc_ares_wrapper.cc:566]   (c-ares resolver) request:0x7fc054001670 c-ares address sorting: input[0]=10.84.2.178:8085

I1020 16:38:39.758183175 3644569 timer_generic.cc:578]         .. shard[2] popped 0

I1020 16:38:39.758206923 3644569 timer_generic.cc:632]         .. result --> 1, shard[2]->min_deadline 1 --> 1003, now=2

I1020 16:38:39.758238309 3644569 timer_generic.cc:537]         .. shard[3]: heap_empty=true

I1020 16:38:39.758263933 3644569 timer_generic.cc:512]         .. shard[3]->queue_deadline_cap --> 1002

I1020 16:38:39.758278009 3644570 grpc_ares_wrapper.cc:566]   (c-ares resolver) request:0x7fc054001670 c-ares address sorting: output[0]=10.84.2.178:8085

I1020 16:38:39.758287013 3644569 timer_generic.cc:578]         .. shard[3] popped 0

D1020 16:38:39.758303078 3644570 dns_resolver_ares.cc:439]   (c-ares resolver) resolver:0x7fc054000fd0 Started resolving. pending_request_:0x7fc054001670

I1020 16:38:39.758310774 3644570 client_channel.cc:1578]     chand=0x15fd278: created resolver=0x7fc054000fd0

D1020 16:38:39.758316997 3644570 transport.h:102]            CLIENT_CHANNEL 0x15fd1c8:0x15fd150 UNREF TryToConnect

I1020 16:38:39.758309122 3644569 timer_generic.cc:632]         .. result --> 1, shard[3]->min_deadline 1 --> 1003, now=2

I1020 16:38:39.758379619 3644569 timer_generic.cc:741]       TIMER CHECK END: r=1; next=1003

I1020 16:38:39.758323267 3644570 ref_counted.h:182]          stream_refcount:0x15fd1c8 /code/grpc-rpms/grpc-1.39.1/src/core/lib/transport/transport.h:105 unref 3 -> 2 TryToConnect

I1020 16:38:39.758514573 3644570 work_serializer.cc:102]     WorkSerializer::DrainQueue() 0x15face0

I1020 16:38:39.758530031 3644570 work_serializer.cc:117]       Queue Drained

D1020 16:38:39.758540007 3644570 exec_ctx.cc:37]             running closure 0x7fc0540010a8: created [/code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_rolver_ares.cc:157]: scheduled [/code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/resolver/dns/c_ares/grpc_ares_wrapper.cc:628]

I1020 16:38:39.758552739 3644570 work_serializer.cc:55]      WorkSerializer::Run() 0x15face0 Scheduling callback [/code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/resolver/dns/ares/dns_resolver_ares.cc:310]

I1020 16:38:39.758558879 3644570 work_serializer.cc:65]        Executing immediately

I1020 16:38:39.758603818 3644570 client_channel.cc:1231]     chand=0x15fd278: got resolver result

I1020 16:38:39.758416708 3644569 timer_manager.cc:188]       sleep for a 1001 milliseconds

I1020 16:38:39.758648411 3644570 client_channel.cc:1285]     chand=0x15fd278: resolver returned no service config. Using default service config for channel.

I1020 16:38:39.758808475 3644570 client_channel.cc:1465]     chand=0x15fd278: resolver returned updated service config: "{}"

I1020 16:38:39.758832322 3644570 client_channel.cc:1492]     chand=0x15fd278: using ConfigSelector (nil)

D1020 16:38:39.758863556 3644570 transport.h:85]             CLIENT_CHANNEL 0x15fd1c8:0x15fd150 REF ClientChannelControlHelper

I1020 16:38:39.758874945 3644570 ref_counted.h:115]          stream_refcount:0x15fd1c8 /code/grpc-rpms/grpc-1.39.1/src/core/lib/transport/transport.h:88 ref 2 -> 3 ClientChannelControlHelper

I1020 16:38:39.758932828 3644570 ev_posix.cc:353]            (polling-api) pollset_set_create(0x7fc0540025c0)

I1020 16:38:39.758961471 3644570 client_channel.cc:1425]     chand=0x15fd278: created new LB policy 0x7fc054002410

I1020 16:38:39.758969591 3644570 ev_posix.cc:378]            (polling-api) pollset_set_add_pollset_set(0x7fc0540025c0, 0x15fd4d0)

I1020 16:38:39.758974899 3644570 ev_epollex_linux.cc:1492]   PSS: merge (0x7fc0540025c0, 0x15fd4d0)

I1020 16:38:39.758984485 3644570 ev_epollex_linux.cc:1526]   PSS: parent 0x7fc0540025c0 to 0x15fd4d0

I1020 16:38:39.759001114 3644570 client_channel.cc:1407]     chand=0x15fd278: Updating child policy 0x7fc054002410

I1020 16:38:39.759021247 3644570 child_policy_handler.cc:214] [child_policy_handler 0x7fc054002410] creating new child policy pick_first

I1020 16:38:39.759041328 3644570 ref_counted.h:86]           LoadBalancingPolicy:0x7fc054002418 /code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/lb_policy/child_policy_handler.:261 ref 1 -> 2 Helper

I1020 16:38:39.759098027 3644570 ev_posix.cc:353]            (polling-api) pollset_set_create(0x7fc054002920)

I1020 16:38:39.759111813 3644570 pick_first.cc:147]          Pick First 0x7fc0540027e0 created.

I1020 16:38:39.759121249 3644570 child_policy_handler.cc:275] [child_policy_handler 0x7fc054002410] created new LB policy "pick_first" (0x7fc0540027e0)

I1020 16:38:39.759141032 3644570 ev_posix.cc:378]            (polling-api) pollset_set_add_pollset_set(0x7fc054002920, 0x7fc0540025c0)

I1020 16:38:39.759147774 3644570 ev_epollex_linux.cc:1492]   PSS: merge (0x7fc054002920, 0x7fc0540025c0)

I1020 16:38:39.759158868 3644570 ev_epollex_linux.cc:1526]   PSS: parent 0x7fc054002920 to 0x15fd4d0

I1020 16:38:39.759168312 3644570 child_policy_handler.cc:233] [child_policy_handler 0x7fc054002410] updating child policy 0x7fc0540027e0

I1020 16:38:39.759178972 3644570 pick_first.cc:266]          Pick First 0x7fc0540027e0 received update with 1 addresses

I1020 16:38:39.759222831 3644570 subchannel_list.h:363]      [pick_first 0x7fc0540027e0] Creating subchannel list 0x7fc054002e50 for 1 subchannels

I1020 16:38:39.761477891 3644570 ref_counted.h:86]           security_connector_refcount:0x7fc054002538 /code/grpc-rpms/grpc-1.39.1/src/core/lib/security/security_connector/security_connectorc:94 ref 1 -> 2 connector_arg_copy

I1020 16:38:39.761553940 3644570 ref_counted.h:182]          security_connector_refcount:0x7fc054002538 /code/grpc-rpms/grpc-1.39.1/src/core/ext/transport/chttp2/client/secure/secure_channel_eate.cc:120 unref 2 -> 1 lb_channel_create

I1020 16:38:39.761611191 3644570 ref_counted.h:86]           security_connector_refcount:0x7fc054002538 /code/grpc-rpms/grpc-1.39.1/src/core/lib/security/security_connector/security_connectorc:94 ref 1 -> 2 connector_arg_copy

I1020 16:38:39.761675376 3644570 ev_posix.cc:353]            (polling-api) pollset_set_create(0x7fc05402ee10)

I1020 16:38:39.761732232 3644570 ref_counted.h:86]           security_connector_refcount:0x7fc054002538 /code/grpc-rpms/grpc-1.39.1/src/core/lib/security/security_connector/security_connectorc:94 ref 2 -> 3 connector_arg_copy

I1020 16:38:39.761786098 3644570 dual_ref_counted.h:262]     Subchannel:0x7fc0540296d0 ref 1 -> 2; (weak_refs=0)

I1020 16:38:39.761827378 3644570 ref_counted.h:86]           security_connector_refcount:0x7fc054002538 /code/grpc-rpms/grpc-1.39.1/src/core/lib/security/security_connector/security_connectorc:94 ref 3 -> 4 connector_arg_copy

I1020 16:38:39.761863498 3644570 dual_ref_counted.h:75]      Subchannel:0x7fc0540296d0 unref 2 -> 1, weak_ref 0 -> 1

I1020 16:38:39.761872483 3644570 dual_ref_counted.h:177]     Subchannel:0x7fc0540296d0 weak_unref 1 -> 0 (refs=1)

I1020 16:38:39.761881778 3644570 ref_counted.h:182]          security_connector_refcount:0x7fc054002538 /code/grpc-rpms/grpc-1.39.1/src/core/lib/security/security_connector/security_connectorc:88 unref 4 -> 3 connector_arg_destroy

I1020 16:38:39.761896496 3644570 subchannel.cc:740]          Subchannel=0x7fc0540296d0: Throttling keepalive time to 300000

I1020 16:38:39.761906689 3644570 ref_counted.h:86]           security_connector_refcount:0x7fc054002538 /code/grpc-rpms/grpc-1.39.1/src/core/lib/security/security_connector/security_connectorc:94 ref 3 -> 4 connector_arg_copy

I1020 16:38:39.761913787 3644570 ref_counted.h:182]          security_connector_refcount:0x7fc054002538 /code/grpc-rpms/grpc-1.39.1/src/core/lib/security/security_connector/security_connectorc:88 unref 4 -> 3 connector_arg_destroy

I1020 16:38:39.761931767 3644570 client_channel.cc:456]      chand=0x15fd278: creating subchannel wrapper 0x7fc05402fce0 for subchannel 0x7fc0540296d0

D1020 16:38:39.761938301 3644570 transport.h:85]             CLIENT_CHANNEL 0x15fd1c8:0x15fd150 REF SubchannelWrapper

I1020 16:38:39.761944076 3644570 ref_counted.h:115]          stream_refcount:0x15fd1c8 /code/grpc-rpms/grpc-1.39.1/src/core/lib/transport/transport.h:88 ref 3 -> 4 SubchannelWrapper

I1020 16:38:39.762136678 3644570 subchannel_list.h:383]      [pick_first 0x7fc0540027e0] subchannel list 0x7fc054002e50 index 0: Created subchannel 0x7fc05402fce0 for address 10.84.2.178:8085 args={

I1020 16:38:39.762159173 3644570 ref_counted.h:86]           LoadBalancingPolicy:0x7fc0540027e8 /code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/lb_policy/pick_first/pick_firstc:94 ref 1 -> 2 subchannel_list

I1020 16:38:39.762182475 3644570 subchannel_list.h:310]      [pick_first 0x7fc0540027e0] subchannel list 0x7fc054002e50 index 0 of 1 (subchannel 0x7fc05402fce0): starting watch (from IDLE)

I1020 16:38:39.762190038 3644570 ref_counted.h:86]           SubchannelList:0x7fc054002e58 /code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/lb_policy/subchannel_list.h:319 ref -> 2 Watcher

I1020 16:38:39.762269265 3644570 ref_counted.h:86]           SubchannelWrapper:0x7fc05402fce8 /code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/client_channel.cc:510 ref 1 -> 2 tcherWrapper

I1020 16:38:39.762309066 3644570 ev_posix.cc:378]            (polling-api) pollset_set_add_pollset_set(0x7fc05402ee10, 0x7fc054002920)

I1020 16:38:39.762315981 3644570 ev_epollex_linux.cc:1492]   PSS: merge (0x7fc05402ee10, 0x7fc054002920)

I1020 16:38:39.762332905 3644570 ev_epollex_linux.cc:1526]   PSS: parent 0x7fc05402ee10 to 0x15fd4d0

I1020 16:38:39.762409072 3644570 dual_ref_counted.h:311]     Subchannel:0x7fc0540296d0 /code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/subchannel.cc:944 weak_ref 0 -> 1 (refs= connecting

I1020 16:38:39.762550323 3644570 socket_utils_common_posix.cc:353] TCP_USER_TIMEOUT is available. TCP_USER_TIMEOUT will be used thereafter

I1020 16:38:39.762571467 3644570 socket_utils_common_posix.cc:361] Enabling TCP_USER_TIMEOUT with a timeout of 10000 ms

I1020 16:38:39.762642445 3644570 ev_posix.cc:254]            (polling-api) fd_create(13, tcp-client:ipv4:10.84.2.178:8085, 1)

I1020 16:38:39.762657242 3644570 ev_posix.cc:255]            (fd-trace) fd_create(13, tcp-client:ipv4:10.84.2.178:8085, 1)

D1020 16:38:39.762696395 3644570 ev_epollex_linux.cc:176]    FD 13 0x7fc05402c610 create tcp-client:ipv4:10.84.2.178:8085 fd=13

I1020 16:38:39.762710773 3644570 ev_posix.cc:395]            (polling-api) pollset_set_add_fd(0x7fc05402ee10, 13)

I1020 16:38:39.762720076 3644570 ev_epollex_linux.cc:1357]   PSS:0x7fc05402ee10: add fd 0x7fc05402c610 (13)

I1020 16:38:39.762729530 3644570 ev_epollex_linux.cc:617]    add fd 0x7fc05402c610 (13) to pollable 0x15fd850

D1020 16:38:39.762741095 3644570 ev_epollex_linux.cc:353]    FD 13 0x7fc05402c610   ref 2 1 -> 3 [pollset_set; /code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/ev_epollex_linux.cc:1371]

I1020 16:38:39.762763350 3644570 ref_counted.h:86]           security_connector_refcount:0x7fc054002538 /code/grpc-rpms/grpc-1.39.1/src/core/lib/security/security_connector/security_connectorc:94 ref 3 -> 4 connector_arg_copy

I1020 16:38:39.762894794 3644570 tcp_client_posix.cc:323]    CLIENT_CONNECT: ipv4:10.84.2.178:8085: asynchronously connecting fd 0x7fc05402c610

I1020 16:38:39.762909873 3644570 timer_generic.cc:367]       TIMER 0x7fc054001900: SET 20004 now 4 call 0x7fc054001938[0x7fc07492155f]

I1020 16:38:39.762930343 3644570 timer_generic.cc:404]         .. add to shard 0 with queue_deadline_cap=1002 => is_first_timer=false

D1020 16:38:39.762944137 3644570 lockfree_event.cc:99]       LockfreeEvent::NotifyOn: 0x7fc05402c658 curr=0 closure=0x7fc054001988

I1020 16:38:39.762969400 3644570 client_channel.cc:1503]     chand=0x15fd278: switching to ConfigSelector (nil)

I1020 16:38:39.763174593 3644570 ref_counted.h:182]          Resolver:0x7fc054000fd8 /code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/resolver/dns/c_ares/dns_resolver_ares.cc:3 unref 2 -> 1 dns-resolving

I1020 16:38:39.763197106 3644570 work_serializer.cc:102]     WorkSerializer::DrainQueue() 0x15face0

I1020 16:38:39.763203878 3644570 work_serializer.cc:117]       Queue Drained

D1020 16:38:39.763211924 3644570 exec_ctx.cc:46]             closure 0x7fc0540010a8 finished

D1020 16:38:39.763220776 3644570 exec_ctx.cc:37]             running closure 0x7fc05402cfa8: created [/code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/subchannel.cc:384]: scheded [/code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/subchannel.cc:375]

I1020 16:38:39.763232740 3644570 client_channel.cc:628]      chand=0x15fd278: connectivity change for subchannel wrapper 0x7fc05402fce0 subchannel 0x7fc0540296d0; hopping into work_serializer

I1020 16:38:39.763257108 3644570 work_serializer.cc:55]      WorkSerializer::Run() 0x15face0 Scheduling callback [/code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/client_channecc:640]

I1020 16:38:39.763266347 3644570 work_serializer.cc:65]        Executing immediately

I1020 16:38:39.763279376 3644570 client_channel.cc:663]      chand=0x15fd278: processing connectivity change in work serializer for subchannel wrapper 0x7fc05402fce0 subchannel 0x7fc0540296d0 watche0x7fc054003590

I1020 16:38:39.763314168 3644570 subchannel_list.h:243]      [pick_first 0x7fc0540027e0] subchannel list 0x7fc054002e50 index 0 of 1 (subchannel 0x7fc05402fce0): connectivity changed: state=CONNECTI, shutting_down=0, pending_watcher=0x7fc054003590

I1020 16:38:39.763328588 3644570 ref_counted.h:86]           LoadBalancingPolicy:0x7fc0540027e8 /code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/lb_policy/pick_first/pick_firstc:415 ref 2 -> 3 QueuePicker

I1020 16:38:39.763368872 3644570 client_channel.cc:995]      chand=0x15fd278: update: state=CONNECTING status=(OK) picker=0x7fc054001ab0

I1020 16:38:39.763398236 3644570 work_serializer.cc:102]     WorkSerializer::DrainQueue() 0x15face0

I1020 16:38:39.763409299 3644570 work_serializer.cc:117]       Queue Drained

D1020 16:38:39.763419194 3644570 exec_ctx.cc:46]             closure 0x7fc05402cfa8 finished

I1020 16:38:39.863537616 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:39.863605654 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:39.963722668 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:39.963788777 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:40.064652620 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:40.064747307 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:40.164962452 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:40.165028831 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:40.265146094 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:40.265218827 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:40.365358415 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:40.365434842 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:40.465644279 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:40.465713169 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:40.565836909 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:40.565927125 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:40.666044076 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:40.666112890 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:40.756867561 3644569 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:40.756951646 3644569 timer_generic.cc:719]       TIMER CHECK BEGIN: now=1003 next=9223372036854775807 tls_min=0 glob_min=1003

I1020 16:38:40.756963366 3644569 timer_generic.cc:614]         .. shard[3]->min_deadline = 1003

I1020 16:38:40.756971806 3644569 timer_generic.cc:537]         .. shard[3]: heap_empty=true

I1020 16:38:40.756978247 3644569 timer_generic.cc:512]         .. shard[3]->queue_deadline_cap --> 2003

I1020 16:38:40.756984185 3644569 timer_generic.cc:578]         .. shard[3] popped 0

I1020 16:38:40.756989436 3644569 timer_generic.cc:632]         .. result --> 1, shard[3]->min_deadline 1003 --> 2004, now=1003

I1020 16:38:40.756998011 3644569 timer_generic.cc:537]         .. shard[2]: heap_empty=true

I1020 16:38:40.757003224 3644569 timer_generic.cc:512]         .. shard[2]->queue_deadline_cap --> 2003

I1020 16:38:40.757008401 3644569 timer_generic.cc:578]         .. shard[2] popped 0

I1020 16:38:40.757013350 3644569 timer_generic.cc:632]         .. result --> 1, shard[2]->min_deadline 1003 --> 2004, now=1003

I1020 16:38:40.757019093 3644569 timer_generic.cc:537]         .. shard[1]: heap_empty=true

I1020 16:38:40.757023783 3644569 timer_generic.cc:512]         .. shard[1]->queue_deadline_cap --> 2003

I1020 16:38:40.757028715 3644569 timer_generic.cc:578]         .. shard[1] popped 0

I1020 16:38:40.757033502 3644569 timer_generic.cc:632]         .. result --> 1, shard[1]->min_deadline 1003 --> 2004, now=1003

I1020 16:38:40.757039181 3644569 timer_generic.cc:537]         .. shard[0]: heap_empty=true

I1020 16:38:40.757043818 3644569 timer_generic.cc:512]         .. shard[0]->queue_deadline_cap --> 2003

I1020 16:38:40.757049800 3644569 timer_generic.cc:578]         .. shard[0] popped 0

I1020 16:38:40.757054663 3644569 timer_generic.cc:632]         .. result --> 1, shard[0]->min_deadline 1003 --> 2004, now=1003

I1020 16:38:40.757068525 3644569 timer_generic.cc:741]       TIMER CHECK END: r=1; next=2004

I1020 16:38:40.757075743 3644569 timer_manager.cc:188]       sleep for a 1001 milliseconds

I1020 16:38:40.766770288 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:40.766825343 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:40.866930500 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:40.866999525 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:40.967126854 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:40.967206642 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:41.067337260 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:41.067420717 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:41.167544059 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:41.167619960 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:41.267740381 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:41.267844411 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:41.367941100 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:41.368033963 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:41.468138881 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:41.468210987 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:41.568285554 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:41.568374662 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:41.668468510 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:41.668539540 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:41.757827308 3644569 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:41.758046485 3644569 timer_generic.cc:719]       TIMER CHECK BEGIN: now=2004 next=9223372036854775807 tls_min=1003 glob_min=2004

I1020 16:38:41.758079486 3644569 timer_generic.cc:614]         .. shard[0]->min_deadline = 2004

I1020 16:38:41.758097046 3644569 timer_generic.cc:537]         .. shard[0]: heap_empty=true

I1020 16:38:41.758109732 3644569 timer_generic.cc:512]         .. shard[0]->queue_deadline_cap --> 3004

I1020 16:38:41.758153661 3644569 timer_generic.cc:578]         .. shard[0] popped 0

I1020 16:38:41.758166964 3644569 timer_generic.cc:632]         .. result --> 1, shard[0]->min_deadline 2004 --> 3005, now=2004

I1020 16:38:41.758181307 3644569 timer_generic.cc:537]         .. shard[1]: heap_empty=true

I1020 16:38:41.758192354 3644569 timer_generic.cc:512]         .. shard[1]->queue_deadline_cap --> 3003

I1020 16:38:41.758203925 3644569 timer_generic.cc:578]         .. shard[1] popped 0

I1020 16:38:41.758214803 3644569 timer_generic.cc:632]         .. result --> 1, shard[1]->min_deadline 2004 --> 3004, now=2004

I1020 16:38:41.758228163 3644569 timer_generic.cc:537]         .. shard[2]: heap_empty=true

I1020 16:38:41.758240200 3644569 timer_generic.cc:512]         .. shard[2]->queue_deadline_cap --> 3003

I1020 16:38:41.758247888 3644569 timer_generic.cc:578]         .. shard[2] popped 0

I1020 16:38:41.758253877 3644569 timer_generic.cc:632]         .. result --> 1, shard[2]->min_deadline 2004 --> 3004, now=2004

I1020 16:38:41.758261267 3644569 timer_generic.cc:537]         .. shard[3]: heap_empty=true

I1020 16:38:41.758267124 3644569 timer_generic.cc:512]         .. shard[3]->queue_deadline_cap --> 3003

I1020 16:38:41.758272963 3644569 timer_generic.cc:578]         .. shard[3] popped 0

I1020 16:38:41.758278805 3644569 timer_generic.cc:632]         .. result --> 1, shard[3]->min_deadline 2004 --> 3004, now=2004

I1020 16:38:41.758288371 3644569 timer_generic.cc:741]       TIMER CHECK END: r=1; next=3004

I1020 16:38:41.758296159 3644569 timer_manager.cc:188]       sleep for a 1000 milliseconds

I1020 16:38:41.768634158 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:41.768676332 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:41.868970652 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:41.869043453 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:41.969153207 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:41.969222213 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:42.069340930 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:42.069430521 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:42.169538272 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:42.169623492 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:42.269743338 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:42.269807243 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:42.369912220 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:42.370006637 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:42.470113514 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:42.470176342 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:42.570279498 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:42.570361318 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:42.670495198 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:42.670570123 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:42.757852909 3644569 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:42.757952068 3644569 timer_generic.cc:719]       TIMER CHECK BEGIN: now=3004 next=9223372036854775807 tls_min=2004 glob_min=3004

I1020 16:38:42.757969878 3644569 timer_generic.cc:614]         .. shard[3]->min_deadline = 3004

I1020 16:38:42.757983630 3644569 timer_generic.cc:537]         .. shard[3]: heap_empty=true

I1020 16:38:42.757992889 3644569 timer_generic.cc:512]         .. shard[3]->queue_deadline_cap --> 4003

I1020 16:38:42.758000922 3644569 timer_generic.cc:578]         .. shard[3] popped 0

I1020 16:38:42.758008342 3644569 timer_generic.cc:632]         .. result --> 1, shard[3]->min_deadline 3004 --> 4004, now=3004

I1020 16:38:42.758019017 3644569 timer_generic.cc:537]         .. shard[2]: heap_empty=true

I1020 16:38:42.758025718 3644569 timer_generic.cc:512]         .. shard[2]->queue_deadline_cap --> 4003

I1020 16:38:42.758032923 3644569 timer_generic.cc:578]         .. shard[2] popped 0

I1020 16:38:42.758039872 3644569 timer_generic.cc:632]         .. result --> 1, shard[2]->min_deadline 3004 --> 4004, now=3004

I1020 16:38:42.758047853 3644569 timer_generic.cc:537]         .. shard[1]: heap_empty=true

I1020 16:38:42.758054350 3644569 timer_generic.cc:512]         .. shard[1]->queue_deadline_cap --> 4003

I1020 16:38:42.758061182 3644569 timer_generic.cc:578]         .. shard[1] popped 0

I1020 16:38:42.758067727 3644569 timer_generic.cc:632]         .. result --> 1, shard[1]->min_deadline 3004 --> 4004, now=3004

I1020 16:38:42.758076637 3644569 timer_generic.cc:741]       TIMER CHECK END: r=1; next=3005

I1020 16:38:42.758084406 3644569 timer_manager.cc:188]       sleep for a 1 milliseconds

I1020 16:38:42.758811399 3644569 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:42.758861116 3644569 timer_generic.cc:719]       TIMER CHECK BEGIN: now=3005 next=9223372036854775807 tls_min=3004 glob_min=3005

I1020 16:38:42.758872568 3644569 timer_generic.cc:614]         .. shard[0]->min_deadline = 3005

I1020 16:38:42.758881269 3644569 timer_generic.cc:537]         .. shard[0]: heap_empty=true

I1020 16:38:42.758888281 3644569 timer_generic.cc:512]         .. shard[0]->queue_deadline_cap --> 4005

I1020 16:38:42.758896088 3644569 timer_generic.cc:578]         .. shard[0] popped 0

I1020 16:38:42.758902807 3644569 timer_generic.cc:632]         .. result --> 1, shard[0]->min_deadline 3005 --> 4006, now=3005

I1020 16:38:42.758912512 3644569 timer_generic.cc:741]       TIMER CHECK END: r=1; next=4004

I1020 16:38:42.758925617 3644569 timer_manager.cc:188]       sleep for a 999 milliseconds

I1020 16:38:42.770683519 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:42.770751566 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:42.870874509 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:42.870949924 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:42.971430171 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:42.971571043 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:43.071698081 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:43.071773011 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:43.171890218 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:43.171962559 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:43.272083882 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:43.272176067 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:43.372308816 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:43.372409132 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:43.472533930 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:43.472613553 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:43.572792921 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:43.572892718 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:43.673013087 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:43.673085726 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:43.757824092 3644569 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:43.757925044 3644569 timer_generic.cc:719]       TIMER CHECK BEGIN: now=4004 next=9223372036854775807 tls_min=3005 glob_min=4004

I1020 16:38:43.757964892 3644569 timer_generic.cc:614]         .. shard[1]->min_deadline = 4004

I1020 16:38:43.757976081 3644569 timer_generic.cc:537]         .. shard[1]: heap_empty=true

I1020 16:38:43.757984251 3644569 timer_generic.cc:512]         .. shard[1]->queue_deadline_cap --> 5004

I1020 16:38:43.757991219 3644569 timer_generic.cc:578]         .. shard[1] popped 0

I1020 16:38:43.757997793 3644569 timer_generic.cc:632]         .. result --> 1, shard[1]->min_deadline 4004 --> 5005, now=4004

I1020 16:38:43.758005742 3644569 timer_generic.cc:537]         .. shard[2]: heap_empty=true

I1020 16:38:43.758011428 3644569 timer_generic.cc:512]         .. shard[2]->queue_deadline_cap --> 5004

I1020 16:38:43.758017142 3644569 timer_generic.cc:578]         .. shard[2] popped 0

I1020 16:38:43.758022751 3644569 timer_generic.cc:632]         .. result --> 1, shard[2]->min_deadline 4004 --> 5005, now=4004

I1020 16:38:43.758029722 3644569 timer_generic.cc:537]         .. shard[3]: heap_empty=true

I1020 16:38:43.758035034 3644569 timer_generic.cc:512]         .. shard[3]->queue_deadline_cap --> 5004

I1020 16:38:43.758040539 3644569 timer_generic.cc:578]         .. shard[3] popped 0

I1020 16:38:43.758046039 3644569 timer_generic.cc:632]         .. result --> 1, shard[3]->min_deadline 4004 --> 5005, now=4004

I1020 16:38:43.758054695 3644569 timer_generic.cc:741]       TIMER CHECK END: r=1; next=4006

I1020 16:38:43.758061873 3644569 timer_manager.cc:188]       sleep for a 2 milliseconds

I1020 16:38:43.759830567 3644569 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:43.759877186 3644569 timer_generic.cc:719]       TIMER CHECK BEGIN: now=4006 next=9223372036854775807 tls_min=4004 glob_min=4006

I1020 16:38:43.759894703 3644569 timer_generic.cc:614]         .. shard[0]->min_deadline = 4006

I1020 16:38:43.759907753 3644569 timer_generic.cc:537]         .. shard[0]: heap_empty=true

I1020 16:38:43.759919007 3644569 timer_generic.cc:512]         .. shard[0]->queue_deadline_cap --> 5006

I1020 16:38:43.759933867 3644569 timer_generic.cc:520]         .. add timer with deadline 5002 to heap

I1020 16:38:43.759977655 3644569 timer_generic.cc:547]         .. check top timer deadline=5002 now=4006

I1020 16:38:43.759996207 3644569 timer_generic.cc:578]         .. shard[0] popped 0

I1020 16:38:43.760005774 3644569 timer_generic.cc:632]         .. result --> 1, shard[0]->min_deadline 4006 --> 5002, now=4006

I1020 16:38:43.760018475 3644569 timer_generic.cc:741]       TIMER CHECK END: r=1; next=5002

I1020 16:38:43.760031220 3644569 timer_manager.cc:188]       sleep for a 996 milliseconds

I1020 16:38:43.773193049 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:43.773243655 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:43.873374330 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:43.873492449 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:43.975034154 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:43.975163148 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:44.075309256 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:44.075429123 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:44.175569750 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:44.175685060 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:44.275830041 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:44.275933705 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:44.376068721 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:44.376165644 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:44.476285562 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:44.476389946 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:44.576497525 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:44.576566363 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:44.676671661 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:44.676746964 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:44.755837980 3644569 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:44.755929799 3644569 timer_generic.cc:719]       TIMER CHECK BEGIN: now=5002 next=9223372036854775807 tls_min=4006 glob_min=5002

I1020 16:38:44.755942988 3644569 timer_generic.cc:614]         .. shard[0]->min_deadline = 5002

I1020 16:38:44.755954105 3644569 timer_generic.cc:537]         .. shard[0]: heap_empty=false

I1020 16:38:44.755961347 3644569 timer_generic.cc:547]         .. check top timer deadline=5002 now=5002

I1020 16:38:44.755967413 3644569 timer_generic.cc:553]       TIMER 0x15fd5d0: FIRE 0ms late

I1020 16:38:44.755992098 3644569 timer_generic.cc:537]         .. shard[0]: heap_empty=true

I1020 16:38:44.755999005 3644569 timer_generic.cc:578]         .. shard[0] popped 1

I1020 16:38:44.756005392 3644569 timer_generic.cc:632]         .. result --> 2, shard[0]->min_deadline 5002 --> 5007, now=5002

I1020 16:38:44.756015067 3644569 timer_generic.cc:741]       TIMER CHECK END: r=2; next=5005

I1020 16:38:44.756030703 3644569 timer_manager.cc:88]        Spawn timer thread

I1020 16:38:44.756544539 3644569 timer_manager.cc:132]       flush exec_ctx

D1020 16:38:44.756581276 3644569 exec_ctx.cc:37]             running closure 0x15fd608: created [/code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/backup_poller.cc:150]: schedul [/code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/timer_generic.cc:571]

I1020 16:38:44.756597718 3644569 ev_posix.cc:322]            (polling-api) pollset_work(0x15f9ee0, 5002) begin

I1020 16:38:44.756594430 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=5002 next=9223372036854775807 tls_min=0 glob_min=5005

I1020 16:38:44.756711152 3644607 timer_generic.cc:741]       TIMER CHECK END: r=1; next=5005

I1020 16:38:44.756726159 3644607 timer_manager.cc:188]       sleep for a 3 milliseconds

I1020 16:38:44.756717290 3644569 ev_epollex_linux.cc:1123]   PS:0x15f9ee0 work hdl=(nil) worker=0x7fc05d7f9a20 now=5002 deadline=5002 kwp=0 pollable=0x15fd850

I1020 16:38:44.756757222 3644569 ref_counted.h:86]           pollable_refcount:0x15fd858 /code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/ev_epollex_linux.cc:1021 ref 1 -> 2 pollset_worker

I1020 16:38:44.756797688 3644569 ev_epollex_linux.cc:941]    POLLABLE:0x15fd850[type=pollset epfd=11 wakeup=12] poll for 0ms

I1020 16:38:44.756818675 3644569 ev_epollex_linux.cc:960]    POLLABLE:0x15fd850 got 1 events

I1020 16:38:44.756826014 3644569 ev_epollex_linux.cc:909]    PS:0x15f9ee0 got fd 0x7fc05402c610: cancel=0 read=0 write=1

D1020 16:38:44.756835924 3644569 lockfree_event.cc:218]      LockfreeEvent::SetReady: 0x7fc05402c658 curr=7fc054001988

D1020 16:38:44.756846571 3644569 exec_ctx.cc:37]             running closure 0x7fc054001988: created [/code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/tcp_client_posix.cc:319]: scheduled [/SCM/M22.2/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/lockfree_event.cc:247]

I1020 16:38:44.756861147 3644569 tcp_client_posix.cc:144]    CLIENT_CONNECT: ipv4:10.84.2.178:8085: on_writable: error="No Error"

I1020 16:38:44.756873417 3644569 timer_generic.cc:470]       TIMER 0x7fc054001900: CANCEL pending=true

I1020 16:38:44.756887501 3644569 ev_posix.cc:401]            (polling-api) pollset_set_del_fd(0x7fc05402ee10, 13)

I1020 16:38:44.756894222 3644569 ev_epollex_linux.cc:1381]   PSS:0x7fc05402ee10: del fd 0x7fc05402c610

D1020 16:38:44.756906325 3644569 ev_epollex_linux.cc:390]    FD 13 0x7fc05402c610 unref 2 3 -> 1 [pollset_set; /code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/ev_epollex_linux.cc:1387]

I1020 16:38:44.756931009 3644569 combiner.cc:62]             C:0x7fc050001a20 create

I1020 16:38:44.757031490 3644569 ref_counted.h:86]           tcp:0x7fc050000f18 /code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/tcp_posix.cc:1840 ref 1 -> 2 error-tracking

D1020 16:38:44.757044422 3644569 lockfree_event.cc:99]       LockfreeEvent::NotifyOn: 0x7fc05402c660 curr=0 closure=0x7fc050001130

I1020 16:38:44.757066070 3644569 executor.cc:304]            EXECUTOR (default-executor) try to schedule 0x7fc05402e968 (short) (created /code/grpc-rpms/grpc-1.39.1/src/core/ext/transport/cht2/client/chttp2_connector.cc:44) to thread 0

D1020 16:38:44.757197877 3644569 exec_ctx.cc:46]             closure 0x7fc054001988 finished

D1020 16:38:44.757237508 3644569 exec_ctx.cc:37]             running closure 0x7fc054001938: created [/code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/tcp_client_posix.cc:328]: scheduled [/SCM/M22.2/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/timer_generic.cc:477]

I1020 16:38:44.757248841 3644569 tcp_client_posix.cc:109]    CLIENT_CONNECT: ipv4:10.84.2.178:8085: on_alarm: error="Cancelled"

I1020 16:38:44.757289024 3644569 ref_counted.h:182]          security_connector_refcount:0x7fc054002538 /code/grpc-rpms/grpc-1.39.1/src/core/lib/security/security_connector/security_connectorc:88 unref 4 -> 3 connector_arg_destroy

D1020 16:38:44.757300830 3644569 exec_ctx.cc:46]             closure 0x7fc054001938 finished

I1020 16:38:44.757311220 3644569 ref_counted.h:182]          pollable_refcount:0x15fd858 /code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/ev_epollex_linux.cc:1088 unref 2 -> 1 pollset_worker

I1020 16:38:44.757318579 3644569 ev_epollex_linux.cc:665]    PS:0x15f9ee0 (pollable:0x15fd850) maybe_finish_shutdown sc=(nil) (target:!NULL) rw=(nil) (target:NULL) cpsc=1 (target:0)

I1020 16:38:44.757324634 3644569 ev_posix.cc:326]            (polling-api) pollset_work(0x15f9ee0, 5002) end

I1020 16:38:44.757332392 3644569 timer_generic.cc:367]       TIMER 0x15fd5d0: SET 10002 now 5002 call 0x15fd608[0x7fc0746d0679]

I1020 16:38:44.757340941 3644569 timer_generic.cc:404]         .. add to shard 0 with queue_deadline_cap=5006 => is_first_timer=false

D1020 16:38:44.757362928 3644569 exec_ctx.cc:46]             closure 0x15fd608 finished

I1020 16:38:44.757376508 3644569 timer_generic.cc:719]       TIMER CHECK BEGIN: now=5003 next=9223372036854775807 tls_min=5002 glob_min=5005

I1020 16:38:44.757383359 3644569 timer_generic.cc:741]       TIMER CHECK END: r=1; next=5005

I1020 16:38:44.757389292 3644569 timer_manager.cc:197]       sleep until kicked

I1020 16:38:44.757412442 3644567 executor.cc:245]            EXECUTOR (default-executor) [0]: execute

I1020 16:38:44.757449178 3644567 executor.cc:121]            EXECUTOR (default-executor) run 0x7fc05402e968 [created by /code/grpc-rpms/grpc-1.39.1/src/core/ext/transport/chttp2/client/chttp2onnector.cc:44]

I1020 16:38:44.757532438 3644567 handshaker.cc:61]           handshake_manager 0x7fc060000dd0: adding handshaker http_connect [0x7fc060000f60] at index 0

I1020 16:38:44.757749575 3644567 ssl_transport_security.cc:223]      HANDSHAKE START -      before SSL initialization  - PINIT

I1020 16:38:44.757801897 3644567 ssl_transport_security.cc:223]                 LOOP -      before SSL initialization  - PINIT

I1020 16:38:44.758001325 3644567 ssl_transport_security.cc:223]                 LOOP -   SSLv3/TLS write client hello  -  TWCH

I1020 16:38:44.758039206 3644567 ref_counted.h:86]           security_connector_refcount:0x7fc054002538 /code/grpc-rpms/grpc-1.39.1/src/core/lib/security/transport/security_handshaker.cc:115 f 3 -> 4 handshake

I1020 16:38:44.758053043 3644567 handshaker.cc:61]           handshake_manager 0x7fc060000dd0: adding handshaker security [0x7fc06001ef10] at index 1

I1020 16:38:44.758069031 3644567 ev_posix.cc:395]            (polling-api) pollset_set_add_fd(0x7fc05402ee10, 13)

I1020 16:38:44.758076337 3644567 ev_epollex_linux.cc:1357]   PSS:0x7fc05402ee10: add fd 0x7fc05402c610 (13)

I1020 16:38:44.758084382 3644567 ev_epollex_linux.cc:617]    add fd 0x7fc05402c610 (13) to pollable 0x15fd850

D1020 16:38:44.758093870 3644567 ev_epollex_linux.cc:353]    FD 13 0x7fc05402c610   ref 2 1 -> 3 [pollset_set; /code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/ev_epollex_linux.cc:1371]

I1020 16:38:44.758112658 3644567 ref_counted.h:86]           security_connector_refcount:0x7fc054002538 /code/grpc-rpms/grpc-1.39.1/src/core/lib/security/security_connector/security_connectorc:94 ref 4 -> 5 connector_arg_copy

I1020 16:38:44.758126829 3644567 timer_generic.cc:367]       TIMER 0x7fc060000e68: SET 20004 now 5004 call 0x7fc060000ea0[0x7fc0748f35aa]

I1020 16:38:44.758156680 3644567 timer_generic.cc:404]         .. add to shard 1 with queue_deadline_cap=5004 => is_first_timer=false

I1020 16:38:44.758303943 3644567 handshaker.cc:88]           handshake_manager 0x7fc060000dd0: error="No Error" shutdown=0 index=0, args={endpoint=0x7fc050000ef0, args=0x7fc06001dbd0 {size=17: grpc.imary_user_agent=grpc-c++/1.39.1, grpc.client_ip=10.10.20.11, grpc.dscp_code=34, grpc.tcp_profile.keep_alive_idle_timer=30, grpc.tcp_profile.keep_alive_interval=30, grpc.tcp_profile.keep_alive_retry0, grpc.keepalive_timeout_ms=10000, grpc.http2.max_pings_without_data=0, grpc.client_channel_factory=0x15f9ea0, grpc.channel_credentials=0x15b7600, grpc.server_uri=dns:///10.84.2.178:8085, grpc.subcnnel_pool=0x15b7700, grpc.default_authority=10.84.2.178:8085, grpc.http2_scheme=https, grpc.security_connector=0x7fc054002530, grpc.subchannel_address=ipv4:10.84.2.178:8085, grpc.keepalive_time_ms=3000}, read_buffer=0x7fc06001f760 (length=0), exit_early=0}

I1020 16:38:44.758323252 3644567 handshaker.cc:135]          handshake_manager 0x7fc060000dd0: calling handshaker http_connect [0x7fc060000f60] at index 0

D1020 16:38:44.758340932 3644567 exec_ctx.cc:37]             running closure 0x7fc060000e18: created [/code/grpc-rpms/grpc-1.39.1/src/core/lib/channel/handshaker.cc:196]: scheduled [/code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/http_connect_handshaker.cc:297]

I1020 16:38:44.758420403 3644567 handshaker.cc:88]           handshake_manager 0x7fc060000dd0: error="No Error" shutdown=0 index=1, args={endpoint=0x7fc050000ef0, args=0x7fc06001dbd0 {size=17: grpc.imary_user_agent=grpc-c++/1.39.1, grpc.client_ip=10.10.20.11, grpc.dscp_code=34, grpc.tcp_profile.keep_alive_idle_timer=30, grpc.tcp_profile.keep_alive_interval=30, grpc.tcp_profile.keep_alive_retry0, grpc.keepalive_timeout_ms=10000, grpc.http2.max_pings_without_data=0, grpc.client_channel_factory=0x15f9ea0, grpc.channel_credentials=0x15b7600, grpc.server_uri=dns:///10.84.2.178:8085, grpc.subcnnel_pool=0x15b7700, grpc.default_authority=10.84.2.178:8085, grpc.http2_scheme=https, grpc.security_connector=0x7fc054002530, grpc.subchannel_address=ipv4:10.84.2.178:8085, grpc.keepalive_time_ms=3000}, read_buffer=0x7fc06001f760 (length=0), exit_early=0}

I1020 16:38:44.758447778 3644567 handshaker.cc:135]          handshake_manager 0x7fc060000dd0: calling handshaker security [0x7fc06001ef10] at index 1

I1020 16:38:44.758484616 3644567 tcp_posix.cc:1572]          WRITE 0x7fc050000ef0 (peer=ipv4:10.84.2.178:8085)

D1020 16:38:44.758549109 3644567 tcp_posix.cc:1576]          DATA: 16 03 01 01 29 01 00 01 25 03 03 6f b6 88 77 0f a7 03 71 74 84 82 3d 09 33 4c 87 e4 1d a3 05 94 17 4f 95 7b 30 a2 40 bb 19 ed f7 20a bf ea 44 e9 0a 0c 54 1c 0d 5b 06 f9 89 81 ec ec 38 34 03 74 e4 32 1c 5d c5 fc b8 84 13 20 16 00 12 13 02 13 03 13 01 13 04 c0 2b c0 2c c0 2f c0 30 00 ff 01 00 00 ca 00 00 00 10 00 0e 00 00 0b 31 32e 38 34 2e 32 2e 31 37 38 00 0b 00 04 03 00 01 02 00 0a 00 04 00 02 00 17 00 23 00 00 33 74 00 00 00 10 00 0e 00 0c 08 67 72 70 63 2d 65 78 70 02 68 32 00 16 00 00 00 17 00 00 00 0d 00 26 00 24 04  05 03 06 03 08 07 08 08 08 09 08 04 08 0a 08 05 08 0b 08 06 04 01 05 01 06 01 03 03 03 01 02 03 02 01 00 2b 00 05 04 03 04 03 03 00 2d 00 02 01 01 00 33 00 47 00 45 00 17 00 41 04 6e 16 b5 4e 4d 2ad 69 ff 51 4b 3d 44 9f e1 2f b7 50 94 40 5f d2 27 76 fc 6d 09 de 52 79 27 5d 52 b3 f7 45 80 bf 27 95 e8 ed 42 f2 76 d1 ed f2 11 25 8e 84 e8 57 f9 80 02 e3 9a 47 63 53 5b f6 '....)...%..o..w...qt..=........O.{0.@.... *..D...T..[......84.t.2.]..... ............+.,./.0...............10.84.2.178.................#..3t.........grpc-exp.h2...........&.$.....................................+........-...3.G.E...A.n..NM*.i.QK=D../.P.@_.'v.m..Ry']R..E..'...B.v....%...W.....GcS[.'

I1020 16:38:44.758606697 3644567 tcp_posix.cc:1621]          write: "No Error"

D1020 16:38:44.758620982 3644567 closure.h:239]              running closure 0x7fc06001f0a0: created [/code/grpc-rpms/grpc-1.39.1/src/core/lib/security/transport/security_handshaker.cc:353]: n [/code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/tcp_posix.cc:1623]

D1020 16:38:44.758702063 3644567 closure.h:248]              closure 0x7fc06001f0a0 finished

D1020 16:38:44.758728146 3644567 exec_ctx.cc:46]             closure 0x7fc060000e18 finished

D1020 16:38:44.758736799 3644567 exec_ctx.cc:37]             running closure 0x7fc06001f0a0: created [/code/grpc-rpms/grpc-1.39.1/src/core/lib/security/transport/security_handshaker.cc:449]: heduled [/code/grpc-rpms/grpc-1.39.1/src/core/lib/security/transport/security_handshaker.cc:446]

I1020 16:38:44.758769116 3644567 ref_counted.h:86]           tcp:0x7fc050000f18 /code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/tcp_posix.cc:912 ref 2 -> 3 read

I1020 16:38:44.758776473 3644567 tcp_posix.cc:544]           TCP:0x7fc050000ef0 notify_on_read

D1020 16:38:44.758784343 3644567 lockfree_event.cc:99]       LockfreeEvent::NotifyOn: 0x7fc05402c650 curr=0 closure=0x7fc0500010a0

D1020 16:38:44.758790738 3644567 exec_ctx.cc:46]             closure 0x7fc06001f0a0 finished

I1020 16:38:44.758797861 3644567 executor.cc:224]            EXECUTOR (default-executor) [0]: step (sub_depth=1)

I1020 16:38:44.758808013 3644607 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:44.758847848 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=5005 next=9223372036854775807 tls_min=5005 glob_min=5005

I1020 16:38:44.758871633 3644607 timer_generic.cc:614]         .. shard[3]->min_deadline = 5005

I1020 16:38:44.758882351 3644607 timer_generic.cc:537]         .. shard[3]: heap_empty=true

I1020 16:38:44.758898465 3644607 timer_generic.cc:512]         .. shard[3]->queue_deadline_cap --> 6005

I1020 16:38:44.758943865 3644607 timer_generic.cc:578]         .. shard[3] popped 0

I1020 16:38:44.758964435 3644607 timer_generic.cc:632]         .. result --> 1, shard[3]->min_deadline 5005 --> 6006, now=5005

I1020 16:38:44.758973283 3644607 timer_generic.cc:537]         .. shard[2]: heap_empty=true

I1020 16:38:44.758980886 3644607 timer_generic.cc:512]         .. shard[2]->queue_deadline_cap --> 6005

I1020 16:38:44.758987119 3644607 timer_generic.cc:578]         .. shard[2] popped 0

I1020 16:38:44.758992740 3644607 timer_generic.cc:632]         .. result --> 1, shard[2]->min_deadline 5005 --> 6006, now=5005

I1020 16:38:44.758998784 3644607 timer_generic.cc:537]         .. shard[1]: heap_empty=true

I1020 16:38:44.759005806 3644607 timer_generic.cc:512]         .. shard[1]->queue_deadline_cap --> 6005

I1020 16:38:44.759011863 3644607 timer_generic.cc:578]         .. shard[1] popped 0

I1020 16:38:44.759017396 3644607 timer_generic.cc:632]         .. result --> 1, shard[1]->min_deadline 5005 --> 6006, now=5005

I1020 16:38:44.759032176 3644607 timer_generic.cc:741]       TIMER CHECK END: r=1; next=5007

I1020 16:38:44.759039824 3644607 timer_manager.cc:188]       sleep for a 2 milliseconds

I1020 16:38:44.760810706 3644607 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:44.760843339 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=5007 next=9223372036854775807 tls_min=5005 glob_min=5007

I1020 16:38:44.760854746 3644607 timer_generic.cc:614]         .. shard[0]->min_deadline = 5007

I1020 16:38:44.760862080 3644607 timer_generic.cc:537]         .. shard[0]: heap_empty=true

I1020 16:38:44.760869629 3644607 timer_generic.cc:512]         .. shard[0]->queue_deadline_cap --> 6007

I1020 16:38:44.760875867 3644607 timer_generic.cc:578]         .. shard[0] popped 0

I1020 16:38:44.760881805 3644607 timer_generic.cc:632]         .. result --> 1, shard[0]->min_deadline 5007 --> 6008, now=5007

I1020 16:38:44.760904891 3644607 timer_generic.cc:741]       TIMER CHECK END: r=1; next=6006

I1020 16:38:44.760934637 3644607 timer_manager.cc:188]       sleep for a 999 milliseconds

I1020 16:38:44.776874418 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:44.776915096 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:44.877023270 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:44.877083942 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:44.977184500 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:44.977251655 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:45.077372763 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:45.077438766 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:45.177552124 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:45.177623244 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:45.277719457 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:45.277788506 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:45.378411850 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:45.378486912 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:45.478589068 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:45.478657064 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:45.578775050 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:45.578862036 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:45.679001314 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:45.679092724 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:45.759840214 3644607 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:45.759946941 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=6006 next=9223372036854775807 tls_min=5007 glob_min=6006

I1020 16:38:45.759994443 3644607 timer_generic.cc:614]         .. shard[1]->min_deadline = 6006

I1020 16:38:45.760016176 3644607 timer_generic.cc:537]         .. shard[1]: heap_empty=true

I1020 16:38:45.760030979 3644607 timer_generic.cc:512]         .. shard[1]->queue_deadline_cap --> 7006

I1020 16:38:45.760044630 3644607 timer_generic.cc:578]         .. shard[1] popped 0

I1020 16:38:45.760057514 3644607 timer_generic.cc:632]         .. result --> 1, shard[1]->min_deadline 6006 --> 7007, now=6006

I1020 16:38:45.760068869 3644607 timer_generic.cc:537]         .. shard[2]: heap_empty=true

I1020 16:38:45.760079935 3644607 timer_generic.cc:512]         .. shard[2]->queue_deadline_cap --> 7005

I1020 16:38:45.760092534 3644607 timer_generic.cc:578]         .. shard[2] popped 0

I1020 16:38:45.760104606 3644607 timer_generic.cc:632]         .. result --> 1, shard[2]->min_deadline 6006 --> 7006, now=6006

I1020 16:38:45.760117526 3644607 timer_generic.cc:537]         .. shard[3]: heap_empty=true

I1020 16:38:45.760124735 3644607 timer_generic.cc:512]         .. shard[3]->queue_deadline_cap --> 7005

I1020 16:38:45.760131756 3644607 timer_generic.cc:578]         .. shard[3] popped 0

I1020 16:38:45.760138505 3644607 timer_generic.cc:632]         .. result --> 1, shard[3]->min_deadline 6006 --> 7006, now=6006

I1020 16:38:45.760149043 3644607 timer_generic.cc:741]       TIMER CHECK END: r=1; next=6008

I1020 16:38:45.760156841 3644607 timer_manager.cc:188]       sleep for a 2 milliseconds

I1020 16:38:45.761816741 3644607 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:45.761853168 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=6008 next=9223372036854775807 tls_min=6006 glob_min=6008

I1020 16:38:45.761862730 3644607 timer_generic.cc:614]         .. shard[0]->min_deadline = 6008

I1020 16:38:45.761869773 3644607 timer_generic.cc:537]         .. shard[0]: heap_empty=true

I1020 16:38:45.761875214 3644607 timer_generic.cc:512]         .. shard[0]->queue_deadline_cap --> 7008

I1020 16:38:45.761881169 3644607 timer_generic.cc:578]         .. shard[0] popped 0

I1020 16:38:45.761886310 3644607 timer_generic.cc:632]         .. result --> 1, shard[0]->min_deadline 6008 --> 7009, now=6008

I1020 16:38:45.761892862 3644607 timer_generic.cc:741]       TIMER CHECK END: r=1; next=7006

I1020 16:38:45.761898432 3644607 timer_manager.cc:188]       sleep for a 998 milliseconds

I1020 16:38:45.779251746 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:45.779375941 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:45.879528438 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:45.879620025 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:45.979990807 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:45.980081545 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:46.080201750 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:46.080285365 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:46.180430363 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:46.180509802 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:46.280658334 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:46.280736116 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:46.380863988 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:46.380961451 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:46.481134797 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:46.481275755 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:46.581395986 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:46.581488725 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:46.681581150 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:46.681658214 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:46.759861348 3644607 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:46.760133347 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=7006 next=9223372036854775807 tls_min=6008 glob_min=7006

I1020 16:38:46.760164257 3644607 timer_generic.cc:614]         .. shard[3]->min_deadline = 7006

I1020 16:38:46.760187714 3644607 timer_generic.cc:537]         .. shard[3]: heap_empty=true

I1020 16:38:46.760202264 3644607 timer_generic.cc:512]         .. shard[3]->queue_deadline_cap --> 8006

I1020 16:38:46.760213835 3644607 timer_generic.cc:578]         .. shard[3] popped 0

I1020 16:38:46.760224564 3644607 timer_generic.cc:632]         .. result --> 1, shard[3]->min_deadline 7006 --> 8007, now=7006

I1020 16:38:46.760245150 3644607 timer_generic.cc:537]         .. shard[2]: heap_empty=true

I1020 16:38:46.760252647 3644607 timer_generic.cc:512]         .. shard[2]->queue_deadline_cap --> 8006

I1020 16:38:46.760259036 3644607 timer_generic.cc:578]         .. shard[2] popped 0

I1020 16:38:46.760264837 3644607 timer_generic.cc:632]         .. result --> 1, shard[2]->min_deadline 7006 --> 8007, now=7006

I1020 16:38:46.760273955 3644607 timer_generic.cc:741]       TIMER CHECK END: r=1; next=7007

I1020 16:38:46.760281003 3644607 timer_manager.cc:188]       sleep for a 1 milliseconds

I1020 16:38:46.760841468 3644607 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:46.760878444 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=7007 next=9223372036854775807 tls_min=7006 glob_min=7007

I1020 16:38:46.760889056 3644607 timer_generic.cc:614]         .. shard[1]->min_deadline = 7007

I1020 16:38:46.760896703 3644607 timer_generic.cc:537]         .. shard[1]: heap_empty=true

I1020 16:38:46.760902904 3644607 timer_generic.cc:512]         .. shard[1]->queue_deadline_cap --> 8007

I1020 16:38:46.760909386 3644607 timer_generic.cc:578]         .. shard[1] popped 0

I1020 16:38:46.760915577 3644607 timer_generic.cc:632]         .. result --> 1, shard[1]->min_deadline 7007 --> 8008, now=7007

I1020 16:38:46.760922873 3644607 timer_generic.cc:741]       TIMER CHECK END: r=1; next=7009

I1020 16:38:46.760929319 3644607 timer_manager.cc:188]       sleep for a 2 milliseconds

I1020 16:38:46.762813245 3644607 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:46.763000073 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=7009 next=9223372036854775807 tls_min=7007 glob_min=7009

I1020 16:38:46.763038444 3644607 timer_generic.cc:614]         .. shard[0]->min_deadline = 7009

I1020 16:38:46.763057098 3644607 timer_generic.cc:537]         .. shard[0]: heap_empty=true

I1020 16:38:46.763066416 3644607 timer_generic.cc:512]         .. shard[0]->queue_deadline_cap --> 8009

I1020 16:38:46.763073739 3644607 timer_generic.cc:578]         .. shard[0] popped 0

I1020 16:38:46.763080162 3644607 timer_generic.cc:632]         .. result --> 1, shard[0]->min_deadline 7009 --> 8010, now=7009

I1020 16:38:46.763089285 3644607 timer_generic.cc:741]       TIMER CHECK END: r=1; next=8007

I1020 16:38:46.763096535 3644607 timer_manager.cc:188]       sleep for a 998 milliseconds

I1020 16:38:46.781772297 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:46.781839677 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:46.881966594 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:46.882056048 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:46.982174901 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:46.982264494 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:47.082393289 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:47.082474867 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:47.182588596 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:47.182666900 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:47.282778924 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:47.282874359 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:47.382970506 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:47.383079323 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:47.483213773 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:47.483303952 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:47.583402518 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:47.583482729 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:47.683617041 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:47.683692079 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:47.760845749 3644607 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:47.760979517 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=8007 next=9223372036854775807 tls_min=7009 glob_min=8007

I1020 16:38:47.761014006 3644607 timer_generic.cc:614]         .. shard[2]->min_deadline = 8007

I1020 16:38:47.761031824 3644607 timer_generic.cc:537]         .. shard[2]: heap_empty=true

I1020 16:38:47.761052054 3644607 timer_generic.cc:512]         .. shard[2]->queue_deadline_cap --> 9007

I1020 16:38:47.761066551 3644607 timer_generic.cc:578]         .. shard[2] popped 0

I1020 16:38:47.761080871 3644607 timer_generic.cc:632]         .. result --> 1, shard[2]->min_deadline 8007 --> 9008, now=8007

I1020 16:38:47.761094941 3644607 timer_generic.cc:537]         .. shard[3]: heap_empty=true

I1020 16:38:47.761104879 3644607 timer_generic.cc:512]         .. shard[3]->queue_deadline_cap --> 9007

I1020 16:38:47.761135004 3644607 timer_generic.cc:578]         .. shard[3] popped 0

I1020 16:38:47.761147325 3644607 timer_generic.cc:632]         .. result --> 1, shard[3]->min_deadline 8007 --> 9008, now=8007

I1020 16:38:47.761183291 3644607 timer_generic.cc:741]       TIMER CHECK END: r=1; next=8008

I1020 16:38:47.761247260 3644607 timer_manager.cc:188]       sleep for a 1 milliseconds

I1020 16:38:47.761814126 3644607 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:47.761847500 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=8008 next=9223372036854775807 tls_min=8007 glob_min=8008

I1020 16:38:47.761859036 3644607 timer_generic.cc:614]         .. shard[1]->min_deadline = 8008

I1020 16:38:47.761874693 3644607 timer_generic.cc:537]         .. shard[1]: heap_empty=true

I1020 16:38:47.761883660 3644607 timer_generic.cc:512]         .. shard[1]->queue_deadline_cap --> 9008

I1020 16:38:47.761892514 3644607 timer_generic.cc:578]         .. shard[1] popped 0

I1020 16:38:47.761898846 3644607 timer_generic.cc:632]         .. result --> 1, shard[1]->min_deadline 8008 --> 9009, now=8008

I1020 16:38:47.761906401 3644607 timer_generic.cc:741]       TIMER CHECK END: r=1; next=8010

I1020 16:38:47.761922081 3644607 timer_manager.cc:188]       sleep for a 2 milliseconds

I1020 16:38:47.763816282 3644607 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:47.763849257 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=8010 next=9223372036854775807 tls_min=8008 glob_min=8010

I1020 16:38:47.763860745 3644607 timer_generic.cc:614]         .. shard[0]->min_deadline = 8010

I1020 16:38:47.763868193 3644607 timer_generic.cc:537]         .. shard[0]: heap_empty=true

I1020 16:38:47.763874116 3644607 timer_generic.cc:512]         .. shard[0]->queue_deadline_cap --> 9010

I1020 16:38:47.763880441 3644607 timer_generic.cc:578]         .. shard[0] popped 0

I1020 16:38:47.763888766 3644607 timer_generic.cc:632]         .. result --> 1, shard[0]->min_deadline 8010 --> 9011, now=8010

I1020 16:38:47.763896301 3644607 timer_generic.cc:741]       TIMER CHECK END: r=1; next=9008

I1020 16:38:47.763902687 3644607 timer_manager.cc:188]       sleep for a 998 milliseconds

I1020 16:38:47.783798309 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:47.783846906 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:47.883960773 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:47.884053353 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:47.984167892 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:47.984235788 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:48.084368295 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:48.084449441 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:48.184559571 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:48.184646893 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:48.284749376 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:48.284822709 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:48.384958429 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:48.385031384 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:48.485128376 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:48.485193088 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:48.585314644 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:48.585405553 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:48.685522594 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:48.685614224 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:48.761874786 3644607 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:48.761996092 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=9008 next=9223372036854775807 tls_min=8010 glob_min=9008

I1020 16:38:48.762112565 3644607 timer_generic.cc:614]         .. shard[3]->min_deadline = 9008

I1020 16:38:48.762165300 3644607 timer_generic.cc:537]         .. shard[3]: heap_empty=true

I1020 16:38:48.762185127 3644607 timer_generic.cc:512]         .. shard[3]->queue_deadline_cap --> 10007

I1020 16:38:48.762199777 3644607 timer_generic.cc:578]         .. shard[3] popped 0

I1020 16:38:48.762213106 3644607 timer_generic.cc:632]         .. result --> 1, shard[3]->min_deadline 9008 --> 10008, now=9008

I1020 16:38:48.762231164 3644607 timer_generic.cc:537]         .. shard[2]: heap_empty=true

I1020 16:38:48.762243428 3644607 timer_generic.cc:512]         .. shard[2]->queue_deadline_cap --> 10007

I1020 16:38:48.762259948 3644607 timer_generic.cc:578]         .. shard[2] popped 0

I1020 16:38:48.762272589 3644607 timer_generic.cc:632]         .. result --> 1, shard[2]->min_deadline 9008 --> 10008, now=9008

I1020 16:38:48.762290363 3644607 timer_generic.cc:741]       TIMER CHECK END: r=1; next=9009

I1020 16:38:48.762311875 3644607 timer_manager.cc:188]       sleep for a 1 milliseconds

I1020 16:38:48.762868311 3644607 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:48.762935099 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=9009 next=9223372036854775807 tls_min=9008 glob_min=9009

I1020 16:38:48.762960205 3644607 timer_generic.cc:614]         .. shard[1]->min_deadline = 9009

I1020 16:38:48.763004277 3644607 timer_generic.cc:537]         .. shard[1]: heap_empty=true

I1020 16:38:48.763035633 3644607 timer_generic.cc:512]         .. shard[1]->queue_deadline_cap --> 10009

I1020 16:38:48.763132587 3644607 timer_generic.cc:578]         .. shard[1] popped 0

I1020 16:38:48.763272761 3644607 timer_generic.cc:632]         .. result --> 1, shard[1]->min_deadline 9009 --> 10010, now=9009

I1020 16:38:48.763329548 3644607 timer_generic.cc:741]       TIMER CHECK END: r=1; next=9011

I1020 16:38:48.763385347 3644607 timer_manager.cc:188]       sleep for a 2 milliseconds

I1020 16:38:48.764830797 3644607 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:48.764885021 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=9011 next=9223372036854775807 tls_min=9009 glob_min=9011

I1020 16:38:48.764906343 3644607 timer_generic.cc:614]         .. shard[0]->min_deadline = 9011

I1020 16:38:48.764921323 3644607 timer_generic.cc:537]         .. shard[0]: heap_empty=true

I1020 16:38:48.764933408 3644607 timer_generic.cc:512]         .. shard[0]->queue_deadline_cap --> 10011

I1020 16:38:48.764944604 3644607 timer_generic.cc:520]         .. add timer with deadline 10002 to heap

I1020 16:38:48.764959575 3644607 timer_generic.cc:547]         .. check top timer deadline=10002 now=9011

I1020 16:38:48.764972543 3644607 timer_generic.cc:578]         .. shard[0] popped 0

I1020 16:38:48.764984805 3644607 timer_generic.cc:632]         .. result --> 1, shard[0]->min_deadline 9011 --> 10002, now=9011

I1020 16:38:48.764999282 3644607 timer_generic.cc:741]       TIMER CHECK END: r=1; next=10002

I1020 16:38:48.765015547 3644607 timer_manager.cc:188]       sleep for a 991 milliseconds

I1020 16:38:48.785750093 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:48.785835709 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:48.885950312 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:48.886032953 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:48.986158233 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:48.986248232 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:49.086512811 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:49.086625516 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:49.186820783 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:49.186920373 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:49.287080693 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:49.287203163 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:49.387389966 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:49.387490207 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:49.487615645 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:49.487710363 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:49.587828627 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:49.587915154 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:49.688052692 3644570 channel_connectivity.cc:34] grpc_channel_check_connectivity_state(channel=0x15fd150, try_to_connect=1)

I1020 16:38:49.688144774 3644570 connectivity_state.cc:179]  ConnectivityStateTracker client_channel[0x15fd338]: get current state: CONNECTING

I1020 16:38:49.755851919 3644607 timer_manager.cc:204]       wait ended: was_timed:1 kicked:0

I1020 16:38:49.755969335 3644607 timer_generic.cc:719]       TIMER CHECK BEGIN: now=10002 next=9223372036854775807 tls_min=9011 glob_min=10002

I1020 16:38:49.755998585 3644607 timer_generic.cc:614]         .. shard[0]->min_deadline = 10002

I1020 16:38:49.756014817 3644607 timer_generic.cc:537]         .. shard[0]: heap_empty=false

I1020 16:38:49.756025347 3644607 timer_generic.cc:547]         .. check top timer deadline=10002 now=10002

I1020 16:38:49.756038385 3644607 timer_generic.cc:553]       TIMER 0x15fd5d0: FIRE 0ms late

I1020 16:38:49.756079633 3644607 timer_generic.cc:537]         .. shard[0]: heap_empty=true

I1020 16:38:49.756116339 3644607 timer_generic.cc:578]         .. shard[0] popped 1

I1020 16:38:49.756155255 3644607 timer_generic.cc:632]         .. result --> 2, shard[0]->min_deadline 10002 --> 10012, now=10002

I1020 16:38:49.756192088 3644607 timer_generic.cc:741]       TIMER CHECK END: r=2; next=10008

I1020 16:38:49.756214446 3644607 timer_manager.cc:124]       kick untimed waiter

I1020 16:38:49.756242935 3644607 timer_manager.cc:132]       flush exec_ctx

D1020 16:38:49.756330308 3644607 exec_ctx.cc:37]             running closure 0x15fd608: created [/code/grpc-rpms/grpc-1.39.1/src/core/ext/filters/client_channel/backup_poller.cc:150]: schedul [/code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/timer_generic.cc:571]

I1020 16:38:49.756379611 3644607 ev_posix.cc:322]            (polling-api) pollset_work(0x15f9ee0, 10002) begin

I1020 16:38:49.756403999 3644607 ev_epollex_linux.cc:1123]   PS:0x15f9ee0 work hdl=(nil) worker=0x7fc04fffea20 now=10002 deadline=10002 kwp=0 pollable=0x15fd850

I1020 16:38:49.756402370 3644569 timer_manager.cc:204]       wait ended: was_timed:0 kicked:0

I1020 16:38:49.756446986 3644569 timer_generic.cc:719]       TIMER CHECK BEGIN: now=10002 next=9223372036854775807 tls_min=5005 glob_min=10008

I1020 16:38:49.756472145 3644569 timer_generic.cc:741]       TIMER CHECK END: r=1; next=10008

I1020 16:38:49.756487933 3644569 timer_manager.cc:188]       sleep for a 6 milliseconds

I1020 16:38:49.756420470 3644607 ref_counted.h:86]           pollable_refcount:0x15fd858 /code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/ev_epollex_linux.cc:1021 ref 1 -> 2 pollset_worker

I1020 16:38:49.756662042 3644607 ev_epollex_linux.cc:941]    POLLABLE:0x15fd850[type=pollset epfd=11 wakeup=12] poll for 0ms

I1020 16:38:49.756686807 3644607 ev_epollex_linux.cc:960]    POLLABLE:0x15fd850 got 1 events

I1020 16:38:49.756694463 3644607 ev_epollex_linux.cc:909]    PS:0x15f9ee0 got fd 0x7fc05402c610: cancel=0 read=1 write=1

D1020 16:38:49.756702012 3644607 lockfree_event.cc:218]      LockfreeEvent::SetReady: 0x7fc05402c650 curr=7fc0500010a0

D1020 16:38:49.756712018 3644607 lockfree_event.cc:218]      LockfreeEvent::SetReady: 0x7fc05402c658 curr=0

D1020 16:38:49.756719857 3644607 exec_ctx.cc:37]             running closure 0x7fc0500010a0: created [/code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/tcp_posix.cc:1811]: scheduled [/code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/lockfree_event.cc:247]

I1020 16:38:49.756732352 3644607 tcp_posix.cc:890]           TCP:0x7fc050000ef0 got_read: "No Error"

I1020 16:38:49.756771752 3644607 tcp_posix.cc:872]           TCP:0x7fc050000ef0 alloc_slices

I1020 16:38:49.756835306 3644607 resource_quota.cc:893]      RQ anonymous_pool_140463952633376 ipv4:10.84.2.178:8085: alloc 8192; free_pool -> -8192

I1020 16:38:49.756858178 3644607 combiner.cc:136]            C:0x7fc050001a20 grpc_combiner_execute c=0x7fc050002478 last=1

D1020 16:38:49.756890249 3644607 exec_ctx.cc:46]             closure 0x7fc0500010a0 finished

I1020 16:38:49.756901899 3644607 combiner.cc:201]            C:0x7fc050001a20 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=0

I1020 16:38:49.756920073 3644607 combiner.cc:224]            C:0x7fc050001a20 maybe_finish_one n=0x7fc050002478

I1020 16:38:49.756932744 3644607 combiner.cc:311]            C:0x7fc050001a20 grpc_combiner_execute_finally c=0x7fc050001e70; ac=0x7fc050001a20

I1020 16:38:49.756939523 3644607 combiner.cc:266]            C:0x7fc050001a20 finish old_state=5

I1020 16:38:49.756945418 3644607 combiner.cc:201]            C:0x7fc050001a20 grpc_combiner_continue_exec_ctx contended=0 exec_ctx_ready_to_finish=0 time_to_execute_final_list=1

I1020 16:38:49.756951635 3644607 combiner.cc:248]            C:0x7fc050001a20 execute_final[0] c=0x7fc050001e70

I1020 16:38:49.756959046 3644607 resource_quota.cc:324]      RQ: check allocation for user 0x7fc050002470 shutdown=0 free_pool=-8192 outstanding_allocations=8192

I1020 16:38:49.756965432 3644607 resource_quota.cc:352]      RQ anonymous_pool_140463952633376 ipv4:10.84.2.178:8085: grant alloc 8192 bytes; rq_free_pool -> 9223372036854767615

I1020 16:38:49.756978109 3644607 combiner.cc:266]            C:0x7fc050001a20 finish old_state=3

D1020 16:38:49.756984963 3644607 exec_ctx.cc:37]             running closure 0x7fc0500011c0: created [/code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/resource_quota.cc:993]: scheduled [/SCM/CM2.2/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/resource_quota.cc:366]

D1020 16:38:49.757015059 3644607 closure.h:239]              running closure 0x7fc050001208: created [/code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/resource_quota.cc:995]: run [/code/pc-rpms/grpc-1.39.1/src/core/lib/iomgr/resource_quota.cc:609]

I1020 16:38:49.757033236 3644607 tcp_posix.cc:853]           TCP:0x7fc050000ef0 read_allocation_done: "No Error"

I1020 16:38:49.757103329 3644607 tcp_posix.cc:684]           TCP:0x7fc050000ef0 call_cb 0x7fc06001f0e8 0x7fc07498de40:0x7fc06001ef10

I1020 16:38:49.757123697 3644607 tcp_posix.cc:686]           READ 0x7fc050000ef0 (peer=ipv4:10.84.2.178:8085) error="No Error"

D1020 16:38:49.757470891 3644607 tcp_posix.cc:692]           DATA: 16 03 03 0a b6 02 00 00 5a 03 03 e9 b7 d4 03 19 84 b4 8b 13 19 02 5f ef dd 88 09 bc 84 ab 00 bc 1d 75 87 f9 1e 9a c5 58 9e f3 90 205 6a 25 47 59 1b a8 67 1a 00 02 e2 d2 a0 2e 06 66 40 b7 99 46 df ac 88 99 a7 fa 44 5e 8e 55 22 c0 2f 00 00 12 00 10 00 05 00 03 02 68 32 00 17 00 00 ff 01 00 01 00 0b 00 07 e6 00 07 e3 00 04 5e 30 804 5a 30 82 03 42 a0 03 02 01 02 02 04 78 34 73 87 30 0d 06 09 2a 86 48 86 f7 0d 01 01 0b 05 00 30 67 31 1a 30 18 06 03 55 04 03 13 11 64 63 61 65 2d 73 69 6d 75 6c 61 74 6f 72 2d 63 61 31 0d 30 0b  03 55 04 0b 13 04 4d 41 4e 4f 31 0e 30 0c 06 03 55 04 0a 13 05 4e 6f 6b 69 61 31 10 30 0e 06 03 55 04 07 13 07 57 72 6f 63 6c 61 77 31 0b 30 09 06 03 55 04 08 13 02 44 4c 31 0b 30 09 06 03 55 04 063 02 50 4c 30 1e 17 0d 32 31 31 30 31 39 31 35 30 30 33 36 5a 17 0d 32 33 31 30 31 39 31 35 30 30 33 36 5a 30 6b 31 1e 30 1c 06 03 55 04 03 13 15 64 63 61 65 2d 73 69 6d 75 6c 61 74 6f 72 2d 73 65 776 65 72 31 0d 30 0b 06 03 55 04 0b 13 04 4d 41 4e 4f 31 0e 30 0c 06 03 55 04 0a 13 05 4e 6f 6b 69 61 31 10 30 0e 06 03 55 04 07 13 07 57 72 6f 63 6c 61 77 31 0b 30 09 06 03 55 04 08 13 02 44 4c 31  30 09 06 03 55 04 06 13 02 50 4c 30 82 01 a2 30 0d 06 09 2a 86 48 86 f7 0d 01 01 01 05 00 03 82 01 8f 00 30 82 01 8a 02 82 01 81 00 ab 5d 72 11 8b 30 0a e0 16 a6 44 5b 8a 52 af cc 93 1e 1c 76 bc c37 b8 0d 08 f5 b7 71 87 82 6e c8 fa 06 4a 24 df 85 df ea 13 25 3a 76 3d 60 4c 6e 58 a6 e0 03 c0 c8 20 ad 9f ef 55 02 ce 3c de 03 a6 1f e8 50 a5 ea 19 04 97 da 9a 5a 71 93 b1 5f a6 e2 e8 5a d3 68 b3 ba2 41 ea c4 0c 48 a3 0f 97 9a d9 10 b5 d7 f1 7e 34 8e b1 8c 93 77 f0 eb b5 aa e9 e4 60 7c 4b 30 04 48 40 a5 18 b0 6f b6 39 d6 b2 42 71 cd e0 12 3e 75 7b fa f2 4a e3 14 3a aa 7f 84 8b 40 d9 6e 02 03  8f 29 6b 89 57 e7 98 7a bf e1 5a e3 9a 89 c7 3b 77 62 ce 8a c5 22 82 44 31 90 7e dd 6f 0c e8 f3 70 d3 d6 01 b8 1d 33 9e 49 a9 5e 53 62 df 77 55 2c 54 5f 9a 88 9f 69 30 a8 8f 37 08 e5 cc 3c 52 b7 3af 3e bc d1 3f 64 c8 3c 2f 3c 18 32 41 ce 4f 00 c1 eb 39 1a 9a a2 d8 5f f9 b5 61 69 be a1 ec 1d 14 0d ce 30 98 6f 7a fb 6f 18 c9 77 fb 5b 46 49 85 4f b8 b0 55 4c fb 78 a4 3b 43 37 f0 ca d8 31 04 ed b10 0f 97 54 55 fe db 6e 11 c9 3e 0c 8b da e9 eb a3 39 1b dd b8 50 bc ce e1 78 fa 3c a3 c0 08 49 22 00 81 6e e2 f5 03 34 64 5a 67 72 99 31 fb 42 95 41 ea bc 47 33 98 2f 80 05 11 8f e8 84 08 89 9a d2  b5 74 10 d2 2d 56 d6 45 dc 2e 53 67 71 f1 6c 27 ec 20 aa 66 66 c4 55 30 8f 4d 27 15 02 03 01 00 01 a3 81 89 30 81 86 30 1f 06 03 55 1d 23 04 18 30 16 80 14 d2 04 7f 51 5f a7 ae e4 06 bd da c8 b3 584 8b e0 4a 8b 7b 30 44 06 03 55 1d 11 04 3d 30 3b 82 11 64 63 61 65 2d 73 69 6d 75 6c 61 74 6f 72 2d 63 61 82 15 64 63 61 65 2d 73 69 6d 75 6c 61 74 6f 72 2d 73 65 72 76 65 72 82 09 6c 6f 63 61 6c 66f 73 74 87 04 0a 54 02 b2 30 1d 06 03 55 1d 0e 04 16 04 14 15 52 96 95 4a 1c 02 65 d6 16 99 76 44 ec 2d ff ce 12 f1 b3 30 0d 06 09 2a 86 48 86 f7 0d 01 01 0b 05 00 03 82 01 01 00 93 de 8a 48 10 4a  f9 e3 f1 80 07 fd db 91 b1 08 04 df e3 9d c9 c3 44 33 21 5f bf bb 41 41 90 51 7f e4 ea 10 5a 9e ce 22 99 07 f9 d0 db 99 b9 bb 98 e5 06 19 12 14 76 75 39 24 04 ed 84 b2 ae 17 97 9e 81 65 ce a4 a7 561 62 8f 4f 7f 4d 9f 13 56 66 1c ec b8 9b fd 44 e0 de a8 85 fb ee 0a d4 bf 6e f8 c1 56 bb 07 49 44 69 a0 8b ce db 29 1b 0e ad f3 17 d1 d1 be e0 82 26 76 df b5 b0 b7 7e 94 6e 5a a8 a0 b7 69 3a 04 4a 3ee 1f 39 33 42 a0 b6 44 15 a6 8d 6d 9c 0f 13 bf 9f 9b 25 1b 4a 74 eb 3e 2b 41 db ef 64 63 e1 14 74 ab 85 da 98 42 fb 73 ff 7a 13 7b eb 7b 23 df a6 00 0f c4 22 4c 07 67 43 d6 82 dc f6 38 38 ef 79 7f  cd bb e6 29 c5 bd 41 af 2a ad b8 0b d2 9a f6 95 3e b5 cf b7 1c ee 74 87 59 92 2b c6 b0 29 7a a4 15 61 2f 5a fb 10 78 05 25 3a c1 05 76 aa cd 7b 61 00 03 7f 30 82 03 7b 30 82 02 63 a0 03 02 01 02 024 5a 21 1f 9c 30 0d 06 09 2a 86 48 86 f7 0d 01 01 0b 05 00 30 67 31 1a 30 18 06 03 55 04 03 13 11 64 63 61 65 2d 73 69 6d 75 6c 61 74 6f 72 2d 63 61 31 0d 30 0b 06 03 55 04 0b 13 04 4d 41 4e 4f 31 030 0c 06 03 55 04 0a 13 05 4e 6f 6b 69 61 31 10 30 0e 06 03 55 04 07 13 07 57 72 6f 63 6c 61 77 31 0b 30 09 06 03 55 04 08 13 02 44 4c 31 0b 30 09 06 03 55 04 06 13 02 50 4c 30 1e 17 0d 32 31 31 30  39 31 35 30 30 31 39 5a 17 0d 32 33 31 30 31 39 31 35 30 30 31 39 5a 30 67 31 1a 30 18 06 03 55 04 03 13 11 64 63 61 65 2d 73 69 6d 75 6c 61 74 6f 72 2d 63 61 31 0d 30 0b 06 03 55 04 0b 13 04 4d 41e 4f 31 0e 30 0c 06 03 55 04 0a 13 05 4e 6f 6b 69 61 31 10 30 0e 06 03 55 04 07 13 07 57 72 6f 63 6c 61 77 31 0b 30 09 06 03 55 04 08 13 02 44 4c 31 0b 30 09 06 03 55 04 06 13 02 50 4c 30 82 01 22 30d 06 09 2a 86 48 86 f7 0d 01 01 01 05 00 03 82 01 0f 00 30 82 01 0a 02 82 01 01 00 9d 25 72 1b 1d a6 e6 85 d5 88 0c 20 ff a6 14 4a e2 e7 bf 74 e9 35 8c 55 d3 23 30 f1 ac 2b 18 29 9c 13 b2 e5 92 f2  0c 47 ff 2d 58 a7 23 e5 cf aa 37 63 23 d0 bc 00 59 f3 05 0a fd f2 c4 a4 cc 5d 18 ed 5a c9 57 e4 60 f0 2f 5c c7 3f 07 fa f4 67 f3 da d3 56 ff 4b d7 92 da 83 c0 da 6d 0d d0 29 a8 91 dc 9b c2 fc 3e 9a0 b5 5f 69 66 b3 4c d6 2c 28 09 c8 f4 6d 66 62 fa 76 e6 29 a9 7b 01 12 fc 8a 35 af 1b e0 43 1b a5 31 41 4f 82 9c 06 ca f9 1f 24 8e 69 7e 5e e9 8b 5e c8 6f 6c 1e 4e 56 60 3e a3 d7 0d f9 b6 77 f0 69 a15 2c da 6c da be 68 35 d7 39 62 62 0f 01 28 0b 71 a9 34 28 f9 34 74 f7 67 a4 1d 43 b0 9b a7 3b de e6 d5 c3 bd 02 82 87 77 af e4 4a 31 8d fb 7e 18 8e cd a7 f4 64 94 3b 3d f0 81 2f fc 2d 47 26 6c 57  49 47 e4 70 77 cd fa 25 68 d8 c8 28 5f 7d 4f f6 21 02 03 01 00 01 a3 2f 30 2d 30 0c 06 03 55 1d 13 04 05 30 03 01 01 ff 30 1d 06 03 55 1d 0e 04 16 04 14 d2 04 7f 51 5f a7 ae e4 06 bd da c8 b3 58 24b e0 4a 8b 7b 30 0d 06 09 2a 86 48 86 f7 0d 01 01 0b 05 00 03 82 01 01 00 2b ac f1 ff 20 b1 de 44 f4 ec 8c 4b a9 62 38 e9 65 2d 94 4a 01 30 78 f4 93 8d 8e b4 2c 68 97 92 05 e6 a0 f5 73 3a 08 04 2b 852 e3 00 9e e3 40 63 0e 50 b8 c1 b0 bf 68 15 82 8f 1e 02 2d 9f 67 63 85 9c df 06 3d 57 18 3c fc 2d a4 65 74 22 61 85 b5 94 15 70 7c 99 f1 b3 3c f6 20 cb 91 01 76 49 bb a5 e7 e6 2d 7f 0b 44 f6 c0 6c  6b 8e 44 59 a7 cf 7c 69 c3 3a 3a 82 7e 37 ad cd bc ac b4 a4 5c c1 e2 73 3e 1b 63 da 2b e6 e7 0f 1b b4 1e b1 89 80 ad a1 7d 56 e0 d4 6c 2c 87 e6 7b 19 64 b4 89 19 f9 04 79 8e 7f 63 e1 ba 1e 91 2a a34 fa 4b 1e a7 21 65 a1 fb d7 2f 99 d7 8d e5 44 fb 87 2b 51 cf 8e f1 d6 79 43 e7 c8 e5 e3 67 6b 3c fc 9b 4a 0f 2f b2 68 3c 68 f6 d1 23 57 9a a2 e5 27 d2 73 b0 66 b6 c7 e0 02 35 4a 45 61 68 c6 df 87 08a 26 89 ae c8 34 20 63 2f d1 39 4b 55 e7 0c 00 01 c9 03 00 17 41 04 24 20 40 84 c5 95 f4 b7 0d 61 bc 59 5a 02 f3 4b 04 26 84 54 6e 7e b5 53 74 d5 f3 7b 57 a3 e4 9c 5b dc 04 7e 56 b3 ef 36 f5 0d 6a  28 b1 60 72 19 85 c1 3f 6c 68 f7 82 ee b8 fc 08 43 1d 91 ca 08 04 01 80 22 a7 6a 90 89 28 55 7e af 78 d2 cd 1b 5f 60 d4 42 36 8f 45 20 2f f3 20 fe e7 98 93 45 ba e6 35 88 55 25 3a e5 d9 e2 be f5 c86 fd 0f 50 11 8d 28 38 55 1a 29 9c 12 95 17 e6 ca 55 af 41 3f 97 fd 98 a9 c5 48 d5 16 aa 93 f8 9a 84 70 99 50 53 58 ca 92 8d ea cf 01 da 5e 35 81 f4 7d 20 16 b4 20 97 7a e5 de 6c 12 90 e9 88 82 97 f97 95 76 6b 9c 81 c7 10 ee 6a c3 fb 81 aa ae f6 bd a8 a9 00 23 fa 06 90 b5 74 c4 5b 57 29 06 1d 10 2b 79 87 d1 57 a8 39 ef f8 e7 7a a1 b6 ce af 5f 10 6d 2a 89 f8 16 c0 ee 38 83 cf b9 04 b6 4a 96 f0  36 06 9a 73 9a fa 93 46 95 15 63 a0 26 e7 95 c5 bc ae d5 75 87 8d bd 43 ae 42 16 94 7d d8 2f 7f 1a c2 af 55 e0 91 e5 fb 6b 8f 00 48 4a 17 d0 b4 81 f4 20 02 65 e7 bf 27 eb 9a 9d f3 d9 85 f8 15 74 aeb d9 5d 89 49 b7 d4 22 f2 f0 fc f6 03 3b 81 84 d5 82 3c 4a e6 d3 09 f2 78 6d 31 51 54 4a 34 0b 54 63 fb 76 6e 3c 5f be f2 b0 79 3a 57 2c 0e 04 83 24 ac c4 f2 c1 57 9c 53 95 a0 47 03 f0 74 2a 77 8d 272 d1 cf 58 78 03 f3 5a 9a 01 a8 8d 40 3f 27 69 51 35 fa 5e 61 7d 18 17 49 18 7f 12 72 af 23 ad ac 56 22 0d 9d 5a b8 0d c1 85 af 73 09 0a ba 17 31 c4 a9 09 59 26 c7 2c 59 25 11 2b ae 9c 90 15 c4 fb  da df 4c b1 17 1c af c2 0d 00 00 99 03 40 01 02 00 26 04 03 05 03 06 03 08 04 08 05 08 06 08 09 08 0a 08 0b 04 01 05 01 06 01 04 02 03 03 03 01 03 02 02 03 02 01 02 02 00 6b 00 69 30 67 31 1a 30 186 03 55 04 03 13 11 64 63 61 65 2d 73 69 6d 75 6c 61 74 6f 72 2d 63 61 31 0d 30 0b 06 03 55 04 0b 13 04 4d 41 4e 4f 31 0e 30 0c 06 03 55 04 0a 13 05 4e 6f 6b 69 61 31 10 30 0e 06 03 55 04 07 13 07 572 6f 63 6c 61 77 31 0b 30 09 06 03 55 04 08 13 02 44 4c 31 0b 30 09 06 03 55 04 06 13 02 50 4c 0e 00 00 00 '........Z............._..........u.....X... 5j%GY..g........f@..F......D^.U"./..........h.................^0..Z0..B.......x4s.0...*.H........0g1.0...U....simulator-ca1.0...U....MANO1.0...U....Ioanna1.0...U....Olarg1.0...U....DL1.0...U....PL0...211019150036Z..231019150036Z0k1.0...U..simulator-server1.0...U....MANO1.0...U....Ioanna1.0...U....Olarg1.0...U....DL1.0...U....PL0...0...*.H.............0.........]r..0....D[.R.....v........q..n...J$.....%:v=`LnX..... ...U..<...........Zq.._...Z.h...A...H.........~4....w......`|K0.H@...o.9..Bq...>u{..J..:....@.n..].)k.W..z..Z....;wb...".D1.~.o...p.....3.I.^Sb.wU,T_...i0..7...<R.:.>..?d.</<.2A.O...9...._..ai.......0.oz.o..w.I.O..UL.x.;C7...1......TU..n..>......9...P...x.<...I"..n...4dZgr.1.B.A..G3./..........K.t..-V.E..Sgq.l'. .ff.U0.M'.........0..0...U.#..0......Q_........X$..J.{0D..U...=0;..simulator-ca..silator-server..localhost...T..0...U.......R..J..e...vD.-.....0...*.H................H.Jj................D3!_..AA.Q....Z.."..............vu9$.........e...Vab.O.M..Vf.....D.........n..V..IDi....)........&v....~.nZ...i:.J2..93B..D...m......%.Jt.>+A..dc..t....B.s.z.{.{#....."L.gC....88.y.....)..A.*.......>.....t.Y.+..)z..a/Z..x.%:..v..{a...0..{0..c.......Z!..0...*.H........0g1.0...U....simulat-ca1.0...U....MANO1.0...U....Ioanna1.0...U....Olarg1.0...U....DL1.0...U....PL0...211019150019Z..231019150019Z0g1.0...U....simulator-ca1.0...U....MANO1.0...U....Ioanna1.0...U....Olarg1.0...U..DL1.0...U....PL0.."0...*.H.............0.........%r........ ...J...t.5.U.#0..+.)......n.G.-X.#...7c#...Y........]..Z.W.`./\.?...g...V.K......m..)......>.p._if.L.,(...mfb.v.).{....5...C..1AO......$.i..^.ol.NV`>.....w.i..,.l..h5.9bb..(.q.4(.4t.g..C...;........w..J1..~.....d.;=../.-G&lW.IG.pw..%h..(_}O.!....../0-0...U....0....0...U.........Q_........X$..J.{0...*.H.............+... ..D...K.b8.e-.Jx.....,h......s:..+.R....@c.P....h.....-.gc....=W.<.-.et"a....p|...<. ...vI....-..D..l.k.DY..|i.::.~7......\..s>.c.+...........}V..l,..{.d.....y..c....*...K..!e.../....D..+Q....yC....gk<..J./.h<h..#..'.s.f....5JEah.....&...4 c/.9KU........A.$ @......a.YZ..K.&.Tn~.St..{W...[..~V..6..jc(.`r...?lh......C.......".j..(U~.x..._`.B6.E /. ....E..5.U%:.........P..(8U.)......U.A?.....H.......p.PSX......5..} .. .z..l.........vk.....j..........#....t.[W)...+y..W.9...z...._.m*.....8.....J...6..s...F..c.&......u...C.B..}./....U....k..HJ..... .e..'........t...].I..".....;....<J....xm1QTJ4.Tc.vn<_...y:W..$....W.S..G..t*w. r..Xx..Z....@?'iQ5.^a}..I...r.#..V"..Z.....s....1...Y&.,Y%.+.........L..........@...&.......................................k.i0g1.0...U....simulator-ca1.0...U....MANO1.0......Ioanna1.0...U....Olarg1.0...U....DL1.0...U....PL....'

D1020 16:38:49.757739540 3644607 closure.h:239]              running closure 0x7fc06001f0e8: created [/code/grpc-rpms/grpc-1.39.1/src/core/lib/security/transport/security_handshaker.cc:469]: n [/code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/tcp_posix.cc:700]

D1020 16:38:49.757764961 3644607 closure.h:248]              closure 0x7fc06001f0e8 finished

I1020 16:38:49.757782463 3644607 ref_counted.h:182]          tcp:0x7fc050000f18 /code/grpc-rpms/grpc-1.39.1/src/core/lib/iomgr/tcp_posix.cc:847 unref 3 -> 2 read

D1020 16:38:49.757795132 3644607 closure.h:248]              closure 0x7fc050001208 finished

D1020 16:38:49.757805975 3644607 exec_ctx.cc:46]             closure 0x7fc0500011c0 finished

D1020 16:38:49.757817762 3644607 exec_ctx.cc:37]             running closure 0x7fc06001f0e8: created [/code/grpc-rpms/grpc-1.39.1/src/core/lib/security/transport/security_handshaker.cc:415]: heduled [/code/grpc-rpms/grpc-1.39.1/src/core/lib/security/transport/security_handshaker.cc:412]

I1020 16:38:49.757904652 3644607 ssl_transport_security.cc:223]                 LOOP -   SSLv3/TLS write client hello  -  TWCH

I1020 16:38:49.757954352 3644607 ssl_transport_security.cc:223]                 LOOP -    SSLv3/TLS read server hello  -  TRSH

I1020 16:38:49.758273052 3644607 ssl_transport_security.cc:223]                 LOOP - SSLv3/TLS read server certific  -  TRSC

I1020 16:38:49.758521506 3644607 ssl_transport_security.cc:223]                 LOOP - SSLv3/TLS read server key exch  - TRSKE

I1020 16:38:49.758579993 3644607 ssl_transport_security.cc:223]                 LOOP - SSLv3/TLS read server certific  -  TRCR

I1020 16:38:49.758595126 3644607 ssl_transport_security.cc:223]                 LOOP -     SSLv3/TLS read server done  -  TRSD

I1020 16:38:49.758737762 3644607 ssl_transport_security.cc:223]                 LOOP - SSLv3/TLS write client certifi  -  TWCC

I1020 16:38:49.759098035 3644607 ssl_transport_security.cc:223]                 LOOP - SSLv3/TLS write client key exc  - TWCKE

`

Thanks

[ioanna del]

Hello,

Finally the issue has been fixed. It was related with the way that the grpc client checked the connectivity state.

[Richard Belleville]

Can you please go into a little more detail on what the problem and fix were? It could be helpful for others for future reference.

[Israel Shapiro]

Can you please share more information about how it was fixed? We are experiencing the same issue. Thank you!

On Friday, October 22, 2021 at 5:56:31 AM UTC-7 ioanna del wrote:

[ioanna del]

Hello,

Yes, sure. I am sorry for the late response. I just read your mail. 
Unfortunately I had not understood the exact root cause of this behavior although I went through the grpc implementation. When I was testing this, it seemed to me that some timer threads were generated and delayed reading from the socket.

Initially, in our implementation we had tried to identify if the channel was connected using the (*channel).GetState(true)iteratively. For example:

while (true) {

state = (*channel).GetState(true);

if (GRPC_CHANNEL_READY == state) {

//...

}

}

Although the above implementation was generally used and proposed in forums and examples, it seemed that triggered the above problem and the delays in our case. Perhaps this happened because we we were always passing the "true" value in GetState. Currently, we have modified this part and we invoke (*channel).GetState(true); only once at the beginning. Then we use the (*channel).WaitForConnected iteratively. For example:

bool isConnected = false;
state = (*channel).GetState(true);
while (true) {
    isConnected = (*channel).WaitForConnected(gpr_time_add(gpr_now(GPR_CLOCK_REALTIME), gpr_time_from_seconds(2, GPR_TIMESPAN)));
    if (isConnected) {
        //...
        break;
    }
}

Best regards,

Ioanna Deli

This electronic communication and the information and any files transmitted with it, or attached to it, are confidential and are intended solely for the use of the individual or entity to whom it is addressed and may contain information that is confidential, legally privileged, protected by privacy laws, or otherwise restricted from disclosure to anyone else. If you are not the intended recipient or the person responsible for delivering the e-mail to the intended recipient, you are hereby notified that any use, copying, distributing, dissemination, forwarding, printing, or copying of this e-mail is strictly prohibited. If you received this e-mail in error, please return the e-mail to the sender, delete it from your computer, and destroy any printed copy of it.

--
You received this message because you are subscribed to a topic in the Google Groups "grpc.io" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/grpc-io/_gdhX9aP7GE/unsubscribe.
To unsubscribe from this group and all its topics, send an email to grpc-io+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/grpc-io/859f004d-1362-4b64-a0cd-eefc4715a828n%40googlegroups.com.

[Israel Shapiro]

Hello and sorry for the delayed response on my end too. 

What you described is similar to what we do as well. We use Channel::WaitForConnected(deadline) at initialization time and then use Channel::GetState(true) only just prior to performing the RPC requests. The problem I am seeing happens even without getting to the GetState(true) call. I see that setting the GRPC_CLIENT_CHANNEL_BACKUP_POLL_INTERVAL_MS environment variable to a lower value than the default 5000ms seems to solve the problem. Essentially it seems that somehow the channel fd doesn't get managed properly by the epoll logic and the only way events get handled is through the timer-based backup poller. 

I also saw some other reports from other people online that stated that this logic also causes RPC latency in some cases. and setting a lower value solves the issue for them. So it seems this is not just for initial connection establishment. 

Thanks,

Israel Shapiro

 

[ioanna del]

Hello,

Thank you for the information! From our side we have not observed any other delays so far. I will this in mind if any delay happens in the future.

Thanks,

Ioanna Deli