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

TestLeader_ClusterID_noUpgrade flaky test #7239

Closed
schmichael opened this issue Feb 28, 2020 · 1 comment · Fixed by #7252
Closed

TestLeader_ClusterID_noUpgrade flaky test #7239

schmichael opened this issue Feb 28, 2020 · 1 comment · Fixed by #7252
Labels
theme/testing Test related issues

Comments

@schmichael
Copy link
Member

Version: v0.11-dev
PR: #7231
Commit: f359bfe
CI: https://circleci.com/gh/hashicorp/nomad/41297

Failed
=== RUN   TestLeader_ClusterID_noUpgrade
=== PAUSE TestLeader_ClusterID_noUpgrade
=== CONT  TestLeader_ClusterID_noUpgrade
--- FAIL: TestLeader_ClusterID_noUpgrade (2.17s)
    testlog.go:34: 2020-02-28T21:50:21.982Z [INFO]  raft/api.go:549: nomad.raft: initial configuration: index=1 servers="[{Suffrage:Voter ID:127.0.0.1:9969 Address:127.0.0.1:9969}]"
    testlog.go:34: 2020-02-28T21:50:21.982Z [INFO]  go-hclog/stdlog.go:46: nomad: serf: EventMemberJoin: nomad-316.global 127.0.0.1
    testlog.go:34: 2020-02-28T21:50:21.982Z [WARN]  nomad/server.go:1370: nomad: no enabled schedulers
    testlog.go:34: 2020-02-28T21:50:21.984Z [INFO]  raft/api.go:549: nomad.raft: initial configuration: index=1 servers="[{Suffrage:Voter ID:127.0.0.1:9975 Address:127.0.0.1:9975}]"
    testlog.go:34: 2020-02-28T21:50:21.985Z [INFO]  go-hclog/stdlog.go:46: nomad: serf: EventMemberJoin: nomad-317.global 127.0.0.1
    testlog.go:34: 2020-02-28T21:50:21.985Z [WARN]  nomad/server.go:1370: nomad: no enabled schedulers
    testlog.go:34: 2020-02-28T21:50:21.986Z [INFO]  raft/api.go:549: nomad.raft: initial configuration: index=1 servers="[{Suffrage:Voter ID:127.0.0.1:9983 Address:127.0.0.1:9983}]"
    testlog.go:34: 2020-02-28T21:50:21.987Z [INFO]  go-hclog/stdlog.go:46: nomad: serf: EventMemberJoin: nomad-318.global 127.0.0.1
    testlog.go:34: 2020-02-28T21:50:21.987Z [WARN]  nomad/server.go:1370: nomad: no enabled schedulers
    testlog.go:34: 2020-02-28T21:50:21.987Z [INFO]  raft/raft.go:152: nomad.raft: entering follower state: follower="Node at 127.0.0.1:9969 [Follower]" leader=
    testlog.go:34: 2020-02-28T21:50:21.987Z [DEBUG] go-hclog/stdlog.go:44: nomad: memberlist: Stream connection from=127.0.0.1:40354
    testlog.go:34: 2020-02-28T21:50:21.987Z [INFO]  nomad/serf.go:60: nomad: adding server: server="nomad-316.global (Addr: 127.0.0.1:9969) (DC: dc1)"
    testlog.go:34: 2020-02-28T21:50:21.987Z [INFO]  raft/raft.go:152: nomad.raft: entering follower state: follower="Node at 127.0.0.1:9975 [Follower]" leader=
    testlog.go:34: 2020-02-28T21:50:21.988Z [INFO]  nomad/serf.go:60: nomad: adding server: server="nomad-317.global (Addr: 127.0.0.1:9975) (DC: dc1)"
    testlog.go:34: 2020-02-28T21:50:21.988Z [INFO]  raft/raft.go:152: nomad.raft: entering follower state: follower="Node at 127.0.0.1:9983 [Follower]" leader=
    testlog.go:34: 2020-02-28T21:50:21.988Z [INFO]  nomad/serf.go:60: nomad: adding server: server="nomad-318.global (Addr: 127.0.0.1:9983) (DC: dc1)"
    testlog.go:34: 2020-02-28T21:50:21.988Z [DEBUG] go-hclog/stdlog.go:44: nomad: memberlist: Initiating push/pull sync with: 127.0.0.1:9962
    testlog.go:34: 2020-02-28T21:50:21.989Z [INFO]  go-hclog/stdlog.go:46: nomad: serf: EventMemberJoin: nomad-317.global 127.0.0.1
    testlog.go:34: 2020-02-28T21:50:21.989Z [INFO]  nomad/serf.go:60: nomad: adding server: server="nomad-317.global (Addr: 127.0.0.1:9975) (DC: dc1)"
    testlog.go:34: 2020-02-28T21:50:21.989Z [INFO]  go-hclog/stdlog.go:46: nomad: serf: EventMemberJoin: nomad-316.global 127.0.0.1
    testlog.go:34: 2020-02-28T21:50:21.989Z [INFO]  nomad/serf.go:60: nomad: adding server: server="nomad-316.global (Addr: 127.0.0.1:9969) (DC: dc1)"
    testlog.go:34: 2020-02-28T21:50:21.989Z [DEBUG] go-hclog/stdlog.go:44: nomad: memberlist: Initiating push/pull sync with: 127.0.0.1:9962
    testlog.go:34: 2020-02-28T21:50:21.989Z [DEBUG] go-hclog/stdlog.go:44: nomad: memberlist: Stream connection from=127.0.0.1:40358
    testlog.go:34: 2020-02-28T21:50:21.989Z [INFO]  go-hclog/stdlog.go:46: nomad: serf: EventMemberJoin: nomad-318.global 127.0.0.1
    testlog.go:34: 2020-02-28T21:50:21.990Z [INFO]  nomad/serf.go:60: nomad: adding server: server="nomad-318.global (Addr: 127.0.0.1:9983) (DC: dc1)"
    testlog.go:34: 2020-02-28T21:50:21.990Z [INFO]  go-hclog/stdlog.go:46: nomad: serf: EventMemberJoin: nomad-317.global 127.0.0.1
    testlog.go:34: 2020-02-28T21:50:21.990Z [INFO]  go-hclog/stdlog.go:46: nomad: serf: EventMemberJoin: nomad-316.global 127.0.0.1
    testlog.go:34: 2020-02-28T21:50:21.990Z [INFO]  nomad/serf.go:60: nomad: adding server: server="nomad-317.global (Addr: 127.0.0.1:9975) (DC: dc1)"
    testlog.go:34: 2020-02-28T21:50:21.990Z [INFO]  nomad/serf.go:60: nomad: adding server: server="nomad-316.global (Addr: 127.0.0.1:9969) (DC: dc1)"
    testlog.go:34: 2020-02-28T21:50:22.039Z [WARN]  raft/raft.go:214: nomad.raft: heartbeat timeout reached, starting election: last-leader=
    testlog.go:34: 2020-02-28T21:50:22.039Z [INFO]  raft/raft.go:250: nomad.raft: entering candidate state: node="Node at 127.0.0.1:9975 [Candidate]" term=2
    testlog.go:34: 2020-02-28T21:50:22.039Z [DEBUG] raft/raft.go:268: nomad.raft: votes: needed=1
    testlog.go:34: 2020-02-28T21:50:22.039Z [DEBUG] raft/raft.go:287: nomad.raft: vote granted: from=127.0.0.1:9975 term=2 tally=1
    testlog.go:34: 2020-02-28T21:50:22.039Z [INFO]  raft/raft.go:292: nomad.raft: election won: tally=1
    testlog.go:34: 2020-02-28T21:50:22.039Z [INFO]  raft/raft.go:363: nomad.raft: entering leader state: leader="Node at 127.0.0.1:9975 [Leader]"
    testlog.go:34: 2020-02-28T21:50:22.039Z [INFO]  nomad/leader.go:71: nomad: cluster leadership acquired
    testlog.go:34: 2020-02-28T21:50:22.040Z [TRACE] nomad/fsm.go:292: nomad.fsm: ClusterSetMetadata: cluster_id=99fb852c-6883-41ce-5c26-549dc690602d create_time=1582926622039975443
    testlog.go:34: 2020-02-28T21:50:22.040Z [INFO]  nomad/leader.go:1415: nomad.core: established cluster id: cluster_id=99fb852c-6883-41ce-5c26-549dc690602d create_time=1582926622039975443
    testlog.go:34: 2020-02-28T21:50:22.040Z [INFO]  raft/raft.go:1018: nomad.raft: updating configuration: command=AddStaging server-id=127.0.0.1:9969 server-addr=127.0.0.1:9969 servers="[{Suffrage:Voter ID:127.0.0.1:9975 Address:127.0.0.1:9975} {Suffrage:Voter ID:127.0.0.1:9969 Address:127.0.0.1:9969}]"
    testlog.go:34: 2020-02-28T21:50:22.040Z [INFO]  raft/raft.go:474: nomad.raft: added peer, starting replication: peer=127.0.0.1:9969
    testlog.go:34: 2020-02-28T21:50:22.040Z [TRACE] drainer/watch_jobs.go:145: nomad.drain.job_watcher: getting job allocs at index: index=1
    testlog.go:34: 2020-02-28T21:50:22.041Z [WARN]  raft/raft.go:1283: nomad.raft: failed to get previous log: previous-index=7 last-index=1 error="log not found"
    testlog.go:34: 2020-02-28T21:50:22.041Z [WARN]  raft/replication.go:248: nomad.raft: appendEntries rejected, sending older logs: peer="{Voter 127.0.0.1:9969 127.0.0.1:9969}" next=2
    testlog.go:34: 2020-02-28T21:50:22.041Z [TRACE] nomad/fsm.go:292: nomad.fsm: ClusterSetMetadata: cluster_id=99fb852c-6883-41ce-5c26-549dc690602d create_time=1582926622039975443
    testlog.go:34: 2020-02-28T21:50:22.042Z [INFO]  raft/replication.go:408: nomad.raft: pipelining replication: peer="{Voter 127.0.0.1:9969 127.0.0.1:9969}"
    testlog.go:34: 2020-02-28T21:50:22.060Z [WARN]  raft/raft.go:214: nomad.raft: heartbeat timeout reached, starting election: last-leader=
    testlog.go:34: 2020-02-28T21:50:22.060Z [INFO]  raft/raft.go:250: nomad.raft: entering candidate state: node="Node at 127.0.0.1:9983 [Candidate]" term=2
    testlog.go:34: 2020-02-28T21:50:22.060Z [DEBUG] raft/raft.go:268: nomad.raft: votes: needed=1
    testlog.go:34: 2020-02-28T21:50:22.060Z [DEBUG] raft/raft.go:287: nomad.raft: vote granted: from=127.0.0.1:9983 term=2 tally=1
    testlog.go:34: 2020-02-28T21:50:22.060Z [INFO]  raft/raft.go:292: nomad.raft: election won: tally=1
    testlog.go:34: 2020-02-28T21:50:22.060Z [INFO]  raft/raft.go:363: nomad.raft: entering leader state: leader="Node at 127.0.0.1:9983 [Leader]"
    testlog.go:34: 2020-02-28T21:50:22.060Z [INFO]  nomad/leader.go:71: nomad: cluster leadership acquired
    testlog.go:34: 2020-02-28T21:50:22.061Z [TRACE] nomad/fsm.go:292: nomad.fsm: ClusterSetMetadata: cluster_id=4bd75cdf-12c5-9b60-2dd2-b49e3cbfe26b create_time=1582926622061209034
    testlog.go:34: 2020-02-28T21:50:22.061Z [INFO]  nomad/leader.go:1415: nomad.core: established cluster id: cluster_id=4bd75cdf-12c5-9b60-2dd2-b49e3cbfe26b create_time=1582926622061209034
    testlog.go:34: 2020-02-28T21:50:22.061Z [INFO]  raft/raft.go:1018: nomad.raft: updating configuration: command=AddStaging server-id=127.0.0.1:9975 server-addr=127.0.0.1:9975 servers="[{Suffrage:Voter ID:127.0.0.1:9983 Address:127.0.0.1:9983} {Suffrage:Voter ID:127.0.0.1:9975 Address:127.0.0.1:9975}]"
    testlog.go:34: 2020-02-28T21:50:22.061Z [INFO]  raft/raft.go:474: nomad.raft: added peer, starting replication: peer=127.0.0.1:9975
    testlog.go:34: 2020-02-28T21:50:22.061Z [INFO]  raft/raft.go:1018: nomad.raft: updating configuration: command=AddStaging server-id=127.0.0.1:9969 server-addr=127.0.0.1:9969 servers="[{Suffrage:Voter ID:127.0.0.1:9983 Address:127.0.0.1:9983} {Suffrage:Voter ID:127.0.0.1:9975 Address:127.0.0.1:9975} {Suffrage:Voter ID:127.0.0.1:9969 Address:127.0.0.1:9969}]"
    testlog.go:34: 2020-02-28T21:50:22.061Z [INFO]  raft/raft.go:474: nomad.raft: added peer, starting replication: peer=127.0.0.1:9969
    testlog.go:34: 2020-02-28T21:50:22.061Z [TRACE] drainer/watch_jobs.go:145: nomad.drain.job_watcher: getting job allocs at index: index=1
    testlog.go:34: 2020-02-28T21:50:22.063Z [INFO]  raft/raft.go:152: nomad.raft: entering follower state: follower="Node at 127.0.0.1:9975 [Follower]" leader=127.0.0.1:9983
    testlog.go:34: 2020-02-28T21:50:22.063Z [DEBUG] nomad/leader.go:80: nomad: shutting down leader loop
    testlog.go:34: 2020-02-28T21:50:22.063Z [INFO]  raft/replication.go:456: nomad.raft: aborting pipeline replication: peer="{Voter 127.0.0.1:9969 127.0.0.1:9969}"
    testlog.go:34: 2020-02-28T21:50:22.063Z [INFO]  nomad/leader.go:84: nomad: cluster leadership lost
    testlog.go:34: 2020-02-28T21:50:22.063Z [TRACE] drainer/watch_jobs.go:147: nomad.drain.job_watcher: retrieved allocs for draining jobs: num_allocs=0 index=0 error="context canceled"
    testlog.go:34: 2020-02-28T21:50:22.063Z [TRACE] drainer/watch_jobs.go:153: nomad.drain.job_watcher: shutting down
    testlog.go:34: 2020-02-28T21:50:22.063Z [INFO]  raft/replication.go:408: nomad.raft: pipelining replication: peer="{Voter 127.0.0.1:9975 127.0.0.1:9975}"
    testlog.go:34: 2020-02-28T21:50:22.063Z [WARN]  raft/raft.go:1283: nomad.raft: failed to get previous log: previous-index=8 last-index=7 error="log not found"
    testlog.go:34: 2020-02-28T21:50:22.064Z [WARN]  raft/replication.go:248: nomad.raft: appendEntries rejected, sending older logs: peer="{Voter 127.0.0.1:9969 127.0.0.1:9969}" next=8
    testlog.go:34: 2020-02-28T21:50:22.064Z [INFO]  raft/replication.go:408: nomad.raft: pipelining replication: peer="{Voter 127.0.0.1:9969 127.0.0.1:9969}"
    testlog.go:34: 2020-02-28T21:50:22.084Z [INFO]  go-hclog/stdlog.go:46: nomad: serf: EventMemberJoin: nomad-318.global 127.0.0.1
    testlog.go:34: 2020-02-28T21:50:22.084Z [INFO]  nomad/serf.go:60: nomad: adding server: server="nomad-318.global (Addr: 127.0.0.1:9983) (DC: dc1)"
    testlog.go:34: 2020-02-28T21:50:22.085Z [DEBUG] go-hclog/stdlog.go:44: nomad: serf: messageJoinType: nomad-318.global
    testlog.go:34: 2020-02-28T21:50:22.085Z [DEBUG] go-hclog/stdlog.go:44: nomad: serf: messageJoinType: nomad-317.global
    testlog.go:34: 2020-02-28T21:50:22.086Z [DEBUG] go-hclog/stdlog.go:44: nomad: serf: messageJoinType: nomad-317.global
    testlog.go:34: 2020-02-28T21:50:22.086Z [DEBUG] go-hclog/stdlog.go:44: nomad: serf: messageJoinType: nomad-318.global
    testlog.go:34: 2020-02-28T21:50:22.087Z [DEBUG] go-hclog/stdlog.go:44: nomad: serf: messageJoinType: nomad-318.global
    testlog.go:34: 2020-02-28T21:50:22.087Z [DEBUG] go-hclog/stdlog.go:44: nomad: serf: messageJoinType: nomad-317.global
    testlog.go:34: 2020-02-28T21:50:22.087Z [DEBUG] go-hclog/stdlog.go:44: nomad: serf: messageJoinType: nomad-317.global
    testlog.go:34: 2020-02-28T21:50:22.088Z [DEBUG] go-hclog/stdlog.go:44: nomad: serf: messageJoinType: nomad-318.global
    testlog.go:34: 2020-02-28T21:50:22.183Z [DEBUG] go-hclog/stdlog.go:44: nomad: serf: messageJoinType: nomad-318.global
    testlog.go:34: 2020-02-28T21:50:22.183Z [DEBUG] go-hclog/stdlog.go:44: nomad: serf: messageJoinType: nomad-317.global
    testlog.go:34: 2020-02-28T21:50:22.183Z [DEBUG] go-hclog/stdlog.go:44: nomad: serf: messageJoinType: nomad-317.global
    testlog.go:34: 2020-02-28T21:50:22.183Z [DEBUG] go-hclog/stdlog.go:44: nomad: serf: messageJoinType: nomad-318.global
    leader_test.go:857: 
        	Error Trace:	leader_test.go:857
        	            				leader_test.go:837
        	Error:      	Should be true
        	Test:       	TestLeader_ClusterID_noUpgrade
        	Messages:   	ids[0] 99fb852c-6883-41ce-5c26-549dc690602d, ids[1] 99fb852c-6883-41ce-5c26-549dc690602d, ids[2] 4bd75cdf-12c5-9b60-2dd2-b49e3cbfe26b
    testlog.go:34: 2020-02-28T21:50:24.143Z [INFO]  nomad/server.go:594: nomad: shutting down server
    testlog.go:34: 2020-02-28T21:50:24.143Z [WARN]  go-hclog/stdlog.go:48: nomad: serf: Shutdown without a Leave
    testlog.go:34: 2020-02-28T21:50:24.143Z [INFO]  raft/replication.go:456: nomad.raft: aborting pipeline replication: peer="{Voter 127.0.0.1:9975 127.0.0.1:9975}"
    testlog.go:34: 2020-02-28T21:50:24.144Z [TRACE] drainer/watch_jobs.go:147: nomad.drain.job_watcher: retrieved allocs for draining jobs: num_allocs=0 index=0 error="context canceled"
    testlog.go:34: 2020-02-28T21:50:24.144Z [TRACE] drainer/watch_jobs.go:153: nomad.drain.job_watcher: shutting down
    testlog.go:34: 2020-02-28T21:50:24.144Z [INFO]  raft/replication.go:456: nomad.raft: aborting pipeline replication: peer="{Voter 127.0.0.1:9969 127.0.0.1:9969}"
    testlog.go:34: 2020-02-28T21:50:24.144Z [INFO]  nomad/server.go:594: nomad: shutting down server
    testlog.go:34: 2020-02-28T21:50:24.144Z [WARN]  go-hclog/stdlog.go:48: nomad: serf: Shutdown without a Leave
    testlog.go:34: 2020-02-28T21:50:24.144Z [INFO]  nomad/server.go:594: nomad: shutting down server
    testlog.go:34: 2020-02-28T21:50:24.144Z [WARN]  go-hclog/stdlog.go:48: nomad: serf: Shutdown without a Leave
@schmichael schmichael added the theme/testing Test related issues label Feb 28, 2020
@notnoop notnoop mentioned this issue Mar 3, 2020
Merged
@github-actions
Copy link

I'm going to lock this issue because it has been closed for 120 days ⏳. This helps our maintainers find and focus on the active issues.
If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Nov 12, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
theme/testing Test related issues
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Simplify Bootstrap logic in tests hashicorp/nomad
1 participant
@schmichael