gnmic 0.38.2 regression test failure

chenrui333 commented 4 months ago

While upgrading gnmic to do 0.38.2, seeing some regression test failure as below:

$ /opt/homebrew/Cellar/gnmic/0.38.2/bin/gnmic -u gnmi -p dummy --skip-verify --timeout 1s -a 127.0.0.1:0 capabilities
target "127.0.0.1:0", capabilities request failed: "127.0.0.1:0" CapabilitiesRequest failed: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:0: connect: can't assign requested address"
Error: one or more requests failed

only pointer? Thanks!

relates to https://github.com/Homebrew/homebrew-core/pull/178522

karimra commented 4 months ago

I'm not sure this is a regression, in earlier versions it kept retrying and eventually timed out. With the new version it just fails fast. Running a capabilities request is probably not the way to test that the installation succeeded. I think running gnmic version is good enough.

chenrui333 commented 3 months ago

I'm not sure this is a regression, in earlier versions it kept retrying and eventually timed out.

do you have references for that? I just looked at the 0.38.0 and 0.38.1 builds, seems pretty clean to me.

karimra commented 3 months ago

you see it if you add --debug | -d to the command:

karim@dev1:~$ gnmic version
version : 0.38.0
 commit : 01ca8fa7
   date : 2024-07-11T06:10:14Z
 gitURL : https://github.com/openconfig/gnmic
   docs : https://gnmic.openconfig.net
