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

[Test] TestLeasingReconnectNonOwnerGet timeout #14487

Closed
fuweid opened this issue Sep 18, 2022 · 2 comments · Fixed by #14834
Closed

[Test] TestLeasingReconnectNonOwnerGet timeout #14487

fuweid opened this issue Sep 18, 2022 · 2 comments · Fixed by #14834
Labels
help wanted type/flake

Comments

@fuweid
Copy link
Contributor

fuweid commented Sep 18, 2022 •
edited

Which github workflows are flaking?

test (linux-amd64-integration-4-cpu)

Which tests are flaking?

TestLeasingReconnectNonOwnerGet

Github Action link

https://github.com/etcd-io/etcd/actions/runs/3071777532/jobs/4963526956

Reason for failure (if possible)

=== Failed
=== FAIL: integration/clientv3/lease TestLeasingReconnectNonOwnerGet (unknown)
    cluster.go:533: Creating listener with addr: 127.0.0.1:2125406054
    cluster.go:533: Creating listener with addr: 127.0.0.1:2125506054
    logger.go:130: 2022-09-17T05:24:30.555Z	INFO	m0	LISTEN GRPC	{"member": "m0", "grpcAddr": "localhost:m0", "m.Name": "m0", "workdir": "/tmp/TestLeasingReconnectNonOwnerGet2462777176/001"}
    logger.go:130: 2022-09-17T05:24:30.555Z	INFO	m0	LISTEN BRIDGE	{"member": "m0", "grpc-address": "localhost:m00", "member": "m0"}
    cluster.go:217: Launching new cluster...
    logger.go:130: 2022-09-17T05:24:30.555Z	INFO	m0	launching a member	{"member": "m0", "name": "m0", "advertise-peer-urls": ["unix://127.0.0.1:2125406054"], "listen-client-urls": ["unix://127.0.0.1:2125506054"], "grpc-url": "unix://localhost:m00"}
    logger.go:130: 2022-09-17T05:24:30.556Z	INFO	m0	opened backend db	{"member": "m0", "path": "/tmp/TestLeasingReconnectNonOwnerGet2462777176/002/etcd3822453242/member/snap/db", "took": "886.412µs"}
    logger.go:130: 2022-09-17T05:24:30.558Z	INFO	m0	starting local member	{"member": "m0", "local-member-id": "816de54200e25e04", "cluster-id": "585b247855404513"}
    logger.go:130: 2022-09-17T05:24:30.558Z	INFO	m0.raft	816de54200e25e04 switched to configuration voters=()	{"member": "m0"}
    logger.go:130: 2022-09-17T05:24:30.558Z	INFO	m0.raft	816de54200e25e04 became follower at term 0	{"member": "m0"}
    logger.go:130: 2022-09-17T05:24:30.558Z	INFO	m0.raft	newRaft 816de54200e25e04 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]	{"member": "m0"}
    logger.go:130: 2022-09-17T05:24:30.559Z	INFO	m0.raft	816de54200e25e04 became follower at term 1	{"member": "m0"}
    logger.go:130: 2022-09-17T05:24:30.559Z	INFO	m0.raft	816de54200e25e04 switched to configuration voters=(9326362474999602692)	{"member": "m0"}
    logger.go:130: 2022-09-17T05:24:30.560Z	WARN	m0	simple token is not cryptographically signed	{"member": "m0"}
    logger.go:130: 2022-09-17T05:24:30.561Z	INFO	m0	kvstore restored	{"member": "m0", "current-rev": 1}
    logger.go:130: 2022-09-17T05:24:30.562Z	INFO	m0	starting etcd server	{"member": "m0", "local-member-id": "816de54200e25e04", "local-server-version": "3.6.0-alpha.0", "cluster-version": "to_be_decided"}
    logger.go:130: 2022-09-17T05:24:30.562Z	INFO	grpc	[[core] [Server #597] Server created]
    logger.go:130: 2022-09-17T05:24:30.562Z	INFO	m0	started as single-node; fast-forwarding election ticks	{"member": "m0", "local-member-id": "816de54200e25e04", "forward-ticks": 9, "forward-duration": "90ms", "election-ticks": 10, "election-timeout": "100ms"}
    logger.go:130: 2022-09-17T05:24:30.562Z	INFO	grpc	[[core] [Channel #598] Channel created]
    logger.go:130: 2022-09-17T05:24:30.562Z	INFO	grpc	[[core] [Channel #598] original dial target is: "etcd-endpoints://0xc000533c20/localhost:m00"]
    logger.go:130: 2022-09-17T05:24:30.562Z	INFO	grpc	[[core] [Channel #598] parsed dial target is: {Scheme:etcd-endpoints Authority:0xc000533c20 Endpoint:localhost:m00 URL:{Scheme:etcd-endpoints Opaque: User: Host:0xc000533c20 Path:/localhost:m00 RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}]
    logger.go:130: 2022-09-17T05:24:30.562Z	INFO	grpc	[[core] [Channel #598] Channel authority set to "localhost:m00"]
    logger.go:130: 2022-09-17T05:24:30.562Z	INFO	grpc	[[core] [Channel #598] Resolver state updated: {
          "Addresses": [
            {
              "Addr": "unix:localhost:m00",
              "ServerName": "localhost",
              "Attributes": null,
              "BalancerAttributes": null,
              "Type": 0,
              "Metadata": null
            }
          ],
          "ServiceConfig": {
            "Config": {
              "Config": null,
              "LB": "round_robin",
              "Methods": {}
            },
            "Err": null
          },
          "Attributes": null
        } (service config updated; resolver returned new addresses)]
    logger.go:130: 2022-09-17T05:24:30.562Z	INFO	grpc	[[core] [Channel #598] Channel switches to new LB policy "round_robin"]
    logger.go:130: 2022-09-17T05:24:30.562Z	INFO	grpc	[[balancer] base.baseBalancer: got new ClientConn state:  {{[{
          "Addr": "unix:localhost:m00",
          "ServerName": "localhost",
          "Attributes": null,
          "BalancerAttributes": null,
          "Type": 0,
          "Metadata": null
        }] 0xc00170a960 <nil>} <nil>}]
    logger.go:130: 2022-09-17T05:24:30.562Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel created]
    logger.go:130: 2022-09-17T05:24:30.562Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.562Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel picks a new address "unix:localhost:m00" to connect]
    logger.go:130: 2022-09-17T05:24:30.563Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.563Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.563Z	INFO	m0.raft	816de54200e25e04 switched to configuration voters=(9326362474999602692)	{"member": "m0"}
    logger.go:130: 2022-09-17T05:24:30.563Z	INFO	m0	added member	{"member": "m0", "cluster-id": "585b247855404513", "local-member-id": "816de54200e25e04", "added-peer-id": "816de54200e25e04", "added-peer-peer-urls": ["unix://127.0.0.1:2125406054"], "added-peer-is-learner": false}
    logger.go:130: 2022-09-17T05:24:30.564Z	INFO	grpc	[[core] [Server #597 ListenSocket #599] ListenSocket created]
    logger.go:130: 2022-09-17T05:24:30.564Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to READY]
    logger.go:130: 2022-09-17T05:24:30.564Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, READY]
    logger.go:130: 2022-09-17T05:24:30.564Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[0xc00155f7d0:{{
          "Addr": "unix:localhost:m00",
          "ServerName": "localhost",
          "Attributes": null,
          "BalancerAttributes": null,
          "Type": 0,
          "Metadata": null
        }}]}]
    logger.go:130: 2022-09-17T05:24:30.564Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to READY]
    logger.go:130: 2022-09-17T05:24:30.564Z	INFO	m0	launched a member	{"member": "m0", "name": "m0", "advertise-peer-urls": ["unix://127.0.0.1:2125406054"], "listen-client-urls": ["unix://127.0.0.1:2125506054"], "grpc-url": "unix://localhost:m00"}
    logger.go:130: 2022-09-17T05:24:30.569Z	INFO	m0.raft	816de54200e25e04 is starting a new election at term 1	{"member": "m0"}
    logger.go:130: 2022-09-17T05:24:30.569Z	INFO	m0.raft	816de54200e25e04 became candidate at term 2	{"member": "m0"}
    logger.go:130: 2022-09-17T05:24:30.569Z	INFO	m0.raft	816de54200e25e04 received MsgVoteResp from 816de54200e25e04 at term 2	{"member": "m0"}
    logger.go:130: 2022-09-17T05:24:30.569Z	INFO	m0.raft	816de54200e25e04 became leader at term 2	{"member": "m0"}
    logger.go:130: 2022-09-17T05:24:30.569Z	INFO	m0.raft	raft.node: 816de54200e25e04 elected leader 816de54200e25e04 at term 2	{"member": "m0"}
    logger.go:130: 2022-09-17T05:24:30.569Z	INFO	m0	setting up initial cluster version using v3 API	{"member": "m0", "cluster-version": "3.6"}
    logger.go:130: 2022-09-17T05:24:30.569Z	INFO	m0	published local member to cluster through raft	{"member": "m0", "local-member-id": "816de54200e25e04", "local-member-attributes": "{Name:m0 ClientURLs:[unix://127.0.0.1:2125506054]}", "cluster-id": "585b247855404513", "publish-timeout": "5.2s"}
    logger.go:130: 2022-09-17T05:24:30.569Z	INFO	m0	set initial cluster version	{"member": "m0", "cluster-id": "585b247855404513", "local-member-id": "816de54200e25e04", "cluster-version": "3.6"}
    logger.go:130: 2022-09-17T05:24:30.570Z	INFO	m0	cluster version is updated	{"member": "m0", "cluster-version": "3.6"}
    logger.go:130: 2022-09-17T05:24:30.570Z	WARN	m0	Failed to detect schema version	{"member": "m0", "error": "missing confstate information"}
    logger.go:130: 2022-09-17T05:24:30.570Z	ERROR	m0	failed to update storage version	{"member": "m0", "cluster-version": "3.6.0", "error": "cannot detect storage schema version: missing confstate information"}
    cluster.go:236:  - m0 -> 816de54200e25e04 (unix://localhost:m00)
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.581Z	WARN	m0.client	retrying of unary invoker failed	{"member": "m0", "target": "etcd-endpoints://0xc000533c20/localhost:m00", "method": "/etcdserverpb.KV/Txn", "attempt": 0, "error": "rpc error: code = Unavailable desc = error reading from server: read unix @->localhost:m00: read: connection reset by peer"}
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[core] blockingPicker: the picked transport is not ready, loop back to repick]
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, IDLE]
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[]}]
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel picks a new address "unix:localhost:m00" to connect]
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to READY]
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, READY]
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[0xc00155f7d0:{{
          "Addr": "unix:localhost:m00",
          "ServerName": "localhost",
          "Attributes": null,
          "BalancerAttributes": null,
          "Type": 0,
          "Metadata": null
        }}]}]
    logger.go:130: 2022-09-17T05:24:30.581Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to READY]
    logger.go:130: 2022-09-17T05:24:30.582Z	WARN	grpc	[[core] [Server #597] grpc: Server.processUnaryRPC failed to write status: connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.582Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.582Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.582Z	WARN	m0.client	retrying of unary invoker failed	{"member": "m0", "target": "etcd-endpoints://0xc000533c20/localhost:m00", "method": "/etcdserverpb.KV/Txn", "attempt": 0, "error": "rpc error: code = Unavailable desc = error reading from server: EOF"}
    logger.go:130: 2022-09-17T05:24:30.582Z	INFO	grpc	[[core] blockingPicker: the picked transport is not ready, loop back to repick]
    logger.go:130: 2022-09-17T05:24:30.582Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, IDLE]
    logger.go:130: 2022-09-17T05:24:30.582Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[]}]
    logger.go:130: 2022-09-17T05:24:30.582Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.582Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.582Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.582Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel picks a new address "unix:localhost:m00" to connect]
    logger.go:130: 2022-09-17T05:24:30.582Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.582Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.583Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to READY]
    logger.go:130: 2022-09-17T05:24:30.583Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, READY]
    logger.go:130: 2022-09-17T05:24:30.583Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[0xc00155f7d0:{{
          "Addr": "unix:localhost:m00",
          "ServerName": "localhost",
          "Attributes": null,
          "BalancerAttributes": null,
          "Type": 0,
          "Metadata": null
        }}]}]
    logger.go:130: 2022-09-17T05:24:30.583Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to READY]
    logger.go:130: 2022-09-17T05:24:30.584Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.584Z	WARN	m0.client	retrying of unary invoker failed	{"member": "m0", "target": "etcd-endpoints://0xc000533c20/localhost:m00", "method": "/etcdserverpb.KV/Txn", "attempt": 0, "error": "rpc error: code = Unavailable desc = error reading from server: EOF"}
    logger.go:130: 2022-09-17T05:24:30.584Z	INFO	grpc	[[core] blockingPicker: the picked transport is not ready, loop back to repick]
    logger.go:130: 2022-09-17T05:24:30.584Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, IDLE]
    logger.go:130: 2022-09-17T05:24:30.584Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[]}]
    logger.go:130: 2022-09-17T05:24:30.584Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.584Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.584Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.584Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel picks a new address "unix:localhost:m00" to connect]
    logger.go:130: 2022-09-17T05:24:30.584Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.584Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.584Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to READY]
    logger.go:130: 2022-09-17T05:24:30.584Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, READY]
    logger.go:130: 2022-09-17T05:24:30.584Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[0xc00155f7d0:{{
          "Addr": "unix:localhost:m00",
          "ServerName": "localhost",
          "Attributes": null,
          "BalancerAttributes": null,
          "Type": 0,
          "Metadata": null
        }}]}]
    logger.go:130: 2022-09-17T05:24:30.584Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to READY]
    logger.go:130: 2022-09-17T05:24:30.585Z	WARN	grpc	[[core] [Server #597] grpc: Server.processUnaryRPC failed to write status: connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.585Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.585Z	WARN	m0.client	retrying of unary invoker failed	{"member": "m0", "target": "etcd-endpoints://0xc000533c20/localhost:m00", "method": "/etcdserverpb.KV/Txn", "attempt": 0, "error": "rpc error: code = Unavailable desc = error reading from server: EOF"}
    logger.go:130: 2022-09-17T05:24:30.585Z	INFO	grpc	[[core] blockingPicker: the picked transport is not ready, loop back to repick]
    logger.go:130: 2022-09-17T05:24:30.585Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.585Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, IDLE]
    logger.go:130: 2022-09-17T05:24:30.585Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[]}]
    logger.go:130: 2022-09-17T05:24:30.585Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.585Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.585Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.585Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel picks a new address "unix:localhost:m00" to connect]
    logger.go:130: 2022-09-17T05:24:30.585Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.585Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.586Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.586Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to READY]
    logger.go:130: 2022-09-17T05:24:30.587Z	WARN	grpc	[[core] [Server #597] grpc: Server.processUnaryRPC failed to write status: connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, READY]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[0xc00155f7d0:{{
          "Addr": "unix:localhost:m00",
          "ServerName": "localhost",
          "Attributes": null,
          "BalancerAttributes": null,
          "Type": 0,
          "Metadata": null
        }}]}]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to READY]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, IDLE]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[]}]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel picks a new address "unix:localhost:m00" to connect]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[core] blockingPicker: the picked transport is not ready, loop back to repick]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.587Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to READY]
    logger.go:130: 2022-09-17T05:24:30.588Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, READY]
    logger.go:130: 2022-09-17T05:24:30.588Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[0xc00155f7d0:{{
          "Addr": "unix:localhost:m00",
          "ServerName": "localhost",
          "Attributes": null,
          "BalancerAttributes": null,
          "Type": 0,
          "Metadata": null
        }}]}]
    logger.go:130: 2022-09-17T05:24:30.588Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to READY]
    logger.go:130: 2022-09-17T05:24:30.588Z	WARN	grpc	[[core] [Server #597] grpc: Server.processUnaryRPC failed to write status: connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.588Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.589Z	WARN	m0.client	retrying of unary invoker failed	{"member": "m0", "target": "etcd-endpoints://0xc000533c20/localhost:m00", "method": "/etcdserverpb.KV/Txn", "attempt": 0, "error": "rpc error: code = Unavailable desc = error reading from server: EOF"}
    logger.go:130: 2022-09-17T05:24:30.589Z	INFO	grpc	[[core] blockingPicker: the picked transport is not ready, loop back to repick]
    logger.go:130: 2022-09-17T05:24:30.589Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.589Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, IDLE]
    logger.go:130: 2022-09-17T05:24:30.589Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[]}]
    logger.go:130: 2022-09-17T05:24:30.589Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.589Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.589Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.589Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel picks a new address "unix:localhost:m00" to connect]
    logger.go:130: 2022-09-17T05:24:30.589Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.590Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.589Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to READY]
    logger.go:130: 2022-09-17T05:24:30.590Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.590Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.590Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.590Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, READY]
    logger.go:130: 2022-09-17T05:24:30.590Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[0xc00155f7d0:{{
          "Addr": "unix:localhost:m00",
          "ServerName": "localhost",
          "Attributes": null,
          "BalancerAttributes": null,
          "Type": 0,
          "Metadata": null
        }}]}]
    logger.go:130: 2022-09-17T05:24:30.590Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to READY]
    logger.go:130: 2022-09-17T05:24:30.590Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, IDLE]
    logger.go:130: 2022-09-17T05:24:30.590Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[]}]
    logger.go:130: 2022-09-17T05:24:30.590Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.590Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.590Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel picks a new address "unix:localhost:m00" to connect]
    logger.go:130: 2022-09-17T05:24:30.590Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.591Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.591Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.591Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.591Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.591Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, IDLE]
    logger.go:130: 2022-09-17T05:24:30.591Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to IDLE]
    logger.go:130: 2022-09-17T05:24:30.591Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.591Z	INFO	grpc	[[core] [Channel #598 SubChannel #600] Subchannel picks a new address "unix:localhost:m00" to connect]
    logger.go:130: 2022-09-17T05:24:30.591Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00155f7d0, CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.591Z	INFO	grpc	[[core] [Channel #598] Channel Connectivity change to CONNECTING]
    logger.go:130: 2022-09-17T05:24:30.592Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:30.592Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2022-09-17T05:24:34.570Z	INFO	m0	cluster version differs from storage version.	{"member": "m0", "cluster-version": "3.6.0", "storage-version": "3.5.0"}
    logger.go:130: 2022-09-17T05:24:34.571Z	INFO	m0	updated storage version	{"member": "m0", "new-storage-version": "3.6.0"}
    logger.go:130: 2022-09-17T05:25:30.634Z	ERROR	m0	failed to detach old lease from a key	{"member": "m0", "error": "lease not found"}
panic: test timed out after 15m0s

goroutine 14977 [running]:
testing.(*M).startAlarm.func1()
	/opt/hostedtoolcache/go/1.17.8/x64/src/testing/testing.go:1788 +0x8e
created by time.goFunc
	/opt/hostedtoolcache/go/1.17.8/x64/src/time/sleep.go:180 +0x31

goroutine 1 [chan receive, 14 minutes]:
testing.(*T).Run(0xc000097040, {0xf55fdc, 0x46ebb3}, 0xf8a828)
	/opt/hostedtoolcache/go/1.17.8/x64/src/testing/testing.go:1307 +0x375
testing.runTests.func1(0xc0005059e0)
	/opt/hostedtoolcache/go/1.17.8/x64/src/testing/testing.go:1598 +0x6e
testing.tRunner(0xc000097040, 0xc0005bfcc0)
	/opt/hostedtoolcache/go/1.17.8/x64/src/testing/testing.go:1259 +0x102
testing.runTests(0xc0001e6300, {0x17acce0, 0x41, 0x41}, {0xc0005bfd90, 0x40f0f4, 0x17bdd20})
	/opt/hostedtoolcache/go/1.17.8/x64/src/testing/testing.go:1596 +0x43f
testing.(*M).Run(0xc0001e6300)
	/opt/hostedtoolcache/go/1.17.8/x64/src/testing/testing.go:1504 +0x51d
go.etcd.io/etcd/client/pkg/v3/testutil.MustTestMainWithLeakDetection(0xc0000001a0)
	/home/runner/work/etcd/etcd/client/pkg/testutil/leak.go:176 +0x19
go.etcd.io/etcd/tests/v3/integration/clientv3/lease_test.TestMain(...)
	/home/runner/work/etcd/etcd/tests/integration/clientv3/lease/main_test.go:14
main.main()
	_testmain.go:175 +0x166

goroutine 14942 [select]:
go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).monitorStorageVersion(0xc0004b3c00)
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:2182 +0x132
go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).GoAttach.func1()
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:2403 +0x64
created by go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).GoAttach
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:2401 +0x117

goroutine 14910 [select]:
go.etcd.io/etcd/server/v3/etcdserver.(*raftNode).start.func1()
	/home/runner/work/etcd/etcd/server/etcdserver/raft.go:166 +0x185
created by go.etcd.io/etcd/server/v3/etcdserver.(*raftNode).start
	/home/runner/work/etcd/etcd/server/etcdserver/raft.go:161 +0x85

goroutine 14955 [select, 14 minutes]:
google.golang.org/grpc.(*ccBalancerWrapper).watcher(0xc000597940)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/balancer_conn_wrappers.go:112 +0x79
created by google.golang.org/grpc.newCCBalancerWrapper
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/balancer_conn_wrappers.go:73 +0x22f

goroutine 14900 [IO wait, 14 minutes]:
internal/poll.runtime_pollWait(0x7f991c576108, 0x72)
	/opt/hostedtoolcache/go/1.17.8/x64/src/runtime/netpoll.go:234 +0x89
internal/poll.(*pollDesc).wait(0xc000fa0c80, 0x1, 0x0)
	/opt/hostedtoolcache/go/1.17.8/x64/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/opt/hostedtoolcache/go/1.17.8/x64/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc000fa0c80)
	/opt/hostedtoolcache/go/1.17.8/x64/src/internal/poll/fd_unix.go:402 +0x22c
