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

Not for checkin/review - Pr3 issue repro #16505

Closed
wants to merge 2 commits into from
Closed

Not for checkin/review - Pr3 issue repro #16505

wants to merge 2 commits into from

Conversation

geetasg
Copy link

@geetasg geetasg commented Aug 29, 2023

Geeta Gharpure added 2 commits August 24, 2023 22:02
@geetasg geetasg marked this pull request as draft August 29, 2023 16:40
@geetasg
Copy link
Author

geetasg commented Aug 29, 2023

Validation error repro:

[root@ip-172-31-3-171 integration]# pwd
/home/ec2-user/geetasg/etcd/tests/integration
[root@ip-172-31-3-171 integration]# go test -v -run TestForceNewCluster > l 2>&1&

Relevant log excerpt

    logger.go:130: 2023-08-29T16:33:52.846Z     INFO    m0      No snapshot found. Recovering WAL from scratch! {"member": "m0"}
    logger.go:130: 2023-08-29T16:33:52.858Z     INFO    m0      forcing restart member  {"member": "m0", "cluster-id": "a91f98ae256f65e4", "local-member-id": "b7a1885e4f5e53af", "commit-index": 11}
    logger.go:130: 2023-08-29T16:33:52.858Z     INFO    m0      Recovering membership from backend      {"member": "m0"}
goroutine 290 [running]:
runtime/debug.Stack()
        /usr/local/go/src/runtime/debug/stack.go:24 +0x65
runtime/debug.PrintStack()
        /usr/local/go/src/runtime/debug/stack.go:16 +0x19
go.etcd.io/etcd/server/v3/etcdserver/api/membership.(*RaftCluster).Recover(0xc001d62f00, 0x1278308)
        /home/ec2-user/geetasg/etcd/server/etcdserver/api/membership/cluster.go:268 +0xea
go.etcd.io/etcd/server/v3/etcdserver.(*bootstrapedCluster).Finalize(_, {{0xc00044c00a, 0x2}, {0x0, 0x0}, {0x0, 0x0}, {{{0x0, 0x0, 0x0}, ...}, ...}, ...}, ...)
        /home/ec2-user/geetasg/etcd/server/etcdserver/bootstrap.go:452 +0x167
go.etcd.io/etcd/server/v3/etcdserver.bootstrap({{0xc00044c00a, 0x2}, {0x0, 0x0}, {0x0, 0x0}, {{{0x0, 0x0, 0x0}, 0x0, ...}, ...}, ...})
        /home/ec2-user/geetasg/etcd/server/etcdserver/bootstrap.go:105 +0x9c5
go.etcd.io/etcd/server/v3/etcdserver.NewServer({{0xc00044c00a, 0x2}, {0x0, 0x0}, {0x0, 0x0}, {{{0x0, 0x0, 0x0}, 0x0, ...}, ...}, ...})
        /home/ec2-user/geetasg/etcd/server/etcdserver/server.go:304 +0x78
go.etcd.io/etcd/tests/v3/framework/integration.(*Member).Launch(0xc000340500)
        /home/ec2-user/geetasg/etcd/tests/framework/integration/cluster.go:966 +0x499
go.etcd.io/etcd/tests/v3/framework/integration.(*Member).Restart(0xc000340500, {0x13b8260, 0xc0004871e0})
        /home/ec2-user/geetasg/etcd/tests/framework/integration/cluster.go:1286 +0x80d
go.etcd.io/etcd/tests/v3/integration.TestForceNewCluster(0xc0004871e0)
        /home/ec2-user/geetasg/etcd/tests/integration/cluster_test.go:157 +0x516
testing.tRunner(0xc0004871e0, 0x12784e8)
        /usr/local/go/src/testing/testing.go:1576 +0x10b
created by testing.(*T).Run
        /usr/local/go/src/testing/testing.go:1629 +0x3ea
    logger.go:130: 2023-08-29T16:33:52.858Z     INFO    m0      recovered/added member from store       {"member": "m0", "cluster-id": "a91f98ae256f65e4", "local-member-id": "b7a1885e4f5e53af", "recovered-remote-peer-id": "87365f82ffec5250", "recovered-remote-peer-urls": ["unix://127.0.0.1:210052627422"], "recovered-remote-peer-is-learner": false}
