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

Flaky Test: Balancer_TwoAddresses_WeightExpiration #7507

Open
easwars opened this issue Aug 13, 2024 · 9 comments
Open

Flaky Test: Balancer_TwoAddresses_WeightExpiration #7507

easwars opened this issue Aug 13, 2024 · 9 comments
Labels
Area: Resolvers/Balancers Includes LB policy & NR APIs, resolver/balancer/picker wrappers, LB policy impls and utilities. Type: Bug

Comments

@easwars
Copy link
Contributor

easwars commented Aug 13, 2024

https://github.com/grpc/grpc-go/actions/runs/10377601227/job/28732125169?pr=7506

--- FAIL: Test (6.19s)
    --- FAIL: Test/Balancer_TwoAddresses_WeightExpiration (1.19s)
        tlogger.go:116: INFO server.go:685 [core] [Server #328]Server created  (t=+1.018725ms)
        tlogger.go:116: INFO server.go:685 [core] [Server #330]Server created  (t=+1.759362ms)
        balancer_test.go:625: Marshaled service config: {"loadBalancingConfig": [ {"weighted_round_robin":{"enableOobLoadReport":true,"oobReportingPeriod":"60s","blackoutPeriod":"0s","weightExpirationPeriod":"60s","weightUpdatePeriod":".050s","errorUtilizationPenalty":0}} ] }
        tlogger.go:116: INFO clientconn.go:1678 [core] original dial target is: "whatever:https:///127.0.0.1:42173"  (t=+2.267587ms)
        tlogger.go:116: INFO server.go:881 [core] [Server #328 ListenSocket #329]ListenSocket created  (t=+2.984119ms)
        tlogger.go:116: INFO server.go:881 [core] [Server #330 ListenSocket #331]ListenSocket created  (t=+3.153685ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #332]Channel created  (t=+3.606116ms)
        tlogger.go:116: INFO clientconn.go:193 [core] [Channel #332]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"whatever", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:42173", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}}  (t=+3.86649ms)
        tlogger.go:116: INFO clientconn.go:194 [core] [Channel #332]Channel authority set to "127.0.0.1:42173"  (t=+4.005739ms)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #332]Channel exiting idle mode  (t=+4.413988ms)
        tlogger.go:116: INFO resolver_wrapper.go:200 [core] [Channel #332]Resolver state updated: {
              "Addresses": [
                {
                  "Addr": "127.0.0.1:42173",
                  "ServerName": "",
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Metadata": null
                }
              ],
              "Endpoints": [
                {
                  "Addresses": [
                    {
                      "Addr": "127.0.0.1:42173",
                      "ServerName": "",
                      "Attributes": null,
                      "BalancerAttributes": null,
                      "Metadata": null
                    }
                  ],
                  "Attributes": null
                }
              ],
              "ServiceConfig": null,
              "Attributes": null
            } (resolver returned new addresses)  (t=+4.704539ms)
        tlogger.go:116: INFO balancer_wrapper.go:107 [core] [Channel #332]Channel switches to new LB policy "weighted_round_robin"  (t=+4.983848ms)
        tlogger.go:116: INFO balancer.go:105 [weighted-round-robin] [0x40000b8460] Created  (t=+5.168582ms)
        tlogger.go:116: INFO balancer.go:166 [weighted-round-robin] [0x40000b8460] UpdateCCS: {{[{Addr: "127.0.0.1:42173", ServerName: "", }] [{[{Addr: "127.0.0.1:42173", ServerName: "", }] <nil>}] <nil> <nil>} 0x400043e400}  (t=+5.486323ms)
        tlogger.go:116: INFO clientconn.go:842 [core] [Channel #332 SubChannel #333]Subchannel created  (t=+5.655888ms)
        tlogger.go:116: INFO clientconn.go:1202 [core] [Channel #332 SubChannel #333]Subchannel Connectivity change to CONNECTING  (t=+6.037838ms)
        tlogger.go:116: INFO clientconn.go:1320 [core] [Channel #332 SubChannel #333]Subchannel picks a new address "127.0.0.1:42173" to connect  (t=+6.201913ms)
        tlogger.go:116: INFO clientconn.go:1202 [core] [Channel #332 SubChannel #333]Subchannel Connectivity change to READY  (t=+7.214086ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #332]Channel Connectivity change to CONNECTING  (t=+7.529052ms)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #332]Channel Connectivity change to READY  (t=+8.971524ms)
        tlogger.go:116: INFO resolver_wrapper.go:200 [core] [Channel #332]Resolver state updated: {
              "Addresses": [
                {
                  "Addr": "127.0.0.1:42173",
                  "ServerName": "",
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Metadata": null
                },
                {
                  "Addr": "127.0.0.1:41821",
                  "ServerName": "",
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Metadata": null
                }
              ],
              "Endpoints": [
                {
                  "Addresses": [
                    {
                      "Addr": "127.0.0.1:42173",
                      "ServerName": "",
                      "Attributes": null,
                      "BalancerAttributes": null,
                      "Metadata": null
                    }
                  ],
                  "Attributes": null
                },
                {
                  "Addresses": [
                    {
                      "Addr": "127.0.0.1:41821",
                      "ServerName": "",
                      "Attributes": null,
                      "BalancerAttributes": null,
                      "Metadata": null
                    }
                  ],
                  "Attributes": null
                }
              ],
              "ServiceConfig": null,
              "Attributes": null
            } ()  (t=+9.309473ms)
        tlogger.go:116: INFO balancer.go:166 [weighted-round-robin] [0x40000b8460] UpdateCCS: {{[{Addr: "127.0.0.1:42173", ServerName: "", } {Addr: "127.0.0.1:41821", ServerName: "", }] [{[{Addr: "127.0.0.1:42173", ServerName: "", }] <nil>} {[{Addr: "127.0.0.1:41821", ServerName: "", }] <nil>}] <nil> <nil>} 0x400043e400}  (t=+9.711981ms)
        tlogger.go:116: INFO clientconn.go:842 [core] [Channel #332 SubChannel #336]Subchannel created  (t=+9.874784ms)
        tlogger.go:116: INFO clientconn.go:1202 [core] [Channel #332 SubChannel #336]Subchannel Connectivity change to CONNECTING  (t=+34.939867ms)
        tlogger.go:116: INFO clientconn.go:1320 [core] [Channel #332 SubChannel #336]Subchannel picks a new address "127.0.0.1:41821" to connect  (t=+35.241417ms)
        tlogger.go:116: INFO clientconn.go:1202 [core] [Channel #332 SubChannel #336]Subchannel Connectivity change to READY  (t=+38.[113](https://github.com/grpc/grpc-go/actions/runs/10377601227/job/28732125169?pr=7506#step:8:114)778ms)
        balancer_test.go:637: Failed iteration 0; counts: map[127.0.0.1:41821:50 127.0.0.1:42173:50]; want [{srv:0x4000598780 w:9} {srv:0x4000598d50 w:90}]
        balancer_test.go:637: Failed iteration 1; counts: map[127.0.0.1:41821:50 127.0.0.1:42173:50]; want [{srv:0x4000598780 w:9} {srv:0x4000598d50 w:90}]
        balancer_test.go:637: Failed iteration 2; counts: map[127.0.0.1:41821:50 127.0.0.1:42173:50]; want [{srv:0x4000598780 w:9} {srv:0x4000598d50 w:90}]
        balancer_test.go:637: Failed iteration 3; counts: map[127.0.0.1:41821:50 127.0.0.1:42173:50]; want [{srv:0x4000598780 w:9} {srv:0x4000598d50 w:90}]
        balancer_test.go:637: Failed iteration 4; counts: map[127.0.0.1:41821:50 127.0.0.1:42173:50]; want [{srv:0x4000598780 w:9} {srv:0x4000598d50 w:90}]
        balancer_test.go:637: Failed iteration 5; counts: map[127.0.0.1:41821:50 127.0.0.1:42173:50]; want [{srv:0x4000598780 w:9} {srv:0x4000598d50 w:90}]
        balancer_test.go:637: Failed iteration 6; counts: map[127.0.0.1:41821:50 127.0.0.1:42173:50]; want [{srv:0x4000598780 w:9} {srv:0x4000598d50 w:90}]
        balancer_test.go:637: Failed iteration 7; counts: map[127.0.0.1:41821:50 127.0.0.1:42173:50]; want [{srv:0x4000598780 w:9} {srv:0x4000598d50 w:90}]
        balancer_test.go:637: Failed iteration 8; counts: map[127.0.0.1:41821:50 127.0.0.1:42173:50]; want [{srv:0x4000598780 w:9} {srv:0x4000598d50 w:90}]
        balancer_test.go:637: Failed iteration 9; counts: map[127.0.0.1:41821:50 127.0.0.1:42173:50]; want [{srv:0x4000598780 w:9} {srv:0x4000598d50 w:90}]
        balancer_test.go:637: Failed to route RPCs with proper ratio
        tlogger.go:[116](https://github.com/grpc/grpc-go/actions/runs/10377601227/job/28732125169?pr=7506#step:8:117): INFO server.go:817 [core] [Server #330 ListenSocket #331]ListenSocket deleted  (t=+1.177759206s)
        tlogger.go:116: INFO clientconn.go:1202 [core] [Channel #332 SubChannel #336]Subchannel Connectivity change to IDLE  (t=+1.178468345s)
        tlogger.go:116: INFO clientconn.go:544 [core] [Channel #332]Channel Connectivity change to SHUTDOWN  (t=+1.178716236s)
        tlogger.go:116: INFO resolver_wrapper.go:100 [core] [Channel #332]Closing the name resolver  (t=+1.178940063s)
        tlogger.go:116: INFO clientconn.go:1202 [core] [Channel #332 SubChannel #336]Subchannel Connectivity change to CONNECTING  (t=+1.179136017s)
        tlogger.go:116: INFO balancer_wrapper.go:145 [core] [Channel #332]ccBalancerWrapper: closing  (t=+1.179310612s)
        tlogger.go:116: INFO clientconn.go:1320 [core] [Channel #332 SubChannel #336]Subchannel picks a new address "127.0.0.1:41821" to connect  (t=+1.179727447s)
        tlogger.go:116: INFO clientconn.go:[120](https://github.com/grpc/grpc-go/actions/runs/10377601227/job/28732125169?pr=7506#step:8:121)2 [core] [Channel #332 SubChannel #333]Subchannel Connectivity change to SHUTDOWN  (t=+1.180289782s)
        tlogger.go:116: INFO clientconn.go:1551 [core] [Channel #332 SubChannel #333]Subchannel deleted  (t=+1.180489033s)
        tlogger.go:116: INFO clientconn.go:1202 [core] [Channel #332 SubChannel #336]Subchannel Connectivity change to SHUTDOWN  (t=+1.180963806s)
        tlogger.go:116: INFO clientconn.go:1551 [core] [Channel #332 SubChannel #336]Subchannel deleted  (t=+1.181167394s)
        tlogger.go:116: INFO clientconn.go:314 [core] [Channel #332]Channel deleted  (t=+1.181333333s)
        tlogger.go:116: INFO server.go:817 [core] [Server #328 ListenSocket #329]ListenSocket deleted  (t=+1.181606[121](https://github.com/grpc/grpc-go/actions/runs/10377601227/job/28732125169?pr=7506#step:8:122)s)
        tlogger.go:116: WARNING clientconn.go:1382 [core] [Channel #332 SubChannel #336]grpc: addrConn.createTransport failed to connect to {Addr: "127.0.0.1:41821", ServerName: "127.0.0.1:42173", }. Err: connection error: desc = "transport: Error while dialing: dial tcp [127](https://github.com/grpc/grpc-go/actions/runs/10377601227/job/28732125169?pr=7506#step:8:128).0.0.1:41821: operation was canceled"  (t=+1.184049915s)
FAIL
FAIL	google.golang.org/grpc/balancer/weightedroundrobin	11.550s
@easwars
Copy link
Contributor Author

easwars commented Aug 15, 2024

https://github.com/grpc/grpc-go/actions/runs/10394308167/job/28783810539?pr=7498

@purnesh42H
Copy link
Contributor

https://github.com/grpc/grpc-go/actions/runs/10465483190/job/28980791860?pr=7462

@easwars
Copy link
Contributor Author

easwars commented Sep 3, 2024

https://github.com/grpc/grpc-go/actions/runs/10685201154/job/29617436939?pr=7579

@dfawley
Copy link
Member

dfawley commented Sep 10, 2024

I believe this was supposed to be fixed by #7523. Maybe that wasn't effective enough?

@zasweq
Copy link
Contributor

zasweq commented Sep 13, 2024

https://github.com/grpc/grpc-go/actions/runs/10855329479/job/30127706645?pr=7614 argh this shows up on a branch with the fix merged. So it still persists.

@purnesh42H
Copy link
Contributor

@eshitachandwani to forge test and confirm the flakiness percentage

@purnesh42H purnesh42H added the Area: Resolvers/Balancers Includes LB policy & NR APIs, resolver/balancer/picker wrappers, LB policy impls and utilities. label Sep 17, 2024
@purnesh42H
Copy link
Contributor

https://github.com/grpc/grpc-go/actions/runs/10858951486/job/30137631363?pr=7609

@eshitachandwani
Copy link
Member

Failed 0/100k (in all 7 iterations) test runs on forge

@zasweq zasweq mentioned this issue Sep 19, 2024
Closed
@dfawley dfawley mentioned this issue Sep 20, 2024
Merged
@zasweq
Copy link
Contributor

zasweq commented Oct 25, 2024

https://github.com/grpc/grpc-go/actions/runs/11524690877/job/32085409887

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

No branches or pull requests
5 participants
@easwars @purnesh42H @dfawley @zasweq @eshitachandwani