Open batmancn opened 4 years ago
Don't see the pcap, but my guess is it's related to authentication or encryption of the gRPC channel, being you've used "-insecure = True" on the Go client.
You may need to use the "-o" flag to specify the CN in the Cert being utilized on the Target (assuming it's a self-signed cert?)
Don't see the pcap, but my guess is it's related to authentication or encryption of the gRPC channel, being you've used "-insecure = True" on the Go client.
You may need to use the "-o" flag to specify the CN in the Cert being utilized on the Target (assuming it's a self-signed cert?)
The server side start command use '--insecure', which is:
/usr/sbin/telemetry -logtostderr --log_to_syslog=true --insecure --port 8080 --allow_no_client_auth -v=2
Which is NOT use any cert or CN ?
And server side is written by GO, using "google.golang.org/grpc"
I guess, is there some additional process between /usr/sbin/telemetry(server side, GO) and gnmi_get(client side, GO), like server send it's cert to client?
I think this may be problem? The py_gnmicli.py send GRPC request by 'Plaintext'. The gnmi_get send GRPC request by 'Encryption text'. This may be use '--insecure' on gnmi_get client and /usr/sbin/telemetry(server side, GO)?
So is there '--insecure' option in py_gnmicli.py? This may be the ROOT CAUSE?
Last, by searching code, I found this is really because of '-insecure' and '-allow_no_client_auth'.
In server side, which is SONiC/TELEMETRY
I start /usr/sbin/telemetry with '-insecure' mode. This mode does NOT mean no cert, it's using testcert, code like this:
import (
testcert "github.com/Azure/sonic-telemetry/testdata/tls"
)
if *insecure {
certificate, err = testcert.NewCert()
...
I start /usr/sbin/telemetry with '-allow_no_client_auth' mode. code like this:
if *allowNoClientCert {
// RequestClientCert will ask client for a certificate but won't
// require it to proceed. If certificate is provided, it will be
// verified.
tlsCfg.ClientAuth = tls.RequestClientCert
}
So I follow gnmi_get, use py_gnmicli.py by '-g -o 172.18.8.241' option, but still failed, like this:
gyw@sonic107:~/go/src/github.com/google/gnxi/gnmi_cli_py$ python py_gnmicli.py -g -o 172.18.8.241 -m get -t 172.18.8.241 -p 8080 -x "/interfaces/interface[name=Ethernet16]"
Performing GetRequest, encoding=JSON_IETF to 172.18.8.241 with the following gNMI Path
-------------------------
elem {
name: "interfaces"
}
elem {
name: "interface"
key {
key: "name"
value: "Ethernet16"
}
}
E0528 15:27:43.755705145 29455 ssl_transport_security.cc:1233] Handshake failed with fatal error SSL_ERROR_SSL: error:1000007d:SSL routines:OPENSSL_internal:CERTIFICATE_VERIFY_FAILED.
Traceback (most recent call last):
File "py_gnmicli.py", line 415, in <module>
main()
File "py_gnmicli.py", line 384, in main
response = _get(stub, paths, user, password)
File "py_gnmicli.py", line 277, in _get
return stub.Get(gnmi_pb2.GetRequest(path=[paths], encoding='JSON_IETF'))
File "/opt/gyw/.local/lib/python2.7/site-packages/grpc/_channel.py", line 550, in __call__
return _end_unary_response_blocking(state, call, False, None)
File "/opt/gyw/.local/lib/python2.7/site-packages/grpc/_channel.py", line 467, in _end_unary_response_blocking
raise _Rendezvous(state, None, None, deadline)
grpc._channel._Rendezvous: <_Rendezvous of RPC that terminated with:
status = StatusCode.UNAVAILABLE
details = "Connect Failed"
debug_error_string = "{"created":"@1590650863.755855836","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590650863.755851300","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590650863.755829959","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590650863.755731795","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]}"
>
Yep, looks related to encryption "TSI_PROTOCOL_FAILURE".
You can add the --debug flag to see more. Is the CN of the test certificate really "172.18.8.241"?
gyw@sonic107:~/go/src/github.com/google/gnxi/gnmi_cli_py$ python py_gnmicli.py -g -m get -t 172.18.8.241 -p 8080 -x "/interfaces/interface[name=Ethernet16]" --debug
I0529 10:47:08.874805604 5682 ev_epoll1_linux.cc:116] grpc epoll fd: 3
D0529 10:47:08.874852138 5682 ev_posix.cc:170] Using polling engine: epoll1
D0529 10:47:08.874906304 5682 dns_resolver.cc:334] Using native dns resolver
I0529 10:47:08.874930196 5682 timer_manager.cc:94] Spawn timer thread
I0529 10:47:08.874976737 5682 init.cc:154] grpc_init(void)
I0529 10:47:08.875019289 5685 timer_generic.cc:715] TIMER CHECK BEGIN: now=0 next=9223372036854775807 tls_min=0 glob_min=0
I0529 10:47:08.875074005 5685 timer_generic.cc:610] .. shard[0]->min_deadline = 1
I0529 10:47:08.875083036 5685 timer_generic.cc:738] TIMER CHECK END: r=1; next=1
I0529 10:47:08.875093511 5685 timer_manager.cc:186] sleep for a 1 milliseconds
I0529 10:47:08.875046889 5682 ssl_credentials.cc:128] grpc_ssl_credentials_create(pem_root_certs=-----BEGIN CERTIFICATE-----
MIIFATCCAumgAwIBAgIQZHEHaKadEdrryxDTUbgakjANBgkqhkiG9w0BAQsFADAV
MRMwEQYDVQQKEwpFeGFtcGxlIENvMB4XDTIwMDUyOTAyMjYzMloXDTIwMDUyOTAz
MjYzMlowFTETMBEGA1UEChMKRXhhbXBsZSBDbzCCAiIwDQYJKoZIhvcNAQEBBQAD
ggIPADCCAgoCggIBALvlTkkHZ2893BPxUncntxiFiIjRLHQYJruqd2rJDUfzEyP1
Z+6t7/BtNB2gjb6NM+g3z7KFkuesvPrBesX/b03Ppo8yjOnv+ufgAdIPgzAuKDaS
OTQ8iVS+l/LOopVFKGmOZ2CesSfwDC30hHXAWyxIiGdf3/GkH1VgJ7EbZLcIp6qP
cTS0ex5I6wn/vh581Stkc5aE1k7KBeOAmmwQMBESYcBtD2sx+sbP7jMbvKSmTePQ
4tBRqgLrGo9v+YLM0EsoX3qRkAcuFTtOsPInTFcVdBD+6H5Jtoqp94b78Jp9kJAP
dw5IXtXrfwXNtzfoICAhkNCY4TJAokW6vyluFQ5nlPcY6ZI+vTBmv7Eb+7425yvA
+rchHtNHCEsG+3HjWUYDxSmU872l3FjBpgh+uPSCTty5DyDv6E3vcDxxzyRtoPFa
WO5iku2latXP82gQxg4GDg6jAOvFSHql+/ldB0kCiq7nVSXyR3HJfZb7iZDC7Btx
BpxfbFvjBcgdRv1y81gcYuxQLaZ8sFjMp+6h6P5z1uQmg8lJ246ulLPajzD1xph+
vGp3wNUoZjbV0SzwH7Wcq+rcYSEtjaTiPYR3n7eS2bwJKE10fewmIi8z6Y7dZbLx
uEGWpanjhGorGJuYxhfYVIM2qHRa9HjV+RrTIvO7WB5jfyzTTQw0vSdzMY1pAgMB
AAGjTTBLMA4GA1UdDwEB/wQEAwIFoDATBgNVHSUEDDAKBggrBgEFBQcDATAMBgNV
HRMBAf8EAjAAMBYGA1UdEQQPMA2CC2V4YW1wbGUuY29tMA0GCSqGSIb3DQEBCwUA
A4ICAQAcrZeQpe0dUl1FQma/QymTW1Q7BUuhPdB/sX3dZLVIVl5nFwqhum7rj7rB
F6SiBfIlJhYGBrCvZ8QqIp1fjp1/GFP5J5vjvxKyg5NKoq7BT6xq97T2XJRm+kUo
D0TtXkns5yAX8nXBlHdqFNO7L5Yq/t9NTG4B+IFPBNOKI0L5IV5ZYNbML7zycMSx
pAq9gzU3D0XkRg67tdyxnlgdiyRsGdB2hs9EHrECXQAJviwgXw777g65ph2/6gTi
coEE7vzhvLJEt7Mb21+9gBvdvVcekrkSIE754fTPskp2pNiW5Gna/nkVtAeIajQv
h8RaSfTvRCeNBaChhrYhsFyL8wb0WOvSoiapjPjC42Ar9zC9LIBDQRDxVzx/rICG
qR1D6PUtB6aMdxc7JvCXlXuF5OFhicyDK/i4p4s+d8bK+xH8okjjMflh5sfeU0u6
ddmtYPM2eNiJy7ZF/q8c5ZGIZK01+QcinP7mzJrUrOBjkFqYu99qJzLqjf9vAwln
7aiUMgsrYwn3r3RtRkARusuLwZcxk9stE3nn27KBvPE+/PHtTas/embi5gNYEHsz
pMvQZvDLnekazIKstfugcaZYqclmfvhjtXaKaj57PHe6ZfJhdsB4tbswnG8x9dfg
KkU9HxT4W/CpuQOT2uNfRS9bkDOaNd+xxEx4qFMZKVSLtmnGhg==
-----END CERTIFICATE-----
, pem_key_cert_pair=(nil), verify_options=(nil), reserved=(nil))
I0529 10:47:08.875194849 5682 secure_channel_create.cc:207] grpc_secure_channel_create(creds=0x13326a0, target=172.18.8.241:8080, args=0x7f547a636440, reserved=(nil))
I0529 10:47:08.875281399 5682 timer_generic.cc:365] TIMER 0x1133fd0: SET 5000 now 0 call 0x1134000[0x7f547afec4e0]
I0529 10:47:08.875295468 5682 timer_generic.cc:401] .. add to shard 14 with queue_deadline_cap=0 => is_first_timer=false
I0529 10:47:08.875328996 5682 channel.cc:285] grpc_channel_get_target(channel=0x132e0e0)
I0529 10:47:08.875350599 5682 credentials.cc:43] grpc_channel_credentials_release(creds=0x13326a0)
I0529 10:47:08.875361535 5682 completion_queue.cc:481] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
I0529 10:47:08.875372079 5682 completion_queue.cc:481] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
Performing GetRequest, encoding=JSON_IETF to 172.18.8.241 with the following gNMI Path
-------------------------
I0529 10:47:08.875716944 5685 timer_manager.cc:206] wait ended: was_timed:1 kicked:0
I0529 10:47:08.875746249 5685 timer_generic.cc:715] TIMER CHECK BEGIN: now=1 next=9223372036854775807 tls_min=0 glob_min=1
I0529 10:47:08.875760698 5685 timer_generic.cc:610] .. shard[0]->min_deadline = 1
I0529 10:47:08.875772553 5685 timer_generic.cc:533] .. shard[0]: heap_empty=true
I0529 10:47:08.875783955 5685 timer_generic.cc:508] .. shard[0]->queue_deadline_cap --> 1001
I0529 10:47:08.875794852 5685 timer_generic.cc:573] .. shard[0] popped 0
I0529 10:47:08.875806939 5685 timer_generic.cc:628] .. result --> 1, shard[0]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.875818667 5685 timer_generic.cc:533] .. shard[1]: heap_empty=true
I0529 10:47:08.875831016 5685 timer_generic.cc:508] .. shard[1]->queue_deadline_cap --> 1001
I0529 10:47:08.875845760 5685 timer_generic.cc:573] .. shard[1] popped 0
I0529 10:47:08.875856814 5685 timer_generic.cc:628] .. result --> 1, shard[1]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.875867786 5685 timer_generic.cc:533] .. shard[2]: heap_empty=true
I0529 10:47:08.875877924 5685 timer_generic.cc:508] .. shard[2]->queue_deadline_cap --> 1001
I0529 10:47:08.875888394 5685 timer_generic.cc:573] .. shard[2] popped 0
I0529 10:47:08.875899388 5685 timer_generic.cc:628] .. result --> 1, shard[2]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.875910178 5685 timer_generic.cc:533] .. shard[3]: heap_empty=true
elem {
name: "interfaces"
}
elem {
name: "interface"
key {
key: "name"
value: "Ethernet16"
}
}
I0529 10:47:08.875920784 5685 timer_generic.cc:508] .. shard[3]->queue_deadline_cap --> 1001
I0529 10:47:08.875948092 5685 timer_generic.cc:573] .. shard[3] popped 0
I0529 10:47:08.875960735 5685 timer_generic.cc:628] .. result --> 1, shard[3]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.875971729 5685 timer_generic.cc:533] .. shard[4]: heap_empty=true
I0529 10:47:08.875982580 5685 timer_generic.cc:508] .. shard[4]->queue_deadline_cap --> 1001
I0529 10:47:08.875992735 5685 timer_generic.cc:573] .. shard[4] popped 0
I0529 10:47:08.876003706 5685 timer_generic.cc:628] .. result --> 1, shard[4]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876014388 5685 timer_generic.cc:533] .. shard[5]: heap_empty=true
I0529 10:47:08.876024568 5685 timer_generic.cc:508] .. shard[5]->queue_deadline_cap --> 1001
I0529 10:47:08.876034864 5685 timer_generic.cc:573] .. shard[5] popped 0
I0529 10:47:08.876045970 5685 timer_generic.cc:628] .. result --> 1, shard[5]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876056549 5685 timer_generic.cc:533] .. shard[6]: heap_empty=true
I0529 10:47:08.876066732 5685 timer_generic.cc:508] .. shard[6]->queue_deadline_cap --> 1001
I0529 10:47:08.876077111 5685 timer_generic.cc:573] .. shard[6] popped 0
I0529 10:47:08.876087752 5685 timer_generic.cc:628] .. result --> 1, shard[6]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876098379 5685 timer_generic.cc:533] .. shard[7]: heap_empty=true
I0529 10:47:08.876108766 5685 timer_generic.cc:508] .. shard[7]->queue_deadline_cap --> 1001
I0529 10:47:08.876119313 5685 timer_generic.cc:573] .. shard[7] popped 0
I0529 10:47:08.876130229 5685 timer_generic.cc:628] .. result --> 1, shard[7]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876141041 5685 timer_generic.cc:533] .. shard[8]: heap_empty=true
I0529 10:47:08.876151142 5685 timer_generic.cc:508] .. shard[8]->queue_deadline_cap --> 1001
I0529 10:47:08.876161566 5685 timer_generic.cc:573] .. shard[8] popped 0
I0529 10:47:08.876172578 5685 timer_generic.cc:628] .. result --> 1, shard[8]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876183021 5685 timer_generic.cc:533] .. shard[9]: heap_empty=true
I0529 10:47:08.876194257 5685 timer_generic.cc:508] .. shard[9]->queue_deadline_cap --> 1001
I0529 10:47:08.876204548 5685 timer_generic.cc:573] .. shard[9] popped 0
I0529 10:47:08.876215405 5685 timer_generic.cc:628] .. result --> 1, shard[9]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876226201 5685 timer_generic.cc:533] .. shard[10]: heap_empty=true
I0529 10:47:08.876236382 5685 timer_generic.cc:508] .. shard[10]->queue_deadline_cap --> 1001
I0529 10:47:08.876247148 5685 timer_generic.cc:573] .. shard[10] popped 0
I0529 10:47:08.876257620 5685 timer_generic.cc:628] .. result --> 1, shard[10]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876276191 5685 timer_generic.cc:533] .. shard[11]: heap_empty=true
I0529 10:47:08.876285442 5685 timer_generic.cc:508] .. shard[11]->queue_deadline_cap --> 1001
I0529 10:47:08.876296339 5685 timer_generic.cc:573] .. shard[11] popped 0
I0529 10:47:08.876307260 5685 timer_generic.cc:628] .. result --> 1, shard[11]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876318094 5685 timer_generic.cc:533] .. shard[12]: heap_empty=true
I0529 10:47:08.876328595 5685 timer_generic.cc:508] .. shard[12]->queue_deadline_cap --> 1001
I0529 10:47:08.876338891 5685 timer_generic.cc:573] .. shard[12] popped 0
I0529 10:47:08.876349596 5685 timer_generic.cc:628] .. result --> 1, shard[12]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876364293 5685 timer_generic.cc:533] .. shard[13]: heap_empty=true
I0529 10:47:08.876374224 5685 timer_generic.cc:508] .. shard[13]->queue_deadline_cap --> 1001
I0529 10:47:08.876387986 5685 timer_generic.cc:573] .. shard[13] popped 0
I0529 10:47:08.876448109 5685 timer_generic.cc:628] .. result --> 1, shard[13]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876457165 5685 timer_generic.cc:533] .. shard[14]: heap_empty=true
I0529 10:47:08.876465250 5685 timer_generic.cc:508] .. shard[14]->queue_deadline_cap --> 1001
I0529 10:47:08.876473651 5685 timer_generic.cc:573] .. shard[14] popped 0
I0529 10:47:08.876481570 5685 timer_generic.cc:628] .. result --> 1, shard[14]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876490105 5685 timer_generic.cc:533] .. shard[15]: heap_empty=true
I0529 10:47:08.876497928 5685 timer_generic.cc:508] .. shard[15]->queue_deadline_cap --> 1001
I0529 10:47:08.876506244 5685 timer_generic.cc:573] .. shard[15] popped 0
I0529 10:47:08.876514177 5685 timer_generic.cc:628] .. result --> 1, shard[15]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876522963 5685 timer_generic.cc:533] .. shard[16]: heap_empty=true
I0529 10:47:08.876530858 5685 timer_generic.cc:508] .. shard[16]->queue_deadline_cap --> 1001
I0529 10:47:08.876538671 5685 timer_generic.cc:573] .. shard[16] popped 0
I0529 10:47:08.876546663 5685 timer_generic.cc:628] .. result --> 1, shard[16]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876555235 5685 timer_generic.cc:533] .. shard[17]: heap_empty=true
I0529 10:47:08.876563480 5685 timer_generic.cc:508] .. shard[17]->queue_deadline_cap --> 1001
I0529 10:47:08.876571200 5685 timer_generic.cc:573] .. shard[17] popped 0
I0529 10:47:08.876579282 5685 timer_generic.cc:628] .. result --> 1, shard[17]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876587814 5685 timer_generic.cc:533] .. shard[18]: heap_empty=true
I0529 10:47:08.876615265 5685 timer_generic.cc:508] .. shard[18]->queue_deadline_cap --> 1001
I0529 10:47:08.876627554 5685 timer_generic.cc:573] .. shard[18] popped 0
I0529 10:47:08.876639358 5685 timer_generic.cc:628] .. result --> 1, shard[18]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876651599 5685 timer_generic.cc:533] .. shard[19]: heap_empty=true
I0529 10:47:08.876663047 5685 timer_generic.cc:508] .. shard[19]->queue_deadline_cap --> 1001
I0529 10:47:08.876674412 5685 timer_generic.cc:573] .. shard[19] popped 0
I0529 10:47:08.876686367 5685 timer_generic.cc:628] .. result --> 1, shard[19]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876590882 5682 completion_queue.cc:481] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
I0529 10:47:08.876698347 5685 timer_generic.cc:533] .. shard[20]: heap_empty=true
I0529 10:47:08.876732036 5685 timer_generic.cc:508] .. shard[20]->queue_deadline_cap --> 1001
I0529 10:47:08.876741452 5685 timer_generic.cc:573] .. shard[20] popped 0
I0529 10:47:08.876750054 5685 timer_generic.cc:628] .. result --> 1, shard[20]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876758588 5685 timer_generic.cc:533] .. shard[21]: heap_empty=true
I0529 10:47:08.876766527 5685 timer_generic.cc:508] .. shard[21]->queue_deadline_cap --> 1001
I0529 10:47:08.876779145 5685 timer_generic.cc:573] .. shard[21] popped 0
I0529 10:47:08.876762071 5682 metadata_array.cc:29] grpc_metadata_array_init(array=0x7f547a6942d8)
I0529 10:47:08.876790761 5685 timer_generic.cc:628] .. result --> 1, shard[21]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876807446 5682 metadata_array.cc:29] grpc_metadata_array_init(array=0x7f547a6310c0)
I0529 10:47:08.876820211 5685 timer_generic.cc:533] .. shard[22]: heap_empty=true
I0529 10:47:08.876835612 5682 call.cc:1903] grpc_call_start_batch(call=0x1341aa0, ops=0x10dcf10, nops=6, tag=0x7f547a636410, reserved=(nil))
I0529 10:47:08.876847108 5685 timer_generic.cc:508] .. shard[22]->queue_deadline_cap --> 1001
I0529 10:47:08.876863720 5682 call.cc:1508] ops[0]: SEND_INITIAL_METADATA(nil)
I0529 10:47:08.876874694 5685 timer_generic.cc:573] .. shard[22] popped 0
I0529 10:47:08.876889530 5682 call.cc:1508] ops[1]: SEND_MESSAGE ptr=0x1319110
I0529 10:47:08.876901121 5685 timer_generic.cc:628] .. result --> 1, shard[22]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.876914595 5682 call.cc:1508] ops[2]: SEND_CLOSE_FROM_CLIENT
I0529 10:47:08.876957751 5682 call.cc:1508] ops[3]: RECV_INITIAL_METADATA ptr=0x7f547a6942d8
I0529 10:47:08.876968199 5682 call.cc:1508] ops[4]: RECV_MESSAGE ptr=0x7f547a6ce820
I0529 10:47:08.876943567 5685 timer_generic.cc:533] .. shard[23]: heap_empty=true
I0529 10:47:08.876984770 5682 call.cc:1508] ops[5]: RECV_STATUS_ON_CLIENT metadata=0x7f547a6310c0 status=0x7f547a6310d8 details=0x7f547a6310e0
I0529 10:47:08.876989385 5685 timer_generic.cc:508] .. shard[23]->queue_deadline_cap --> 1001
I0529 10:47:08.877004479 5682 call_combiner.cc:116] ==> grpc_call_combiner_start() [0x1341ab0] closure=0x1342a28 [executing batch] error="No Error"
I0529 10:47:08.877007512 5685 timer_generic.cc:573] .. shard[23] popped 0
I0529 10:47:08.877019297 5682 call_combiner.cc:125] size: 0 -> 1
I0529 10:47:08.877030731 5685 timer_generic.cc:628] .. result --> 1, shard[23]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.877042347 5682 call_combiner.cc:134] EXECUTING IMMEDIATELY
I0529 10:47:08.877053714 5685 timer_generic.cc:533] .. shard[24]: heap_empty=true
I0529 10:47:08.877080498 5685 timer_generic.cc:508] .. shard[24]->queue_deadline_cap --> 1001
I0529 10:47:08.877088865 5682 call.cc:613] OP[client-channel:0x1342420]: SEND_INITIAL_METADATA{key=3a 70 61 74 68 ':path' value=2f 67 6e 6d 69 2e 67 4e 4d 49 2f 47 65 74 '/gnmi.gNMI/Get'} SEND_MESSAGE:flags=0x00000000:len=51 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA
I0529 10:47:08.877089748 5685 timer_generic.cc:573] .. shard[24] popped 0
I0529 10:47:08.877109012 5682 client_channel.cc:754] chand=0x132e1a8 calld=0x1342440: adding pending batch at index 0
I0529 10:47:08.877121556 5685 timer_generic.cc:628] .. result --> 1, shard[24]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.877134387 5682 client_channel.cc:2486] chand=0x132e1a8 calld=0x1342440: entering client_channel combiner
I0529 10:47:08.877147293 5685 timer_generic.cc:533] .. shard[25]: heap_empty=true
I0529 10:47:08.877162502 5682 connectivity_state.cc:81] CONWATCH: 0x132e250 request_router: get IDLE
I0529 10:47:08.877169181 5685 timer_generic.cc:508] .. shard[25]->queue_deadline_cap --> 1001
I0529 10:47:08.877174660 5682 request_routing.cc:610] request_router=0x132e1a8: starting name resolution
I0529 10:47:08.877186437 5685 timer_generic.cc:573] .. shard[25] popped 0
D0529 10:47:08.877199989 5682 dns_resolver.cc:275] Start resolving.
I0529 10:47:08.877212876 5685 timer_generic.cc:628] .. result --> 1, shard[25]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.877228732 5682 executor.cc:243] EXECUTOR (resolver-executor) try to schedule 0x11315a0 (short) to thread 0
I0529 10:47:08.877234709 5685 timer_generic.cc:533] .. shard[26]: heap_empty=true
I0529 10:47:08.877246503 5685 timer_generic.cc:508] .. shard[26]->queue_deadline_cap --> 1001
I0529 10:47:08.877249497 5682 request_routing.cc:80] request_router=0x132e1a8 request=0x1342550: deferring pick pending resolver result
I0529 10:47:08.877261944 5685 timer_generic.cc:573] .. shard[26] popped 0
I0529 10:47:08.877275564 5682 call_combiner.cc:215] call_combiner=0x1341ab0: setting notify_on_cancel=0x12eaeb0
I0529 10:47:08.877263112 5684 executor.cc:188] EXECUTOR (resolver-executor) [0]: execute
I0529 10:47:08.877288686 5685 timer_generic.cc:628] .. result --> 1, shard[26]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.877324210 5684 executor.cc:73] EXECUTOR (resolver-executor) run 0x11315a0
I0529 10:47:08.877332387 5685 timer_generic.cc:533] .. shard[27]: heap_empty=true
I0529 10:47:08.877327738 5682 completion_queue.cc:963] grpc_completion_queue_next(cq=0x130c770, deadline=gpr_timespec { tv_sec: 1590720429, tv_nsec: 77321814, clock_type: 1 }, reserved=(nil))
I0529 10:47:08.877344392 5685 timer_generic.cc:508] .. shard[27]->queue_deadline_cap --> 1001
I0529 10:47:08.877361282 5682 ev_epoll1_linux.cc:748] PS:0x130c838 BEGIN_STARTS:0x7ffd9a5c34a0
I0529 10:47:08.877366177 5685 timer_generic.cc:573] .. shard[27] popped 0
I0529 10:47:08.877373678 5682 ev_epoll1_linux.cc:767] PS:0x130c838 BEGIN_REORG:0x7ffd9a5c34a0 kick_state=UNKICKED is_reassigning=1
I0529 10:47:08.877366591 5684 request_routing.cc:771] request_router=0x132e1a8: got resolver result: resolver_result=0x7f546c000b00 error="No Error"
I0529 10:47:08.877388429 5682 ev_epoll1_linux.cc:836] PS:0x130c838 BEGIN_DONE:0x7ffd9a5c34a0 kick_state=DESIGNATED_POLLER shutdown=0 kicked_without_poller: 0
I0529 10:47:08.877383958 5685 timer_generic.cc:628] .. result --> 1, shard[27]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.877402217 5684 client_channel.cc:131] chand=0x132e1a8: resolver returned service config: "(null)"
I0529 10:47:08.877406576 5685 timer_generic.cc:533] .. shard[28]: heap_empty=true
I0529 10:47:08.877423891 5684 pick_first.cc:164] Pick First 0x7f546c0011d0 created.
I0529 10:47:08.877427507 5685 timer_generic.cc:508] .. shard[28]->queue_deadline_cap --> 1001
I0529 10:47:08.877443770 5684 pick_first.cc:361] Pick First 0x7f546c0011d0 received update with 1 addresses
I0529 10:47:08.877449653 5685 timer_generic.cc:573] .. shard[28] popped 0
I0529 10:47:08.877457856 5684 subchannel_list.h:497] [pick_first 0x7f546c0011d0] Creating subchannel list 0x7f546c001770 for 1 subchannels
I0529 10:47:08.877459521 5685 timer_generic.cc:628] .. result --> 1, shard[28]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.877480362 5685 timer_generic.cc:533] .. shard[29]: heap_empty=true
I0529 10:47:08.877488150 5685 timer_generic.cc:508] .. shard[29]->queue_deadline_cap --> 1001
I0529 10:47:08.877495633 5685 timer_generic.cc:573] .. shard[29] popped 0
I0529 10:47:08.877503368 5685 timer_generic.cc:628] .. result --> 1, shard[29]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.877511053 5685 timer_generic.cc:533] .. shard[30]: heap_empty=true
I0529 10:47:08.877518558 5685 timer_generic.cc:508] .. shard[30]->queue_deadline_cap --> 1001
I0529 10:47:08.877525938 5685 timer_generic.cc:573] .. shard[30] popped 0
I0529 10:47:08.877533447 5685 timer_generic.cc:628] .. result --> 1, shard[30]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.877541208 5685 timer_generic.cc:533] .. shard[31]: heap_empty=true
I0529 10:47:08.877548522 5685 timer_generic.cc:508] .. shard[31]->queue_deadline_cap --> 1001
I0529 10:47:08.877556463 5685 timer_generic.cc:573] .. shard[31] popped 0
I0529 10:47:08.877563777 5685 timer_generic.cc:628] .. result --> 1, shard[31]->min_deadline 1 --> 1002, now=1
I0529 10:47:08.877572360 5685 timer_generic.cc:738] TIMER CHECK END: r=1; next=1002
I0529 10:47:08.877580296 5685 timer_manager.cc:186] sleep for a 1001 milliseconds
I0529 10:47:08.877946133 5684 subchannel_list.h:548] [pick_first 0x7f546c0011d0] subchannel list 0x7f546c001770 index 0: Created subchannel 0x7f546c004d90 for address uri ipv4:172.18.8.241:8080
I0529 10:47:08.877965238 5684 connectivity_state.cc:92] CONWATCH: 0x7f546c004e78 subchannel: get IDLE
I0529 10:47:08.877978067 5684 request_routing.cc:683] request_router=0x132e1a8: created new LB policy "pick_first" (0x7f546c0011d0)
I0529 10:47:08.877989737 5684 connectivity_state.cc:92] CONWATCH: 0x7f546c001228 pick_first: get IDLE
I0529 10:47:08.878000225 5684 connectivity_state.cc:116] CONWATCH: 0x7f546c001228 pick_first: from IDLE [cur=IDLE] notify=0x7f546c000bd0
I0529 10:47:08.878016546 5684 request_routing.cc:596] request_router=0x132e1a8: setting connectivity state to IDLE
I0529 10:47:08.878030151 5684 connectivity_state.cc:164] SET: 0x132e250 request_router: IDLE --> IDLE [resolver_result] error=(nil) "No Error"
I0529 10:47:08.878041146 5684 request_routing.cc:168] request_router=0x132e1a8 request=0x1342550: resolver returned, doing LB pick
I0529 10:47:08.878051197 5684 client_channel.cc:2302] chand=0x132e1a8 calld=0x1342440: applying service config to call
I0529 10:47:08.878061440 5684 connectivity_state.cc:81] CONWATCH: 0x132e250 request_router: get IDLE
I0529 10:47:08.878071356 5684 request_routing.cc:338] request_router=0x132e1a8 request=0x1342550: starting pick on lb_policy=0x7f546c0011d0
I0529 10:47:08.878080915 5684 connectivity_state.cc:92] CONWATCH: 0x7f546c004e78 subchannel: get IDLE
I0529 10:47:08.878092171 5684 subchannel_list.h:328] [pick_first 0x7f546c0011d0] subchannel list 0x7f546c001770 index 0 of 1 (subchannel 0x7f546c004d90): starting watch: requesting connectivity change notification (from IDLE)
I0529 10:47:08.878104393 5684 connectivity_state.cc:116] CONWATCH: 0x7f546c004e78 subchannel: from IDLE [cur=IDLE] notify=0x7f546c001128
I0529 10:47:08.878118546 5684 connectivity_state.cc:164] SET: 0x7f546c004e78 subchannel: IDLE --> CONNECTING [connecting] error=(nil) "No Error"
I0529 10:47:08.878128940 5684 connectivity_state.cc:190] NOTIFY: 0x7f546c004e78 subchannel: 0x7f546c001128
I0529 10:47:08.878138455 5684 connectivity_state.cc:164] SET: 0x7f546c004e98 subchannel: IDLE --> CONNECTING [connecting] error=(nil) "No Error"
I0529 10:47:08.878217208 5684 socket_utils_common_posix.cc:315] TCP_USER_TIMEOUT not supported for this platform
I0529 10:47:08.878237365 5684 ev_posix.cc:253] (fd-trace) fd_create(6, tcp-client:ipv4:172.18.8.241:8080, 1)
I0529 10:47:08.878268817 5682 ev_epoll1_linux.cc:728] ps: 0x130c838 poll got 1 events
E0529 10:47:08.878286471 5682 lockfree_event.cc:213] LockfreeEvent::SetReady: 0x7f546c001c68 curr=(nil)
E0529 10:47:08.878301907 5682 lockfree_event.cc:213] LockfreeEvent::SetReady: 0x7f546c001c70 curr=(nil)
I0529 10:47:08.878313865 5684 tcp_client_posix.cc:332] CLIENT_CONNECT: ipv4:172.18.8.241:8080: asynchronously connecting fd 0x7f546c001c60
I0529 10:47:08.878316872 5682 ev_epoll1_linux.cc:928] PS:0x130c838 END_WORKER:0x7ffd9a5c34a0
I0529 10:47:08.878334309 5684 timer_generic.cc:365] TIMER 0x7f546c0039c0: SET 20003 now 3 call 0x7f546c0039f0[0x7f547af71370]
I0529 10:47:08.878353002 5682 ev_epoll1_linux.cc:908] .. mark pollset 0x130c838 inactive
I0529 10:47:08.878361796 5684 timer_generic.cc:401] .. add to shard 0 with queue_deadline_cap=1001 => is_first_timer=false
I0529 10:47:08.878374094 5682 ev_epoll1_linux.cc:990] .. remove worker
E0529 10:47:08.878375828 5684 lockfree_event.cc:98] LockfreeEvent::NotifyOn: 0x7f546c001c70 curr=0x2 closure=0x7f546c003a20
I0529 10:47:08.878395584 5682 ev_epoll1_linux.cc:748] PS:0x130c838 BEGIN_STARTS:0x7ffd9a5c34a0
I0529 10:47:08.878403883 5684 call_combiner.cc:215] call_combiner=0x1341ab0: setting notify_on_cancel=0x7f546c003bc8
I0529 10:47:08.878412096 5682 ev_epoll1_linux.cc:767] PS:0x130c838 BEGIN_REORG:0x7ffd9a5c34a0 kick_state=UNKICKED is_reassigning=1
I0529 10:47:08.878416633 5684 call_combiner.cc:224] call_combiner=0x1341ab0: scheduling old cancel callback=0x12eaeb0
I0529 10:47:08.878434638 5682 ev_epoll1_linux.cc:836] PS:0x130c838 BEGIN_DONE:0x7ffd9a5c34a0 kick_state=DESIGNATED_POLLER shutdown=0 kicked_without_poller: 0
I0529 10:47:08.878442844 5684 tcp_client_posix.cc:150] CLIENT_CONNECT: ipv4:172.18.8.241:8080: on_writable: error="No Error"
I0529 10:47:08.878459515 5682 ev_epoll1_linux.cc:728] ps: 0x130c838 poll got 1 events
I0529 10:47:08.878465108 5684 timer_generic.cc:467] TIMER 0x7f546c0039c0: CANCEL pending=true
E0529 10:47:08.878478894 5682 lockfree_event.cc:213] LockfreeEvent::SetReady: 0x7f546c001c70 curr=(nil)
I0529 10:47:08.878494640 5682 ev_epoll1_linux.cc:928] PS:0x130c838 END_WORKER:0x7ffd9a5c34a0
I0529 10:47:08.878502204 5684 tcp_client_posix.cc:113] CLIENT_CONNECT: ipv4:172.18.8.241:8080: on_alarm: error="Cancelled"
I0529 10:47:08.878508268 5682 ev_epoll1_linux.cc:908] .. mark pollset 0x130c838 inactive
I0529 10:47:08.878524586 5684 handshaker.cc:141] handshake_manager 0x7f546c003990: adding handshaker http_connect [0x7f546c006190] at index 0
I0529 10:47:08.878526608 5682 ev_epoll1_linux.cc:990] .. remove worker
I0529 10:47:08.878557409 5682 ev_epoll1_linux.cc:748] PS:0x130c838 BEGIN_STARTS:0x7ffd9a5c34a0
I0529 10:47:08.878572424 5682 ev_epoll1_linux.cc:767] PS:0x130c838 BEGIN_REORG:0x7ffd9a5c34a0 kick_state=UNKICKED is_reassigning=1
I0529 10:47:08.878572454 5684 ssl_transport_security.cc:217] HANDSHAKE START - TLS client start_connect - !!!!!!
I0529 10:47:08.878599774 5682 ev_epoll1_linux.cc:836] PS:0x130c838 BEGIN_DONE:0x7ffd9a5c34a0 kick_state=DESIGNATED_POLLER shutdown=0 kicked_without_poller: 0
I0529 10:47:08.878664711 5684 ssl_transport_security.cc:217] LOOP - TLS client enter_early_data - !!!!!!
I0529 10:47:08.878678990 5684 ssl_transport_security.cc:217] LOOP - TLS client read_server_hello - !!!!!!
I0529 10:47:08.878696003 5684 handshaker.cc:141] handshake_manager 0x7f546c003990: adding handshaker security [0x7f546c010b70] at index 1
I0529 10:47:08.878714686 5684 timer_generic.cc:365] TIMER 0x7f546c003a10: SET 20003 now 3 call 0x7f546c003a40[0x7f547af54440]
I0529 10:47:08.878725097 5684 timer_generic.cc:401] .. add to shard 28 with queue_deadline_cap=1001 => is_first_timer=false
I0529 10:47:08.878755898 5684 handshaker.cc:212] handshake_manager 0x7f546c003990: error="No Error" shutdown=0 index=0, args={endpoint=0x7f546c005cf0, args=0x7f546c000fa0 {size=9: grpc.primary_user_agent=grpc-python/1.18.0, grpc.client_channel_factory=0x7f547b44b498, grpc.channel_credentials=0x13326a0, grpc.server_uri=dns:///172.18.8.241:8080, grpc.channelz_channel_node_creation_func=0x7f547aff4aa0, grpc.default_authority=172.18.8.241:8080, grpc.http2_scheme=https, grpc.security_connector=0x7f546c001400, grpc.subchannel_address=ipv4:172.18.8.241:8080}, read_buffer=0x7f546c010ee0 (length=0), exit_early=0}
I0529 10:47:08.878770028 5684 handshaker.cc:258] handshake_manager 0x7f546c003990: calling handshaker http_connect [0x7f546c006190] at index 0
I0529 10:47:08.878798096 5684 handshaker.cc:212] handshake_manager 0x7f546c003990: error="No Error" shutdown=0 index=1, args={endpoint=0x7f546c005cf0, args=0x7f546c000fa0 {size=9: grpc.primary_user_agent=grpc-python/1.18.0, grpc.client_channel_factory=0x7f547b44b498, grpc.channel_credentials=0x13326a0, grpc.server_uri=dns:///172.18.8.241:8080, grpc.channelz_channel_node_creation_func=0x7f547aff4aa0, grpc.default_authority=172.18.8.241:8080, grpc.http2_scheme=https, grpc.security_connector=0x7f546c001400, grpc.subchannel_address=ipv4:172.18.8.241:8080}, read_buffer=0x7f546c010ee0 (length=0), exit_early=0}
I0529 10:47:08.878811056 5684 handshaker.cc:258] handshake_manager 0x7f546c003990: calling handshaker security [0x7f546c010b70] at index 1
I0529 10:47:08.878831086 5684 tcp_posix.cc:966] WRITE 0x7f546c005cf0 (peer=ipv4:172.18.8.241:8080): 16 03 01 00 93 01 00 00 8f 03 03 fd 8a 96 03 70 b0 37 2e 60 39 f4 0f 2f 54 5d 34 fd 11 6b 23 3b a6 4b 8f 0c e2 e5 76 45 ae c1 1a 00 00 08 c0 2b c0 2c c0 2f c0 30 01 00 00 5e ff 01 00 01 00 00 00 00 11 00 0f 00 00 0c 31 37 32 2e 31 38 2e 38 2e 32 34 31 00 17 00 00 00 23 00 00 00 0d 00 14 00 12 04 03 08 04 04 01 05 03 08 05 05 01 08 06 06 01 02 01 33 74 00 00 00 10 00 0e 00 0c 08 67 72 70 63 2d 65 78 70 02 68 32 00 0b 00 02 01 00 00 0a 00 04 00 02 00 17 '...............p.7.`9../T]4..k#;.K....vE.......+.,./.0...^..............172.18.8.241.....#..........................3t.........grpc-exp.h2..............'
I0529 10:47:08.878876237 5684 tcp_posix.cc:999] write: "No Error"
I0529 10:47:08.878888846 5684 tcp_posix.cc:253] TCP:0x7f546c005cf0 notify_on_read
E0529 10:47:08.878898746 5684 lockfree_event.cc:98] LockfreeEvent::NotifyOn: 0x7f546c001c68 curr=0x2 closure=0x7f546c005e90
I0529 10:47:08.878909224 5684 tcp_posix.cc:535] TCP:0x7f546c005cf0 got_read: "No Error"
I0529 10:47:08.878918462 5684 tcp_posix.cc:520] TCP:0x7f546c005cf0 alloc_slices
I0529 10:47:08.878928131 5684 resource_quota.cc:886] RQ anonymous_pool_7f546c005b20 ipv4:172.18.8.241:8080: alloc 8192; free_pool -> -8192
I0529 10:47:08.878941495 5684 subchannel_list.h:443] [pick_first 0x7f546c0011d0] subchannel list 0x7f546c001770 index 0 of 1 (subchannel 0x7f546c004d90): connectivity changed: state=CONNECTING, error="No Error", shutting_down=0
I0529 10:47:08.878953576 5684 connectivity_state.cc:164] SET: 0x7f546c001228 pick_first: IDLE --> CONNECTING [connecting_changed] error=(nil) "No Error"
I0529 10:47:08.878963336 5684 connectivity_state.cc:190] NOTIFY: 0x7f546c001228 pick_first: 0x7f546c000bd0
I0529 10:47:08.878974331 5684 subchannel_list.h:350] [pick_first 0x7f546c0011d0] subchannel list 0x7f546c001770 index 0 of 1 (subchannel 0x7f546c004d90): renewing watch: requesting connectivity change notification (from CONNECTING)
I0529 10:47:08.878985771 5684 connectivity_state.cc:116] CONWATCH: 0x7f546c004e78 subchannel: from CONNECTING [cur=CONNECTING] notify=0x7f546c011278
I0529 10:47:08.878997485 5684 request_routing.cc:427] request_router=0x132e1a8: lb_policy=0x7f546c0011d0 state changed to CONNECTING
I0529 10:47:08.879007969 5684 request_routing.cc:596] request_router=0x132e1a8: setting connectivity state to CONNECTING
I0529 10:47:08.879021504 5684 connectivity_state.cc:164] SET: 0x132e250 request_router: IDLE --> CONNECTING [lb_changed] error=(nil) "No Error"
I0529 10:47:08.879031925 5684 connectivity_state.cc:116] CONWATCH: 0x7f546c001228 pick_first: from CONNECTING [cur=CONNECTING] notify=0x7f546c000bd0
I0529 10:47:08.879044346 5684 resource_quota.cc:320] RQ: check allocation for user 0x7f546c005fe0 shutdown=0 free_pool=-8192
I0529 10:47:08.879056267 5684 resource_quota.cc:346] RQ anonymous_pool_7f546c005b20 ipv4:172.18.8.241:8080: grant alloc 8192 bytes; rq_free_pool -> 9223372036854767615
I0529 10:47:08.879072806 5684 tcp_posix.cc:502] TCP:0x7f546c005cf0 read_allocation_done: "No Error"
I0529 10:47:08.879087750 5684 tcp_posix.cc:253] TCP:0x7f546c005cf0 notify_on_read
E0529 10:47:08.879097172 5684 lockfree_event.cc:98] LockfreeEvent::NotifyOn: 0x7f546c001c68 curr=(nil) closure=0x7f546c005e90
I0529 10:47:08.879107496 5684 executor.cc:167] EXECUTOR (resolver-executor) [0]: step (sub_depth=1)
I0529 10:47:08.914936366 5682 ev_epoll1_linux.cc:728] ps: 0x130c838 poll got 1 events
E0529 10:47:08.914964865 5682 lockfree_event.cc:213] LockfreeEvent::SetReady: 0x7f546c001c68 curr=0x7f546c005e90
E0529 10:47:08.914976552 5682 lockfree_event.cc:213] LockfreeEvent::SetReady: 0x7f546c001c70 curr=0x2
I0529 10:47:08.914985012 5682 ev_epoll1_linux.cc:928] PS:0x130c838 END_WORKER:0x7ffd9a5c34a0
I0529 10:47:08.914993325 5682 ev_epoll1_linux.cc:908] .. mark pollset 0x130c838 inactive
I0529 10:47:08.915008744 5682 tcp_posix.cc:535] TCP:0x7f546c005cf0 got_read: "No Error"
I0529 10:47:08.915019405 5682 tcp_posix.cc:526] TCP:0x7f546c005cf0 do_read
I0529 10:47:08.915037955 5682 tcp_posix.cc:411] TCP:0x7f546c005cf0 call_cb 0x7f546c010d40 0x7f547afd6ca0:0x7f546c010b70
I0529 10:47:08.915048669 5682 tcp_posix.cc:414] read: error="No Error"
I0529 10:47:08.915167054 5682 tcp_posix.cc:419] READ 0x7f546c005cf0 (peer=ipv4:172.18.8.241:8080): 16 03 03 00 3e 02 00 00 3a 03 03 e7 19 53 4e ee ae 44 e6 3b 18 a6 63 57 75 4f bc 9a bb 26 86 42 37 a8 60 e3 9e f9 80 00 e0 0e 94 00 c0 2f 00 00 12 00 23 00 00 ff 01 00 01 00 00 10 00 05 00 03 02 68 32 16 03 03 05 0f 0b 00 05 0b 00 05 08 00 05 05 30 82 05 01 30 82 02 e9 a0 03 02 01 02 02 10 64 71 07 68 a6 9d 11 da eb cb 10 d3 51 b8 1a 92 30 0d 06 09 2a 86 48 86 f7 0d 01 01 0b 05 00 30 15 31 13 30 11 06 03 55 04 0a 13 0a 45 78 61 6d 70 6c 65 20 43 6f 30 1e 17 0d 32 30 30 35 32 39 30 32 32 36 33 32 5a 17 0d 32 30 30 35 32 39 30 33 32 36 33 32 5a 30 15 31 13 30 11 06 03 55 04 0a 13 0a 45 78 61 6d 70 6c 65 20 43 6f 30 82 02 22 30 0d 06 09 2a 86 48 86 f7 0d 01 01 01 05 00 03 82 02 0f 00 30 82 02 0a 02 82 02 01 00 bb e5 4e 49 07 67 6f 3d dc 13 f1 52 77 27 b7 18 85 88 88 d1 2c 74 18 26 bb aa 77 6a c9 0d 47 f3 13 23 f5 67 ee ad ef f0 6d 34 1d a0 8d be 8d 33 e8 37 cf b2 85 92 e7 ac bc fa c1 7a c5 ff 6f 4d cf a6 8f 32 8c e9 ef fa e7 e0 01 d2 0f 83 30 2e 28 36 92 39 34 3c 89 54 be 97 f2 ce a2 95 45 28 69 8e 67 60 9e b1 27 f0 0c 2d f4 84 75 c0 5b 2c 48 88 67 5f df f1 a4 1f 55 60 27 b1 1b 64 b7 08 a7 aa 8f 71 34 b4 7b 1e 48 eb 09 ff be 1e 7c d5 2b 64 73 96 84 d6 4e ca 05 e3 80 9a 6c 10 30 11 12 61 c0 6d 0f 6b 31 fa c6 cf ee 33 1b bc a4 a6 4d e3 d0 e2 d0 51 aa 02 eb 1a 8f 6f f9 82 cc d0 4b 28 5f 7a 91 90 07 2e 15 3b 4e b0 f2 27 4c 57 15 74 10 fe e8 7e 49 b6 8a a9 f7 86 fb f0 9a 7d 90 90 0f 77 0e 48 5e d5 eb 7f 05 cd b7 37 e8 20 20 21 90 d0 98 e1 32 40 a2 45 ba bf 29 6e 15 0e 67 94 f7 18 e9 92 3e bd 30 66 bf b1 1b fb be 36 e7 2b c0 fa b7 21 1e d3 47 08 4b 06 fb 71 e3 59 46 03 c5 29 94 f3 bd a5 dc 58 c1 a6 08 7e b8 f4 82 4e dc b9 0f 20 ef e8 4d ef 70 3c 71 cf 24 6d a0 f1 5a 58 ee 62 92 ed a5 6a d5 cf f3 68 10 c6 0e 06 0e 0e a3 00 eb c5 48 7a a5 fb f9 5d 07 49 02 8a ae e7 55 25 f2 47 71 c9 7d 96 fb 89 90 c2 ec 1b 71 06 9c 5f 6c 5b e3 05 c8 1d 46 fd 72 f3 58 1c 62 ec 50 2d a6 7c b0 58 cc a7 ee a1 e8 fe 73 d6 e4 26 83 c9 49 db 8e ae 94 b3 da 8f 30 f5 c6 98 7e bc 6a 77 c0 d5 28 66 36 d5 d1 2c f0 1f b5 9c ab ea dc 61 21 2d 8d a4 e2 3d 84 77 9f b7 92 d9 bc 09 28 4d 74 7d ec 26 22 2f 33 e9 8e dd 65 b2 f1 b8 41 96 a5 a9 e3 84 6a 2b 18 9b 98 c6 17 d8 54 83 36 a8 74 5a f4 78 d5 f9 1a d3 22 f3 bb 58 1e 63 7f 2c d3 4d 0c 34 bd 27 73 31 8d 69 02 03 01 00 01 a3 4d 30 4b 30 0e 06 03 55 1d 0f 01 01 ff 04 04 03 02 05 a0 30 13 06 03 55 1d 25 04 0c 30 0a 06 08 2b 06 01 05 05 07 03 01 30 0c 06 03 55 1d 13 01 01 ff 04 02 30 00 30 16 06 03 55 1d 11 04 0f 30 0d 82 0b 65 78 61 6d 70 6c 65 2e 63 6f 6d 30 0d 06 09 2a 86 48 86 f7 0d 01 01 0b 05 00 03 82 02 01 00 1c ad 97 90 a5 ed 1d 52 5d 45 42 66 bf 43 29 93 5b 54 3b 05 4b a1 3d d0 7f b1 7d dd 64 b5 48 56 5e 67 17 0a a1 ba 6e eb 8f ba c1 17 a4 a2 05 f2 25 26 16 06 06 b0 af 67 c4 2a 22 9d 5f 8e 9d 7f 18 53 f9 27 9b e3 bf 12 b2 83 93 4a a2 ae c1 4f ac 6a f7 b4 f6 5c 94 66 fa 45 28 0f 44 ed 5e 49 ec e7 20 17 f2 75 c1 94 77 6a 14 d3 bb 2f 96 2a fe df 4d 4c 6e 01 f8 81 4f 04 d3 8a 23 42 f9 21 5e 59 60 d6 cc 2f bc f2 70 c4 b1 a4 0a bd 83 35 37 0f 45 e4 46 0e bb b5 dc b1 9e 58 1d 8b 24 6c 19 d0 76 86 cf 44 1e b1 02 5d 00 09 be 2c 20 5f 0e fb ee 0e b9 a6 1d bf ea 04 e2 72 81 04 ee fc e1 bc b2 44 b7 b3 1b db 5f bd 80 1b dd bd 57 1e 92 b9 12 20 4e f9 e1 f4 cf b2 4a 76 a4 d8 96 e4 69 da fe 79 15 b4 07 88 6a 34 2f 87 c4 5a 49 f4 ef 44 27 8d 05 a0 a1 86 b6 21 b0 5c 8b f3 06 f4 58 eb d2 a2 26 a9 8c f8 c2 e3 60 2b f7 30 bd 2c 80 43 41 10 f1 57 3c 7f ac 80 86 a9 1d 43 e8 f5 2d 07 a6 8c 77 17 3b 26 f0 97 95 7b 85 e4 e1 61 89 cc 83 2b f8 b8 a7 8b 3e 77 c6 ca fb 11 fc a2 48 e3 31 f9 61 e6 c7 de 53 4b ba 75 d9 ad 60 f3 36 78 d8 89 cb b6 45 fe af 1c e5 91 88 64 ad 35 f9 07 22 9c fe e6 cc 9a d4 ac e0 63 90 5a 98 bb df 6a 27 32 ea 8d ff 6f 03 09 67 ed a8 94 32 0b 2b 63 09 f7 af 74 6d 46 40 11 ba cb 8b c1 97 31 93 db 2d 13 79 e7 db b2 81 bc f1 3e fc f1 ed 4d ab 3f 7a 66 e2 e6 03 58 10 7b 33 a4 cb d0 66 f0 cb 9d e9 1a cc 82 ac b5 fb a0 71 a6 58 a9 c9 66 7e f8 63 b5 76 8a 6a 3e 7b 3c 77 ba 65 f2 61 76 c0 78 b5 bb 30 9c 6f 31 f5 d7 e0 2a 45 3d 1f 14 f8 5b f0 a9 b9 03 93 da e3 5f 45 2f 5b 90 33 9a 35 df b1 c4 4c 78 a8 53 19 29 54 8b b6 69 c6 86 16 03 03 02 4d 0c 00 02 49 03 00 17 41 04 e0 d1 d8 f9 c2 7d 7d 25 0f 4a c6 ae 12 13 c0 24 24 fe 10 21 54 5d d1 ba bd d2 e0 38 e2 c0 62 f4 2e c8 98 33 8b e4 30 05 b3 ca 35 81 43 52 da 00 cb 0a fb 98 c7 2c a0 73 b5 2c f3 38 d0 25 d3 f5 04 01 02 00 af f4 ac b2 a6 a0 37 65 f1 df ad 58 a3 db a5 6d d8 64 37 b9 ea bc 96 a7 c4 d3 16 b2 8b 97 fc 47 7b 9f 09 87 a0 b9 52 32 a4 1e 77 10 20 92 86 8d 00 26 a2 3b 74 a0 8c a6 be bc 3f 26 a9 f4 b2 a4 a1 52 d7 ea 49 83 d6 6c 55 ce 90 e2 83 8a b1 07 b2 f0 c6 8a d3 e7 60 4d ee 9e b1 ff c7 91 0b 1b 1a 3b 0d de ec 1c fa b4 cf 5a 5a 2b 08 6d 3a 00 dd d6 cf 45 c0 53 72 8c d5 24 e5 5d f1 45 f2 01 2f dd 73 01 d5 ad 23 2e a4 6c a5 b0 3a 07 48 2d 2e fa 81 d6 ea c8 3c 90 2f de 22 18 9a 12 ea 48 7d a5 34 a8 33 f0 c3 36 af 24 1c 17 8c 73 9e 60 3a 6c 51 21 21 08 27 1f 9a e7 c2 10 6b 54 23 26 1c 07 2a f9 7a 51 ff 43 71 74 6b 7f f8 c2 5e 44 a2 65 b0 f8 11 21 6c 45 21 62 0c 0e 42 b1 d2 62 ae 95 fc 82 7d 98 4b 89 73 10 ab 56 c3 0a ee d7 ed e0 dc 32 16 dc 6f ec c5 a8 3a 9a 64 3a 5d d4 1b ed 89 cc e9 d3 66 bc e8 3b f1 18 94 79 43 48 fc a8 7f 5a b7 d5 fe 2f 94 ba 00 4d 55 76 42 67 c7 ed 0c 5f 1c 66 0a ba 98 23 48 99 ad 06 a8 bd 03 e6 74 b1 55 a5 10 e0 75 d4 81 f9 c7 68 32 9c 14 ee d3 fa 8e ac 37 b5 c1 91 6d b6 86 0e b0 bb 84 ed 16 e6 30 1d 18 0c bf d1 5a e9 d2 ec ce ec a6 87 e4 10 d1 42 bd 8f c6 4e 6a 85 65 08 a1 6e 2e 9f e1 39 0d 50 25 2c 20 45 cf 24 6b 9d cd cb 6e e4 23 d1 17 1f 23 59 66 f2 50 65 e7 bc 58 4c 2b c3 b1 d4 d8 cf 80 60 b9 85 4b 59 cd c1 50 79 32 86 75 df 04 86 51 05 19 a2 1d 4a 81 4c 60 d0 4e 15 e4 48 b4 a9 20 cf 4f 72 92 ad fe 4d 4b d4 a1 12 dc 28 7f 0f 4a 45 ae 43 8f 70 68 72 e3 52 aa c4 72 36 59 02 ae 86 df 32 38 46 2e 9f 8c e7 a2 8d cc d1 f9 94 58 75 4e 37 5b 00 53 71 d4 ac 0a 20 66 23 71 83 c6 f6 2c ff a2 cb eb 9e a4 90 16 03 03 00 1b 0d 00 00 17 02 01 40 00 10 04 01 04 03 05 01 05 03 06 01 06 03 02 01 02 03 00 00 16 03 03 00 04 0e 00 00 00 '....>...:....SN..D.;..cWuO...&.B7.`........../....#..............h2...............0...0..........dq.h........Q...0...*.H........0.1.0...U....Example Co0...200529022632Z..200529032632Z0.1.0...U....Example Co0.."0...*.H.............0..........NI.go=...Rw'......,t.&..wj..G..#.g....m4.....3.7.........z..oM...2..........0.(6.94<.T......E(i.g`..'..-..u.[,H.g_....U`'..d.....q4.{.H.....|.+ds...N.....l.0..a.m.k1....3....M....Q.....o....K(_z.....;N..'LW.t...~I........}...w.H^......7. !....2@.E..)n..g.....>.0f.....6.+...!..G.K..q.YF..).....X...~...N... ..M.p<q.$m..ZX.b...j...h..........Hz...].I....U%.Gq.}.......q.._l[....F.r.X.b.P-.|.X......s..&..I.......0...~.jw..(f6..,.......a!-...=.w......(Mt}.&"/3...e...A.....j+......T.6.tZ.x...."..X.c.,.M.4.'s1.i......M0K0...U...........0...U.%..0...+.......0...U.......0.0...U....0...example.com0...*.H....................R]EBf.C).[T;.K.=...}.d.HV^g....n.........%&.....g.*"._....S.'.......J...O.j...\.f.E(.D.^I.. ..u..wj.../.*..MLn...O...#B.!^Y`../..p......57.E.F......X..$l..v..D...]..., _...........r.......D...._.....W.... N.....Jv....i..y....j4/..ZI..D'......!.\....X...&.....`+.0.,.CA..W<......C..-...w.;&...{...a...+....>w......H.1.a...SK.u..`.6x....E......d.5.."........c.Z...j'2...o..g...2.+c...tmF@......1..-.y......>...M.?zf...X.{3...f...........q.X..f~.c.v.j>{<w.e.av.x..0.o1...*E=...[......._E/[.3.5...Lx.S.)T..i......M...I...A......}}%.J.....$$..!T].....8..b....3..0...5.CR.......,.s.,.8.%............7e...X...m.d7............G{.....R2..w. ....&.;t.....?&.....R..I..lU.............`M.........;.......ZZ+.m:....E.Sr..$.].E../.s...#..l..:.H-......<./."....H}.4.3..6.$...s.`:lQ!!.'.....kT#&..*.zQ.Cqtk...^D.e...!lE!b..B..b....}.K.s..V.......2..o...:.d:].......f..;...yCH...Z.../...MUvBg..._.f...#H.......t.U...u....h2.......7...m.........0.....Z..........B...Nj.e..n...9.P%, E.$k...n.#...#Yf.Pe..XL+......`..KY..Py2.u...Q....J.L`.N..H.. .Or...MK....(..JE.C.phr.R..r6Y....28F..........XuN7[.Sq... f#q...,..................@.............................'
I0529 10:47:08.915297055 5682 ssl_transport_security.cc:217] LOOP - TLS client read_server_certifi - !!!!!!
I0529 10:47:08.915409348 5682 ssl_transport_security.cc:217] LOOP - TLS client read_certificate_st - !!!!!!
I0529 10:47:08.915421610 5682 ssl_transport_security.cc:217] LOOP - TLS client verify_server_certi - !!!!!!
E0529 10:47:08.915533025 5682 ssl_transport_security.cc:1233] Handshake failed with fatal error SSL_ERROR_SSL: error:1000007d:SSL routines:OPENSSL_internal:CERTIFICATE_VERIFY_FAILED.
D0529 10:47:08.915570702 5682 security_handshaker.cc:138] Security handshake failed: {"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}
I0529 10:47:08.915582683 5682 ev_posix.cc:273] (fd-trace) fd_shutdown(6)
E0529 10:47:08.915594587 5682 lockfree_event.cc:164] LockfreeEvent::SetShutdown: 0x7f546c001c68 curr=(nil) err={"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}
E0529 10:47:08.915629739 5682 lockfree_event.cc:164] LockfreeEvent::SetShutdown: 0x7f546c001c70 curr=0x2 err={"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}
E0529 10:47:08.915642218 5682 lockfree_event.cc:164] LockfreeEvent::SetShutdown: 0x7f546c001c78 curr=(nil) err={"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}
I0529 10:47:08.915668559 5682 handshaker.cc:212] handshake_manager 0x7f546c003990: error={"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"} shutdown=0 index=2, args={endpoint=(nil), args=(nil) {size=0: (null)}, read_buffer=(nil) (length=0), exit_early=0}
I0529 10:47:08.915682471 5682 handshaker.cc:245] handshake_manager 0x7f546c003990: handshaking complete -- scheduling on_handshake_done with error={"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}
I0529 10:47:08.915695314 5682 timer_generic.cc:467] TIMER 0x7f546c003a10: CANCEL pending=true
I0529 10:47:08.915816317 5682 resource_quota.cc:945] RQ anonymous_pool_7f546c005b20 ipv4:172.18.8.241:8080: free 8192; free_pool -> 8192
I0529 10:47:08.915838572 5682 ev_posix.cc:266] (fd-trace) grpc_fd_orphan, fd:6 closed
I0529 10:47:08.915916262 5682 connectivity_state.cc:164] SET: 0x7f546c004e78 subchannel: CONNECTING --> TRANSIENT_FAILURE [connect_failed] error=0x132d9f0 {"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}
I0529 10:47:08.915940732 5682 connectivity_state.cc:190] NOTIFY: 0x7f546c004e78 subchannel: 0x7f546c011278
I0529 10:47:08.915979154 5682 connectivity_state.cc:164] SET: 0x7f546c004e98 subchannel: CONNECTING --> TRANSIENT_FAILURE [connect_failed] error=0x100dd00 {"created":"@1590720428.915955169","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":873,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}
I0529 10:47:08.916000474 5682 subchannel.cc:878] Connect failed: {"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}
I0529 10:47:08.916020396 5682 resource_quota.cc:544] RU shutdown 0x7f546c005fe0
I0529 10:47:08.916046296 5682 subchannel_list.h:443] [pick_first 0x7f546c0011d0] subchannel list 0x7f546c001770 index 0 of 1 (subchannel 0x7f546c004d90): connectivity changed: state=TRANSIENT_FAILURE, error={"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}, shutting_down=0
I0529 10:47:08.916070269 5682 subchannel_list.h:370] [pick_first 0x7f546c0011d0] subchannel list 0x7f546c001770 index 0 of 1 (subchannel 0x7f546c004d90): stopping connectivity watch
I0529 10:47:08.916088086 5682 lb_policy.cc:47] pick_first 0x7f546c0011d0: scheduling re-resolution closure with error="No Error".
I0529 10:47:08.916107896 5682 connectivity_state.cc:164] SET: 0x7f546c001228 pick_first: CONNECTING --> TRANSIENT_FAILURE [exhausted_subchannels] error=0x132d9f0 {"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}
I0529 10:47:08.916129496 5682 connectivity_state.cc:190] NOTIFY: 0x7f546c001228 pick_first: 0x7f546c000bd0
I0529 10:47:08.916146191 5682 connectivity_state.cc:92] CONWATCH: 0x7f546c004e78 subchannel: get TRANSIENT_FAILURE
I0529 10:47:08.916165038 5682 subchannel_list.h:328] [pick_first 0x7f546c0011d0] subchannel list 0x7f546c001770 index 0 of 1 (subchannel 0x7f546c004d90): starting watch: requesting connectivity change notification (from TRANSIENT_FAILURE)
I0529 10:47:08.916184039 5682 connectivity_state.cc:116] CONWATCH: 0x7f546c004e78 subchannel: from TRANSIENT_FAILURE [cur=TRANSIENT_FAILURE] notify=0x1131598
I0529 10:47:08.916201342 5682 subchannel.cc:760] Subchannel 0x7f546c004d90: Retry in 962 milliseconds
I0529 10:47:08.916218198 5682 timer_generic.cc:365] TIMER 0x7f546c004f50: SET 1003 now 41 call 0x7f546c004e00[0x7f547b000630]
I0529 10:47:08.916235217 5682 timer_generic.cc:401] .. add to shard 19 with queue_deadline_cap=1001 => is_first_timer=false
I0529 10:47:08.916253263 5682 request_routing.cc:486] request_router=0x132e1a8: started name re-resolving
D0529 10:47:08.916271475 5682 dns_resolver.cc:255] In cooldown from last resolution (from 39 ms ago). Will resolve again in 961 ms
I0529 10:47:08.916288377 5682 timer_generic.cc:365] TIMER 0xfd58f8: SET 961 now 41 call 0xfd5928[0x7f547b028770]
I0529 10:47:08.916305700 5682 timer_generic.cc:401] .. add to shard 22 with queue_deadline_cap=1001 => is_first_timer=true
I0529 10:47:08.916321323 5682 timer_generic.cc:423] .. old shard min_deadline=1002
I0529 10:47:08.916349094 5682 request_routing.cc:427] request_router=0x132e1a8: lb_policy=0x7f546c0011d0 state changed to TRANSIENT_FAILURE
I0529 10:47:08.916359130 5685 timer_manager.cc:206] wait ended: was_timed:0 kicked:1
I0529 10:47:08.916369184 5682 request_routing.cc:596] request_router=0x132e1a8: setting connectivity state to TRANSIENT_FAILURE
I0529 10:47:08.916442474 5685 timer_generic.cc:715] TIMER CHECK BEGIN: now=41 next=9223372036854775807 tls_min=0 glob_min=961
I0529 10:47:08.916470679 5685 timer_generic.cc:738] TIMER CHECK END: r=1; next=961
I0529 10:47:08.916471508 5682 connectivity_state.cc:164] SET: 0x132e250 request_router: CONNECTING --> TRANSIENT_FAILURE [lb_changed] error=0x132d9f0 {"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}
I0529 10:47:08.916480491 5685 timer_manager.cc:186] sleep for a 920 milliseconds
I0529 10:47:08.916503969 5682 connectivity_state.cc:116] CONWATCH: 0x7f546c001228 pick_first: from TRANSIENT_FAILURE [cur=TRANSIENT_FAILURE] notify=0x7f546c000bd0
I0529 10:47:08.916529846 5682 request_routing.cc:379] request_router=0x132e1a8 request=0x1342550: pick completed asynchronously
I0529 10:47:08.916620232 5682 client_channel.cc:2263] chand=0x132e1a8 calld=0x1342440: failed to create subchannel: error={"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]}
I0529 10:47:08.916653082 5682 client_channel.cc:845] chand=0x132e1a8 calld=0x1342440: failing 1 pending batches: {"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]}
I0529 10:47:08.916685640 5682 call_combiner.h:180] CallCombinerClosureList executing closure while already holding call_combiner 0x1341ab0: closure=0x13429d8 error={"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]} reason=pending_batches_fail
I0529 10:47:08.916723234 5682 call_combiner.cc:116] ==> grpc_call_combiner_start() [0x1341ab0] closure=0x13422f8 [failing recv_message_ready] error={"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]}
I0529 10:47:08.916749512 5682 call_combiner.cc:125] size: 1 -> 2
I0529 10:47:08.916764453 5682 call_combiner.cc:140] QUEUING
I0529 10:47:08.916790440 5682 call_combiner.cc:116] ==> grpc_call_combiner_start() [0x1341ab0] closure=0x13424b0 [failing recv_trailing_metadata_ready] error={"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]}
I0529 10:47:08.916816132 5682 call_combiner.cc:125] size: 2 -> 3
I0529 10:47:08.916829931 5682 call_combiner.cc:140] QUEUING
I0529 10:47:08.916849737 5682 call_combiner.cc:116] ==> grpc_call_combiner_start() [0x1341ab0] closure=0x1342a50 [failing on_complete] error={"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]}
I0529 10:47:08.916875340 5682 call_combiner.cc:125] size: 3 -> 4
I0529 10:47:08.916889583 5682 call_combiner.cc:140] QUEUING
I0529 10:47:08.916909967 5682 call_combiner.h:180] CallCombinerClosureList executing closure while already holding call_combiner 0x1341ab0: closure=0x1342320 error={"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]} reason=failing recv_initial_metadata_ready
I0529 10:47:08.916938068 5682 call_combiner.cc:153] ==> grpc_call_combiner_stop() [0x1341ab0] [recv_initial_metadata_ready]
I0529 10:47:08.916954339 5682 call_combiner.cc:160] size: 4 -> 3
I0529 10:47:08.916968272 5682 call_combiner.cc:167] checking queue
I0529 10:47:08.916987747 5682 call_combiner.cc:181] EXECUTING FROM QUEUE: closure=0x13422f8 error={"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]}
I0529 10:47:08.917014983 5682 call_combiner.cc:252] call_combiner=0x1341ab0: scheduling notify_on_cancel callback=0x7f546c003bc8
I0529 10:47:08.917033386 5682 call_combiner.cc:116] ==> grpc_call_combiner_start() [0x1341ab0] closure=0x132e068 [executing batch] error="No Error"
I0529 10:47:08.917049009 5682 call_combiner.cc:125] size: 3 -> 4
I0529 10:47:08.917061969 5682 call_combiner.cc:140] QUEUING
I0529 10:47:08.917077337 5682 call_combiner.cc:153] ==> grpc_call_combiner_stop() [0x1341ab0] [recv_message_ready]
I0529 10:47:08.917092215 5682 call_combiner.cc:160] size: 4 -> 3
I0529 10:47:08.917105977 5682 call_combiner.cc:167] checking queue
I0529 10:47:08.917124921 5682 call_combiner.cc:181] EXECUTING FROM QUEUE: closure=0x13424b0 error={"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]}
I0529 10:47:08.917152131 5682 call_combiner.cc:153] ==> grpc_call_combiner_stop() [0x1341ab0] [recv_trailing_metadata_ready]
I0529 10:47:08.917167132 5682 call_combiner.cc:160] size: 3 -> 2
I0529 10:47:08.917180827 5682 call_combiner.cc:167] checking queue
I0529 10:47:08.917199323 5682 call_combiner.cc:181] EXECUTING FROM QUEUE: closure=0x1342a50 error={"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]}
D0529 10:47:08.917224689 5682 call.cc:719] set_final_status CLI
D0529 10:47:08.917245290 5682 call.cc:720] {"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]}
I0529 10:47:08.917274307 5682 call_combiner.cc:153] ==> grpc_call_combiner_stop() [0x1341ab0] [on_complete]
I0529 10:47:08.917308352 5682 call_combiner.cc:160] size: 2 -> 1
I0529 10:47:08.917321633 5682 call_combiner.cc:167] checking queue
I0529 10:47:08.917336244 5682 call_combiner.cc:181] EXECUTING FROM QUEUE: closure=0x132e068 error="No Error"
I0529 10:47:08.917357583 5682 completion_queue.cc:699] cq_end_op_for_next(cq=0x130c770, tag=0x7f547a636410, error="No Error", done=0x7f547af86b60, done_arg=0x13429b0, storage=0x1342a00)
D0529 10:47:08.917386026 5682 ev_epoll1_linux.cc:1081] PS:0x130c838 KICK:(nil) curps=0x130c838 curworker=(nil) root=0x7ffd9a5c34a0 {kick_state=KICKED next=0x7ffd9a5c34a0 {kick_state=KICKED}}
I0529 10:47:08.917402845 5682 ev_epoll1_linux.cc:1165] .. kicked while waking up
I0529 10:47:08.917447214 5682 call.cc:613] OP[client-channel:0x1342420]: CANCEL:{"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]}
I0529 10:47:08.917479789 5682 client_channel.cc:2448] chand=0x132e1a8 calld=0x1342440: recording cancel_error={"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]}
I0529 10:47:08.917509151 5682 client_channel.cc:845] chand=0x132e1a8 calld=0x1342440: failing 0 pending batches: {"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]}
I0529 10:47:08.917541479 5682 call_combiner.h:180] CallCombinerClosureList executing closure while already holding call_combiner 0x1341ab0: closure=0x104db20 error={"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]} reason=failing on_complete
I0529 10:47:08.917569086 5682 call_combiner.cc:153] ==> grpc_call_combiner_stop() [0x1341ab0] [on_complete for cancel_stream op]
I0529 10:47:08.917583469 5682 call_combiner.cc:160] size: 1 -> 0
I0529 10:47:08.917595918 5682 call_combiner.cc:189] queue empty
I0529 10:47:08.917609981 5682 ev_epoll1_linux.cc:990] .. remove worker
I0529 10:47:08.917628267 5682 completion_queue.cc:1063] RETURN_EVENT[0x130c770]: OP_COMPLETE: tag:0x7f547a636410 OK
I0529 10:47:08.917669997 5682 metadata_array.cc:34] grpc_metadata_array_destroy(array=0x7f547a6942d8)
I0529 10:47:08.917693929 5682 metadata_array.cc:34] grpc_metadata_array_destroy(array=0x7f547a6310c0)
I0529 10:47:08.917742134 5682 call.cc:561] grpc_call_unref(c=0x1341aa0)
I0529 10:47:08.917761779 5682 call_combiner.cc:204] call_combiner=0x1341ab0: scheduling notify_on_cancel callback=(nil) for pre-existing cancellation
I0529 10:47:08.917788194 5682 completion_queue.cc:1389] grpc_completion_queue_shutdown(cq=0x130c770)
I0529 10:47:08.917805310 5682 completion_queue.cc:1395] grpc_completion_queue_destroy(cq=0x130c770)
I0529 10:47:08.917819540 5682 completion_queue.cc:1389] grpc_completion_queue_shutdown(cq=0x130c770)
Traceback (most recent call last):
File "py_gnmicli.py", line 415, in <module>
main()
File "py_gnmicli.py", line 384, in main
response = _get(stub, paths, user, password)
File "py_gnmicli.py", line 277, in _get
return stub.Get(gnmi_pb2.GetRequest(path=[paths], encoding='JSON_IETF'))
File "/opt/gyw/.local/lib/python2.7/site-packages/grpc/_channel.py", line 550, in __call__
return _end_unary_response_blocking(state, call, False, None)
File "/opt/gyw/.local/lib/python2.7/site-packages/grpc/_channel.py", line 467, in _end_unary_response_blocking
raise _Rendezvous(state, None, None, deadline)
grpc._channel._Rendezvous: <_Rendezvous of RPC that terminated with:
status = StatusCode.UNAVAILABLE
details = "Connect Failed"
debug_error_string = "{"created":"@1590720428.916547785","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590720428.916366114","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590720428.915877202","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590720428.915552139","description":"Handshake failed","file":"src/core/lib/security/transport/security_handshaker.cc","file_line":257,"tsi_code":10,"tsi_error":"TSI_PROTOCOL_FAILURE"}]}]}]}"
>
Why I use cert, also could NOT work?
I generate cert by:
gyw@sonic107:~/go/src/github.com/google/gnxi/gnmi_cli_py$ openssl req -x509 -newkey rsa:4096 -keyout private.key -out cert.pem -days 365 -nodes -subj '/CN=localhost'
I copy cert to server side:
scp private.key admin@172.18.8.241:/home/admin
scp cert.pem admin@172.18.8.241:/home/admin
I start SONiC/TELEMETRY with cert:
/usr/sbin/telemetry -logtostderr --log_to_syslog=true --server_crt /cert.pem --server_key /private.key --port 8080 --allow_no_client_auth -v=2
I use py_gnmicli.py to request:
gyw@sonic107:~/go/src/github.com/google/gnxi/gnmi_cli_py$ python py_gnmicli.py -rcert ./cert.pem -m get -t 172.18.8.241 -p 8080 -x "/interfaces/interface[name=Ethernet16]"
Performing GetRequest, encoding=JSON_IETF to 172.18.8.241 with the following gNMI Path
-------------------------
elem {
name: "interfaces"
}
elem {
name: "interface"
key {
key: "name"
value: "Ethernet16"
}
}
Traceback (most recent call last):
File "py_gnmicli.py", line 415, in <module>
main()
File "py_gnmicli.py", line 384, in main
response = _get(stub, paths, user, password)
File "py_gnmicli.py", line 277, in _get
return stub.Get(gnmi_pb2.GetRequest(path=[paths], encoding='JSON_IETF'))
File "/opt/gyw/.local/lib/python2.7/site-packages/grpc/_channel.py", line 550, in __call__
return _end_unary_response_blocking(state, call, False, None)
File "/opt/gyw/.local/lib/python2.7/site-packages/grpc/_channel.py", line 467, in _end_unary_response_blocking
raise _Rendezvous(state, None, None, deadline)
grpc._channel._Rendezvous: <_Rendezvous of RPC that terminated with:
status = StatusCode.UNAVAILABLE
details = "Connect Failed"
debug_error_string = "{"created":"@1590728327.787907576","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728327.787901509","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728327.787871472","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728327.787749039","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]}"
>
Detail of failure:
gyw@sonic107:~/go/src/github.com/google/gnxi/gnmi_cli_py$ python py_gnmicli.py -rcert ./cert.pem -m get -t 172.18.8.241 -p 8080 -x "/interfaces/interface[name=Ethernet16]" --debug
I0529 12:58:32.008503686 37106 ev_epoll1_linux.cc:116] grpc epoll fd: 3
D0529 12:58:32.008547976 37106 ev_posix.cc:170] Using polling engine: epoll1
D0529 12:58:32.008718109 37106 dns_resolver.cc:334] Using native dns resolver
I0529 12:58:32.008795268 37106 timer_manager.cc:94] Spawn timer thread
I0529 12:58:32.008907207 37106 init.cc:154] grpc_init(void)
I0529 12:58:32.008954239 37109 timer_generic.cc:715] TIMER CHECK BEGIN: now=0 next=9223372036854775807 tls_min=0 glob_min=0
I0529 12:58:32.008999554 37109 timer_generic.cc:610] .. shard[0]->min_deadline = 1
I0529 12:58:32.009016096 37109 timer_generic.cc:738] TIMER CHECK END: r=1; next=1
I0529 12:58:32.009029240 37109 timer_manager.cc:186] sleep for a 1 milliseconds
I0529 12:58:32.009022407 37106 ssl_credentials.cc:128] grpc_ssl_credentials_create(pem_root_certs=-----BEGIN CERTIFICATE-----
MIIE+zCCAuOgAwIBAgIJAJIt44Bc63CuMA0GCSqGSIb3DQEBCwUAMBQxEjAQBgNV
BAMMCWxvY2FsaG9zdDAeFw0yMDA1MjkwNDUzNTVaFw0yMTA1MjkwNDUzNTVaMBQx
EjAQBgNVBAMMCWxvY2FsaG9zdDCCAiIwDQYJKoZIhvcNAQEBBQADggIPADCCAgoC
ggIBAL9KWatQepiZyzWG9YN8HVQM1FulDwsxAsSykFUaEoqf9qzdr5NLYem5gV1K
55tia90WihNJKJ1qXvmOTDIlQYxZDu/noHyDRfQwkjrU1meUtVx4qIUTF4nWpgKg
W5FuAGO9irx1aNZXsb8YX1Q47I4fApk+WbCMCYtC/7KEW9RHgMRy8YgvWmYsL0hW
d+nDCieiHEyBoC13syxFFsPcDw8qZbRZNvu4DxirjHzMfG14RrA9tPHckBlqerma
lzYTn1jrSqfszBqNe3embeZRze4lebyFI+1j4oV3Xb5qNlH5R2wdrdJ5uajuBmE/
/kD8wFiKBP+yzvf8lk7a9iKzzOtjrtrWIh49w/KTIhusc2n+cEopBb/lVYoufvlm
/RHk/v3ukV61Db49IZHYvM6Ga858XMZwz/er+JhsJYRiZyXSFRn2BH2zCbYN3Wja
1KGGxmGrad9q4hzyXw0JGJ26oprIHDU8HglozZjIhcoZLR3MbGHa9PfPmoitaeks
4sVfvHRNlzNEwOdFF/nAjHBB9RsRzjtoGQbXEfSgo+uk5T4CRRx/qZk+UAIirmSC
WGFHf38wREeWV8DUKejMVqCosLrcB+8C9GHoALDsSyda+4Z9XQ2IYgsdEueIkbax
9BlHF+yXLli7VhelWGAzQakogltXKb0KagpDDwaIteMsbqGfAgMBAAGjUDBOMB0G
A1UdDgQWBBRbGaSidCT67qX1rPmsqHfZ4+O30jAfBgNVHSMEGDAWgBRbGaSidCT6
7qX1rPmsqHfZ4+O30jAMBgNVHRMEBTADAQH/MA0GCSqGSIb3DQEBCwUAA4ICAQA8
M0Bz6GRLvHvbSZGZ1DqeBkiF1tX4gaV+RGyeuA9BBG6FOBaoHz9zbT8qyJlfnnaV
RnX7l0VCAq3WkR4W5XDQY625XOxseCkwySNZ69rJTJfLsZotuPDD9iXUA6ydgSYp
bb9IESZ2mFeMd0SN7kVfdiVMNdzacA2paiQ5glbgjsC+UvzbvDmFRnWnUeHl02JQ
na0/h0hx6TNdI3wGDQqQ29D9HjzBT9ImBlVAhAaZqsqhZLMbWam48Q+e5IdLeiI4
EpL9IsofmOImmR8Ci2NscV+YA+kWD/3tPjAK/w1BNekMNZSq/C4jZb0EGU3WXhqt
rBFHiW7vZ8hPTbXng0vSOtMhCm82zAe52uWVz5zscCfJwzJTgRa0gILcvySDyVas
LO9WPSoZfoIctG3+qndjKEo92fLHy2hQtGdxU9gMh2m3b4ZXj+Fp4JtIXIneyaUH
Lqq/Wlr9Fq9/IjqaSvkwLsEmM/fvW/haOqWb0eFX5K8qW2Q4MOK4cjo6m32+Pahu
cdrZnNQ2FeoL1O//3yYa+Pdex/RNfa0B+IwRLvo39zPX8tT8jaAzyB/xyBU3FML7
KX36vPxYf3Rc8j67aEpAV/oEC5Xer6LBS5K5ziW5BVms/COVm/wI0c9ITHh1WHoA
5sBh5epsh5Kqz24hhH64BK3blqkvKTDeEEwBoelDdg==
-----END CERTIFICATE-----
, pem_key_cert_pair=(nil), verify_options=(nil), reserved=(nil))
I0529 12:58:32.009160531 37106 secure_channel_create.cc:207] grpc_secure_channel_create(creds=0x16c0c20, target=172.18.8.241:8080, args=0x7f0cb30ab320, reserved=(nil))
I0529 12:58:32.009226610 37106 timer_generic.cc:365] TIMER 0x166dc50: SET 5000 now 0 call 0x166dc80[0x7f0cb3a674e0]
I0529 12:58:32.009242534 37106 timer_generic.cc:401] .. add to shard 16 with queue_deadline_cap=0 => is_first_timer=false
I0529 12:58:32.009280886 37106 channel.cc:285] grpc_channel_get_target(channel=0x19a8dd0)
I0529 12:58:32.009309065 37106 credentials.cc:43] grpc_channel_credentials_release(creds=0x16c0c20)
I0529 12:58:32.009325062 37106 completion_queue.cc:481] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
I0529 12:58:32.009342298 37106 completion_queue.cc:481] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
I0529 12:58:32.009415281 37109 timer_manager.cc:206] wait ended: was_timed:1 kicked:0
I0529 12:58:32.009449135 37109 timer_generic.cc:715] TIMER CHECK BEGIN: now=1 next=9223372036854775807 tls_min=0 glob_min=1
I0529 12:58:32.009461855 37109 timer_generic.cc:610] .. shard[0]->min_deadline = 1
I0529 12:58:32.009472286 37109 timer_generic.cc:533] .. shard[0]: heap_empty=true
I0529 12:58:32.009481678 37109 timer_generic.cc:508] .. shard[0]->queue_deadline_cap --> 1001
I0529 12:58:32.009491878 37109 timer_generic.cc:573] .. shard[0] popped 0
I0529 12:58:32.009502232 37109 timer_generic.cc:628] .. result --> 1, shard[0]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.009513311 37109 timer_generic.cc:533] .. shard[1]: heap_empty=true
I0529 12:58:32.009522886 37109 timer_generic.cc:508] .. shard[1]->queue_deadline_cap --> 1001
I0529 12:58:32.009532522 37109 timer_generic.cc:573] .. shard[1] popped 0
I0529 12:58:32.009542368 37109 timer_generic.cc:628] .. result --> 1, shard[1]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.009552619 37109 timer_generic.cc:533] .. shard[2]: heap_empty=true
I0529 12:58:32.009561676 37109 timer_generic.cc:508] .. shard[2]->queue_deadline_cap --> 1001
I0529 12:58:32.009571335 37109 timer_generic.cc:573] .. shard[2] popped 0
Performing GetRequest, encoding=JSON_IETF to 172.18.8.241 with the following gNMI Path
I0529 12:58:32.009581235 37109 timer_generic.cc:628] .. result --> 1, shard[2]->min_deadline 1 --> 1002, now=1
-------------------------
I0529 12:58:32.009594118 37109 timer_generic.cc:533] .. shard[3]: heap_empty=true
I0529 12:58:32.009604225 37109 timer_generic.cc:508] .. shard[3]->queue_deadline_cap --> 1001
I0529 12:58:32.009613673 37109 timer_generic.cc:573] .. shard[3] popped 0
I0529 12:58:32.009623439 37109 timer_generic.cc:628] .. result --> 1, shard[3]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.009633957 37109 timer_generic.cc:533] .. shard[4]: heap_empty=true
I0529 12:58:32.009642066 37109 timer_generic.cc:508] .. shard[4]->queue_deadline_cap --> 1001
I0529 12:58:32.009651765 37109 timer_generic.cc:573] .. shard[4] popped 0
I0529 12:58:32.009661454 37109 timer_generic.cc:628] .. result --> 1, shard[4]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.009671567 37109 timer_generic.cc:533] .. shard[5]: heap_empty=true
I0529 12:58:32.009680949 37109 timer_generic.cc:508] .. shard[5]->queue_deadline_cap --> 1001
I0529 12:58:32.009690518 37109 timer_generic.cc:573] .. shard[5] popped 0
I0529 12:58:32.009700411 37109 timer_generic.cc:628] .. result --> 1, shard[5]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.009710584 37109 timer_generic.cc:533] .. shard[6]: heap_empty=true
I0529 12:58:32.009719816 37109 timer_generic.cc:508] .. shard[6]->queue_deadline_cap --> 1001
I0529 12:58:32.009729174 37109 timer_generic.cc:573] .. shard[6] popped 0
I0529 12:58:32.009738693 37109 timer_generic.cc:628] .. result --> 1, shard[6]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.009749044 37109 timer_generic.cc:533] .. shard[7]: heap_empty=true
I0529 12:58:32.009758365 37109 timer_generic.cc:508] .. shard[7]->queue_deadline_cap --> 1001
I0529 12:58:32.009773751 37109 timer_generic.cc:573] .. shard[7] popped 0
I0529 12:58:32.009783399 37109 timer_generic.cc:628] .. result --> 1, shard[7]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.009793470 37109 timer_generic.cc:533] .. shard[8]: heap_empty=true
I0529 12:58:32.009803165 37109 timer_generic.cc:508] .. shard[8]->queue_deadline_cap --> 1001
I0529 12:58:32.009812727 37109 timer_generic.cc:573] .. shard[8] popped 0
I0529 12:58:32.009822490 37109 timer_generic.cc:628] .. result --> 1, shard[8]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.009832580 37109 timer_generic.cc:533] .. shard[9]: heap_empty=true
I0529 12:58:32.009842426 37109 timer_generic.cc:508] .. shard[9]->queue_deadline_cap --> 1001
I0529 12:58:32.009851865 37109 timer_generic.cc:573] .. shard[9] popped 0
I0529 12:58:32.009861430 37109 timer_generic.cc:628] .. result --> 1, shard[9]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.009871945 37109 timer_generic.cc:533] .. shard[10]: heap_empty=true
I0529 12:58:32.009881390 37109 timer_generic.cc:508] .. shard[10]->queue_deadline_cap --> 1001
I0529 12:58:32.009890782 37109 timer_generic.cc:573] .. shard[10] popped 0
I0529 12:58:32.009900424 37109 timer_generic.cc:628] .. result --> 1, shard[10]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.009916598 37109 timer_generic.cc:533] .. shard[11]: heap_empty=true
I0529 12:58:32.009926327 37109 timer_generic.cc:508] .. shard[11]->queue_deadline_cap --> 1001
I0529 12:58:32.009935455 37109 timer_generic.cc:573] .. shard[11] popped 0
I0529 12:58:32.009945101 37109 timer_generic.cc:628] .. result --> 1, shard[11]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.009954723 37109 timer_generic.cc:533] .. shard[12]: heap_empty=true
I0529 12:58:32.009963777 37109 timer_generic.cc:508] .. shard[12]->queue_deadline_cap --> 1001
I0529 12:58:32.009972598 37109 timer_generic.cc:573] .. shard[12] popped 0
I0529 12:58:32.009981632 37109 timer_generic.cc:628] .. result --> 1, shard[12]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.009991371 37109 timer_generic.cc:533] .. shard[13]: heap_empty=true
I0529 12:58:32.010000048 37109 timer_generic.cc:508] .. shard[13]->queue_deadline_cap --> 1001
elem {
name: "interfaces"
}
elem {
name: "interface"
key {
key: "name"
value: "Ethernet16"
}
}
I0529 12:58:32.010009146 37109 timer_generic.cc:573] .. shard[13] popped 0
I0529 12:58:32.010038711 37109 timer_generic.cc:628] .. result --> 1, shard[13]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010048607 37109 timer_generic.cc:533] .. shard[14]: heap_empty=true
I0529 12:58:32.010057354 37109 timer_generic.cc:508] .. shard[14]->queue_deadline_cap --> 1001
I0529 12:58:32.010066449 37109 timer_generic.cc:573] .. shard[14] popped 0
I0529 12:58:32.010075406 37109 timer_generic.cc:628] .. result --> 1, shard[14]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010084948 37109 timer_generic.cc:533] .. shard[15]: heap_empty=true
I0529 12:58:32.010093742 37109 timer_generic.cc:508] .. shard[15]->queue_deadline_cap --> 1001
I0529 12:58:32.010102596 37109 timer_generic.cc:573] .. shard[15] popped 0
I0529 12:58:32.010111476 37109 timer_generic.cc:628] .. result --> 1, shard[15]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010120928 37109 timer_generic.cc:533] .. shard[16]: heap_empty=true
I0529 12:58:32.010129822 37109 timer_generic.cc:508] .. shard[16]->queue_deadline_cap --> 1001
I0529 12:58:32.010138923 37109 timer_generic.cc:573] .. shard[16] popped 0
I0529 12:58:32.010147807 37109 timer_generic.cc:628] .. result --> 1, shard[16]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010157265 37109 timer_generic.cc:533] .. shard[17]: heap_empty=true
I0529 12:58:32.010165832 37109 timer_generic.cc:508] .. shard[17]->queue_deadline_cap --> 1001
I0529 12:58:32.010174579 37109 timer_generic.cc:573] .. shard[17] popped 0
I0529 12:58:32.010183483 37109 timer_generic.cc:628] .. result --> 1, shard[17]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010192865 37109 timer_generic.cc:533] .. shard[18]: heap_empty=true
I0529 12:58:32.010201508 37109 timer_generic.cc:508] .. shard[18]->queue_deadline_cap --> 1001
I0529 12:58:32.010210302 37109 timer_generic.cc:573] .. shard[18] popped 0
I0529 12:58:32.010219249 37109 timer_generic.cc:628] .. result --> 1, shard[18]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010228530 37109 timer_generic.cc:533] .. shard[19]: heap_empty=true
I0529 12:58:32.010237164 37109 timer_generic.cc:508] .. shard[19]->queue_deadline_cap --> 1001
I0529 12:58:32.010246178 37109 timer_generic.cc:573] .. shard[19] popped 0
I0529 12:58:32.010255052 37109 timer_generic.cc:628] .. result --> 1, shard[19]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010264370 37109 timer_generic.cc:533] .. shard[20]: heap_empty=true
I0529 12:58:32.010273197 37109 timer_generic.cc:508] .. shard[20]->queue_deadline_cap --> 1001
I0529 12:58:32.010282054 37109 timer_generic.cc:573] .. shard[20] popped 0
I0529 12:58:32.010290959 37109 timer_generic.cc:628] .. result --> 1, shard[20]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010300390 37109 timer_generic.cc:533] .. shard[21]: heap_empty=true
I0529 12:58:32.010308990 37109 timer_generic.cc:508] .. shard[21]->queue_deadline_cap --> 1001
I0529 12:58:32.010317774 37109 timer_generic.cc:573] .. shard[21] popped 0
I0529 12:58:32.010331476 37109 timer_generic.cc:628] .. result --> 1, shard[21]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010340884 37109 timer_generic.cc:533] .. shard[22]: heap_empty=true
I0529 12:58:32.010349551 37109 timer_generic.cc:508] .. shard[22]->queue_deadline_cap --> 1001
I0529 12:58:32.010358331 37109 timer_generic.cc:573] .. shard[22] popped 0
I0529 12:58:32.010367118 37109 timer_generic.cc:628] .. result --> 1, shard[22]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010376587 37109 timer_generic.cc:533] .. shard[23]: heap_empty=true
I0529 12:58:32.010385601 37109 timer_generic.cc:508] .. shard[23]->queue_deadline_cap --> 1001
I0529 12:58:32.010394431 37109 timer_generic.cc:573] .. shard[23] popped 0
I0529 12:58:32.010403365 37109 timer_generic.cc:628] .. result --> 1, shard[23]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010412884 37109 timer_generic.cc:533] .. shard[24]: heap_empty=true
I0529 12:58:32.010421521 37109 timer_generic.cc:508] .. shard[24]->queue_deadline_cap --> 1001
I0529 12:58:32.010430345 37109 timer_generic.cc:573] .. shard[24] popped 0
I0529 12:58:32.010439325 37109 timer_generic.cc:628] .. result --> 1, shard[24]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010448483 37109 timer_generic.cc:533] .. shard[25]: heap_empty=true
I0529 12:58:32.010457077 37109 timer_generic.cc:508] .. shard[25]->queue_deadline_cap --> 1001
I0529 12:58:32.010465864 37109 timer_generic.cc:573] .. shard[25] popped 0
I0529 12:58:32.010474784 37109 timer_generic.cc:628] .. result --> 1, shard[25]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010484009 37109 timer_generic.cc:533] .. shard[26]: heap_empty=true
I0529 12:58:32.010492659 37109 timer_generic.cc:508] .. shard[26]->queue_deadline_cap --> 1001
I0529 12:58:32.010501657 37109 timer_generic.cc:573] .. shard[26] popped 0
I0529 12:58:32.010510530 37109 timer_generic.cc:628] .. result --> 1, shard[26]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010519922 37109 timer_generic.cc:533] .. shard[27]: heap_empty=true
I0529 12:58:32.010528749 37109 timer_generic.cc:508] .. shard[27]->queue_deadline_cap --> 1001
I0529 12:58:32.010537530 37109 timer_generic.cc:573] .. shard[27] popped 0
I0529 12:58:32.010546437 37109 timer_generic.cc:628] .. result --> 1, shard[27]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010555645 37109 timer_generic.cc:533] .. shard[28]: heap_empty=true
I0529 12:58:32.010564242 37109 timer_generic.cc:508] .. shard[28]->queue_deadline_cap --> 1001
I0529 12:58:32.010573045 37109 timer_generic.cc:573] .. shard[28] popped 0
I0529 12:58:32.010582109 37109 timer_generic.cc:628] .. result --> 1, shard[28]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010591414 37109 timer_generic.cc:533] .. shard[29]: heap_empty=true
I0529 12:58:32.010600004 37109 timer_generic.cc:508] .. shard[29]->queue_deadline_cap --> 1001
I0529 12:58:32.010608805 37109 timer_generic.cc:573] .. shard[29] popped 0
I0529 12:58:32.010617936 37109 timer_generic.cc:628] .. result --> 1, shard[29]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010627184 37109 timer_generic.cc:533] .. shard[30]: heap_empty=true
I0529 12:58:32.010635797 37109 timer_generic.cc:508] .. shard[30]->queue_deadline_cap --> 1001
I0529 12:58:32.010644574 37109 timer_generic.cc:573] .. shard[30] popped 0
I0529 12:58:32.010653488 37109 timer_generic.cc:628] .. result --> 1, shard[30]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010662606 37109 timer_generic.cc:533] .. shard[31]: heap_empty=true
I0529 12:58:32.010653398 37106 completion_queue.cc:481] grpc_completion_queue_create_internal(completion_type=0, polling_type=0)
I0529 12:58:32.010678282 37109 timer_generic.cc:508] .. shard[31]->queue_deadline_cap --> 1001
I0529 12:58:32.010709769 37109 timer_generic.cc:573] .. shard[31] popped 0
I0529 12:58:32.010720594 37109 timer_generic.cc:628] .. result --> 1, shard[31]->min_deadline 1 --> 1002, now=1
I0529 12:58:32.010730821 37109 timer_generic.cc:738] TIMER CHECK END: r=1; next=1002
I0529 12:58:32.010740062 37109 timer_manager.cc:186] sleep for a 1001 milliseconds
I0529 12:58:32.010753456 37106 metadata_array.cc:29] grpc_metadata_array_init(array=0x7f0cb310c2d8)
I0529 12:58:32.010769179 37106 metadata_array.cc:29] grpc_metadata_array_init(array=0x7f0cb30a80c0)
I0529 12:58:32.010781645 37106 call.cc:1903] grpc_call_start_batch(call=0x199ca80, ops=0x174ff30, nops=6, tag=0x7f0cb30ab2f0, reserved=(nil))
I0529 12:58:32.010795123 37106 call.cc:1508] ops[0]: SEND_INITIAL_METADATA(nil)
I0529 12:58:32.010805787 37106 call.cc:1508] ops[1]: SEND_MESSAGE ptr=0x17e8160
I0529 12:58:32.010815329 37106 call.cc:1508] ops[2]: SEND_CLOSE_FROM_CLIENT
I0529 12:58:32.010825383 37106 call.cc:1508] ops[3]: RECV_INITIAL_METADATA ptr=0x7f0cb310c2d8
I0529 12:58:32.010835700 37106 call.cc:1508] ops[4]: RECV_MESSAGE ptr=0x7f0cb314b6a0
I0529 12:58:32.010848433 37106 call.cc:1508] ops[5]: RECV_STATUS_ON_CLIENT metadata=0x7f0cb30a80c0 status=0x7f0cb30a80d8 details=0x7f0cb30a80e0
I0529 12:58:32.010863270 37106 call_combiner.cc:116] ==> grpc_call_combiner_start() [0x199ca90] closure=0x199da08 [executing batch] error="No Error"
I0529 12:58:32.010873578 37106 call_combiner.cc:125] size: 0 -> 1
I0529 12:58:32.010882625 37106 call_combiner.cc:134] EXECUTING IMMEDIATELY
I0529 12:58:32.010906527 37106 call.cc:613] OP[client-channel:0x199d400]: SEND_INITIAL_METADATA{key=3a 70 61 74 68 ':path' value=2f 67 6e 6d 69 2e 67 4e 4d 49 2f 47 65 74 '/gnmi.gNMI/Get'} SEND_MESSAGE:flags=0x00000000:len=51 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA
I0529 12:58:32.010919711 37106 client_channel.cc:754] chand=0x19a8e98 calld=0x199d420: adding pending batch at index 0
I0529 12:58:32.010929828 37106 client_channel.cc:2486] chand=0x19a8e98 calld=0x199d420: entering client_channel combiner
I0529 12:58:32.010941411 37106 connectivity_state.cc:81] CONWATCH: 0x19a8f40 request_router: get IDLE
I0529 12:58:32.010951391 37106 request_routing.cc:610] request_router=0x19a8e98: starting name resolution
D0529 12:58:32.010961588 37106 dns_resolver.cc:275] Start resolving.
I0529 12:58:32.010973653 37106 executor.cc:243] EXECUTOR (resolver-executor) try to schedule 0x197f860 (short) to thread 0
I0529 12:58:32.010990342 37106 request_routing.cc:80] request_router=0x19a8e98 request=0x199d530: deferring pick pending resolver result
I0529 12:58:32.011000816 37106 call_combiner.cc:215] call_combiner=0x199ca90: setting notify_on_cancel=0x19a8a30
I0529 12:58:32.011009669 37108 executor.cc:188] EXECUTOR (resolver-executor) [0]: execute
I0529 12:58:32.011035563 37106 completion_queue.cc:963] grpc_completion_queue_next(cq=0x199c8e0, deadline=gpr_timespec { tv_sec: 1590728312, tv_nsec: 211030070, clock_type: 1 }, reserved=(nil))
I0529 12:58:32.011054771 37108 executor.cc:73] EXECUTOR (resolver-executor) run 0x197f860
I0529 12:58:32.011077637 37106 ev_epoll1_linux.cc:748] PS:0x199c9a8 BEGIN_STARTS:0x7ffe00c19760
I0529 12:58:32.011100951 37106 ev_epoll1_linux.cc:767] PS:0x199c9a8 BEGIN_REORG:0x7ffe00c19760 kick_state=UNKICKED is_reassigning=1
I0529 12:58:32.011113380 37106 ev_epoll1_linux.cc:836] PS:0x199c9a8 BEGIN_DONE:0x7ffe00c19760 kick_state=DESIGNATED_POLLER shutdown=0 kicked_without_poller: 0
I0529 12:58:32.011131485 37108 request_routing.cc:771] request_router=0x19a8e98: got resolver result: resolver_result=0x7f0ca4000b00 error="No Error"
I0529 12:58:32.011149694 37108 client_channel.cc:131] chand=0x19a8e98: resolver returned service config: "(null)"
I0529 12:58:32.011164104 37108 pick_first.cc:164] Pick First 0x7f0ca40011d0 created.
I0529 12:58:32.011178611 37108 pick_first.cc:361] Pick First 0x7f0ca40011d0 received update with 1 addresses
I0529 12:58:32.011191046 37108 subchannel_list.h:497] [pick_first 0x7f0ca40011d0] Creating subchannel list 0x7f0ca4001770 for 1 subchannels
I0529 12:58:32.011745116 37108 subchannel_list.h:548] [pick_first 0x7f0ca40011d0] subchannel list 0x7f0ca4001770 index 0: Created subchannel 0x7f0ca4004d00 for address uri ipv4:172.18.8.241:8080
I0529 12:58:32.011766670 37108 connectivity_state.cc:92] CONWATCH: 0x7f0ca4004de8 subchannel: get IDLE
I0529 12:58:32.011778911 37108 request_routing.cc:683] request_router=0x19a8e98: created new LB policy "pick_first" (0x7f0ca40011d0)
I0529 12:58:32.011790582 37108 connectivity_state.cc:92] CONWATCH: 0x7f0ca4001228 pick_first: get IDLE
I0529 12:58:32.011801607 37108 connectivity_state.cc:116] CONWATCH: 0x7f0ca4001228 pick_first: from IDLE [cur=IDLE] notify=0x7f0ca4000bd0
I0529 12:58:32.011817965 37108 request_routing.cc:596] request_router=0x19a8e98: setting connectivity state to IDLE
I0529 12:58:32.011831413 37108 connectivity_state.cc:164] SET: 0x19a8f40 request_router: IDLE --> IDLE [resolver_result] error=(nil) "No Error"
I0529 12:58:32.011842632 37108 request_routing.cc:168] request_router=0x19a8e98 request=0x199d530: resolver returned, doing LB pick
I0529 12:58:32.011852869 37108 client_channel.cc:2302] chand=0x19a8e98 calld=0x199d420: applying service config to call
I0529 12:58:32.011863380 37108 connectivity_state.cc:81] CONWATCH: 0x19a8f40 request_router: get IDLE
I0529 12:58:32.011873400 37108 request_routing.cc:338] request_router=0x19a8e98 request=0x199d530: starting pick on lb_policy=0x7f0ca40011d0
I0529 12:58:32.011883417 37108 connectivity_state.cc:92] CONWATCH: 0x7f0ca4004de8 subchannel: get IDLE
I0529 12:58:32.011894819 37108 subchannel_list.h:328] [pick_first 0x7f0ca40011d0] subchannel list 0x7f0ca4001770 index 0 of 1 (subchannel 0x7f0ca4004d00): starting watch: requesting connectivity change notification (from IDLE)
I0529 12:58:32.011905889 37108 connectivity_state.cc:116] CONWATCH: 0x7f0ca4004de8 subchannel: from IDLE [cur=IDLE] notify=0x7f0ca4001128
I0529 12:58:32.011919042 37108 connectivity_state.cc:164] SET: 0x7f0ca4004de8 subchannel: IDLE --> CONNECTING [connecting] error=(nil) "No Error"
I0529 12:58:32.011928805 37108 connectivity_state.cc:190] NOTIFY: 0x7f0ca4004de8 subchannel: 0x7f0ca4001128
I0529 12:58:32.011939413 37108 connectivity_state.cc:164] SET: 0x7f0ca4004e08 subchannel: IDLE --> CONNECTING [connecting] error=(nil) "No Error"
I0529 12:58:32.012016274 37108 socket_utils_common_posix.cc:315] TCP_USER_TIMEOUT not supported for this platform
I0529 12:58:32.012034366 37108 ev_posix.cc:253] (fd-trace) fd_create(6, tcp-client:ipv4:172.18.8.241:8080, 1)
I0529 12:58:32.012116700 37108 tcp_client_posix.cc:332] CLIENT_CONNECT: ipv4:172.18.8.241:8080: asynchronously connecting fd 0x7f0ca4001c60
I0529 12:58:32.012130746 37108 timer_generic.cc:365] TIMER 0x7f0ca40039c0: SET 20003 now 3 call 0x7f0ca40039f0[0x7f0cb39ec370]
I0529 12:58:32.012141387 37108 timer_generic.cc:401] .. add to shard 0 with queue_deadline_cap=1001 => is_first_timer=false
E0529 12:58:32.012151471 37108 lockfree_event.cc:98] LockfreeEvent::NotifyOn: 0x7f0ca4001c70 curr=(nil) closure=0x7f0ca4003a20
I0529 12:58:32.012162573 37108 call_combiner.cc:215] call_combiner=0x199ca90: setting notify_on_cancel=0x7f0ca4000f68
I0529 12:58:32.012172135 37108 call_combiner.cc:224] call_combiner=0x199ca90: scheduling old cancel callback=0x19a8a30
I0529 12:58:32.012186031 37108 subchannel_list.h:443] [pick_first 0x7f0ca40011d0] subchannel list 0x7f0ca4001770 index 0 of 1 (subchannel 0x7f0ca4004d00): connectivity changed: state=CONNECTING, error="No Error", shutting_down=0
I0529 12:58:32.012198356 37108 connectivity_state.cc:164] SET: 0x7f0ca4001228 pick_first: IDLE --> CONNECTING [connecting_changed] error=(nil) "No Error"
I0529 12:58:32.012208195 37108 connectivity_state.cc:190] NOTIFY: 0x7f0ca4001228 pick_first: 0x7f0ca4000bd0
I0529 12:58:32.012219040 37108 subchannel_list.h:350] [pick_first 0x7f0ca40011d0] subchannel list 0x7f0ca4001770 index 0 of 1 (subchannel 0x7f0ca4004d00): renewing watch: requesting connectivity change notification (from CONNECTING)
I0529 12:58:32.012230153 37108 connectivity_state.cc:116] CONWATCH: 0x7f0ca4004de8 subchannel: from CONNECTING [cur=CONNECTING] notify=0x7f0ca4001128
I0529 12:58:32.012242742 37108 request_routing.cc:427] request_router=0x19a8e98: lb_policy=0x7f0ca40011d0 state changed to CONNECTING
I0529 12:58:32.012253711 37108 request_routing.cc:596] request_router=0x19a8e98: setting connectivity state to CONNECTING
I0529 12:58:32.012267276 37108 connectivity_state.cc:164] SET: 0x19a8f40 request_router: IDLE --> CONNECTING [lb_changed] error=(nil) "No Error"
I0529 12:58:32.012278729 37108 connectivity_state.cc:116] CONWATCH: 0x7f0ca4001228 pick_first: from CONNECTING [cur=CONNECTING] notify=0x7f0ca4000bd0
I0529 12:58:32.012289754 37108 executor.cc:167] EXECUTOR (resolver-executor) [0]: step (sub_depth=1)
I0529 12:58:32.012316656 37106 ev_epoll1_linux.cc:728] ps: 0x199c9a8 poll got 1 events
E0529 12:58:32.012344865 37106 lockfree_event.cc:213] LockfreeEvent::SetReady: 0x7f0ca4001c70 curr=0x7f0ca4003a20
I0529 12:58:32.012357353 37106 ev_epoll1_linux.cc:928] PS:0x199c9a8 END_WORKER:0x7ffe00c19760
I0529 12:58:32.012365798 37106 ev_epoll1_linux.cc:908] .. mark pollset 0x199c9a8 inactive
I0529 12:58:32.012377179 37106 tcp_client_posix.cc:150] CLIENT_CONNECT: ipv4:172.18.8.241:8080: on_writable: error="No Error"
I0529 12:58:32.012389843 37106 timer_generic.cc:467] TIMER 0x7f0ca40039c0: CANCEL pending=true
I0529 12:58:32.012431107 37106 tcp_client_posix.cc:113] CLIENT_CONNECT: ipv4:172.18.8.241:8080: on_alarm: error="Cancelled"
I0529 12:58:32.012465306 37106 handshaker.cc:141] handshake_manager 0x199e580: adding handshaker http_connect [0x19b2de0] at index 0
I0529 12:58:32.012509480 37106 ssl_transport_security.cc:217] HANDSHAKE START - TLS client start_connect - !!!!!!
I0529 12:58:32.012573445 37106 ssl_transport_security.cc:217] LOOP - TLS client enter_early_data - !!!!!!
I0529 12:58:32.012585730 37106 ssl_transport_security.cc:217] LOOP - TLS client read_server_hello - !!!!!!
I0529 12:58:32.012604806 37106 handshaker.cc:141] handshake_manager 0x199e580: adding handshaker security [0x19bcfb0] at index 1
I0529 12:58:32.012622083 37106 timer_generic.cc:365] TIMER 0x199e600: SET 20003 now 4 call 0x199e630[0x7f0cb39cf440]
I0529 12:58:32.012632565 37106 timer_generic.cc:401] .. add to shard 20 with queue_deadline_cap=1001 => is_first_timer=false
I0529 12:58:32.012661994 37106 handshaker.cc:212] handshake_manager 0x199e580: error="No Error" shutdown=0 index=0, args={endpoint=0x199e290, args=0x1931410 {size=9: grpc.primary_user_agent=grpc-python/1.18.0, grpc.client_channel_factory=0x7f0cb3ec6498, grpc.channel_credentials=0x16c0c20, grpc.server_uri=dns:///172.18.8.241:8080, grpc.channelz_channel_node_creation_func=0x7f0cb3a6faa0, grpc.default_authority=172.18.8.241:8080, grpc.http2_scheme=https, grpc.security_connector=0x7f0ca4001400, grpc.subchannel_address=ipv4:172.18.8.241:8080}, read_buffer=0x1757c50 (length=0), exit_early=0}
I0529 12:58:32.012675529 37106 handshaker.cc:258] handshake_manager 0x199e580: calling handshaker http_connect [0x19b2de0] at index 0
I0529 12:58:32.012720205 37106 handshaker.cc:212] handshake_manager 0x199e580: error="No Error" shutdown=0 index=1, args={endpoint=0x199e290, args=0x1931410 {size=9: grpc.primary_user_agent=grpc-python/1.18.0, grpc.client_channel_factory=0x7f0cb3ec6498, grpc.channel_credentials=0x16c0c20, grpc.server_uri=dns:///172.18.8.241:8080, grpc.channelz_channel_node_creation_func=0x7f0cb3a6faa0, grpc.default_authority=172.18.8.241:8080, grpc.http2_scheme=https, grpc.security_connector=0x7f0ca4001400, grpc.subchannel_address=ipv4:172.18.8.241:8080}, read_buffer=0x1757c50 (length=0), exit_early=0}
I0529 12:58:32.012733642 37106 handshaker.cc:258] handshake_manager 0x199e580: calling handshaker security [0x19bcfb0] at index 1
I0529 12:58:32.012755329 37106 tcp_posix.cc:966] WRITE 0x199e290 (peer=ipv4:172.18.8.241:8080): 16 03 01 00 93 01 00 00 8f 03 03 79 fc 40 b4 a2 83 26 1f 67 aa 2b 0a 7f 33 09 ca 71 42 8a 1f ef 1c c7 bf 6e a0 6f 35 a1 9e 99 bb 00 00 08 c0 2b c0 2c c0 2f c0 30 01 00 00 5e ff 01 00 01 00 00 00 00 11 00 0f 00 00 0c 31 37 32 2e 31 38 2e 38 2e 32 34 31 00 17 00 00 00 23 00 00 00 0d 00 14 00 12 04 03 08 04 04 01 05 03 08 05 05 01 08 06 06 01 02 01 33 74 00 00 00 10 00 0e 00 0c 08 67 72 70 63 2d 65 78 70 02 68 32 00 0b 00 02 01 00 00 0a 00 04 00 02 00 17 '...........y.@...&.g.+..3..qB......n.o5........+.,./.0...^..............172.18.8.241.....#..........................3t.........grpc-exp.h2..............'
I0529 12:58:32.012794433 37106 tcp_posix.cc:999] write: "No Error"
I0529 12:58:32.012807046 37106 tcp_posix.cc:253] TCP:0x199e290 notify_on_read
E0529 12:58:32.012817132 37106 lockfree_event.cc:98] LockfreeEvent::NotifyOn: 0x7f0ca4001c68 curr=(nil) closure=0x199e430
I0529 12:58:32.012827978 37106 ev_epoll1_linux.cc:990] .. remove worker
I0529 12:58:32.012839297 37106 ev_epoll1_linux.cc:748] PS:0x199c9a8 BEGIN_STARTS:0x7ffe00c19760
I0529 12:58:32.012850179 37106 ev_epoll1_linux.cc:767] PS:0x199c9a8 BEGIN_REORG:0x7ffe00c19760 kick_state=UNKICKED is_reassigning=1
I0529 12:58:32.012878414 37106 ev_epoll1_linux.cc:836] PS:0x199c9a8 BEGIN_DONE:0x7ffe00c19760 kick_state=DESIGNATED_POLLER shutdown=0 kicked_without_poller: 0
I0529 12:58:32.087651891 37106 ev_epoll1_linux.cc:728] ps: 0x199c9a8 poll got 1 events
E0529 12:58:32.087678941 37106 lockfree_event.cc:213] LockfreeEvent::SetReady: 0x7f0ca4001c68 curr=0x199e430
E0529 12:58:32.087691500 37106 lockfree_event.cc:213] LockfreeEvent::SetReady: 0x7f0ca4001c70 curr=(nil)
I0529 12:58:32.087701797 37106 ev_epoll1_linux.cc:928] PS:0x199c9a8 END_WORKER:0x7ffe00c19760
I0529 12:58:32.087712264 37106 ev_epoll1_linux.cc:908] .. mark pollset 0x199c9a8 inactive
I0529 12:58:32.087725913 37106 tcp_posix.cc:535] TCP:0x199e290 got_read: "No Error"
I0529 12:58:32.087735468 37106 tcp_posix.cc:520] TCP:0x199e290 alloc_slices
I0529 12:58:32.087745695 37106 resource_quota.cc:886] RQ anonymous_pool_16bc2f0 ipv4:172.18.8.241:8080: alloc 8192; free_pool -> -8192
I0529 12:58:32.087758345 37106 resource_quota.cc:320] RQ: check allocation for user 0x167bb10 shutdown=0 free_pool=-8192
I0529 12:58:32.087770870 37106 resource_quota.cc:346] RQ anonymous_pool_16bc2f0 ipv4:172.18.8.241:8080: grant alloc 8192 bytes; rq_free_pool -> 9223372036854767615
I0529 12:58:32.087792113 37106 tcp_posix.cc:502] TCP:0x199e290 read_allocation_done: "No Error"
I0529 12:58:32.087809840 37106 tcp_posix.cc:411] TCP:0x199e290 call_cb 0x19bd180 0x7f0cb3a51ca0:0x19bcfb0
I0529 12:58:32.087820048 37106 tcp_posix.cc:414] read: error="No Error"
I0529 12:58:32.087928008 37106 tcp_posix.cc:419] READ 0x199e290 (peer=ipv4:172.18.8.241:8080): 16 03 03 00 3e 02 00 00 3a 03 03 88 df a1 a3 25 8f f1 76 33 db 53 9e c0 32 ab 12 d4 6d bf c7 aa 61 55 96 d1 02 e5 fd 2b 7e 69 3b 00 c0 2f 00 00 12 00 23 00 00 ff 01 00 01 00 00 10 00 05 00 03 02 68 32 16 03 03 05 09 0b 00 05 05 00 05 02 00 04 ff 30 82 04 fb 30 82 02 e3 a0 03 02 01 02 02 09 00 92 2d e3 80 5c eb 70 ae 30 0d 06 09 2a 86 48 86 f7 0d 01 01 0b 05 00 30 14 31 12 30 10 06 03 55 04 03 0c 09 6c 6f 63 61 6c 68 6f 73 74 30 1e 17 0d 32 30 30 35 32 39 30 34 35 33 35 35 5a 17 0d 32 31 30 35 32 39 30 34 35 33 35 35 5a 30 14 31 12 30 10 06 03 55 04 03 0c 09 6c 6f 63 61 6c 68 6f 73 74 30 82 02 22 30 0d 06 09 2a 86 48 86 f7 0d 01 01 01 05 00 03 82 02 0f 00 30 82 02 0a 02 82 02 01 00 bf 4a 59 ab 50 7a 98 99 cb 35 86 f5 83 7c 1d 54 0c d4 5b a5 0f 0b 31 02 c4 b2 90 55 1a 12 8a 9f f6 ac dd af 93 4b 61 e9 b9 81 5d 4a e7 9b 62 6b dd 16 8a 13 49 28 9d 6a 5e f9 8e 4c 32 25 41 8c 59 0e ef e7 a0 7c 83 45 f4 30 92 3a d4 d6 67 94 b5 5c 78 a8 85 13 17 89 d6 a6 02 a0 5b 91 6e 00 63 bd 8a bc 75 68 d6 57 b1 bf 18 5f 54 38 ec 8e 1f 02 99 3e 59 b0 8c 09 8b 42 ff b2 84 5b d4 47 80 c4 72 f1 88 2f 5a 66 2c 2f 48 56 77 e9 c3 0a 27 a2 1c 4c 81 a0 2d 77 b3 2c 45 16 c3 dc 0f 0f 2a 65 b4 59 36 fb b8 0f 18 ab 8c 7c cc 7c 6d 78 46 b0 3d b4 f1 dc 90 19 6a 7a b9 9a 97 36 13 9f 58 eb 4a a7 ec cc 1a 8d 7b 77 a6 6d e6 51 cd ee 25 79 bc 85 23 ed 63 e2 85 77 5d be 6a 36 51 f9 47 6c 1d ad d2 79 b9 a8 ee 06 61 3f fe 40 fc c0 58 8a 04 ff b2 ce f7 fc 96 4e da f6 22 b3 cc eb 63 ae da d6 22 1e 3d c3 f2 93 22 1b ac 73 69 fe 70 4a 29 05 bf e5 55 8a 2e 7e f9 66 fd 11 e4 fe fd ee 91 5e b5 0d be 3d 21 91 d8 bc ce 86 6b ce 7c 5c c6 70 cf f7 ab f8 98 6c 25 84 62 67 25 d2 15 19 f6 04 7d b3 09 b6 0d dd 68 da d4 a1 86 c6 61 ab 69 df 6a e2 1c f2 5f 0d 09 18 9d ba a2 9a c8 1c 35 3c 1e 09 68 cd 98 c8 85 ca 19 2d 1d cc 6c 61 da f4 f7 cf 9a 88 ad 69 e9 2c e2 c5 5f bc 74 4d 97 33 44 c0 e7 45 17 f9 c0 8c 70 41 f5 1b 11 ce 3b 68 19 06 d7 11 f4 a0 a3 eb a4 e5 3e 02 45 1c 7f a9 99 3e 50 02 22 ae 64 82 58 61 47 7f 7f 30 44 47 96 57 c0 d4 29 e8 cc 56 a0 a8 b0 ba dc 07 ef 02 f4 61 e8 00 b0 ec 4b 27 5a fb 86 7d 5d 0d 88 62 0b 1d 12 e7 88 91 b6 b1 f4 19 47 17 ec 97 2e 58 bb 56 17 a5 58 60 33 41 a9 28 82 5b 57 29 bd 0a 6a 0a 43 0f 06 88 b5 e3 2c 6e a1 9f 02 03 01 00 01 a3 50 30 4e 30 1d 06 03 55 1d 0e 04 16 04 14 5b 19 a4 a2 74 24 fa ee a5 f5 ac f9 ac a8 77 d9 e3 e3 b7 d2 30 1f 06 03 55 1d 23 04 18 30 16 80 14 5b 19 a4 a2 74 24 fa ee a5 f5 ac f9 ac a8 77 d9 e3 e3 b7 d2 30 0c 06 03 55 1d 13 04 05 30 03 01 01 ff 30 0d 06 09 2a 86 48 86 f7 0d 01 01 0b 05 00 03 82 02 01 00 3c 33 40 73 e8 64 4b bc 7b db 49 91 99 d4 3a 9e 06 48 85 d6 d5 f8 81 a5 7e 44 6c 9e b8 0f 41 04 6e 85 38 16 a8 1f 3f 73 6d 3f 2a c8 99 5f 9e 76 95 46 75 fb 97 45 42 02 ad d6 91 1e 16 e5 70 d0 63 ad b9 5c ec 6c 78 29 30 c9 23 59 eb da c9 4c 97 cb b1 9a 2d b8 f0 c3 f6 25 d4 03 ac 9d 81 26 29 6d bf 48 11 26 76 98 57 8c 77 44 8d ee 45 5f 76 25 4c 35 dc da 70 0d a9 6a 24 39 82 56 e0 8e c0 be 52 fc db bc 39 85 46 75 a7 51 e1 e5 d3 62 50 9d ad 3f 87 48 71 e9 33 5d 23 7c 06 0d 0a 90 db d0 fd 1e 3c c1 4f d2 26 06 55 40 84 06 99 aa ca a1 64 b3 1b 59 a9 b8 f1 0f 9e e4 87 4b 7a 22 38 12 92 fd 22 ca 1f 98 e2 26 99 1f 02 8b 63 6c 71 5f 98 03 e9 16 0f fd ed 3e 30 0a ff 0d 41 35 e9 0c 35 94 aa fc 2e 23 65 bd 04 19 4d d6 5e 1a ad ac 11 47 89 6e ef 67 c8 4f 4d b5 e7 83 4b d2 3a d3 21 0a 6f 36 cc 07 b9 da e5 95 cf 9c ec 70 27 c9 c3 32 53 81 16 b4 80 82 dc bf 24 83 c9 56 ac 2c ef 56 3d 2a 19 7e 82 1c b4 6d fe aa 77 63 28 4a 3d d9 f2 c7 cb 68 50 b4 67 71 53 d8 0c 87 69 b7 6f 86 57 8f e1 69 e0 9b 48 5c 89 de c9 a5 07 2e aa bf 5a 5a fd 16 af 7f 22 3a 9a 4a f9 30 2e c1 26 33 f7 ef 5b f8 5a 3a a5 9b d1 e1 57 e4 af 2a 5b 64 38 30 e2 b8 72 3a 3a 9b 7d be 3d a8 6e 71 da d9 9c d4 36 15 ea 0b d4 ef ff df 26 1a f8 f7 5e c7 f4 4d 7d ad 01 f8 8c 11 2e fa 37 f7 33 d7 f2 d4 fc 8d a0 33 c8 1f f1 c8 15 37 14 c2 fb 29 7d fa bc fc 58 7f 74 5c f2 3e bb 68 4a 40 57 fa 04 0b 95 de af a2 c1 4b 92 b9 ce 25 b9 05 59 ac fc 23 95 9b fc 08 d1 cf 48 4c 78 75 58 7a 00 e6 c0 61 e5 ea 6c 87 92 aa cf 6e 21 84 7e b8 04 ad db 96 a9 2f 29 30 de 10 4c 01 a1 e9 43 76 16 03 03 02 4d 0c 00 02 49 03 00 17 41 04 61 67 b5 7a 91 ff 5c e4 72 8a 3e 4a f7 37 f3 18 5d a1 58 97 31 69 6a 5f 95 59 22 81 50 bc 5b 4a 08 ef 9e 73 2a 1e c9 2c 20 ac 51 78 c6 aa 1d 9e e4 a6 6a 43 c2 c9 bd 55 16 dd 00 94 3c 90 8d b9 04 01 02 00 46 42 c4 35 2f f9 e4 a6 70 fd 2d 85 6d dd c6 05 f6 98 c7 f9 cf 66 6c f8 3b d2 c3 4d d8 5c ad 44 78 9d 09 63 4c 80 78 5c bd 82 d2 a5 a2 fd ef 3d 9d f5 9d 64 a9 de 92 3f 07 5c 04 8c c6 8c 04 49 ac 72 b9 b9 e2 8f a8 0e 91 86 9e 9e 24 d7 13 b5 6f 13 71 1c 27 a9 43 0e 8f 36 a9 04 0a 1a 19 e2 0e 85 67 8d 71 ef 54 a4 2b 7c 8a c2 42 e4 9b d7 fb 5c 94 0b 37 45 9d d1 31 6d 84 bd 3b 60 b7 96 c7 b6 54 46 cd 95 99 96 e1 d5 eb c3 ef 58 18 f5 9f 2d e5 c1 4c 0b 90 af cc 54 ed da a4 f1 28 40 99 26 9d 36 8c af 10 a0 6c 5a 7d ab 64 39 59 cf b3 76 13 cb d8 48 f7 67 c4 2d 4d 14 59 bd ec c1 79 86 73 cd 19 41 0b de 2b f5 54 16 82 69 59 d0 63 aa f7 61 4a e1 fd 62 cc 78 de 62 0d 94 54 20 a6 4b e8 7c 4e fa 52 97 3b 88 40 20 4e b2 e8 9b fc a9 8c 08 b9 00 eb 07 80 e1 4f 18 e1 ec 10 a6 f2 6f 1d 37 a7 46 a2 82 dd 3d 6a 76 15 c2 b4 e2 48 4e 4c 38 2b 3c ee 0c b4 34 de a1 63 e1 85 6d be e3 1c 3b 02 6b 83 34 c1 93 95 cd d5 f6 8d 4a af c5 37 7c 17 b0 7f 1b d4 d4 f4 ce 36 64 ab 54 2c f1 95 cb a0 ea aa cc cf d4 ef f1 00 a1 f5 96 c5 90 42 fe 7f ce cd d1 38 d3 ac 1d 96 31 f4 8d 2f bb e7 99 2a f7 ff 80 b9 83 30 1e 9c a8 c4 d9 af 2e 41 fa c7 58 a5 8a 18 db 8e f7 49 43 d5 38 1b 3f 89 24 63 cf da 25 67 98 44 df 5b 19 5e a9 d5 fc d2 47 21 a2 47 6a 0b 88 9b 19 31 5a 0d dd f0 53 72 00 a8 71 3f be 67 09 b7 6f 27 81 69 1b d3 7d c9 cd d2 c6 c7 60 5b 1f 70 bd 38 72 1f fb 25 b6 62 33 d3 ab 25 a8 6b 49 e1 c0 3f d8 99 0a 74 d2 99 7d e6 55 b5 03 8d 99 fb e6 97 6f 72 e9 15 9c 9d 10 e5 28 46 6c 43 84 34 9d c9 3a ac 93 44 d4 7c 3b 1f ba 15 43 5d 2f 5a 5c 4a 1d f9 1b 16 03 03 00 1b 0d 00 00 17 02 01 40 00 10 04 01 04 03 05 01 05 03 06 01 06 03 02 01 02 03 00 00 16 03 03 00 04 0e 00 00 00 '....>...:......%..v3.S..2...m...aU.....+~i;../....#..............h2...............0...0............-..\.p.0...*.H........0.1.0...U....localhost0...200529045355Z..210529045355Z0.1.0...U....localhost0.."0...*.H.............0.........JY.Pz...5...|.T..[...1....U.........Ka...]J..bk....I(.j^..L2%A.Y....|.E.0.:..g..\x.........[.n.c...uh.W..._T8.....>Y....B...[.G..r../Zf,/HVw...'..L..-w.,E.....*e.Y6......|.|mxF.=.....jz...6..X.J.....{w.m.Q..%y..#.c..w].j6Q.Gl...y....a?.@..X........N.."...c...".=..."..si.pJ)...U..~.f.......^...=!.....k.|\.p.....l%.bg%.....}.....h.....a.i.j..._.........5<..h......-..la.......i.,.._.tM.3D..E....pA....;h..........>.E....>P.".d.XaG..0DG.W..)..V.........a....K'Z..}]..b..........G....X.V..X`3A.(.[W)..j.C.....,n........P0N0...U......[...t$........w.....0...U.#..0...[...t$........w.....0...U....0....0...*.H.............<3@s.dK.{.I...:..H......~Dl...A.n.8...?sm?*.._.v.Fu..EB.......p.c..\.lx)0.#Y...L....-....%.....&)m.H.&v.W.wD..E_v%L5..p..j$9.V....R...9.Fu.Q...bP..?.Hq.3]#|........<.O.&.U@......d..Y.......Kz"8..."....&....clq_.......>0...A5..5....#e...M.^....G.n.g.OM...K.:.!.o6.........p'..2S.......$..V.,.V=*.~...m..wc(J=....hP.gqS...i.o.W..i..H\........ZZ....":.J.0..&3..[.Z:....W..*[d80..r::.}.=.nq....6.......&...^..M}.......7.3......3.....7...)}...X.t\.>.hJ@W........K...%..Y..#......HLxuXz...a..l....n!.~....../)0..L...Cv....M...I...A.ag.z..\.r.>J.7..].X.1ij_.Y".P.[J...s*.., .Qx......jC...U....<.......FB.5/...p.-.m........fl.;..M.\.Dx..cL.x\.......=...d...?.\.....I.r..........$...o.q.'.C..6........g.q.T.+|..B....\..7E..1m..;`....TF.........X...-..L....T....(@.&.6....lZ}.d9Y..v...H.g.-M.Y...y.s..A..+.T..iY.c..aJ..b.x.b..T .K.|N.R.;.@ N.............O......o.7.F...=jv....HNL8+<...4..c..m...;.k.4.......J..7|........6d.T,.................B.....8....1../...*.....0.......A..X......IC.8.?.$c..%g.D.[.^....G!.Gj....1Z...Sr..q?.g..o'.i..}.....`[.p.8r..%.b3..%.kI..?...t..}.U.......or......(FlC.4..:..D.|;...C]/Z\J..............@.............................'
I0529 12:58:32.088038410 37106 ssl_transport_security.cc:217] LOOP - TLS client read_server_certifi - !!!!!!
I0529 12:58:32.088145481 37106 ssl_transport_security.cc:217] LOOP - TLS client read_certificate_st - !!!!!!
I0529 12:58:32.088158461 37106 ssl_transport_security.cc:217] LOOP - TLS client verify_server_certi - !!!!!!
I0529 12:58:32.088251617 37106 ssl_transport_security.cc:217] LOOP - TLS client read_server_key_exc - !!!!!!
I0529 12:58:32.091566077 37106 ssl_transport_security.cc:217] LOOP - TLS client read_certificate_re - !!!!!!
I0529 12:58:32.091585769 37106 ssl_transport_security.cc:217] LOOP - TLS client read_server_hello_d - !!!!!!
I0529 12:58:32.091595505 37106 ssl_transport_security.cc:217] LOOP - TLS client send_client_certifi - !!!!!!
I0529 12:58:32.091608184 37106 ssl_transport_security.cc:217] LOOP - TLS client send_client_key_exc - !!!!!!
I0529 12:58:32.092926511 37106 ssl_transport_security.cc:217] LOOP - TLS client send_client_certifi - !!!!!!
I0529 12:58:32.092938706 37106 ssl_transport_security.cc:217] LOOP - TLS client send_client_finishe - !!!!!!
I0529 12:58:32.092990433 37106 ssl_transport_security.cc:217] LOOP - TLS client finish_flight - !!!!!!
I0529 12:58:32.093004819 37106 ssl_transport_security.cc:217] LOOP - TLS client read_session_ticket - !!!!!!
I0529 12:58:32.093029984 37106 tcp_posix.cc:966] WRITE 0x199e290 (peer=ipv4:172.18.8.241:8080): 16 03 03 00 07 0b 00 00 03 00 00 00 16 03 03 00 46 10 00 00 42 41 04 92 a6 70 2e 36 44 2d 48 fd 8b 21 b1 15 8e e5 09 ba 20 7e 4d e2 ca 2d 26 7a 25 3a 42 5a 3c 41 75 a6 b4 c1 fc 79 fa a8 15 84 cc 43 0c dd 18 ee f0 e8 ce 16 70 05 03 9b cd b0 8a ee f0 3e 24 22 b8 14 03 03 00 01 01 16 03 03 00 28 00 00 00 00 00 00 00 00 94 fb 65 88 c0 02 76 7c ed b9 58 b6 84 b5 03 12 85 49 8c 9c ca ad d3 0e 1b d8 cf 87 08 3b f5 98 '................F...BA...p.6D-H..!...... ~M..-&z%:BZ<Au....y.....C........p........>$"...........(..........e...v|..X......I...........;..'
I0529 12:58:32.093071697 37106 tcp_posix.cc:999] write: "No Error"
I0529 12:58:32.093085105 37106 tcp_posix.cc:535] TCP:0x199e290 got_read: "No Error"
I0529 12:58:32.093094717 37106 tcp_posix.cc:526] TCP:0x199e290 do_read
I0529 12:58:32.093106595 37106 tcp_posix.cc:253] TCP:0x199e290 notify_on_read
E0529 12:58:32.093116541 37106 lockfree_event.cc:98] LockfreeEvent::NotifyOn: 0x7f0ca4001c68 curr=(nil) closure=0x199e430
I0529 12:58:32.093147346 37106 ev_epoll1_linux.cc:990] .. remove worker
I0529 12:58:32.093159972 37106 ev_epoll1_linux.cc:748] PS:0x199c9a8 BEGIN_STARTS:0x7ffe00c19760
I0529 12:58:32.093170706 37106 ev_epoll1_linux.cc:767] PS:0x199c9a8 BEGIN_REORG:0x7ffe00c19760 kick_state=UNKICKED is_reassigning=1
I0529 12:58:32.093182153 37106 ev_epoll1_linux.cc:836] PS:0x199c9a8 BEGIN_DONE:0x7ffe00c19760 kick_state=DESIGNATED_POLLER shutdown=0 kicked_without_poller: 0
I0529 12:58:32.093781558 37106 ev_epoll1_linux.cc:728] ps: 0x199c9a8 poll got 1 events
E0529 12:58:32.093807458 37106 lockfree_event.cc:213] LockfreeEvent::SetReady: 0x7f0ca4001c68 curr=0x199e430
E0529 12:58:32.093819830 37106 lockfree_event.cc:213] LockfreeEvent::SetReady: 0x7f0ca4001c70 curr=0x2
I0529 12:58:32.093830157 37106 ev_epoll1_linux.cc:928] PS:0x199c9a8 END_WORKER:0x7ffe00c19760
I0529 12:58:32.093840859 37106 ev_epoll1_linux.cc:908] .. mark pollset 0x199c9a8 inactive
I0529 12:58:32.093854306 37106 tcp_posix.cc:535] TCP:0x199e290 got_read: "No Error"
I0529 12:58:32.093863822 37106 tcp_posix.cc:526] TCP:0x199e290 do_read
I0529 12:58:32.093879588 37106 tcp_posix.cc:411] TCP:0x199e290 call_cb 0x19bd180 0x7f0cb3a51ca0:0x19bcfb0
I0529 12:58:32.093889445 37106 tcp_posix.cc:414] read: error="No Error"
I0529 12:58:32.093918291 37106 tcp_posix.cc:419] READ 0x199e290 (peer=ipv4:172.18.8.241:8080): 16 03 03 00 82 04 00 00 7e 00 00 00 00 00 78 bb 4f 19 32 be 8b 27 2c 17 89 f0 09 e4 97 52 ec 29 44 b4 43 b0 3c 16 8c fd ae 40 df df 57 a8 e8 94 b9 59 a1 75 93 66 00 c8 69 aa 63 ac 44 33 43 71 48 5f 3e 2a 5d 02 10 38 49 d6 bb 8b 39 d1 78 84 c5 85 35 e7 73 0a a3 59 e4 6d cb 50 0b 9b bc a5 26 da 40 82 78 8c ab 48 1f bb 9e 96 8f dc 21 cb dc 1e 21 30 fa 55 c3 c5 12 ad 4b 4e 08 9d 06 2b 4c ad 86 1e a1 5a f9 14 03 03 00 01 01 16 03 03 00 28 00 00 00 00 00 00 00 00 5a 3e d2 82 e9 47 02 f7 d1 84 af 15 34 dd 40 a4 cf a4 1a 62 fd 27 6d 4b f1 12 47 cb 0b 7a 8f 5f '........~.....x.O.2..',......R.)D.C.<....@..W....Y.u.f..i.c.D3CqH_>*]..8I...9.x...5.s..Y.m.P....&.@.x..H......!...!0.U....KN...+L....Z...........(........Z>...G......4.@....b.'mK..G..z._'
I0529 12:58:32.093955263 37106 ssl_transport_security.cc:217] LOOP - TLS client process_change_ciph - !!!!!!
I0529 12:58:32.093972453 37106 ssl_transport_security.cc:217] LOOP - TLS client read_server_finishe - !!!!!!
I0529 12:58:32.094002389 37106 ssl_transport_security.cc:217] LOOP - TLS client finish_client_hands - !!!!!!
I0529 12:58:32.094019509 37106 ssl_transport_security.cc:217] LOOP - TLS client done - !!!!!!
I0529 12:58:32.094032105 37106 ssl_transport_security.cc:217] HANDSHAKE DONE - TLS client done - !!!!!!
D0529 12:58:32.094111068 37106 security_handshaker.cc:138] Security handshake failed: {"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}
I0529 12:58:32.094125127 37106 ev_posix.cc:273] (fd-trace) fd_shutdown(6)
E0529 12:58:32.094138481 37106 lockfree_event.cc:164] LockfreeEvent::SetShutdown: 0x7f0ca4001c68 curr=(nil) err={"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}
E0529 12:58:32.094174842 37106 lockfree_event.cc:164] LockfreeEvent::SetShutdown: 0x7f0ca4001c70 curr=0x2 err={"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}
E0529 12:58:32.094188430 37106 lockfree_event.cc:164] LockfreeEvent::SetShutdown: 0x7f0ca4001c78 curr=(nil) err={"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}
I0529 12:58:32.094246678 37106 handshaker.cc:212] handshake_manager 0x199e580: error={"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64} shutdown=0 index=2, args={endpoint=(nil), args=(nil) {size=0: (null)}, read_buffer=(nil) (length=0), exit_early=0}
I0529 12:58:32.094263267 37106 handshaker.cc:245] handshake_manager 0x199e580: handshaking complete -- scheduling on_handshake_done with error={"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}
I0529 12:58:32.094277948 37106 timer_generic.cc:467] TIMER 0x199e600: CANCEL pending=true
I0529 12:58:32.094375838 37106 resource_quota.cc:945] RQ anonymous_pool_16bc2f0 ipv4:172.18.8.241:8080: free 8192; free_pool -> 8192
I0529 12:58:32.094389706 37106 ev_posix.cc:266] (fd-trace) grpc_fd_orphan, fd:6 closed
I0529 12:58:32.094447233 37106 connectivity_state.cc:164] SET: 0x7f0ca4004de8 subchannel: CONNECTING --> TRANSIENT_FAILURE [connect_failed] error=0x19914b0 {"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}
I0529 12:58:32.094461623 37106 connectivity_state.cc:190] NOTIFY: 0x7f0ca4004de8 subchannel: 0x7f0ca4001128
I0529 12:58:32.094486263 37106 connectivity_state.cc:164] SET: 0x7f0ca4004e08 subchannel: CONNECTING --> TRANSIENT_FAILURE [connect_failed] error=0x19449b0 {"created":"@1590728312.094471212","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":873,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}
I0529 12:58:32.094499344 37106 subchannel.cc:878] Connect failed: {"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}
I0529 12:58:32.094514315 37106 resource_quota.cc:544] RU shutdown 0x167bb10
I0529 12:58:32.094531465 37106 subchannel_list.h:443] [pick_first 0x7f0ca40011d0] subchannel list 0x7f0ca4001770 index 0 of 1 (subchannel 0x7f0ca4004d00): connectivity changed: state=TRANSIENT_FAILURE, error={"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}, shutting_down=0
I0529 12:58:32.094547285 37106 subchannel_list.h:370] [pick_first 0x7f0ca40011d0] subchannel list 0x7f0ca4001770 index 0 of 1 (subchannel 0x7f0ca4004d00): stopping connectivity watch
I0529 12:58:32.094557194 37106 lb_policy.cc:47] pick_first 0x7f0ca40011d0: scheduling re-resolution closure with error="No Error".
I0529 12:58:32.094570017 37106 connectivity_state.cc:164] SET: 0x7f0ca4001228 pick_first: CONNECTING --> TRANSIENT_FAILURE [exhausted_subchannels] error=0x19914b0 {"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}
I0529 12:58:32.094582606 37106 connectivity_state.cc:190] NOTIFY: 0x7f0ca4001228 pick_first: 0x7f0ca4000bd0
I0529 12:58:32.094593084 37106 connectivity_state.cc:92] CONWATCH: 0x7f0ca4004de8 subchannel: get TRANSIENT_FAILURE
I0529 12:58:32.094605062 37106 subchannel_list.h:328] [pick_first 0x7f0ca40011d0] subchannel list 0x7f0ca4001770 index 0 of 1 (subchannel 0x7f0ca4004d00): starting watch: requesting connectivity change notification (from TRANSIENT_FAILURE)
I0529 12:58:32.094616766 37106 connectivity_state.cc:116] CONWATCH: 0x7f0ca4004de8 subchannel: from TRANSIENT_FAILURE [cur=TRANSIENT_FAILURE] notify=0x1990728
I0529 12:58:32.094627627 37106 subchannel.cc:760] Subchannel 0x7f0ca4004d00: Retry in 917 milliseconds
I0529 12:58:32.094637871 37106 timer_generic.cc:365] TIMER 0x7f0ca4004ec0: SET 1003 now 86 call 0x7f0ca4004d70[0x7f0cb3a7b630]
I0529 12:58:32.094648112 37106 timer_generic.cc:401] .. add to shard 10 with queue_deadline_cap=1001 => is_first_timer=false
I0529 12:58:32.094659899 37106 request_routing.cc:486] request_router=0x19a8e98: started name re-resolving
D0529 12:58:32.094671111 37106 dns_resolver.cc:255] In cooldown from last resolution (from 84 ms ago). Will resolve again in 916 ms
I0529 12:58:32.094681569 37106 timer_generic.cc:365] TIMER 0x1733998: SET 916 now 86 call 0x17339c8[0x7f0cb3aa3770]
I0529 12:58:32.094692187 37106 timer_generic.cc:401] .. add to shard 9 with queue_deadline_cap=1001 => is_first_timer=true
I0529 12:58:32.094701876 37106 timer_generic.cc:423] .. old shard min_deadline=1002
I0529 12:58:32.094722945 37106 request_routing.cc:427] request_router=0x19a8e98: lb_policy=0x7f0ca40011d0 state changed to TRANSIENT_FAILURE
I0529 12:58:32.094735467 37106 request_routing.cc:596] request_router=0x19a8e98: setting connectivity state to TRANSIENT_FAILURE
I0529 12:58:32.094735928 37109 timer_manager.cc:206] wait ended: was_timed:0 kicked:1
I0529 12:58:32.094750479 37106 connectivity_state.cc:164] SET: 0x19a8f40 request_router: CONNECTING --> TRANSIENT_FAILURE [lb_changed] error=0x19914b0 {"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}
I0529 12:58:32.094774982 37109 timer_generic.cc:715] TIMER CHECK BEGIN: now=86 next=9223372036854775807 tls_min=0 glob_min=916
I0529 12:58:32.094791825 37106 connectivity_state.cc:116] CONWATCH: 0x7f0ca4001228 pick_first: from TRANSIENT_FAILURE [cur=TRANSIENT_FAILURE] notify=0x7f0ca4000bd0
I0529 12:58:32.094805062 37109 timer_generic.cc:738] TIMER CHECK END: r=1; next=916
I0529 12:58:32.094822201 37106 request_routing.cc:379] request_router=0x19a8e98 request=0x199d530: pick completed asynchronously
I0529 12:58:32.094830327 37109 timer_manager.cc:186] sleep for a 830 milliseconds
I0529 12:58:32.094880476 37106 client_channel.cc:2263] chand=0x19a8e98 calld=0x199d420: failed to create subchannel: error={"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]}
I0529 12:58:32.094901996 37106 client_channel.cc:845] chand=0x19a8e98 calld=0x199d420: failing 1 pending batches: {"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]}
I0529 12:58:32.094921421 37106 call_combiner.h:180] CallCombinerClosureList executing closure while already holding call_combiner 0x199ca90: closure=0x199d9b8 error={"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]} reason=pending_batches_fail
I0529 12:58:32.094943689 37106 call_combiner.cc:116] ==> grpc_call_combiner_start() [0x199ca90] closure=0x199d2d8 [failing recv_message_ready] error={"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]}
I0529 12:58:32.094959105 37106 call_combiner.cc:125] size: 1 -> 2
I0529 12:58:32.094967832 37106 call_combiner.cc:140] QUEUING
I0529 12:58:32.094982623 37106 call_combiner.cc:116] ==> grpc_call_combiner_start() [0x199ca90] closure=0x199d490 [failing recv_trailing_metadata_ready] error={"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]}
I0529 12:58:32.094997758 37106 call_combiner.cc:125] size: 2 -> 3
I0529 12:58:32.095005112 37106 call_combiner.cc:140] QUEUING
I0529 12:58:32.095017377 37106 call_combiner.cc:116] ==> grpc_call_combiner_start() [0x199ca90] closure=0x199da30 [failing on_complete] error={"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]}
I0529 12:58:32.095031881 37106 call_combiner.cc:125] size: 3 -> 4
I0529 12:58:32.095041406 37106 call_combiner.cc:140] QUEUING
I0529 12:58:32.095055338 37106 call_combiner.h:180] CallCombinerClosureList executing closure while already holding call_combiner 0x199ca90: closure=0x199d300 error={"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]} reason=failing recv_initial_metadata_ready
I0529 12:58:32.095073056 37106 call_combiner.cc:153] ==> grpc_call_combiner_stop() [0x199ca90] [recv_initial_metadata_ready]
I0529 12:58:32.095083246 37106 call_combiner.cc:160] size: 4 -> 3
I0529 12:58:32.095092561 37106 call_combiner.cc:167] checking queue
I0529 12:58:32.095105424 37106 call_combiner.cc:181] EXECUTING FROM QUEUE: closure=0x199d2d8 error={"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]}
I0529 12:58:32.095123045 37106 call_combiner.cc:252] call_combiner=0x199ca90: scheduling notify_on_cancel callback=0x7f0ca4000f68
I0529 12:58:32.095136426 37106 call_combiner.cc:116] ==> grpc_call_combiner_start() [0x199ca90] closure=0x1994f58 [executing batch] error="No Error"
I0529 12:58:32.095146336 37106 call_combiner.cc:125] size: 3 -> 4
I0529 12:58:32.095154631 37106 call_combiner.cc:140] QUEUING
I0529 12:58:32.095165610 37106 call_combiner.cc:153] ==> grpc_call_combiner_stop() [0x199ca90] [recv_message_ready]
I0529 12:58:32.095175089 37106 call_combiner.cc:160] size: 4 -> 3
I0529 12:58:32.095183989 37106 call_combiner.cc:167] checking queue
I0529 12:58:32.095196856 37106 call_combiner.cc:181] EXECUTING FROM QUEUE: closure=0x199d490 error={"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]}
I0529 12:58:32.095213611 37106 call_combiner.cc:153] ==> grpc_call_combiner_stop() [0x199ca90] [recv_trailing_metadata_ready]
I0529 12:58:32.095223595 37106 call_combiner.cc:160] size: 3 -> 2
I0529 12:58:32.095234566 37106 call_combiner.cc:167] checking queue
I0529 12:58:32.095248829 37106 call_combiner.cc:181] EXECUTING FROM QUEUE: closure=0x199da30 error={"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]}
D0529 12:58:32.095263390 37106 call.cc:719] set_final_status CLI
D0529 12:58:32.095277643 37106 call.cc:720] {"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]}
I0529 12:58:32.095295324 37106 call_combiner.cc:153] ==> grpc_call_combiner_stop() [0x199ca90] [on_complete]
I0529 12:58:32.095306958 37106 call_combiner.cc:160] size: 2 -> 1
I0529 12:58:32.095315658 37106 call_combiner.cc:167] checking queue
I0529 12:58:32.095324779 37106 call_combiner.cc:181] EXECUTING FROM QUEUE: closure=0x1994f58 error="No Error"
I0529 12:58:32.095338096 37106 completion_queue.cc:699] cq_end_op_for_next(cq=0x199c8e0, tag=0x7f0cb30ab2f0, error="No Error", done=0x7f0cb3a01b60, done_arg=0x199d990, storage=0x199d9e0)
D0529 12:58:32.095356258 37106 ev_epoll1_linux.cc:1081] PS:0x199c9a8 KICK:(nil) curps=0x199c9a8 curworker=(nil) root=0x7ffe00c19760 {kick_state=KICKED next=0x7ffe00c19760 {kick_state=KICKED}}
I0529 12:58:32.095367521 37106 ev_epoll1_linux.cc:1165] .. kicked while waking up
I0529 12:58:32.095393308 37106 call.cc:613] OP[client-channel:0x199d400]: CANCEL:{"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]}
I0529 12:58:32.095412462 37106 client_channel.cc:2448] chand=0x19a8e98 calld=0x199d420: recording cancel_error={"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]}
I0529 12:58:32.095433647 37106 client_channel.cc:845] chand=0x19a8e98 calld=0x199d420: failing 0 pending batches: {"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]}
I0529 12:58:32.095453808 37106 call_combiner.h:180] CallCombinerClosureList executing closure while already holding call_combiner 0x199ca90: closure=0x17d5eb0 error={"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]} reason=failing on_complete
I0529 12:58:32.095470673 37106 call_combiner.cc:153] ==> grpc_call_combiner_stop() [0x199ca90] [on_complete for cancel_stream op]
I0529 12:58:32.095480510 37106 call_combiner.cc:160] size: 1 -> 0
I0529 12:58:32.095489006 37106 call_combiner.cc:189] queue empty
I0529 12:58:32.095499306 37106 ev_epoll1_linux.cc:990] .. remove worker
I0529 12:58:32.095513850 37106 completion_queue.cc:1063] RETURN_EVENT[0x199c8e0]: OP_COMPLETE: tag:0x7f0cb30ab2f0 OK
I0529 12:58:32.095546198 37106 metadata_array.cc:34] grpc_metadata_array_destroy(array=0x7f0cb310c2d8)
I0529 12:58:32.095560375 37106 metadata_array.cc:34] grpc_metadata_array_destroy(array=0x7f0cb30a80c0)
I0529 12:58:32.095602335 37106 call.cc:561] grpc_call_unref(c=0x199ca80)
I0529 12:58:32.095614824 37106 call_combiner.cc:204] call_combiner=0x199ca90: scheduling notify_on_cancel callback=(nil) for pre-existing cancellation
I0529 12:58:32.095636875 37106 completion_queue.cc:1389] grpc_completion_queue_shutdown(cq=0x199c8e0)
I0529 12:58:32.095648515 37106 completion_queue.cc:1395] grpc_completion_queue_destroy(cq=0x199c8e0)
I0529 12:58:32.095659444 37106 completion_queue.cc:1389] grpc_completion_queue_shutdown(cq=0x199c8e0)
Traceback (most recent call last):
File "py_gnmicli.py", line 415, in <module>
main()
File "py_gnmicli.py", line 384, in main
response = _get(stub, paths, user, password)
File "py_gnmicli.py", line 277, in _get
return stub.Get(gnmi_pb2.GetRequest(path=[paths], encoding='JSON_IETF'))
File "/opt/gyw/.local/lib/python2.7/site-packages/grpc/_channel.py", line 550, in __call__
return _end_unary_response_blocking(state, call, False, None)
File "/opt/gyw/.local/lib/python2.7/site-packages/grpc/_channel.py", line 467, in _end_unary_response_blocking
raise _Rendezvous(state, None, None, deadline)
grpc._channel._Rendezvous: <_Rendezvous of RPC that terminated with:
status = StatusCode.UNAVAILABLE
details = "Connect Failed"
debug_error_string = "{"created":"@1590728312.094836772","description":"Failed to create subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":2261,"referenced_errors":[{"created":"@1590728312.094733322","description":"Pick Cancelled","file":"src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":245,"referenced_errors":[{"created":"@1590728312.094420648","description":"Connect Failed","file":"src/core/ext/filters/client_channel/subchannel.cc","file_line":867,"grpc_status":14,"referenced_errors":[{"created":"@1590728312.094093848","description":"Peer name 172.18.8.241 is not in peer certificate","file":"src/core/lib/security/security_connector/ssl/ssl_security_connector.cc","file_line":64}]}]}]}"
>
is this problem resolved?
It's a certificate verification problem: "E0529 10:47:08.915533025 5682 ssl_transport_security.cc:1233] Handshake failed with fatal error SSL_ERROR_SSL: error:1000007d:SSL routines:OPENSSL_internal:CERTIFICATE_VERIFY_FAILED."
"So is there '--insecure' option in py_gnmicli.py?" No. There is no --insecure option in the Python gRPC library, as this is considered insecure. Unsure why the authors put that option in the Go library. It still looks to me that you need the -o option.
I can confirm it is the cert issue. When the server starts with certs, I can use following commands to get the data.
python py_gnmicli.py -g -t 10.250.0.101 -p 50051 -m get -x PORT -o "ndastreamingservertest"
I haven't figure out how to support the --insecure option in py_gnmicli.py yet.
Hi all,
I write gnmi server follow SONiC/TELEMETRY. The server side start command use '--insecure', which is:
And server side is written by GO, using "google.golang.org/grpc"
And I use gnmi_get as gnmi client, and it works, like this:
And this is written by GO, using "google.golang.org/grpc"
But when I change to py_gnmicli.py, it NOT work, like this, WHY ???
And this is written by PYTHON, using "grpc"
Then I capture TCP message using tcpdump, I found: 1) It's TCP message, NOT GRPC message (this is show by wireshark, maybe wireshark is wrong?), when I use gnmi_get as client to send gRPC request. 2) It's GRPC message(this is show by wireshark), when I use py_gnmicli.py as client to send gRPC request.