net.(*netFD).accept(0xc000fa0c80)
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/fd_unix.go:173 +0x35
net.(*UnixListener).accept(0xc00006fec0)
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/unixsock_posix.go:167 +0x1c
net.(*UnixListener).Accept(0xc000acd2c0)
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/unixsock.go:260 +0x3d
go.etcd.io/etcd/tests/v3/framework/integration.(*bridge).serveListen(0xc0004e7080)
	/home/runner/work/etcd/etcd/tests/framework/integration/bridge.go:107 +0x8d
created by go.etcd.io/etcd/tests/v3/framework/integration.newBridge
	/home/runner/work/etcd/etcd/tests/framework/integration/bridge.go:54 +0x1a7

goroutine 14903 [select]:
go.etcd.io/etcd/server/v3/storage/backend.(*backend).run(0xc000dc8240)
	/home/runner/work/etcd/etcd/server/storage/backend/backend.go:417 +0x10f
created by go.etcd.io/etcd/server/v3/storage/backend.newBackend
	/home/runner/work/etcd/etcd/server/storage/backend/backend.go:225 +0x5b0

goroutine 14905 [select]:
go.etcd.io/etcd/raft/v3.(*node).run(0xc0004e7c80)
	/home/runner/work/etcd/etcd/raft/node.go:344 +0x78a
created by go.etcd.io/etcd/raft/v3.StartNode
	/home/runner/work/etcd/etcd/raft/node.go:233 +0x359

goroutine 14907 [select]:
go.etcd.io/etcd/server/v3/lease.(*lessor).runLoop(0xc000dc83c0)
	/home/runner/work/etcd/etcd/server/lease/lessor.go:613 +0xd2
created by go.etcd.io/etcd/server/v3/lease.newLessor
	/home/runner/work/etcd/etcd/server/lease/lessor.go:234 +0x373

goroutine 14858 [select, 14 minutes]:
google.golang.org/grpc.(*pickerWrapper).pick(0xc000accf60, {0x10a48d8, 0xc000acdd40}, 0x0, {{0xf543af, 0x0}, {0x10a48d8, 0xc000acdd40}})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/picker_wrapper.go:103 +0x21b
google.golang.org/grpc.(*ClientConn).getTransport(0x26, {0x10a48d8, 0xc000acdd40}, 0xb8, {0xf543af, 0xf543af})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/clientconn.go:929 +0x35
google.golang.org/grpc.(*csAttempt).getTransport(0xc0009502c0)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:430 +0x48
google.golang.org/grpc.newClientStreamWithParams.func2(0xc0009502c0)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:315 +0x2b
google.golang.org/grpc.(*clientStream).withRetry(0xc000676000, 0xc00155e540, 0xc00064b700)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:709 +0xd3
google.golang.org/grpc.newClientStreamWithParams({0x10a48d8, 0xc000acdbf0}, 0x17b7260, 0xc000259c00, {0xf543af, 0x7e6700}, {0x0, 0x0, 0x0, 0x0, ...}, ...)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:327 +0x9ce
google.golang.org/grpc.newClientStream.func2({0x10a48d8, 0xc000acdbf0}, 0xc000acdbf0)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:192 +0x9f
google.golang.org/grpc.newClientStream({0x10a48d8, 0xc000acdbf0}, 0x17b7260, 0xc000259c00, {0xf543af, 0xc0004e08f0}, {0xc0002aec80, 0x3, 0x4})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:220 +0x4bf
google.golang.org/grpc.invoke({0x10a48d8, 0xc000acdbf0}, {0xf543af, 0x3030303063783028}, {0xef3ae0, 0xc000acdb90}, {0xefe040, 0xc000cf7310}, 0x6d6f682f090a2930, {0xc0002aec80, ...})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/call.go:66 +0x7d
go.etcd.io/etcd/client/v3.(*Client).unaryClientInterceptor.func1({0x10a4830, 0xc000597800}, {0xf543af, 0x1e}, {0xef3ae0, 0xc000acdb90}, {0xefe040, 0xc000cf7310}, 0xc000259c00, 0xf8abb8, ...)
	/home/runner/work/etcd/etcd/client/v3/retry_interceptor.go:60 +0x50a
google.golang.org/grpc.(*ClientConn).Invoke(0x60, {0x10a4830, 0xc000597800}, {0xf543af, 0x6}, {0xef3ae0, 0xc000acdb90}, {0xefe040, 0xc000cf7310}, {0xc0006f15c0, ...})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/call.go:35 +0x223
go.etcd.io/etcd/api/v3/etcdserverpb.(*leaseClient).LeaseGrant(0xc000b88068, {0x10a4830, 0xc000597800}, 0xc000634800, {0xc0006f15c0, 0x4, 0x6})
	/home/runner/work/etcd/etcd/api/etcdserverpb/rpc.pb.go:6853 +0xc9
go.etcd.io/etcd/client/v3.(*retryLeaseClient).LeaseGrant(0xc000f705f0, {0x10a4830, 0xc000597800}, 0x40f0f4, {0x17b7c80, 0x3, 0x3})
	/home/runner/work/etcd/etcd/client/v3/retry.go:144 +0x130
go.etcd.io/etcd/client/v3.(*lessor).Grant(0xc0002d60a0, {0x10a4830, 0xc000597800}, 0x3c)
	/home/runner/work/etcd/etcd/client/v3/lease.go:216 +0x78
go.etcd.io/etcd/client/v3/concurrency.NewSession(0xc000533c20, {0x0, 0x0, 0x0})
	/home/runner/work/etcd/etcd/client/v3/concurrency/session.go:46 +0xec
