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.

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

Flaky Test: Test/PickFirstLeaf_StopConnectedServer_SecondServerToFirst #7868

Closed
purnesh42H opened this issue Nov 23, 2024 · 1 comment · Fixed by #7872
Closed

Flaky Test: Test/PickFirstLeaf_StopConnectedServer_SecondServerToFirst #7868

purnesh42H opened this issue Nov 23, 2024 · 1 comment · Fixed by #7872
Assignees
Labels
Area: Resolvers/Balancers Includes LB policy & NR APIs, resolver/balancer/picker wrappers, LB policy impls and utilities. Type: Testing

Comments

@purnesh42H
Copy link
Contributor

--- FAIL: Test (3.10s)
    --- FAIL: Test/PickFirstLeaf_StopConnectedServer_SecondServerToFirst (0.17s)
        tlogger.go:116: INFO server.go:685 [core] [Server #331]Server created  (t=+1.460984ms)
        stubserver.go:288: Started test service backend at "127.0.0.1:39795"
        tlogger.go:116: INFO server.go:881 [core] [Server #331 ListenSocket #332]ListenSocket created  (t=+2.063269ms)
        tlogger.go:116: INFO server.go:685 [core] [Server #333]Server created  (t=+2.215611ms)
        stubserver.go:288: Started test service backend at "127.0.0.1:38005"
        tlogger.go:116: INFO clientconn.go:1[65](https://github.com/grpc/grpc-go/actions/runs/11989223270/job/33425355899?pr=7865#step:8:66)4 [core] original dial target is: "whatever:///test.server"  (t=+2.453214ms)
        tlogger.go:116: INFO server.go:881 [core] [Server #333 ListenSocket #334]ListenSocket created  (t=+2.608856ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #335]Channel created  (t=+2.703702ms)
        tlogger.go:116: INFO clientconn.go:193 [core] [Channel #335]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"whatever", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/test.server", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}}  (t=+2.833413ms)
        tlogger.go:116: INFO clientconn.go:194 [core] [Channel #335]Channel authority set to "test.server"  (t=+2.909595ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #335]Channel exiting idle mode  (t=+3.189119ms)
        tlogger.go:116: INFO server.go:817 [core] [Server #331 ListenSocket #332]ListenSocket deleted  (t=+103.746268ms)
        tlogger.go:116: INFO resolver_wrapper.go:200 [core] [Channel #335]Resolver state updated: {
              "Addresses": [
                {
                  "Addr": "127.0.0.1:39795",
                  "ServerName": "",
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Metadata": null
                },
                {
                  "Addr": "127.0.0.1:38005",
                  "ServerName": "",
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Metadata": null
                }
              ],
              "Endpoints": [
                {
                  "Addresses": [
                    {
                      "Addr": "127.0.0.1:39795",
                      "ServerName": "",
                      "Attributes": null,
                      "BalancerAttributes": null,
                      "Metadata": null
                    }
                  ],
                  "Attributes": null
                },
                {
                  "Addresses": [
                    {
                      "Addr": "127.0.0.1:38005",
                      "ServerName": "",
                      "Attributes": null,
                      "BalancerAttributes": null,
                      "Metadata": null
                    }
                  ],
                  "Attributes": null
                }
              ],
              "ServiceConfig": null,
              "Attributes": null
            } (resolver returned new addresses)  (t=+104.399937ms)
        tlogger.go:116: INFO balancer_wrapper.go:109 [core] [Channel #335]Channel switches to new LB policy "state_storing"  (t=+104.79791ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #335]Channel Connectivity change to CONNECTING  (t=+105.222231ms)
        tlogger.go:116: INFO clientconn.go:838 [core] [Channel #335 SubChannel #336]Subchannel created  (t=+105.458091ms)
        tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #335 SubChannel #336]Subchannel Connectivity change to CONNECTING  (t=+105.976808ms)
        tlogger.go:116: INFO clientconn.go:1319 [core] [Channel #335 SubChannel #336]Subchannel picks a new address "127.0.0.1:39795" to connect  (t=+106.240219ms)
        tlogger.go:116: WARNING clientconn.go:1381 [core] [Channel #335 SubChannel #336]grpc: addrConn.createTransport failed to connect to {Addr: "127.0.0.1:39795", ServerName: "test.server", }. Err: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:39795: connect: connection refused"  (t=+106.914386ms)
        tlogger.go:116: INFO clientconn.go:1201 [core] [Channel #335 SubChannel #336]Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:39795: connect: connection refused"  (t=+107.201271ms)
        tlogger.go:116: INFO clientconn.go:838 [core] [Channel #335 SubChannel #337]Subchannel created  (t=+107.446539ms)
        tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #335 SubChannel #337]Subchannel Connectivity change to CONNECTING  (t=+107.761787ms)
        tlogger.go:116: INFO clientconn.go:1319 [core] [Channel #335 SubChannel #337]Subchannel picks a new address "127.0.0.1:38005" to connect  (t=+107.9297ms)
        tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #335 SubChannel #337]Subchannel Connectivity change to READY  (t=+108.860055ms)
        tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #335 SubChannel #336]Subchannel Connectivity change to SHUTDOWN  (t=+109.075006ms)
        tlogger.go:116: INFO clientconn.go:1527 [core] [Channel #335 SubChannel #336]Subchannel deleted  (t=+109.244752ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #335]Channel Connectivity change to READY  (t=+109.448222ms)
        tlogger.go:116: INFO server.go:817 [core] [Server #333 ListenSocket #334]ListenSocket deleted  (t=+1[66](https://github.com/grpc/grpc-go/actions/runs/11989223270/job/33425355899?pr=7865#step:8:67).155594ms)
        tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #335 SubChannel #337]Subchannel Connectivity change to IDLE  (t=+166.711573ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #335]Channel Connectivity change to IDLE  (t=+1[67](https://github.com/grpc/grpc-go/actions/runs/11989223270/job/33425355899?pr=7865#step:8:68).187921ms)
        pickfirstleaf_ext_test.go:700: Failed to start server: net.Listen("tcp", "127.0.0.1:39795") = listen tcp 127.0.0.1:39795: bind: address already in use
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #335]Channel Connectivity change to SHUTDOWN  (t=+1[68](https://github.com/grpc/grpc-go/actions/runs/11989223270/job/33425355899?pr=7865#step:8:69).877822ms)
        tlogger.go:116: INFO resolver_wrapper.go:100 [core] [Channel #335]Closing the name resolver  (t=+1[69](https://github.com/grpc/grpc-go/actions/runs/11989223270/job/33425355899?pr=7865#step:8:70).140923ms)
        tlogger.go:116: INFO balancer_wrapper.go:147 [core] [Channel #335]ccBalancerWrapper: closing  (t=+169.365181ms)
        tlogger.go:116: INFO clientconn.go:1199 [core] [Channel #335 SubChannel #337]Subchannel Connectivity change to SHUTDOWN  (t=+169.843233ms)
        tlogger.go:116: INFO clientconn.go:1527 [core] [Channel #335 SubChannel #337]Subchannel deleted  (t=+1[70](https://github.com/grpc/grpc-go/actions/runs/11989223270/job/33425355899?pr=7865#step:8:71).014462ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #335]Channel deleted  (t=+170.217891ms)
FAIL
FAIL	google.golang.org/grpc/balancer/pickfirst/pickfirstleaf	7.381s
@purnesh42H purnesh42H added Type: Bug Area: Testing Includes tests and testing utilities that we have for unit and e2e tests within our repo. Type: Testing Area: Resolvers/Balancers Includes LB policy & NR APIs, resolver/balancer/picker wrappers, LB policy impls and utilities. and removed Type: Bug Area: Testing Includes tests and testing utilities that we have for unit and e2e tests within our repo. labels Nov 23, 2024
@arjan-bal arjan-bal self-assigned this Nov 25, 2024
@arjan-bal
Copy link
Contributor

Failure link:

The error log: https://github.com/grpc/grpc-go/actions/runs/11989223270/job/33425355899?pr=7865

pickfirstleaf_ext_test.go:700: Failed to start server: net.Listen("tcp", "127.0.0.1:39795") = listen tcp 127.0.0.1:39795: bind: address already in use

The server was shut down, it couldn't bind to the same port when it tried to start again. I'll raise a PR that uses RestartableListeners so that the listener is not closed when the server is temporarily stopped.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Area: Resolvers/Balancers Includes LB policy & NR APIs, resolver/balancer/picker wrappers, LB policy impls and utilities. Type: Testing
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants