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: MetricsAndTracesOptionEnabled #8053

Open
arjan-bal opened this issue Jan 30, 2025 · 13 comments · May be fixed by #8077
Open

Flaky Test: MetricsAndTracesOptionEnabled #8053

arjan-bal opened this issue Jan 30, 2025 · 13 comments · May be fixed by #8077
Assignees
@purnesh42H
Labels
Area: Observability Includes Stats, Tracing, Channelz, Healthz, Binlog, Reflection, Admin, GCP Observability P1 Type: Bug

Comments

@arjan-bal
Copy link
Contributor

arjan-bal commented Jan 30, 2025 •
edited
Loading

Failure logs 
--- FAIL: Test (0.05s)
    --- FAIL: Test/MetricsAndTracesOptionEnabled (0.02s)
        tlogger.go:116: INFO server.go:685 [core] [Server #78]Server created  (t=+1.489331ms)
        tlogger.go:116: INFO clientconn.go:1659 [core] original dial target is: "whatever:///127.0.0.1:40059"  (t=+2.815239ms)
        tlogger.go:116: INFO clientconn.go:319 [core] [Channel #80]Channel created  (t=+2.890119ms)
        tlogger.go:116: INFO clientconn.go:193 [core] [Channel #80]parsed dial target is: resolver.Target{URL:url.URL{Scheme:"whatever", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/127.0.0.1:40059", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}}  (t=+3.028558ms)
        tlogger.go:116: INFO clientconn.go:194 [core] [Channel #80]Channel authority set to "127.0.0.1:40059"  (t=+3.088591ms)
        tlogger.go:116: INFO server.go:881 [core] [Server #78 ListenSocket #79]ListenSocket created  (t=+3.219637ms)
        tlogger.go:116: INFO clientconn.go:319 [core] [Channel #80]Channel exiting idle mode  (t=+3.279916ms)
        tlogger.go:116: INFO resolver_wrapper.go:210 [core] [Channel #80]Resolver state updated: {
              "Addresses": [
                {
                  "Addr": "127.0.0.1:40059",
                  "ServerName": "",
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Metadata": null
                }
              ],
              "Endpoints": [
                {
                  "Addresses": [
                    {
                      "Addr": "127.0.0.1:40059",
                      "ServerName": "",
                      "Attributes": null,
                      "BalancerAttributes": null,
                      "Metadata": null
                    }
                  ],
                  "Attributes": null
                }
              ],
              "ServiceConfig": null,
              "Attributes": null
            } (resolver returned new addresses)  (t=+3.476044ms)
        tlogger.go:116: INFO balancer_wrapper.go:117 [core] [Channel #80]Channel switches to new LB policy "pick_first"  (t=+3.600347ms)
        tlogger.go:116: INFO clientconn.go:843 [core] [Channel #80 SubChannel #81]Subchannel created  (t=+3.683543ms)
        tlogger.go:116: INFO clientconn.go:549 [core] [Channel #80]Channel Connectivity change to CONNECTING  (t=+3.743345ms)
        tlogger.go:116: INFO clientconn.go:1[204](https://github.com/grpc/grpc-go/actions/runs/13050755654/job/36410287206?pr=8052#step:8:205) [core] [Channel #80 SubChannel #81]Subchannel Connectivity change to CONNECTING  (t=+3.889919ms)
        tlogger.go:116: INFO clientconn.go:1324 [core] [Channel #80 SubChannel #81]Subchannel picks a new address "127.0.0.1:40059" to connect  (t=+3.966603ms)
        tlogger.go:116: INFO clientconn.go:1204 [core] [Channel #80 SubChannel #81]Subchannel Connectivity change to READY  (t=+4.59175ms)
        tlogger.go:116: INFO clientconn.go:549 [core] [Channel #80]Channel Connectivity change to READY  (t=+4.681948ms)
        e2e_test.go:890: Span name is "Attempt.grpc.testing.TestService.UnaryCall", want "grpc.testing.TestService.UnaryCall"
        e2e_test.go:894: Got span kind "internal", want "server"
        e2e_test.go:911: Got event name for span name "Attempt.grpc.testing.TestService.UnaryCall" as "Outbound compressed message", want "Inbound compressed message"
        e2e_test.go:911: Got event name for span name "Attempt.grpc.testing.TestService.UnaryCall" as "Inbound compressed message", want "Outbound compressed message"
        e2e_test.go:890: Span name is "grpc.testing.TestService.UnaryCall", want "Attempt.grpc.testing.TestService.UnaryCall"
        e2e_test.go:894: Got span kind "client", want "internal"
        e2e_test.go:898: Got attributes list of size '\x00', want '\x04'
        e2e_test.go:907: Event length is '\x00', want '\x02'
        e2e_test.go:894: Got span kind "server", want "client"
        e2e_test.go:898: Got attributes list of size '\x04', want '\x00'
        tlogger.go:116: INFO clientconn.go:549 [core] [Channel #80]Channel Connectivity change to SHUTDOWN  (t=+15.790665ms)
        tlogger.go:116: INFO resolver_wrapper.go:110 [core] [Channel #80]Closing the name resolver  (t=+15.850547ms)
        tlogger.go:116: INFO balancer_wrapper.go:155 [core] [Channel #80]ccBalancerWrapper: closing  (t=+15.928293ms)
        tlogger.go:116: INFO clientconn.go:1204 [core] [Channel #80 SubChannel #81]Subchannel Connectivity change to SHUTDOWN  (t=+16.056723ms)
        tlogger.go:116: INFO clientconn.go:1532 [core] [Channel #80 SubChannel #81]Subchannel deleted  (t=+16.128548ms)
        tlogger.go:116: INFO clientconn.go:319 [core] [Channel #80]Channel deleted  (t=+16.9[213](https://github.com/grpc/grpc-go/actions/runs/13050755654/job/36410287206?pr=8052#step:8:214)51ms)
        tlogger.go:116: INFO server.go:817 [core] [Server #78 ListenSocket #79]ListenSocket deleted  (t=+17.073196ms)
panic: runtime error: index out of range [0] with length 0 [recovered]
	panic: runtime error: index out of range [0] with length 0

goroutine 300 [running]:
testing.tRunner.func1.2({0x193cc40, 0xc0006400f0})
	/opt/hostedtoolcache/go/1.23.5/x64/src/testing/testing.go:1632 +0x3fc
testing.tRunner.func1()
	/opt/hostedtoolcache/go/1.23.5/x64/src/testing/testing.go:1635 +0x6b6
panic({0x193cc40?, 0xc0006400f0?})
	/opt/hostedtoolcache/go/1.23.5/x64/src/runtime/panic.go:785 +0x132
google.golang.org/grpc/stats/opentelemetry_test.s.TestMetricsAndTracesOptionEnabled({{}}, 0xc0000ead00)
	/home/runner/work/grpc-go/grpc-go/stats/opentelemetry/e2e_test.go:901 +0x41e5
google.golang.org/grpc/internal/grpctest.RunSubTests.func1(0xc0000ead00)
	/home/runner/work/grpc-go/grpc-go/internal/grpctest/grpctest.go:122 +0x10e
testing.tRunner(0xc0000ead00, 0xc0005f84a0)
	/opt/hostedtoolcache/go/1.23.5/x64/src/testing/testing.go:1690 +0x[227](https://github.com/grpc/grpc-go/actions/runs/13050755654/job/36410287206?pr=8052#step:8:228)
created by testing.(*T).Run in goroutine 283
	/opt/hostedtoolcache/go/1.23.5/x64/src/testing/testing.go:1743 +0x826
FAIL	google.golang.org/grpc/stats/opentelemetry	1.639s

Sample run: https://github.com/grpc/grpc-go/actions/runs/13050755654/job/36410287206?pr=8052
@arjan-bal arjan-bal added Area: Observability Includes Stats, Tracing, Channelz, Healthz, Binlog, Reflection, Admin, GCP Observability P1 Type: Bug labels Jan 30, 2025
@arjan-bal
Copy link
Contributor Author

This test was introduced recently in #7852

@pvsravani
Copy link
Contributor

https://github.com/grpc/grpc-go/actions/runs/13070785590/job/36471793421?pr=7907

@arjan-bal
Copy link
Contributor Author

https://github.com/grpc/grpc-go/actions/runs/13107321383/job/36564442258?pr=8052

@purnesh42H
Copy link
Contributor

https://github.com/grpc/grpc-go/actions/runs/13108699558/job/36567812574

@purnesh42H
Copy link
Contributor

https://github.com/grpc/grpc-go/actions/runs/13119957858/job/36603360818?pr=8050

@pvsravani
Copy link
Contributor

https://github.com/grpc/grpc-go/actions/runs/13154328469/job/36707920463?pr=7907

@arjan-bal
Copy link
Contributor Author

https://github.com/grpc/grpc-go/actions/runs/13172707955/job/36765790721?pr=8026

@arjan-bal
Copy link
Contributor Author

https://github.com/grpc/grpc-go/actions/runs/13180924503/job/36791224975?pr=8069

@arjan-bal
Copy link
Contributor Author

https://github.com/grpc/grpc-go/actions/runs/13260367403/job/37015380539?pr=8047

@purnesh42H purnesh42H linked a pull request Feb 11, 2025 that will close this issue
Open
@janardhanvissa
Copy link
Contributor

https://github.com/grpc/grpc-go/actions/runs/13313732140/job/37182480405

@easwars
Copy link
Contributor

easwars commented Feb 15, 2025

https://github.com/grpc/grpc-go/actions/runs/13339500904/job/37261539329?pr=8093

@janardhanvissa
Copy link
Contributor

https://github.com/grpc/grpc-go/actions/runs/13433651353/job/37530918710?pr=7967

@janardhanvissa
Copy link
Contributor

https://github.com/grpc/grpc-go/actions/runs/13451780771/job/37587379418?pr=8056

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@purnesh42H purnesh42H

Labels
Area: Observability Includes Stats, Tracing, Channelz, Healthz, Binlog, Reflection, Admin, GCP Observability P1 Type: Bug
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

stats/openetelemetry: refactor and make e2e test stats verification deterministic purnesh42H/grpc-go
5 participants
@easwars @purnesh42H @arjan-bal @janardhanvissa @pvsravani