gnmic icon indicating copy to clipboard operation
gnmic copied to clipboard

GET intermittently failing with TLS13(DeadlineExceeded desc = context deadline exceeded)

Open Shikha-Chowdhary opened this issue 10 months ago • 2 comments

My SSL library recently upgraded to support TLS13. But gRPC GET commands are intermittently failing now with timeout error.

  • Is there a way to enable more logs except --debug flag ?
  • Also, can we configure this GET timeout value ? I am using --timeout flag with 25s , but results are same.
  • Workaround : Force --tls-version "1.2"

`bash-4.4$ time gnmic -a 192.168.0.15 --port 10161 -u ADMIN -p ADMIN get --path "/shelves/shelf" --skip-verify --format prototext --debug 2024/04/24 04:28:07.251632 /home/runner/work/gnmic/gnmic/pkg/app/app.go:227: [gnmic] version=0.36.2, commit=a7844a6d, date=2024-03-05T20:10:26Z, gitURL=https://github.com/openconfig/gnmic, docs=https://gnmic.openconfig.net 2024/04/24 04:28:07.251670 /home/runner/work/gnmic/gnmic/pkg/app/app.go:232: [gnmic] using config file "" 2024/04/24 04:28:07.252242 /home/runner/work/gnmic/gnmic/pkg/app/app.go:270: [gnmic] set flags/config: address:

  • 192.168.0.15 api: "" auth-scheme: "" calculate-latency: false capabilities-version: false cluster-name: default-cluster config: "" debug: true diff-compare: [] diff-model: [] diff-path: [] diff-prefix: "" diff-qos: "0" diff-ref: "" diff-set-to-notifs-full: false diff-set-to-notifs-response: "" diff-set-to-notifs-setrequest: "" diff-setrequest-full: false diff-setrequest-new: "" diff-setrequest-ref: "" diff-sub: false diff-target: "" diff-type: ALL dir: [] encoding: json exclude: [] file: [] format: prototext generate-camel-case: false generate-config-only: false generate-path: "" generate-snake-case: false get-model: [] get-path:
  • /shelves/shelf get-prefix: "" get-processor: [] get-target: "" get-type: ALL get-values-only: false getset-condition: any([true]) getset-delete: "" getset-get: "" getset-model: [] getset-prefix: "" getset-replace: "" getset-target: "" getset-type: ALL getset-update: "" getset-value: "" gzip: false insecure: false instance-name: "" listen-max-concurrent-streams: "256" listen-prometheus-address: "" log: true log-file: "" log-tls-secret: false max-msg-size: 536870912 metadata: {} no-prefix: false password: ADMIN path-config-only: false path-descr: false path-path-type: xpath path-search: false path-state-only: false path-types: false path-with-non-leaves: false path-with-prefix: false port: "10161" print-request: false processors-plugins-path: "" prompt-description-bg-color: dark_gray prompt-description-with-prefix: false prompt-description-with-types: false prompt-max-suggestions: "10" prompt-prefix-color: dark_blue prompt-suggest-all-flags: false prompt-suggest-with-origin: false prompt-suggestions-bg-color: dark_blue proto-dir: [] proto-file: [] proxy-from-env: false retry: 10s set-delete: [] set-delimiter: ':::' set-dry-run: false set-prefix: "" set-proto-file: [] set-replace: [] set-replace-cli: [] set-replace-cli-file: "" set-replace-file: [] set-replace-path: [] set-replace-value: [] set-request-file: [] set-request-replace: [] set-request-update: [] set-request-vars: "" set-target: "" set-union-replace: [] set-union-replace-file: [] set-union-replace-path: [] set-union-replace-value: [] set-update: [] set-update-cli: [] set-update-cli-file: "" set-update-file: [] set-update-path: [] set-update-value: [] skip-verify: true subscribe-backoff: 0s subscribe-heartbeat-interval: 0s subscribe-history-end: "" subscribe-history-snapshot: "" subscribe-history-start: "" subscribe-lock-retry: 5s subscribe-mode: stream subscribe-model: [] subscribe-name: [] subscribe-output: [] subscribe-path: [] subscribe-prefix: "" subscribe-qos: "0" subscribe-quiet: false subscribe-sample-interval: 0s subscribe-set-target: false subscribe-stream-mode: target-defined subscribe-suppress-redundant: false subscribe-target: "" subscribe-updates-only: false subscribe-watch-config: false targets-file: "" timeout: 10s tls-ca: "" tls-cert: "" tls-key: "" tls-max-version: "" tls-min-version: "" tls-server-name: "" tls-version: "" token: "" upgrade-use-pkg: false use-tunnel-server: false username: ADMIN

2024/04/24 04:28:07.252404 /home/runner/work/gnmic/gnmic/pkg/app/app.go:280: [gnmic] address='[192.168.0.15]'([]string) 2024/04/24 04:28:07.252417 /home/runner/work/gnmic/gnmic/pkg/app/app.go:280: [gnmic] debug='true'(bool) 2024/04/24 04:28:07.252434 /home/runner/work/gnmic/gnmic/pkg/app/app.go:280: [gnmic] format='prototext'(string) 2024/04/24 04:28:07.252446 /home/runner/work/gnmic/gnmic/pkg/app/app.go:280: [gnmic] get-path='[/shelves/shelf]'([]string) 2024/04/24 04:28:07.252467 /home/runner/work/gnmic/gnmic/pkg/app/app.go:280: [gnmic] password='ADMIN'(string) 2024/04/24 04:28:07.252478 /home/runner/work/gnmic/gnmic/pkg/app/app.go:280: [gnmic] port='10161'(string) 2024/04/24 04:28:07.252505 /home/runner/work/gnmic/gnmic/pkg/app/app.go:280: [gnmic] skip-verify='true'(bool) 2024/04/24 04:28:07.252529 /home/runner/work/gnmic/gnmic/pkg/app/app.go:280: [gnmic] username='ADMIN'(string) 2024/04/24 04:28:07.252557 /home/runner/work/gnmic/gnmic/pkg/config/config.go:387: [config] cmd=get, flagName=help, changed=false, isSetInFile=false 2024/04/24 04:28:07.252578 /home/runner/work/gnmic/gnmic/pkg/config/config.go:387: [config] cmd=get, flagName=model, changed=false, isSetInFile=false 2024/04/24 04:28:07.252583 /home/runner/work/gnmic/gnmic/pkg/config/config.go:387: [config] cmd=get, flagName=path, changed=true, isSetInFile=true 2024/04/24 04:28:07.252590 /home/runner/work/gnmic/gnmic/pkg/config/config.go:387: [config] cmd=get, flagName=prefix, changed=false, isSetInFile=false 2024/04/24 04:28:07.252595 /home/runner/work/gnmic/gnmic/pkg/config/config.go:387: [config] cmd=get, flagName=processor, changed=false, isSetInFile=false 2024/04/24 04:28:07.252599 /home/runner/work/gnmic/gnmic/pkg/config/config.go:387: [config] cmd=get, flagName=target, changed=false, isSetInFile=false 2024/04/24 04:28:07.252604 /home/runner/work/gnmic/gnmic/pkg/config/config.go:387: [config] cmd=get, flagName=type, changed=false, isSetInFile=false 2024/04/24 04:28:07.252608 /home/runner/work/gnmic/gnmic/pkg/config/config.go:387: [config] cmd=get, flagName=values-only, changed=false, isSetInFile=false 2024/04/24 04:28:07.252890 /home/runner/work/gnmic/gnmic/pkg/config/targets.go:47: [config] targets: map[192.168.0.15:{"name":"192.168.0.15","address":"192.168.0.15:10161","username":"ADMIN","password":"****","timeout":10000000000,"insecure":false,"tls-cert":"","tls-key":"","skip-verify":true,"buffer-size":100,"retry-timer":10000000000,"log-tls-secret":false,"gzip":false,"token":""}] 2024/04/24 04:28:07.253293 /home/runner/work/gnmic/gnmic/pkg/config/actions.go:49: [config] actions: map[] 2024/04/24 04:28:07.253309 /home/runner/work/gnmic/gnmic/pkg/config/processors.go:45: [config] processors: map[] 2024/04/24 04:28:07.253355 /home/runner/work/gnmic/gnmic/pkg/app/get.go:132: [gnmic] sending gNMI GetRequest: prefix='', path='[elem:{name:"shelves"} elem:{name:"shelf"}]', type='ALL', encoding='JSON', models='[]', extension='[]' to 192.168.0.15 2024/04/24 04:28:07.254759 /home/runner/work/gnmic/gnmic/pkg/app/app.go:523: [gnmic] creating gRPC client for target "192.168.0.15" 2024/04/24 04:28:07.254842 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1] Channel created 2024/04/24 04:28:07.254858 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1] original dial target is: "192.168.0.15:10161" 2024/04/24 04:28:07.254868 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1] dial target "192.168.0.15:10161" parse failed: parse "192.168.0.15:10161": first path segment in URL cannot contain colon 2024/04/24 04:28:07.254873 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1] fallback to scheme "passthrough" 2024/04/24 04:28:07.254881 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1] parsed dial target is: passthrough:///192.168.0.15:10161 2024/04/24 04:28:07.254886 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1] Channel authority set to "192.168.0.15:10161" 2024/04/24 04:28:07.255021 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1] Resolver state updated: { "Addresses": [ { "Addr": "192.168.0.15:10161", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Endpoints": [ { "Addresses": [ { "Addr": "192.168.0.15:10161", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Attributes": null } ], "ServiceConfig": null, "Attributes": null } (resolver returned new addresses) 2024/04/24 04:28:07.255049 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1] Channel switches to new LB policy "pick_first" 2024/04/24 04:28:07.255078 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [pick-first-lb 0xc000b10810] Received new config { "shuffleAddressList": false }, resolver state { "Addresses": [ { "Addr": "192.168.0.15:10161", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Endpoints": [ { "Addresses": [ { "Addr": "192.168.0.15:10161", "ServerName": "", "Attributes": null, "BalancerAttributes": null, "Metadata": null } ], "Attributes": null } ], "ServiceConfig": null, "Attributes": null } 2024/04/24 04:28:07.255098 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1 SubChannel #2] Subchannel created 2024/04/24 04:28:07.255107 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1] Channel Connectivity change to CONNECTING 2024/04/24 04:28:07.255124 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1] Channel exiting idle mode 2024/04/24 04:28:07.255147 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING 2024/04/24 04:28:07.255173 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1 SubChannel #2] Subchannel picks a new address "192.168.0.15:10161" to connect 2024/04/24 04:28:07.255295 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [pick-first-lb 0xc000b10810] Received SubConn state update: 0xc000b10990, {ConnectivityState:CONNECTING ConnectionError:} 2024/04/24 04:28:11.464366 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to READY 2024/04/24 04:28:11.464404 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [pick-first-lb 0xc000b10810] Received SubConn state update: 0xc000b10990, {ConnectivityState:READY ConnectionError:} 2024/04/24 04:28:11.464413 /home/runner/go/pkg/mod/google.golang.org/[email protected]/grpclog/logger.go:53: [gnmic] [core] [Channel #1] Channel Connectivity change to READY 2024/04/24 04:28:21.464999 /home/runner/work/gnmic/gnmic/pkg/app/logging.go:21: [gnmic] target "192.168.0.15" get request failed: "192.168.0.15:10161" GetRequest failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded 2024/04/24 04:28:21.465039 /home/runner/work/gnmic/gnmic/pkg/app/logging.go:21: [gnmic] target "192.168.0.15" Get request failed: "192.168.0.15:10161" GetRequest failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded target "192.168.0.15" get request failed: "192.168.0.15:10161" GetRequest failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded target "192.168.0.15" Get request failed: "192.168.0.15:10161" GetRequest failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded Error: one or more requests failed

real 0m14.243s user 0m0.039s sys 0m0.012s `

Shikha-Chowdhary avatar Apr 24 '24 08:04 Shikha-Chowdhary

bash-4.4$ gnmic version version : 0.36.2 commit : a7844a6d date : 2024-03-05T20:10:26Z gitURL : https://github.com/openconfig/gnmic docs : https://gnmic.openconfig.net bash-4.4$

Shikha-Chowdhary avatar Apr 24 '24 08:04 Shikha-Chowdhary

Is there a way to enable more logs except --debug flag ?

No, that's as much as you can get without editing code.

Also, can we configure this GET timeout value ? I am using --timeout flag with 25s , but results are same.

The --timeout flag works fine from my tests. Can you give an example where you pass --timeout 25s and a 10s timeout is applied ?

My SSL library recently upgraded to support TLS13. But gRPC GET commands are intermittently failing now with timeout error.

Can you detail what you mean by "intermittently". What kind of errors do you get ? Just a timeout ?

karimra avatar Apr 24 '24 23:04 karimra