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

Flaky test: 6/10k: Test/CZServerSocketMetricsStreamsAndMessagesCount

Open menghanl opened this issue 3 years ago • 7 comments
trafficstars

https://github.com/grpc/grpc-go/runs/6329576820?check_suite_focus=true

--- FAIL: Test (173.15s)
    --- FAIL: Test/CZServerSocketMetricsStreamsAndMessagesCount (10.60s)
        channelz_test.go:1225: Running test in tcp-clear environment...
        tlogger.go:116: INFO server.go:588 [core] [Server #1] Server created  (t=+1.119807ms)
        tlogger.go:116: INFO clientconn.go:105 [core] [Channel #2] Channel created  (t=+1.434509ms)
        tlogger.go:116: INFO clientconn.go:1555 [core] [Channel #2] original dial target is: "passthrough:///localhost:40813"  (t=+1.599011ms)
        tlogger.go:116: INFO server.go:776 [core] [Server #1 ListenSocket #3] ListenSocket created  (t=+1.821212ms)
        tlogger.go:116: INFO clientconn.go:1562 [core] [Channel #2] parsed dial target is: {Scheme:passthrough Authority: Endpoint:localhost:40813 URL:{Scheme:passthrough Opaque: User: Host: Path:/localhost:40813 RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+3.613923ms)
        tlogger.go:116: INFO clientconn.go:259 [core] [Channel #2] Channel authority set to "localhost:40813"  (t=+3.899025ms)
        tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #2] Resolver state updated: {
              "Addresses": [
                {
                  "Addr": "localhost:40813",
                  "ServerName": "",
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Type": 0,
                  "Metadata": null
                }
              ],
              "ServiceConfig": null,
              "Attributes": null
            } (resolver returned new addresses)  (t=+4.276828ms)
        tlogger.go:116: INFO balancer_conn_wrappers.go:271 [core] [Channel #2] Channel switches to new LB policy "round_robin"  (t=+4.536429ms)
        tlogger.go:116: INFO clientconn.go:721 [core] [Channel #2 SubChannel #4] Subchannel created  (t=+4.927732ms)
        tlogger.go:116: INFO clientconn.go:1078 [core] [Channel #2 SubChannel #4] Subchannel Connectivity change to CONNECTING  (t=+5.285334ms)
        tlogger.go:116: INFO clientconn.go:1189 [core] [Channel #2 SubChannel #4] Subchannel picks a new address "localhost:40813" to connect  (t=+5.477135ms)
        tlogger.go:116: INFO clientconn.go:414 [core] [Channel #2] Channel Connectivity change to CONNECTING  (t=+5.911938ms)
        tlogger.go:116: INFO clientconn.go:1078 [core] [Channel #2 SubChannel #4] Subchannel Connectivity change to READY  (t=+10.761669ms)
        tlogger.go:116: INFO roundrobin.go:50 [roundrobin] roundrobinPicker: Build called with info: {map[0xc00009b700:{{
              "Addr": "localhost:40813",
              "ServerName": "",
              "Attributes": null,
              "BalancerAttributes": null,
              "Type": 0,
              "Metadata": null
            }}]}  (t=+11.339273ms)
        tlogger.go:116: INFO clientconn.go:414 [core] [Channel #2] Channel Connectivity change to READY  (t=+23.199949ms)
        channelz_test.go:1275: server socket metric with ID 5, want (StreamsStarted, StreamsSucceeded, StreamsFailed, MessagesSent, MessagesReceived) = (3, 2, 1, 2, 2), got (3, 3, 1, 2, 2)
        tlogger.go:116: INFO clientconn.go:414 [core] [Channel #2] Channel Connectivity change to SHUTDOWN  (t=+10.57529787s)
        tlogger.go:116: INFO clientconn.go:1078 [core] [Channel #2 SubChannel #4] Subchannel Connectivity change to SHUTDOWN  (t=+10.575934[174](https://github.com/grpc/grpc-go/runs/6329576820?check_suite_focus=true#step:8:174)s)
        tlogger.go:116: INFO clientconn.go:1433 [core] [Channel #2 SubChannel #4] Subchannel deleted  (t=+10.576205[176](https://github.com/grpc/grpc-go/runs/6329576820?check_suite_focus=true#step:8:176)s)
        tlogger.go:116: INFO clientconn.go:1033 [core] [Channel #2] Channel deleted  (t=+10.576292976s)
        tlogger.go:116: INFO server.go:727 [core] [Server #1 ListenSocket #3] ListenSocket deleted  (t=+10.576668979s)
        tlogger.go:116: INFO types.go:68 [channelz] attempt to delete child with id 4 from a parent (id=2) that doesn't currently exist  (t=+10.577411[184](https://github.com/grpc/grpc-go/runs/6329576820?check_suite_focus=true#step:8:184)s)
        tlogger.go:116: INFO types.go:68 [channelz] attempt to delete child with id 4 from a parent (id=2) that doesn't currently exist  (t=+10.577557985s)

menghanl avatar May 10 '22 17:05 menghanl

https://github.com/zasweq/grpc-go/runs/8240447618?check_suite_focus=true

zasweq avatar Sep 08 '22 01:09 zasweq

Flaked 6 out of 10K times in a test run

prioritizing this for fixit week

arvindbr8 avatar Nov 28 '22 19:11 arvindbr8

https://github.com/grpc/grpc-go/actions/runs/4623084256/jobs/8176532401?pr=6164

easwars avatar Apr 05 '23 21:04 easwars

https://github.com/grpc/grpc-go/actions/runs/5754612753/job/15600281057?pr=6501#step:8:203

dfawley avatar Aug 03 '23 19:08 dfawley

I'll take a look at this as part of my channelz reworking.

dfawley avatar Sep 18 '23 23:09 dfawley