go.etcd.io/etcd/client/v3/leasing.(*leasingKV).monitorSession(0xc0006ac210)
	/home/runner/work/etcd/etcd/client/v3/leasing/kv.go:142 +0x19f
go.etcd.io/etcd/client/v3/leasing.NewKV.func1()
	/home/runner/work/etcd/etcd/client/v3/leasing/kv.go:71 +0x5a
created by go.etcd.io/etcd/client/v3/leasing.NewKV
	/home/runner/work/etcd/etcd/client/v3/leasing/kv.go:69 +0x212

goroutine 14936 [select]:
go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).run(0xc0004b3c00)
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:843 +0x7e7
created by go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).start
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:591 +0xfc5

goroutine 14954 [IO wait, 14 minutes]:
internal/poll.runtime_pollWait(0x7f991c750580, 0x72)
	/opt/hostedtoolcache/go/1.17.8/x64/src/runtime/netpoll.go:234 +0x89
internal/poll.(*pollDesc).wait(0xc000fa0900, 0xc00006acf8, 0x0)
	/opt/hostedtoolcache/go/1.17.8/x64/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/opt/hostedtoolcache/go/1.17.8/x64/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc000fa0900)
	/opt/hostedtoolcache/go/1.17.8/x64/src/internal/poll/fd_unix.go:402 +0x22c
net.(*netFD).accept(0xc000fa0900)
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/fd_unix.go:173 +0x35
net.(*UnixListener).accept(0xeb4b40)
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/unixsock_posix.go:167 +0x1c
net.(*UnixListener).Accept(0xc000acce70)
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/unixsock.go:260 +0x3d
net/http.(*Server).Serve(0xc000143260, {0x1099f68, 0xc00155f100})
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/http/server.go:3002 +0x394
net/http/httptest.(*Server).goServe.func1()
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/http/httptest/server.go:308 +0x6a
created by net/http/httptest.(*Server).goServe
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/http/httptest/server.go:306 +0x6f

goroutine 14943 [select, 14 minutes]:
go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).linearizableReadLoop(0xc0004b3c00)
	/home/runner/work/etcd/etcd/server/etcdserver/v3_server.go:729 +0xe5
