grpc-go icon indicating copy to clipboard operation
grpc-go copied to clipboard

Published 20 hours ago • verified publisher icon grpc

[35/100k] Flaky test: ProducerMultipleListeners

Open easwars opened this issue 2 years ago • 6 comments 

--- FAIL: Test (5.28s)
    --- FAIL: Test/ProducerMultipleListeners (5.00s)
        tlogger.go:116: INFO server.go:667 [core] [Server #91] Server created  (t=+374.323µs)
        tlogger.go:116: INFO clientconn.go:318 [core] [Channel #92] Channel created  (t=+462.128µs)
        tlogger.go:116: INFO clientconn.go:1839 [core] [Channel #92] original dial target is: "whatever:///whatever"  (t=+577.935µs)
        tlogger.go:116: INFO clientconn.go:1846 [core] [Channel #92] parsed dial target is: {URL:{Scheme:whatever Opaque: User: Host: Path:/whatever RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+645.44µs)
        tlogger.go:116: INFO clientconn.go:2001 [core] [Channel #92] Channel authority set to "whatever"  (t=+699.643µs)
        tlogger.go:116: INFO server.go:855 [core] [Server #91 ListenSocket #93] ListenSocket created  (t=+788.848µs)
        tlogger.go:116: INFO resolver_conn_wrapper.go:246 [core] [Channel #92] Resolver state updated: {
              "Addresses": [
                {
                  "Addr": "127.0.0.1:42531",
                  "ServerName": "",
                  "Attributes": {
                    "\u003c%!p(orca_test.listenerInfoKey={})\u003e": "\u003c0xc00019e2a0\u003e"
                  },
                  "BalancerAttributes": null,
                  "Metadata": null
                }
              ],
              "Endpoints": [
                {
                  "Addresses": [
                    {
                      "Addr": "127.0.0.1:42531",
                      "ServerName": "",
                      "Attributes": {
                        "\u003c%!p(orca_test.listenerInfoKey={})\u003e": "\u003c0xc00019e2a0\u003e"
                      },
                      "BalancerAttributes": null,
                      "Metadata": null
                    }
                  ],
                  "Attributes": null
                }
              ],
              "ServiceConfig": null,
              "Attributes": null
            } (resolver returned new addresses)  (t=+1.081566ms)
        tlogger.go:116: INFO balancer_conn_wrappers.go:180 [core] [Channel #92] Channel switches to new LB policy "customLB"  (t=+1.178072ms)
        tlogger.go:116: INFO clientconn.go:956 [core] [Channel #92 SubChannel #94] Subchannel created  (t=+1.250476ms)
        tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[]}  (t=+1.375784ms)
        tlogger.go:116: INFO clientconn.go:592 [core] [Channel #92] Channel Connectivity change to CONNECTING  (t=+1.421287ms)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #92 SubChannel #94] Subchannel Connectivity change to CONNECTING  (t=+1.508392ms)
        tlogger.go:116: INFO clientconn.go:1453 [core] [Channel #92 SubChannel #94] Subchannel picks a new address "127.0.0.1:42531" to connect  (t=+1.552895ms)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #92 SubChannel #94] Subchannel Connectivity change to READY  (t=+2.738467ms)
        tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[SubConn(id:94):{{Addr: "127.0.0.1:42531", ServerName: "", Attributes: {"<%!p(orca_test.listenerInfoKey={})>": "<0xc00019e2a0>" }, }}]}  (t=+2.883876ms)
        tlogger.go:116: INFO clientconn.go:592 [core] [Channel #92] Channel Connectivity change to READY  (t=+2.93828ms)
        producer_test.go:458: Load report 1 received:  cpu_utilization:10 mem_utilization:0.1 utilization:{key:"bob" value:0.555}
        producer_test.go:458: Load report 1 received:  cpu_utilization:10 mem_utilization:0.1 utilization:{key:"bob" value:0.555}
        producer_test.go:466: Load report 2 received:  cpu_utilization:10 mem_utilization:0.1 utilization:{key:"bob" value:0.555}
        producer_test.go:458: Load report 1 received:  cpu_utilization:10 mem_utilization:0.1 utilization:{key:"bob" value:0.555}
        producer_test.go:466: Load report 2 received:  cpu_utilization:10 mem_utilization:0.1 utilization:{key:"bob" value:0.555}
        producer_test.go:474: Load report 3 received:  cpu_utilization:10 mem_utilization:0.1 utilization:{key:"bob" value:0.555}
        producer_test.go:466: Load report 2 received:  cpu_utilization:10 mem_utilization:0.1 utilization:{key:"bob" value:0.555}
        producer_test.go:474: Load report 3 received:  cpu_utilization:10 mem_utilization:0.1 utilization:{key:"bob" value:0.555}
        producer_test.go:458: Load report 1 received:  cpu_utilization:10 mem_utilization:0.1 utilization:{key:"bob" value:0.555}
        producer_test.go:474: Load report 3 received:  cpu_utilization:10 mem_utilization:0.1 utilization:{key:"bob" value:0.555}
        producer_test.go:458: Load report 1 received:  cpu_utilization:10 mem_utilization:0.1 utilization:{key:"bob" value:0.555}
        producer_test.go:543: timed out waiting for reports received. got 5 3 3; want 6 3 3
        tlogger.go:116: INFO clientconn.go:592 [core] [Channel #92] Channel Connectivity change to SHUTDOWN  (t=+5.001404657s)
        tlogger.go:116: INFO balancer_conn_wrappers.go:191 [core] [Channel #92] ccBalancerWrapper: closing  (t=+5.001467561s)
        tlogger.go:116: INFO resolver_conn_wrapper.go:126 [core] [Channel #92] Closing the name resolver  (t=+5.001551966s)
        tlogger.go:116: INFO clientconn.go:1338 [core] [Channel #92 SubChannel #94] Subchannel Connectivity change to SHUTDOWN  (t=+5.001645372s)
        tlogger.go:116: INFO clientconn.go:1684 [core] [Channel #92 SubChannel #94] Subchannel deleted  (t=+5.001722577s)
        tlogger.go:116: INFO clientconn.go:318 [core] [Channel #92] Channel deleted  (t=+5.00[189](https://github.com/grpc/grpc-go/actions/runs/6191873520/job/16810932491?pr=6634#step:8:190)0887s)
        tlogger.go:116: INFO server.go:806 [core] [Server #91 ListenSocket #93] ListenSocket deleted  (t=+5.00[203](https://github.com/grpc/grpc-go/actions/runs/6191873520/job/16810932491?pr=6634#step:8:204)2696s)
FAIL
FAIL	google.golang.org/grpc/orca	5.882s

https://github.com/grpc/grpc-go/actions/runs/6191873520/job/16810932491?pr=6634

easwars avatar Sep 15 '23 00:09 easwars

Made P2 since it doesn't look like this is occurring too frequently. I reviewed this PR, Doug wrote the test, thus assigning to Doug.

zasweq avatar Sep 19 '23 00:09 zasweq

https://github.com/grpc/grpc-go/actions/runs/6317329369/job/17153865917?pr=6665

easwars avatar Sep 26 '23 20:09 easwars

https://github.com/grpc/grpc-go/actions/runs/6399400068/job/17371377399?pr=6681

easwars avatar Oct 03 '23 23:10 easwars

https://github.com/grpc/grpc-go/actions/runs/6473390734/job/17575983599?pr=6705

zasweq avatar Oct 10 '23 18:10 zasweq

https://github.com/grpc/grpc-go/actions/runs/6566180296/job/17836303715

zasweq avatar Oct 18 '23 20:10 zasweq

low flake rate on forge [35/100k] - sponge2/e9e27ddd-2d25-4338-bb20-9946440453da

arvindbr8 avatar Oct 19 '23 22:10 arvindbr8