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

integration/clientv3/lease TestLeaseDeleteRangeContendDel #15336

Closed
ahrtr opened this issue Feb 18, 2023 · 4 comments
Closed

integration/clientv3/lease TestLeaseDeleteRangeContendDel #15336

ahrtr opened this issue Feb 18, 2023 · 4 comments
Assignees
@fuweid
Labels
help wanted type/flake

Comments

@ahrtr
Copy link
Member

ahrtr commented Feb 18, 2023

Which github workflows are flaking?

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

Which tests are flaking?

TestLeaseDeleteRangeContendDel

Github Action link

https://github.com/etcd-io/etcd/actions/runs/4210662140/jobs/7308496910

Reason for failure (if possible)

=== FAIL: integration/clientv3/lease TestLeaseDeleteRangeContendDel (0.13s)
    cluster.go:537: Creating listener with addr: 127.0.0.1:2122106362
    cluster.go:537: Creating listener with addr: 127.0.0.1:2122206362
    logger.go:130: 2023-02-18T10:07:15.385Z	INFO	m0	LISTEN GRPC	{"member": "m0", "grpcAddr": "localhost:m0", "m.Name": "m0", "workdir": "/tmp/TestLeaseDeleteRangeContendDel2789031753/001"}
    logger.go:130: 2023-02-18T10:07:15.385Z	INFO	m0	LISTEN GRPC SUCCESS	{"member": "m0", "grpcAddr": "unix://localhost:m0", "m.Name": "m0", "workdir": "/tmp/TestLeaseDeleteRangeContendDel2789031753/001", "port": "m0"}
    cluster.go:218: Launching new cluster...
    logger.go:130: 2023-02-18T10:07:15.385Z	INFO	m0	launching a member	{"member": "m0", "name": "m0", "advertise-peer-urls": ["unix://127.0.0.1:2122106362"], "listen-client-urls": ["unix://127.0.0.1:2122206362"], "grpc-url": "unix://localhost:m0"}
    logger.go:130: 2023-02-18T10:07:15.386Z	INFO	m0	opened backend db	{"member": "m0", "path": "/tmp/TestLeaseDeleteRangeContendDel2789031753/002/etcd3996327631/member/snap/db", "took": "1.094896ms"}
    logger.go:130: 2023-02-18T10:07:15.388Z	INFO	m0	starting local member	{"member": "m0", "local-member-id": "84f8240de9accda", "cluster-id": "921f8c3d0b93c6b5"}
    logger.go:130: 2023-02-18T10:07:15.388Z	INFO	m0.raft	84f8240de9accda switched to configuration voters=()	{"member": "m0"}
    logger.go:130: 2023-02-18T10:07:15.388Z	INFO	m0.raft	84f8240de9accda became follower at term 0	{"member": "m0"}
    logger.go:130: 2023-02-18T10:07:15.388Z	INFO	m0.raft	newRaft 84f8240de9accda [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]	{"member": "m0"}
    logger.go:130: 2023-02-18T10:07:15.388Z	INFO	m0.raft	84f8240de9accda became follower at term 1	{"member": "m0"}
    logger.go:130: 2023-02-18T10:07:15.388Z	INFO	m0.raft	84f8240de9accda switched to configuration voters=(598840490587770074)	{"member": "m0"}
    logger.go:130: 2023-02-18T10:07:15.389Z	WARN	m0	simple token is not cryptographically signed	{"member": "m0"}
    logger.go:130: 2023-02-18T10:07:15.394Z	INFO	m0	kvstore restored	{"member": "m0", "current-rev": 1}
    logger.go:130: 2023-02-18T10:07:15.395Z	INFO	m0	starting etcd server	{"member": "m0", "local-member-id": "84f8240de9accda", "local-server-version": "3.6.0-alpha.0", "cluster-version": "to_be_decided"}
    logger.go:130: 2023-02-18T10:07:15.395Z	INFO	grpc	[[core] [Server #465] Server created]
    logger.go:130: 2023-02-18T10:07:15.395Z	INFO	m0	started as single-node; fast-forwarding election ticks	{"member": "m0", "local-member-id": "84f8240de9accda", "forward-ticks": 9, "forward-duration": "90ms", "election-ticks": 10, "election-timeout": "100ms"}
    logger.go:130: 2023-02-18T10:07:15.395Z	INFO	m0.raft	84f8240de9accda switched to configuration voters=(598840490587770074)	{"member": "m0"}
    logger.go:130: 2023-02-18T10:07:15.395Z	INFO	m0	added member	{"member": "m0", "cluster-id": "921f8c3d0b93c6b5", "local-member-id": "84f8240de9accda", "added-peer-id": "84f8240de9accda", "added-peer-peer-urls": ["unix://127.0.0.1:2122106362"], "added-peer-is-learner": false}
    logger.go:130: 2023-02-18T10:07:15.396Z	INFO	grpc	[[core] [Server #465 ListenSocket #466] ListenSocket created]
    logger.go:130: 2023-02-18T10:07:15.396Z	INFO	grpc	[[core] [Channel #467] Channel created]
    logger.go:130: 2023-02-18T10:07:15.396Z	INFO	grpc	[[core] [Channel #467] original dial target is: "etcd-endpoints://0xc001b60780/localhost:m0"]
    logger.go:130: 2023-02-18T10:07:15.396Z	INFO	grpc	[[core] [Channel #467] parsed dial target is: {Scheme:etcd-endpoints Authority:0xc001b60780 Endpoint:localhost:m0 URL:{Scheme:etcd-endpoints Opaque: User: Host:0xc001b60780 Path:/localhost:m0 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}]
    logger.go:130: 2023-02-18T10:07:15.396Z	INFO	grpc	[[core] [Channel #467] Channel authority set to "localhost:m0"]
    logger.go:130: 2023-02-18T10:07:15.396Z	INFO	grpc	[[core] [Channel #467] Resolver state updated: {
          "Addresses": [
            {
              "Addr": "unix:localhost:m0",
              "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: 2023-02-18T10:07:15.397Z	INFO	grpc	[[core] [Channel #467] Channel switches to new LB policy "round_robin"]
    logger.go:130: 2023-02-18T10:07:15.397Z	INFO	grpc	[[balancer] base.baseBalancer: got new ClientConn state:  {{[{
          "Addr": "unix:localhost:m0",
          "ServerName": "localhost",
          "Attributes": null,
          "BalancerAttributes": null,
          "Type": 0,
          "Metadata": null
        }] 0xc0012cd0c0 <nil>} <nil>}]
    logger.go:130: 2023-02-18T10:07:15.398Z	INFO	grpc	[[core] [Channel #467 SubChannel #468] Subchannel created]
    logger.go:130: 2023-02-18T10:07:15.398Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[]}]
    logger.go:130: 2023-02-18T10:07:15.398Z	INFO	grpc	[[core] [Channel #467 SubChannel #468] Subchannel Connectivity change to CONNECTING]
    logger.go:130: 2023-02-18T10:07:15.398Z	INFO	grpc	[[core] [Channel #467 SubChannel #468] Subchannel picks a new address "unix:localhost:m0" to connect]
    logger.go:130: 2023-02-18T10:07:15.398Z	INFO	grpc	[[core] [Channel #467 SubChannel #468] Subchannel Connectivity change to READY]
    logger.go:130: 2023-02-18T10:07:15.398Z	INFO	grpc	[[core] [Channel #467] Channel Connectivity change to CONNECTING]
    logger.go:130: 2023-02-18T10:07:15.398Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00412b620, CONNECTING]
    logger.go:130: 2023-02-18T10:07:15.398Z	INFO	grpc	[[balancer] base.baseBalancer: handle SubConn state change: 0xc00412b620, READY]
    logger.go:130: 2023-02-18T10:07:15.399Z	INFO	grpc	[[roundrobin] roundrobinPicker: Build called with info: {map[0xc00412b620:{{
          "Addr": "unix:localhost:m0",
          "ServerName": "localhost",
          "Attributes": null,
          "BalancerAttributes": null,
          "Type": 0,
          "Metadata": null
        }}]}]
    logger.go:130: 2023-02-18T10:07:15.399Z	INFO	grpc	[[core] [Channel #467] Channel Connectivity change to READY]
    logger.go:130: 2023-02-18T10:07:15.399Z	INFO	m0	launched a member	{"member": "m0", "name": "m0", "advertise-peer-urls": ["unix://127.0.0.1:2122106362"], "listen-client-urls": ["unix://127.0.0.1:2122206362"], "grpc-url": "unix://localhost:m0"}
    logger.go:130: 2023-02-18T10:07:15.419Z	INFO	m0.raft	84f8240de9accda is starting a new election at term 1	{"member": "m0"}
    logger.go:130: 2023-02-18T10:07:15.419Z	INFO	m0.raft	84f8240de9accda became candidate at term 2	{"member": "m0"}
    logger.go:130: 2023-02-18T10:07:15.419Z	INFO	m0.raft	84f8240de9accda received MsgVoteResp from 84f8240de9accda at term 2	{"member": "m0"}
    logger.go:130: 2023-02-18T10:07:15.419Z	INFO	m0.raft	84f8240de9accda became leader at term 2	{"member": "m0"}
    logger.go:130: 2023-02-18T10:07:15.419Z	INFO	m0.raft	raft.node: 84f8240de9accda elected leader 84f8240de9accda at term 2	{"member": "m0"}
    logger.go:130: 2023-02-18T10:07:15.420Z	INFO	m0	setting up initial cluster version using v3 API	{"member": "m0", "cluster-version": "3.6"}
    logger.go:130: 2023-02-18T10:07:15.420Z	INFO	m0	published local member to cluster through raft	{"member": "m0", "local-member-id": "84f8240de9accda", "local-member-attributes": "{Name:m0 ClientURLs:[unix://127.0.0.1:2122206362]}", "cluster-id": "921f8c3d0b93c6b5", "publish-timeout": "5.2s"}
    logger.go:130: 2023-02-18T10:07:15.420Z	INFO	m0	set initial cluster version	{"member": "m0", "cluster-id": "921f8c3d0b93c6b5", "local-member-id": "84f8240de9accda", "cluster-version": "3.6"}
    logger.go:130: 2023-02-18T10:07:15.420Z	INFO	m0	cluster version is updated	{"member": "m0", "cluster-version": "3.6"}
    logger.go:130: 2023-02-18T10:07:15.420Z	WARN	m0	Failed to detect schema version	{"member": "m0", "error": "missing confstate information"}
    logger.go:130: 2023-02-18T10:07:15.420Z	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:237:  - m0 -> 84f8240de9accda (unix://localhost:m0)
    logger.go:130: 2023-02-18T10:07:15.496Z	WARN	m0.client	retrying of unary invoker failed	{"member": "m0", "target": "etcd-endpoints://0xc001b60780/localhost:m0", "method": "/etcdserverpb.KV/Txn", "attempt": 0, "error": "rpc error: code = Canceled desc = context canceled"}
    logger.go:130: 2023-02-18T10:07:15.496Z	WARN	m0.client	retrying of unary invoker failed	{"member": "m0", "target": "etcd-endpoints://0xc001b60780/localhost:m0", "method": "/etcdserverpb.KV/Txn", "attempt": 0, "error": "rpc error: code = Canceled desc = context canceled"}
    logger.go:130: 2023-02-18T10:07:15.496Z	WARN	m0.client	retrying of unary invoker failed	{"member": "m0", "target": "etcd-endpoints://0xc001b60780/localhost:m0", "method": "/etcdserverpb.KV/Range", "attempt": 0, "error": "rpc error: code = Canceled desc = context canceled"}
    leasing_test.go:1313: #0: expected [key:"key/0" create_revision:67 mod_revision:67 version:1 value:"123" ], got []
    cluster.go:1404: ========= Cluster termination started =====================
    logger.go:130: 2023-02-18T10:07:15.499Z	INFO	grpc	[[core] [Channel #467] Channel Connectivity change to SHUTDOWN]
    logger.go:130: 2023-02-18T10:07:15.499Z	INFO	grpc	[[core] [Channel #467 SubChannel #468] Subchannel Connectivity change to SHUTDOWN]
    logger.go:130: 2023-02-18T10:07:15.499Z	INFO	grpc	[[core] [Channel #467 SubChannel #468] Subchannel deleted]
    logger.go:130: 2023-02-18T10:07:15.499Z	INFO	grpc	[[core] [Channel #467] Channel deleted]
    logger.go:130: 2023-02-18T10:07:15.499Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2023-02-18T10:07:15.499Z	INFO	grpc	[[transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"]
    logger.go:130: 2023-02-18T10:07:15.499Z	INFO	m0	terminating a member	{"member": "m0", "name": "m0", "advertise-peer-urls": ["unix://127.0.0.1:2122106362"], "listen-client-urls": ["unix://127.0.0.1:2122206362"], "grpc-url": "unix://localhost:m0"}
    logger.go:130: 2023-02-18T10:07:15.500Z	INFO	grpc	[[core] [Server #465 ListenSocket #466] ListenSocket deleted]
    logger.go:130: 2023-02-18T10:07:15.501Z	INFO	m0	verification of persisted state	{"member": "m0", "data-dir": "/tmp/TestLeaseDeleteRangeContendDel2789031753/002/etcd3996327631"}
    logger.go:130: 2023-02-18T10:07:15.506Z	INFO	m0	verification: consistentIndex OK	{"member": "m0", "backend-consistent-index": 72, "hardstate-commit": 72}
    logger.go:130: 2023-02-18T10:07:15.507Z	INFO	m0	verification of persisted state successful	{"member": "m0", "data-dir": "/tmp/TestLeaseDeleteRangeContendDel2789031753/002/etcd3996327631"}
    logger.go:130: 2023-02-18T10:07:15.509Z	INFO	m0	terminated a member	{"member": "m0", "name": "m0", "advertise-peer-urls": ["unix://127.0.0.1:2122106362"], "listen-client-urls": ["unix://127.0.0.1:2122206362"], "grpc-url": "unix://localhost:m0"}
    cluster.go:1421: ========= Cluster termination succeeded ===================

Anything else we need to know?

No response
@fuweid
Copy link
Member

fuweid commented Feb 19, 2023

@ahrtr Please assign it to me, if there is no one working on this. I run into this issue in my local several times and still try to fix it. Thanks

@ahrtr
Copy link
Member Author

ahrtr commented Feb 19, 2023

Just assigned to you. Thanks @fuweid

@tjungblu
Copy link
Contributor

tjungblu commented Mar 3, 2023

sorry @fuweid, I think I have just fixed this as part of #15352

@fuweid
Copy link
Member

fuweid commented Mar 4, 2023

@tjungblu Thanks for fixing this. I focused on the project's release and sorry for late reply. Will take a look at your patch!.

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

@fuweid fuweid

Labels
help wanted type/flake
Milestone
No milestone
Development

No branches or pull requests
4 participants
@serathius @fuweid @ahrtr @tjungblu