go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).GoAttach.func1()
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:2403 +0x64
created by go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).GoAttach
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:2401 +0x117

goroutine 14908 [select, 14 minutes]:
go.etcd.io/etcd/pkg/v3/schedule.(*fifo).run(0xc000496770)
	/home/runner/work/etcd/etcd/pkg/schedule/schedule.go:173 +0x193
created by go.etcd.io/etcd/pkg/v3/schedule.NewFIFOScheduler
	/home/runner/work/etcd/etcd/pkg/schedule/schedule.go:101 +0x188

goroutine 14917 [select]:
go.etcd.io/etcd/client/v3.(*lessor).deadlineLoop(0xc0002d60a0)
	/home/runner/work/etcd/etcd/client/v3/lease.go:551 +0x85
created by go.etcd.io/etcd/client/v3.(*lessor).KeepAlive.func1
	/home/runner/work/etcd/etcd/client/v3/lease.go:300 +0xa7

goroutine 14904 [select, 14 minutes]:
go.etcd.io/etcd/server/v3/storage/wal.(*filePipeline).run(0xc0002af400)
	/home/runner/work/etcd/etcd/server/storage/wal/file_pipeline.go:98 +0x111
created by go.etcd.io/etcd/server/v3/storage/wal.newFilePipeline
	/home/runner/work/etcd/etcd/server/storage/wal/file_pipeline.go:55 +0x288

goroutine 14948 [IO wait, 14 minutes]:
internal/poll.runtime_pollWait(0x7f991c575710, 0x72)
	/opt/hostedtoolcache/go/1.17.8/x64/src/runtime/netpoll.go:234 +0x89
internal/poll.(*pollDesc).wait(0xc000fa0a80, 0x20, 0x0)
	/opt/hostedtoolcache/go/1.17.8/x64/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/opt/hostedtoolcache/go/1.17.8/x64/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc000fa0a80)
	/opt/hostedtoolcache/go/1.17.8/x64/src/internal/poll/fd_unix.go:402 +0x22c
net.(*netFD).accept(0xc000fa0a80)
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/fd_unix.go:173 +0x35
net.(*UnixListener).accept(0xc0004e1e80)
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/unixsock_posix.go:167 +0x1c
net.(*UnixListener).Accept(0xc000acd260)
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/unixsock.go:260 +0x3d
google.golang.org/grpc.(*Server).Serve(0xc0009ba380, {0x109ac88, 0xc000acd260})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/server.go:780 +0x477
created by go.etcd.io/etcd/tests/v3/framework/integration.(*Member).Launch
	/home/runner/work/etcd/etcd/tests/framework/integration/cluster.go:946 +0x94f

goroutine 14916 [select, 14 minutes]:
google.golang.org/grpc.(*pickerWrapper).pick(0xc000accf60, {0x10a48d8, 0xc000e095c0}, 0x0, {{0xf5aacb, 0x0}, {0x10a48d8, 0xc000e095c0}})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/picker_wrapper.go:103 +0x21b
google.golang.org/grpc.(*ClientConn).getTransport(0x10000c000b32bd0, {0x10a48d8, 0xc000e095c0}, 0x10, {0xf5aacb, 0xf5aacb})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/clientconn.go:929 +0x35
google.golang.org/grpc.(*csAttempt).getTransport(0xc0006ac160)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:430 +0x48
google.golang.org/grpc.newClientStreamWithParams.func2(0xc0006ac160)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:315 +0x2b
google.golang.org/grpc.(*clientStream).withRetry(0xc00040e240, 0xc001412930, 0xc000a118b0)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:709 +0xd3
google.golang.org/grpc.newClientStreamWithParams({0x10a48d8, 0xc000e094a0}, 0x179aa40, 0xc000259c00, {0xf5aacb, 0x7e6700}, {0x0, 0x0, 0x0, 0x0, ...}, ...)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:327 +0x9ce
google.golang.org/grpc.newClientStream.func2({0x10a48d8, 0xc000e094a0}, 0xc000e094a0)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:192 +0x9f
google.golang.org/grpc.newClientStream({0x10a48d8, 0xc000e094a0}, 0x179aa40, 0xc000259c00, {0xf5aacb, 0x2}, {0xc000362c80, 0x3, 0x4})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:220 +0x4bf
go.etcd.io/etcd/client/v3.(*Client).streamClientInterceptor.func1({0x10a4830, 0xc000362c00}, 0x179aa40, 0xc000259c00, {0xf5aacb, 0x410ebd}, 0xf8abc8, {0xc0006b1560, 0x5, 0x6})
	/home/runner/work/etcd/etcd/client/v3/retry_interceptor.go:131 +0x5c6
google.golang.org/grpc.(*ClientConn).NewStream(0xc000b88148, {0x10a4830, 0xc000362c00}, 0xc000a11d10, {0xf5aacb, 0xe80f00}, {0xc0006b1560, 0xc000a11d60, 0xc000b88148})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:159 +0x187
go.etcd.io/etcd/api/v3/etcdserverpb.(*leaseClient).LeaseKeepAlive(0x1096cb8, {0x10a4830, 0xc000362c00}, {0xc0006b1560, 0x6, 0x30})
	/home/runner/work/etcd/etcd/api/etcdserverpb/rpc.pb.go:6870 +0x67
go.etcd.io/etcd/client/v3.(*retryLeaseClient).LeaseKeepAlive(0xc000f705f0, {0x10a4830, 0xc000362c00}, {0xc0006b1560, 0x4, 0x6})
	/home/runner/work/etcd/etcd/client/v3/retry.go:152 +0x11d
go.etcd.io/etcd/client/v3.(*lessor).resetRecv(0xc0002d60a0)
	/home/runner/work/etcd/etcd/client/v3/lease.go:486 +0x174
go.etcd.io/etcd/client/v3.(*lessor).recvKeepAliveLoop(0xc0002d60a0)
	/home/runner/work/etcd/etcd/client/v3/lease.go:449 +0xaf
created by go.etcd.io/etcd/client/v3.(*lessor).KeepAlive.func1
	/home/runner/work/etcd/etcd/client/v3/lease.go:299 +0x65