karim@dev1:~$ gnmic -u gnmi -p dummy --skip-verify --timeout 1s -a 127.0.0.1:0 capabilities -d
2024/07/30 21:19:08.369082 /home/runner/work/gnmic/gnmic/pkg/app/app.go:226: [gnmic] version=0.38.0, commit=01ca8fa7, date=2024-07-11T06:10:14Z, gitURL=https://github.com/openconfig/gnmic, docs=https://gnmic.openconfig.net
2024/07/30 21:19:08.369105 /home/runner/work/gnmic/gnmic/pkg/app/app.go:231: [gnmic] using config file ""
2024/07/30 21:19:08.369173 /home/runner/work/gnmic/gnmic/pkg/app/app.go:278: [gnmic] address='[127.0.0.1:0]'([]string)
2024/07/30 21:19:08.369181 /home/runner/work/gnmic/gnmic/pkg/app/app.go:278: [gnmic] debug='true'(bool)
2024/07/30 21:19:08.369206 /home/runner/work/gnmic/gnmic/pkg/app/app.go:278: [gnmic] password='***'(string)
2024/07/30 21:19:08.369234 /home/runner/work/gnmic/gnmic/pkg/app/app.go:278: [gnmic] skip-verify='true'(bool)
2024/07/30 21:19:08.369246 /home/runner/work/gnmic/gnmic/pkg/app/app.go:278: [gnmic] timeout='1s'(string)
2024/07/30 21:19:08.369252 /home/runner/work/gnmic/gnmic/pkg/app/app.go:278: [gnmic] username='gnmi'(string)
2024/07/30 21:19:08.369266 /home/runner/work/gnmic/gnmic/pkg/config/config.go:399: [config] cmd=capabilities, flagName=help, changed=false, isSetInFile=false
2024/07/30 21:19:08.369278 /home/runner/work/gnmic/gnmic/pkg/config/config.go:399: [config] cmd=capabilities, flagName=version, changed=false, isSetInFile=false
2024/07/30 21:19:08.369292 /home/runner/work/gnmic/gnmic/pkg/config/targets.go:47: [config] targets: map[127.0.0.1:0:{"name":"127.0.0.1:0","address":"127.0.0.1:0","username":"gnmi","password":"****","timeout":1000000000,"insecure":false,"tls-cert":"","tls-key":"","skip-verify":true,"buffer-size":100,"retry-timer":10000000000,"log-tls-secret":false,"gzip":false,"token":""}]
2024/07/30 21:19:08.369356 /home/runner/work/gnmic/gnmic/pkg/app/capabilities.go:76: [gnmic] sending gNMI CapabilityRequest: gnmi_ext.Extension='[]' to 127.0.0.1:0
2024/07/30 21:19:08.369376 /home/runner/work/gnmic/gnmic/pkg/app/app.go:521: [gnmic] creating gRPC client for target "127.0.0.1:0"
2024/07/30 21:19:08.369416 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]Channel created
2024/07/30 21:19:08.369426 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]original dial target is: "127.0.0.1:0"
2024/07/30 21:19:08.369432 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]dial target "127.0.0.1:0" parse failed: parse "127.0.0.1:0": first path segment in URL cannot contain colon
2024/07/30 21:19:08.369435 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]fallback to scheme "passthrough"
2024/07/30 21:19:08.369439 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]parsed dial target is: passthrough:///127.0.0.1:0
2024/07/30 21:19:08.369443 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]Channel authority set to "127.0.0.1:0"
2024/07/30 21:19:08.369511 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]Resolver state updated: {
  "Addresses": [
    {
      "Addr": "127.0.0.1:0",
      "ServerName": "",
      "Attributes": null,
      "BalancerAttributes": null,
      "Metadata": null
    }
  ],
  "Endpoints": [
    {
      "Addresses": [
        {
          "Addr": "127.0.0.1:0",
          "ServerName": "",
          "Attributes": null,
          "BalancerAttributes": null,
          "Metadata": null
        }
      ],
      "Attributes": null
    }
  ],
  "ServiceConfig": null,
  "Attributes": null
} (resolver returned new addresses)
2024/07/30 21:19:08.369527 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]Channel switches to new LB policy "pick_first"
2024/07/30 21:19:08.369543 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [pick-first-lb 0xc000b2f2c0] Received new config {
  "shuffleAddressList": false
}, resolver state {
  "Addresses": [
    {
      "Addr": "127.0.0.1:0",
      "ServerName": "",
      "Attributes": null,
      "BalancerAttributes": null,
      "Metadata": null
    }
  ],
  "Endpoints": [
    {
      "Addresses": [
        {
          "Addr": "127.0.0.1:0",
          "ServerName": "",
          "Attributes": null,
          "BalancerAttributes": null,
          "Metadata": null
        }
      ],
      "Attributes": null
    }
  ],
  "ServiceConfig": null,
  "Attributes": null
}
2024/07/30 21:19:08.369557 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1 SubChannel #2]Subchannel created
2024/07/30 21:19:08.369562 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]Channel Connectivity change to CONNECTING
2024/07/30 21:19:08.369570 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]Channel exiting idle mode
2024/07/30 21:19:08.369608 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to CONNECTING
2024/07/30 21:19:08.369625 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1 SubChannel #2]Subchannel picks a new address "127.0.0.1:0" to connect
2024/07/30 21:19:08.369713 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [pick-first-lb 0xc000b2f2c0] Received SubConn state update: 0xc000b2f350, {ConnectivityState:CONNECTING ConnectionError:<nil>}
2024/07/30 21:19:08.369773 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] Creating new client transport to "{Addr: \"127.0.0.1:0\", ServerName: \"127.0.0.1:0\", }": connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:0: connect: connection refused"
2024/07/30 21:19:08.369786 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:65: [gnmic] [core] [Channel #1 SubChannel #2]grpc: addrConn.createTransport failed to connect to {Addr: "127.0.0.1:0", ServerName: "127.0.0.1:0", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:0: connect: connection refused"
2024/07/30 21:19:08.369797 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:0: connect: connection refused"
2024/07/30 21:19:08.369814 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [pick-first-lb 0xc000b2f2c0] Received SubConn state update: 0xc000b2f350, {ConnectivityState:TRANSIENT_FAILURE ConnectionError:connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:0: connect: connection refused"}
2024/07/30 21:19:08.369821 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]Channel Connectivity change to TRANSIENT_FAILURE
2024/07/30 21:19:09.369957 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]Channel Connectivity change to SHUTDOWN
2024/07/30 21:19:09.369957 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to IDLE, last error: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:0: connect: connection refused"
2024/07/30 21:19:09.369970 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]Closing the name resolver
2024/07/30 21:19:09.369981 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]ccBalancerWrapper: closing
2024/07/30 21:19:09.369988 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [pick-first-lb 0xc000b2f2c0] Received SubConn state update: 0xc000b2f350, {ConnectivityState:IDLE ConnectionError:connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:0: connect: connection refused"}
2024/07/30 21:19:09.370000 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1 SubChannel #2]Subchannel Connectivity change to SHUTDOWN
2024/07/30 21:19:09.370004 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1 SubChannel #2]Subchannel deleted
2024/07/30 21:19:09.370007 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] [Channel #1]Channel deleted
2024/07/30 21:19:09.370018 /home/runner/work/gnmic/gnmic/pkg/app/logging.go:21: [gnmic] target "127.0.0.1:0", capabilities request failed: failed to create a gRPC client for target "127.0.0.1:0" : 127.0.0.1:0: context deadline exceeded
target "127.0.0.1:0", capabilities request failed: failed to create a gRPC client for target "127.0.0.1:0" : 127.0.0.1:0: context deadline exceeded
2024/07/30 21:19:09.370044 /home/runner/go/pkg/mod/google.golang.org/grpc@v1.63.2/grpclog/logger.go:53: [gnmic] [core] connect called on shutdown addrConn; ignoring.
Error: one or more requests failed

chenrui333 commented 1 month ago

make sense, I just update the test accordingly. Thanks!

openconfig / gnmic

gnmic 0.38.2 regression test failure #494