search

hashicorp / nomad

Nomad is an easy-to-use, flexible, and performant workload orchestrator that can deploy a mix of microservice, batch, containerized, and non-containerized applications. Nomad is easy to operate and scale and has native Consul and Vault integrations.
https://www.nomadproject.io/
Other
14.86k stars 1.95k forks source link

TestLeader_ClusterID_noUpgrade flaky test #7239

Closed schmichael closed 4 years ago

schmichael commented 4 years ago

Version: v0.11-dev PR: #7231 Commit: f359bfe85323f0870bdfd7c1e475675fc77f816b 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
github-actions[bot] commented 1 year ago

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.