grpc-go
grpc-go copied to clipboard
Published
20 hours ago •
grpc
grpc
[5/10k] Data race in Test/WithBackoffMaxDelay
--- FAIL: Test (29.60s)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #182] Channel Connectivity change to SHUTDOWN (t=+3.294277ms)
tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #182] Resolver state updated: {
"Addresses": null,
"ServiceConfig": {
"Config": {
"Config": null,
"LB": "round_robin",
"Methods": {}
},
"Err": null
},
"Attributes": null
} (service config updated) (t=+3.467581ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #183] Channel Connectivity change to SHUTDOWN (t=+3.521682ms)
tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #183] Channel deleted (t=+3.577883ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #184] Channel Connectivity change to SHUTDOWN (t=+3.707186ms)
tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #184] Channel deleted (t=+3.755787ms)
tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #185] Resolver state updated: {
"Addresses": null,
"ServiceConfig": {
"Config": {
"Config": null,
"LB": "round_robin",
"Methods": {}
},
"Err": null
},
"Attributes": null
} (service config updated) (t=+3.85809ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #185] Channel Connectivity change to SHUTDOWN (t=+3.915991ms)
tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #186] Resolver state updated: {
"Addresses": null,
"ServiceConfig": {
"Config": {
"Config": null,
"LB": "round_robin",
"Methods": {}
},
"Err": null
},
"Attributes": null
} (service config updated) (t=+4.146597ms)
tlogger.go:116: INFO balancer_conn_wrappers.go:274 [core] [Channel #186] Channel switches to new LB policy "round_robin" (t=+4.416703ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #186] Channel Connectivity change to TRANSIENT_FAILURE (t=+4.477604ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #186] Channel Connectivity change to SHUTDOWN (t=+4.847313ms)
tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #187] Resolver state updated: {
"Addresses": null,
"ServiceConfig": {
"Config": {
"Config": null,
"LB": "round_robin",
"Methods": {}
},
"Err": null
},
"Attributes": null
} (service config updated) (t=+4.965816ms)
tlogger.go:116: INFO balancer_conn_wrappers.go:274 [core] [Channel #187] Channel switches to new LB policy "round_robin" (t=+5.011617ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #187] Channel Connectivity change to TRANSIENT_FAILURE (t=+5.059318ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #187] Channel Connectivity change to SHUTDOWN (t=+5.098419ms)
tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #187] Channel deleted (t=+5.14392ms)
tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #188] Resolver state updated: {
"Addresses": null,
"ServiceConfig": {
"Config": {
"Config": null,
"LB": "round_robin",
"Methods": {}
},
"Err": null
},
"Attributes": null
} (service config updated) (t=+5.232622ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #188] Channel Connectivity change to SHUTDOWN (t=+5.271623ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #189] Channel Connectivity change to SHUTDOWN (t=+5.316424ms)
tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #189] Resolver state updated: {
"Addresses": null,
"ServiceConfig": {
"Config": {
"Config": null,
"LB": "round_robin",
"Methods": {}
},
"Err": null
},
"Attributes": null
} (service config updated) (t=+5.407626ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #190] Channel Connectivity change to SHUTDOWN (t=+5.449727ms)
tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #190] Resolver state updated: {
"Addresses": null,
"ServiceConfig": {
"Config": {
"Config": null,
"LB": "round_robin",
"Methods": {}
},
"Err": null
},
"Attributes": null
} (service config updated) (t=+5.556329ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #191] Channel Connectivity change to SHUTDOWN (t=+5.59573ms)
tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #191] Resolver state updated: {
"Addresses": null,
"ServiceConfig": {
"Config": {
"Config": null,
"LB": "round_robin",
"Methods": {}
},
"Err": null
},
"Attributes": null
} (service config updated) (t=+5.704333ms)
tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #185] Channel deleted (t=+5.7913[35](https://github.com/grpc/grpc-go/actions/runs/3963019517/jobs/6790383696#step:8:36)ms)
tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #186] Channel deleted (t=+6.049941ms)
tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #188] Channel deleted (t=+6.083842ms)
tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #189] Channel deleted (t=+6.116843ms)
tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #191] Channel deleted (t=+6.147343ms)
--- FAIL: Test/WithBackoffMaxDelay (10.03s)
tlogger.go:116: INFO clientconn.go:105 [core] [Channel #203] Channel created (t=+62.601µs)
tlogger.go:116: INFO clientconn.go:1552 [core] [Channel #203] original dial target is: "passthrough:///foo:80" (t=+119.603µs)
tlogger.go:116: INFO clientconn.go:1559 [core] [Channel #203] parsed dial target is: {Scheme:passthrough Authority: Endpoint:foo:80 URL:{Scheme:passthrough Opaque: User: Host: Path:/foo:80 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}} (t=+182.204µs)
tlogger.go:116: INFO clientconn.go:263 [core] [Channel #203] Channel authority set to "foo:80" (t=+217.205µs)
tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #203] Resolver state updated: {
"Addresses": [
{
"Addr": "foo:80",
"ServerName": "",
"Attributes": null,
"BalancerAttributes": null,
"Type": 0,
"Metadata": null
}
],
"ServiceConfig": null,
"Attributes": null
} (resolver returned new addresses) (t=+343.008µs)
tlogger.go:116: INFO balancer_conn_wrappers.go:274 [core] [Channel #203] Channel switches to new LB policy "pick_first" (t=+603.014µs)
tlogger.go:116: INFO clientconn.go:725 [core] [Channel #203 SubChannel #204] Subchannel created (t=+878.92µs)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #203] Channel Connectivity change to CONNECTING (t=+915.021µs)
tlogger.go:116: INFO clientconn.go:1106 [core] [Channel #203 SubChannel #204] Subchannel Connectivity change to CONNECTING (t=+957.522µs)
tlogger.go:116: INFO clientconn.go:1217 [core] [Channel #203 SubChannel #204] Subchannel picks a new address "foo:80" to connect (t=+1.000723ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #203] Channel Connectivity change to SHUTDOWN (t=+1.101726ms)
tlogger.go:116: INFO clientconn.go:1106 [core] [Channel #203 SubChannel #204] Subchannel Connectivity change to SHUTDOWN (t=+1.170227ms)
tlogger.go:116: INFO clientconn.go:1430 [core] [Channel #203 SubChannel #204] Subchannel deleted (t=+1.214828ms)
tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #203] Channel deleted (t=+1.242329ms)
tlogger.go:116: WARNING clientconn.go:1278 [core] [Channel #203 SubChannel #204] grpc: addrConn.createTransport failed to connect to {
"Addr": "foo:80",
"ServerName": "foo:80",
"Attributes": null,
"BalancerAttributes": null,
"Type": 0,
"Metadata": null
}. Err: connection error: desc = "transport: Error while dialing: dial tcp: lookup foo: operation was canceled" (t=+2.056348ms)
grpctest.go:39: Leaked goroutine: goroutine 584 [syscall]:
net._C2func_getaddrinfo(0xc00017e97c, 0x0, 0xc000127260, 0xc000014080)
_cgo_gotypes.go:94 +0x8b
net.cgoLookupIPCNAME.func1({0xc00017e97c, 0x4, 0xcdf719?}, 0x4a7259?, 0x4a8977?)
/opt/hostedtoolcache/go/1.19.5/x64/src/net/cgo_unix.go:160 +0xb2
net.cgoLookupIPCNAME({0xcd2cd7, 0x3}, {0xcdf719, 0x3})
/opt/hostedtoolcache/go/1.19.5/x64/src/net/cgo_unix.go:160 +0x27d
net.cgoIPLookup(0x11a44f0?, {0xcd2cd7, 0x3}, {0xcdf719, 0x3})
/opt/hostedtoolcache/go/1.19.5/x64/src/net/cgo_unix.go:217 +0x67
created by net.cgoLookupIP
/opt/hostedtoolcache/go/1.19.5/x64/src/net/cgo_unix.go:227 +0x1c5
grpctest.go:60: Leak check disabled for future tests
tlogger.go:116: WARNING clientconn.go:1278 [core] [Channel #207 SubChannel #208] grpc: addrConn.createTransport failed to connect to {
"Addr": "Non-Existent.Server:80",
"ServerName": "Non-Existent.Server:80",
"Attributes": null,
"BalancerAttributes": null,
"Type": 0,
"Metadata": null
}. Err: connection error: desc = "transport: Error while dialing: dial tcp: lookup Non-Existent.Server: operation was canceled" (t=+1.982745ms)
tlogger.go:116: WARNING clientconn.go:1278 [core] [Channel #209 SubChannel #210] grpc: addrConn.createTransport failed to connect to {
"Addr": "Non-Existent.Server:80",
"ServerName": "x.test.example.com",
"Attributes": null,
"BalancerAttributes": null,
"Type": 0,
"Metadata": null
}. Err: connection error: desc = "transport: Error while dialing: dial tcp: lookup Non-Existent.Server: operation was canceled" (t=+1.860143ms)
==================
WARNING: DATA RACE
Read at 0x00c0005c06c3 by goroutine 1103:
testing.(*common).logDepth()
/opt/hostedtoolcache/go/1.19.5/x64/src/testing/testing.go:883 +0xc4
testing.(*common).log()
/opt/hostedtoolcache/go/1.19.5/x64/src/testing/testing.go:876 +0x84
testing.(*common).Log()
/opt/hostedtoolcache/go/1.19.5/x64/src/testing/testing.go:917 +0x5b
google.golang.org/grpc/internal/grpctest.(*tLogger).log()
/home/runner/work/grpc-go/grpc-go/internal/grpctest/tlogger.go:116 +0x4a9
google.golang.org/grpc/internal/grpctest.(*tLogger).WarningDepth()
/home/runner/work/grpc-go/grpc-go/internal/grpctest/tlogger.go:226 +0x64
google.golang.org/grpc/internal/grpclog.WarningDepth()
/home/runner/work/grpc-go/grpc-go/internal/grpclog/grpclog.go:44 +0x85
google.golang.org/grpc/grpclog.(*componentData).WarningDepth()
/home/runner/work/grpc-go/grpc-go/grpclog/component.go:41 +0x16b
google.golang.org/grpc/internal/channelz.AddTraceEvent()
/home/runner/work/grpc-go/grpc-go/internal/channelz/funcs.go:342 +0x2f8
google.golang.org/grpc/internal/channelz.Warningf()
/home/runner/work/grpc-go/grpc-go/internal/channelz/logging.go:59 +0xd3
google.golang.org/grpc.(*addrConn).createTransport()
/home/runner/work/grpc-go/grpc-go/clientconn.go:1278 +0x865
google.golang.org/grpc.(*addrConn).tryAllAddrs()
/home/runner/work/grpc-go/grpc-go/clientconn.go:1219 +0x557
google.golang.org/grpc.(*addrConn).resetTransport()
/home/runner/work/grpc-go/grpc-go/clientconn.go:1154 +0x217
google.golang.org/grpc.(*addrConn).connect()
/home/runner/work/grpc-go/grpc-go/clientconn.go:809 +0x258
google.golang.org/grpc.(*acBalancerWrapper).Connect.func2()
/home/runner/work/grpc-go/grpc-go/balancer_conn_wrappers.go:413 +0x39
Previous write at 0x00c0005c06c3 by goroutine 933:
testing.tRunner.func1()
/opt/hostedtoolcache/go/1.19.5/x64/src/testing/testing.go:1433 +0x7e4
runtime.deferreturn()
/opt/hostedtoolcache/go/1.19.5/x64/src/runtime/panic.go:476 +0x32
testing.(*T).Run.func1()
/opt/hostedtoolcache/go/1.19.5/x64/src/testing/testing.go:1493 +0x47
Goroutine 1103 (running) created at:
google.golang.org/grpc.(*acBalancerWrapper).Connect()
/home/runner/work/grpc-go/grpc-go/balancer_conn_wrappers.go:413 +0x116
google.golang.org/grpc.(*pickfirstBalancer).UpdateClientConnState()
/home/runner/work/grpc-go/grpc-go/pickfirst.go:108 +0x6e1
google.golang.org/grpc/internal/balancer/gracefulswitch.(*Balancer).UpdateClientConnState()
/home/runner/work/grpc-go/grpc-go/internal/balancer/gracefulswitch/gracefulswitch.go:164 +0x10d
google.golang.org/grpc.(*ccBalancerWrapper).handleClientConnStateChange()
/home/runner/work/grpc-go/grpc-go/balancer_conn_wrappers.go:192 +0x2c8
google.golang.org/grpc.(*ccBalancerWrapper).watcher()
/home/runner/work/grpc-go/grpc-go/balancer_conn_wrappers.go:123 +0x419
google.golang.org/grpc.newCCBalancerWrapper.func1()
/home/runner/work/grpc-go/grpc-go/balancer_conn_wrappers.go:76 +0x39
Goroutine 933 (finished) created at:
testing.(*T).Run()
/opt/hostedtoolcache/go/1.19.5/x64/src/testing/testing.go:1493 +0x75d
google.golang.org/grpc/internal/grpctest.RunSubTests()
/home/runner/work/grpc-go/grpc-go/internal/grpctest/grpctest.go:101 +0x50e
google.golang.org/grpc.Test()
/home/runner/work/grpc-go/grpc-go/grpc_test.go:32 +0x3c
testing.tRunner()
/opt/hostedtoolcache/go/1.19.5/x64/src/testing/testing.go:1446 +0x216
testing.(*T).Run.func1()
/opt/hostedtoolcache/go/1.19.5/x64/src/testing/testing.go:1493 +0x47
==================
--- FAIL: Test (13.65s)
tlogger.go:116: WARNING clientconn.go:1278 [core] [Channel #251 SubChannel #252] grpc: addrConn.createTransport failed to connect to {
"Addr": "foo:80",
"ServerName": "foo:80",
"Attributes": null,
"BalancerAttributes": null,
"Type": 0,
"Metadata": null
}. Err: connection error: desc = "transport: Error while dialing: dial tcp: lookup foo: operation was canceled" (t=+960.02µs)
tlogger.go:116: WARNING clientconn.go:1278 [core] [Channel #271 SubChannel #272] grpc: addrConn.createTransport failed to connect to {
"Addr": "127.0.0.1:34471",
"ServerName": "127.0.0.1:34471",
"Attributes": null,
"BalancerAttributes": null,
"Type": 0,
"Metadata": null
}. Err: connection error: desc = "error reading server preface: read tcp 127.0.0.1:46986->127.0.0.1:34471: use of closed network connection" (t=+1.00185017s)
tlogger.go:116: WARNING clientconn.go:1278 [core] [Channel #284 SubChannel #285] grpc: addrConn.createTransport failed to connect to {
"Addr": "127.0.0.1:42283",
"ServerName": "this-gets-overwritten",
"Attributes": null,
"BalancerAttributes": null,
"Type": 0,
"Metadata": null
}. Err: write tcp 127.0.0.1:47056->127.0.0.1:42283: write: broken pipe (t=+1.786238ms)
tlogger.go:116: WARNING clientconn.go:1278 [core] [Channel #[36](https://github.com/grpc/grpc-go/actions/runs/3963019517/jobs/6790383696#step:8:37)6 SubChannel #367] grpc: addrConn.createTransport failed to connect to {
"Addr": "unregistered:/a/b/c",
"ServerName": "unregistered:/a/b/c",
"Attributes": null,
"BalancerAttributes": null,
"Type": 0,
"Metadata": null
}. Err: connection error: desc = "transport: Error while dialing: dial tcp: address tcp//a/b/c: unknown port" (t=+44.953528ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #400] Channel Connectivity change to SHUTDOWN (t=+2.85414ms)
tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #401] Resolver state updated: {
"Addresses": null,
"ServiceConfig": {
"Config": {
"Config": null,
"LB": "round_robin",
"Methods": {}
},
"Err": null
},
"Attributes": null
} (service config updated) (t=+2.982342ms)
tlogger.go:116: INFO balancer_conn_wrappers.go:274 [core] [Channel #401] Channel switches to new LB policy "round_robin" (t=+3.034842ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #401] Channel Connectivity change to TRANSIENT_FAILURE (t=+3.095043ms)
tlogger.go:116: INFO clientconn.go:418 [core] [Channel #401] Channel Connectivity change to SHUTDOWN (t=+3.1[38](https://github.com/grpc/grpc-go/actions/runs/3963019517/jobs/6790383696#step:8:39)444ms)
tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #[39](https://github.com/grpc/grpc-go/actions/runs/3963019517/jobs/6790383696#step:8:40)6] Channel deleted (t=+98.701µs)
tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #[40](https://github.com/grpc/grpc-go/actions/runs/3963019517/jobs/6790383696#step:8:41)0] Channel deleted (t=+139.502µs)
tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #398] Channel deleted (t=+200.803µs)
tlogger.go:116: INFO clientconn.go:1061 [core] [Channel #401] Channel deleted (t=+230.603µs)
tlogger.go:116: WARNING clientconn.go:1278 [core] [Channel #403 SubChannel #404] grpc: addrConn.createTransport failed to connect to {
"Addr": "127.0.0.1:40095",
"ServerName": "this-gets-overwritten",
"Attributes": null,
"BalancerAttributes": null,
"Type": 0,
"Metadata": null
}. Err: connection error: desc = "error reading server preface: read tcp 127.0.0.1:[41](https://github.com/grpc/grpc-go/actions/runs/3963019517/jobs/6790383696#step:8:42)994->127.0.0.1:40095: use of closed network connection" (t=+3.516649ms)
tlogger.go:116: WARNING clientconn.go:1278 [core] [Channel #415 SubChannel #416] grpc: addrConn.createTransport failed to connect to {
"Addr": "foo:80",
"ServerName": "foo:80",
"Attributes": null,
"BalancerAttributes": null,
"Type": 0,
"Metadata": null
}. Err: connection error: desc = "transport: Error while dialing: dial tcp: lookup foo: operation was canceled" (t=+6.130685ms)
tlogger.go:116: WARNING clientconn.go:1278 [core] [Channel #419 SubChannel #[42](https://github.com/grpc/grpc-go/actions/runs/3963019517/jobs/6790383696#step:8:43)0] grpc: addrConn.createTransport failed to connect to {
"Addr": "Non-Existent.Server:80",
"ServerName": "x.test.example.com",
"Attributes": null,
"BalancerAttributes": null,
"Type": 0,
"Metadata": null
}. Err: connection error: desc = "transport: Error while dialing: dial tcp: lookup Non-Existent.Server: operation was canceled" (t=+1.503321ms)
testing.go:1319: race detected during execution of test
FAIL
FAIL google.golang.org/grpc
https://github.com/grpc/grpc-go/actions/runs/3963019517/jobs/6790383696
I see a write in a panic goroutine and a read in the same testing goroutine calling log. So I think the root cause for this is the panic itself.