Member: &{87365f82ffec5250 {[unix://127.0.0.1:210052627422] false} {m1 [unix://127.0.0.1:210062627422]}}
    logger.go:130: 2023-08-29T16:33:52.858Z     INFO    m0      recovered/added member from store       {"member": "m0", "cluster-id": "a91f98ae256f65e4", "local-member-id": "b7a1885e4f5e53af", "recovered-remote-peer-id": "b7a1885e4f5e53af", "recovered-remote-peer-urls": ["unix://127.0.0.1:210022627422"], "recovered-remote-peer-is-learner": false}
Member: &{b7a1885e4f5e53af {[unix://127.0.0.1:210022627422] false} {m0 [unix://127.0.0.1:210032627422]}}
    logger.go:130: 2023-08-29T16:33:52.858Z     INFO    m0      recovered/added member from store       {"member": "m0", "cluster-id": "a91f98ae256f65e4", "local-member-id": "b7a1885e4f5e53af", "recovered-remote-peer-id": "d60eb23c0d1eb60f", "recovered-remote-peer-urls": ["unix://127.0.0.1:210082627422"], "recovered-remote-peer-is-learner": false}
Member: &{d60eb23c0d1eb60f {[unix://127.0.0.1:210082627422] false} {m2 [unix://127.0.0.1:210092627422]}}
    logger.go:130: 2023-08-29T16:33:52.858Z     INFO    m0      set cluster version from store  {"member": "m0", "cluster-version": "3.6"}
    logger.go:130: 2023-08-29T16:33:52.858Z     INFO    m0.raft b7a1885e4f5e53af switched to configuration voters=()    {"member": "m0"}
    logger.go:130: 2023-08-29T16:33:52.858Z     INFO    m0.raft b7a1885e4f5e53af became follower at term 2      {"member": "m0"}
    logger.go:130: 2023-08-29T16:33:52.858Z     INFO    m0.raft newRaft b7a1885e4f5e53af [peers: [], term: 2, commit: 11, applied: 0, lastindex: 11, lastterm: 2]       {"member": "m0"}
    logger.go:130: 2023-08-29T16:33:52.858Z     WARN    m0      simple token is not cryptographically signed    {"member": "m0"}
    logger.go:130: 2023-08-29T16:33:52.858Z     INFO    m0      kvstore restored        {"member": "m0", "current-rev": 2}
    logger.go:130: 2023-08-29T16:33:52.858Z     INFO    m0      starting remote peer    {"member": "m0", "remote-peer-id": "87365f82ffec5250"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      started HTTP pipelining with remote peer        {"member": "m0", "local-member-id": "b7a1885e4f5e53af", "remote-peer-id": "87365f82ffec5250"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      started remote peer     {"member": "m0", "remote-peer-id": "87365f82ffec5250"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      added remote peer       {"member": "m0", "local-member-id": "b7a1885e4f5e53af", "remote-peer-id": "87365f82ffec5250", "remote-peer-urls": ["unix://127.0.0.1:210052627422"]}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      started stream writer with remote peer  {"member": "m0", "local-member-id": "b7a1885e4f5e53af", "remote-peer-id": "87365f82ffec5250"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      started stream reader with remote peer  {"member": "m0", "stream-reader-type": "stream Message", "local-member-id": "b7a1885e4f5e53af", "remote-peer-id": "87365f82ffec5250"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      started stream writer with remote peer  {"member": "m0", "local-member-id": "b7a1885e4f5e53af", "remote-peer-id": "87365f82ffec5250"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      started stream reader with remote peer  {"member": "m0", "stream-reader-type": "stream MsgApp v2", "local-member-id": "b7a1885e4f5e53af", "remote-peer-id": "87365f82ffec5250"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      starting remote peer    {"member": "m0", "remote-peer-id": "d60eb23c0d1eb60f"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      started HTTP pipelining with remote peer        {"member": "m0", "local-member-id": "b7a1885e4f5e53af", "remote-peer-id": "d60eb23c0d1eb60f"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      started stream writer with remote peer  {"member": "m0", "local-member-id": "b7a1885e4f5e53af", "remote-peer-id": "d60eb23c0d1eb60f"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      started remote peer     {"member": "m0", "remote-peer-id": "d60eb23c0d1eb60f"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      added remote peer       {"member": "m0", "local-member-id": "b7a1885e4f5e53af", "remote-peer-id": "d60eb23c0d1eb60f", "remote-peer-urls": ["unix://127.0.0.1:210082627422"]}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      started stream reader with remote peer  {"member": "m0", "stream-reader-type": "stream MsgApp v2", "local-member-id": "b7a1885e4f5e53af", "remote-peer-id": "d60eb23c0d1eb60f"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      started stream writer with remote peer  {"member": "m0", "local-member-id": "b7a1885e4f5e53af", "remote-peer-id": "d60eb23c0d1eb60f"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      started stream reader with remote peer  {"member": "m0", "stream-reader-type": "stream Message", "local-member-id": "b7a1885e4f5e53af", "remote-peer-id": "d60eb23c0d1eb60f"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      starting etcd server    {"member": "m0", "local-member-id": "b7a1885e4f5e53af", "local-server-version": "3.6.0-alpha.0", "cluster-id": "a91f98ae256f65e4", "cluster-version": "3.6"}
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    grpc    [[core] [Server #19] Server created]
    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      starting initial election tick advance  {"member": "m0", "election-ticks": 10}
    logger.go:130: 2023-08-29T16:33:52.859Z     ERROR   m0      Failing to add duplicate member id      {"member": "m0", "memberid": "87365f82ffec5250"}
    logger.go:130: 2023-08-29T16:33:52.859Z     ERROR   m0      failed conf change      {"member": "m0", "error": "membership: ID exists"}
Failed to applyConfChange. err:removed all voters
panic: removed all voters

goroutine 843 [running]:
go.etcd.io/raft/v3.(*raft).applyConfChange(0x0?, {0x0, {0xc000717c50, 0x1, 0x1}, {0xc001aefda0, 0x53, 0x60}})
        /root/go/pkg/mod/go.etcd.io/raft/[email protected]/raft.go:1682 +0x246
go.etcd.io/raft/v3.(*node).run(0xc000d21aa0)
        /root/go/pkg/mod/go.etcd.io/raft/[email protected]/node.go:361 +0xb17
created by go.etcd.io/raft/v3.RestartNode
        /root/go/pkg/mod/go.etcd.io/raft/[email protected]/node.go:245 +0x24a
exit status 2
FAIL    go.etcd.io/etcd/tests/v3/integration    0.224s

@geetasg
Copy link
Author

geetasg commented Aug 29, 2023

More specifically, following conf change fails for the test since the member is considered already present (because the recovery from backend picked it up.)

    logger.go:130: 2023-08-29T16:33:52.859Z     INFO    m0      starting initial election tick advance  {"member": "m0", "election-ticks": 10}
    logger.go:130: 2023-08-29T16:33:52.859Z     ERROR   m0      Failing to add duplicate member id      {"member": "m0", "memberid": "87365f82ffec5250"}
    logger.go:130: 2023-08-29T16:33:52.859Z     ERROR   m0      failed conf change      {"member": "m0", "error": "membership: ID exists"}
Failed to applyConfChange. err:removed all voters

@geetasg
Copy link
Author

geetasg commented Aug 29, 2023

Full log from modified main branch
modified_main_branch.log

@geetasg
Copy link
Author

geetasg commented Aug 29, 2023

Full log from pr3-issue-repro branch
repro-branch.log

@jmhbnz
Copy link
Member

jmhbnz commented Jan 4, 2024

Discussed during sig-etcd triage meeting. cc @ahrtr to consider if this pull request can be closed.

@jmhbnz
Copy link
Member

jmhbnz commented Jun 6, 2024

Closing old repro pr as this is not for merge.

@jmhbnz jmhbnz closed this Jun 6, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@geetasg @jmhbnz