goroutine 14941 [select]:
go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).monitorClusterVersions(0xc0004b3c00)
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:2164 +0x11e
go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).GoAttach.func1()
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:2403 +0x64
created by go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).GoAttach
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:2401 +0x117

goroutine 14932 [select, 14 minutes]:
go.etcd.io/etcd/server/v3/storage/mvcc.(*watchableStore).syncVictimsLoop(0xc000cc00a0)
	/home/runner/work/etcd/etcd/server/storage/mvcc/watchable_store.go:259 +0x16a
created by go.etcd.io/etcd/server/v3/storage/mvcc.newWatchableStore
	/home/runner/work/etcd/etcd/server/storage/mvcc/watchable_store.go:96 +0x611

goroutine 14940 [select, 6 minutes]:
go.etcd.io/etcd/server/v3/etcdserver.monitorFileDescriptor(0xc000b28db0, 0xc000424480)
	/home/runner/work/etcd/etcd/server/etcdserver/metrics.go:212 +0x35e
go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).Start.func3()
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:530 +0x36
go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).GoAttach.func1()
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:2403 +0x64
created by go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).GoAttach
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:2401 +0x117

goroutine 14859 [select]:
go.etcd.io/etcd/client/v3/leasing.(*leaseCache).clearOldRevokes(0xc0006ac238, {0x10a4830, 0xc000118f80})
	/home/runner/work/etcd/etcd/client/v3/leasing/cache.go:253 +0xb9
go.etcd.io/etcd/client/v3/leasing.NewKV.func2()
	/home/runner/work/etcd/etcd/client/v3/leasing/kv.go:75 +0x6a
created by go.etcd.io/etcd/client/v3/leasing.NewKV
	/home/runner/work/etcd/etcd/client/v3/leasing/kv.go:73 +0x27f

goroutine 14939 [select, 14 minutes]:
go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).purgeFile(0xc0004b3c00)
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:606 +0x3aa
go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).GoAttach.func1()
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:2403 +0x64
created by go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).GoAttach
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:2401 +0x117

goroutine 14950 [IO wait, 14 minutes]:
internal/poll.runtime_pollWait(0x7f991c7501e0, 0x72)
	/opt/hostedtoolcache/go/1.17.8/x64/src/runtime/netpoll.go:234 +0x89
internal/poll.(*pollDesc).wait(0xc000fa0780, 0x0, 0x0)
	/opt/hostedtoolcache/go/1.17.8/x64/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/opt/hostedtoolcache/go/1.17.8/x64/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc000fa0780)
	/opt/hostedtoolcache/go/1.17.8/x64/src/internal/poll/fd_unix.go:402 +0x22c
net.(*netFD).accept(0xc000fa0780)
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/fd_unix.go:173 +0x35
net.(*UnixListener).accept(0x0)
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/unixsock_posix.go:167 +0x1c
net.(*UnixListener).Accept(0xc000acce10)
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/unixsock.go:260 +0x3d
github.com/soheilhy/cmux.(*cMux).Serve(0xc001bde230)
	/home/runner/go/pkg/mod/github.com/soheilhy/cmux@v0.1.5/cmux.go:170 +0xa9
go.etcd.io/etcd/tests/v3/framework/integration.(*Member).Launch.func2()
	/home/runner/work/etcd/etcd/tests/framework/integration/cluster.go:984 +0x5d
created by go.etcd.io/etcd/tests/v3/framework/integration.(*Member).Launch
	/home/runner/work/etcd/etcd/tests/framework/integration/cluster.go:982 +0xe68

goroutine 14899 [select, 14 minutes]:
google.golang.org/grpc.(*pickerWrapper).pick(0xc000accf60, {0x10a48d8, 0xc000e08540}, 0x0, {{0xf476b3, 0x0}, {0x10a48d8, 0xc000e08540}})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/picker_wrapper.go:103 +0x21b
google.golang.org/grpc.(*ClientConn).getTransport(0x26, {0x10a48d8, 0xc000e08540}, 0x68, {0xf476b3, 0xf476b3})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/clientconn.go:929 +0x35
google.golang.org/grpc.(*csAttempt).getTransport(0xc0006ac0b0)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:430 +0x48
google.golang.org/grpc.newClientStreamWithParams.func2(0xc0006ac0b0)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:315 +0x2b
google.golang.org/grpc.(*clientStream).withRetry(0xc00040e000, 0xc0006d8350, 0xc0005acb20)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:709 +0xd3
google.golang.org/grpc.newClientStreamWithParams({0x10a48d8, 0xc000e08390}, 0x17b7260, 0xc000259c00, {0xf476b3, 0x7e6700}, {0x0, 0x0, 0x0, 0x0, ...}, ...)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:327 +0x9ce
google.golang.org/grpc.newClientStream.func2({0x10a48d8, 0xc000e08390}, 0xc000e08390)
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:192 +0x9f
google.golang.org/grpc.newClientStream({0x10a48d8, 0xc000e08390}, 0x17b7260, 0xc000259c00, {0xf476b3, 0xc0005acd10}, {0xc000362080, 0x3, 0x4})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/stream.go:220 +0x4bf
google.golang.org/grpc.invoke({0x10a48d8, 0xc000e08390}, {0xf476b3, 0x203000}, {0xefafa0, 0xc0004a0230}, {0xefb100, 0xc0006ee9b0}, 0x0, {0xc000362080, ...})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/call.go:66 +0x7d
go.etcd.io/etcd/client/v3.(*Client).unaryClientInterceptor.func1({0x10a4868, 0xc0000c0008}, {0xf476b3, 0x14}, {0xefafa0, 0xc0004a0230}, {0xefb100, 0xc0006ee9b0}, 0xc000259c00, 0xf8abb8, ...)
	/home/runner/work/etcd/etcd/client/v3/retry_interceptor.go:60 +0x50a
