Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Why gnmi_get work, but py_gnmicli.py NOT work ? #91

Open
batmancn opened this issue May 27, 2020 · 9 comments
Open

Why gnmi_get work, but py_gnmicli.py NOT work ? #91

batmancn opened this issue May 27, 2020 · 9 comments
Labels
gnmi py

Comments

@batmancn
Copy link

batmancn commented May 27, 2020 •
edited
Loading

Hi all,

I write gnmi server follow SONiC/TELEMETRY. 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

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:

gyw@sonic107:~/go/src/github.com/google/gnxi/gnmi_get$ gnmi_get -xpath_target "MTNOS" -xpath "/interfaces/interface[name=Ethernet16]" -target_addr 172.18.8.241:8080 -alsologtostderr -insecure true
== getRequest:
prefix: <
  target: "MTNOS"
>
path: <
  elem: <
    name: "interfaces"
  >
  elem: <
    name: "interface"
    key: <
      key: "name"
      value: "Ethernet16"
    >
  >
>
encoding: JSON_IETF

== getResponse:
notification: <
  prefix: <
    target: "MTNOS"
  >
  update: <
    path: <
      elem: <
        name: "interfaces"
      >
      elem: <
        name: "interface"
        key: <
          key: "name"
          value: "Ethernet16"
        >
      >
    >
    val: <
      json_ietf_val: "{\"admin_status\":2,\"enabled\":{},\"oper_status\":3}"
    >
  >
>

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 ???

gyw@sonic107:~/go/src/github.com/google/gnxi/gnmi_cli_py$ python3 py_gnmicli.py -m get -t 172.18.8.241 -p 8080 -x "/interfaces/interface[name=Ethernet16]"  -n
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 "/usr/local/lib/python3.5/dist-packages/grpc/_channel.py", line 550, in __call__
    return _end_unary_response_blocking(state, call, False, None)
  File "/usr/local/lib/python3.5/dist-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 = "Socket closed"
	debug_error_string = "{"created":"@1590563380.688673642","description":"Error received from peer","file":"src/core/lib/surface/call.cc","file_line":1036,"grpc_message":"Socket closed","grpc_status":14}"
>

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.
@mike-albano
Copy link
Collaborator

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?)

@batmancn
Copy link
Author

batmancn commented May 28, 2020 •
edited
Loading

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?

@batmancn
Copy link
Author

batmancn commented May 28, 2020 •
edited
Loading

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"}]}]}]}"
>

@mike-albano
Copy link
Collaborator

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"?

@batmancn
Copy link
Author 

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.  [email protected]..)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'[email protected]......>...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"}]}]}]}"
>

@batmancn
Copy link
Author

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 [email protected]:/home/admin
scp cert.pem [email protected]:/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][email protected].."...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.............<[email protected].{.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.&[email protected]"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\.>[email protected]...%..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.<[email protected]_>*]..8I...9.x...5.s..Y.m.P....&[email protected]......!...!0.U....KN...+L....Z...........(........Z>[email protected].'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}]}]}]}"
>

@lguohan
Copy link

lguohan commented Jun 24, 2020

is this problem resolved?

@mike-albano
Copy link
Collaborator

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.

@lguohan
Copy link

lguohan commented Jul 3, 2020

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
gnmi py
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@lguohan @batmancn @mike-albano @samribeiro