google.golang.org/grpc.(*ClientConn).Invoke(0x40f0f4, {0x10a4868, 0xc0000c0008}, {0xf476b3, 0xa0ab40}, {0xefafa0, 0xc0004a0230}, {0xefb100, 0xc0006ee9b0}, {0x17b7c80, ...})
	/home/runner/go/pkg/mod/google.golang.org/grpc@v1.47.0/call.go:35 +0x223
go.etcd.io/etcd/api/v3/etcdserverpb.(*kVClient).Txn(0xc000b88060, {0x10a4868, 0xc0000c0008}, 0x40f447, {0x17b7c80, 0x3, 0x3})
	/home/runner/work/etcd/etcd/api/etcdserverpb/rpc.pb.go:6528 +0xc9
go.etcd.io/etcd/client/v3.(*retryKVClient).Txn(0x0, {0x10a4868, 0xc0000c0008}, 0x0, {0x17b7c80, 0x0, 0x0})
	/home/runner/work/etcd/etcd/client/v3/retry.go:117 +0x30
go.etcd.io/etcd/client/v3.(*txn).Commit(0xc000b32000)
	/home/runner/work/etcd/etcd/client/v3/txn.go:146 +0x[158](https://github.com/etcd-io/etcd/actions/runs/3071777532/jobs/4963526956#step:5:159)
go.etcd.io/etcd/client/v3/leasing.(*leasingKV).acquire(_, {_, _}, {_, _}, {0x1, {0xc000b28a98, 0x3, 0x8}, {0x0, ...}, ...})
	/home/runner/work/etcd/etcd/client/v3/leasing/kv.go:275 +0x66b
go.etcd.io/etcd/client/v3/leasing.(*leasingKV).get(_, {_, _}, {0x1, {0xc000b28a88, 0x3, 0x8}, {0x0, 0x0, 0x0}, ...})
	/home/runner/work/etcd/etcd/client/v3/leasing/kv.go:317 +0x1e5
go.etcd.io/etcd/client/v3/leasing.(*leasingKV).Get(0xf38819, {0x10a4868, 0xc0000c0008}, {0xc000b28a85, 0x1}, {0x0, 0xc0010a854d, 0x474})
	/home/runner/work/etcd/etcd/client/v3/leasing/kv.go:86 +0xd0
go.etcd.io/etcd/tests/v3/integration/clientv3/lease_test.TestLeasingReconnectNonOwnerGet(0xc00086e000)
	/home/runner/work/etcd/etcd/tests/integration/clientv3/lease/leasing_test.go:1715 +0x416
testing.tRunner(0xc00086e000, 0xf8a828)
	/opt/hostedtoolcache/go/1.17.8/x64/src/testing/testing.go:1259 +0x102
created by testing.(*T).Run
	/opt/hostedtoolcache/go/1.17.8/x64/src/testing/testing.go:1306 +0x35a

goroutine 14947 [select]:
go.etcd.io/etcd/server/v3/etcdserver/api/v3rpc.monitorLeader.func1()
	/home/runner/work/etcd/etcd/server/etcdserver/api/v3rpc/interceptor.go:322 +0xc5
go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).GoAttach.func1()
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:2403 +0x64
created by go.etcd.io/etcd/server/v3/etcdserver.(*EtcdServer).GoAttach
	/home/runner/work/etcd/etcd/server/etcdserver/server.go:2401 +0x117

goroutine 14931 [select]:
go.etcd.io/etcd/server/v3/storage/mvcc.(*watchableStore).syncWatchersLoop(0xc000cc00a0)
	/home/runner/work/etcd/etcd/server/storage/mvcc/watchable_store.go:233 +0x1ab
created by go.etcd.io/etcd/server/v3/storage/mvcc.newWatchableStore
	/home/runner/work/etcd/etcd/server/storage/mvcc/watchable_store.go:95 +0x5cf

goroutine 14949 [select, 14 minutes]:
github.com/soheilhy/cmux.muxListener.Accept({{0x1099f68, 0xc00155f080}, 0xc0004e63c0, 0xc000424840})
	/home/runner/go/pkg/mod/github.com/soheilhy/cmux@v0.1.5/cmux.go:262 +0x7f
net/http.(*Server).Serve(0xc000143180, {0x109b2e8, 0xc00[170](https://github.com/etcd-io/etcd/actions/runs/3071777532/jobs/4963526956#step:5:171)a3e0})
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/http/server.go:3002 +0x394
net/http/httptest.(*Server).goServe.func1()
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/http/httptest/server.go:308 +0x6a
created by net/http/httptest.(*Server).goServe
	/opt/hostedtoolcache/go/1.17.8/x64/src/net/http/httptest/server.go:306 +0x6f

goroutine 14909 [select, 14 minutes]:
go.etcd.io/etcd/pkg/v3/schedule.(*fifo).run(0xc0004a04d0)
	/home/runner/work/etcd/etcd/pkg/schedule/schedule.go:[173](https://github.com/etcd-io/etcd/actions/runs/3071777532/jobs/4963526956#step:5:174) +0x193
created by go.etcd.io/etcd/pkg/v3/schedule.NewFIFOScheduler
	/home/runner/work/etcd/etcd/pkg/schedule/schedule.go:101 +0x[188](https://github.com/etcd-io/etcd/actions/runs/3071777532/jobs/4963526956#step:5:189)

Anything else we need to know?

No response
@chaochn47
Copy link
Member

another data point https://github.com/etcd-io/etcd/actions/runs/3108126683/jobs/5036981692

@fuweid fuweid mentioned this issue Oct 5, 2022
Closed
@fuweid
Copy link
Contributor Author

fuweid commented Oct 19, 2022

@serathius @ahrtr it is related to grpc issue fixed by grpc/grpc-go#5714. Is it possible to bump to new grpc version when it is ready?

@lavacat lavacat mentioned this issue Nov 22, 2022
Closed
@fuweid fuweid mentioned this issue Nov 23, 2022
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
help wanted type/flake
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

bump grpc to v1.51.0 from v1.47.0 fuweid/etcd
3 participants
@serathius @fuweid @chaochn47