[pkg-go] Bug#907764: golang-github-hashicorp-raft: FTBFS in buster/sid (failing tests)
Santiago Vila
sanvila at debian.org
Sat Sep 1 17:30:49 BST 2018
Package: src:golang-github-hashicorp-raft
Version: 1.0.0+git20180118.077966db-1
Severity: serious
Tags: ftbfs
Dear maintainer:
I tried to build this package in buster but it failed:
--------------------------------------------------------------------------------
[...]
debian/rules build-indep
dh build-indep --buildsystem=golang --with=golang
dh_update_autotools_config -i -O--buildsystem=golang
dh_auto_configure -i -O--buildsystem=golang
dh_auto_build -i -O--buildsystem=golang
cd obj-x86_64-linux-gnu && go install -gcflags=\"-trimpath=/<<BUILDDIR>>/golang-github-hashicorp-raft-1.0.0\+git20180118.077966db/obj-x86_64-linux-gnu/src\" -asmflags=\"-trimpath=/<<BUILDDIR>>/golang-github-hashicorp-raft-1.0.0\+git20180118.077966db/obj-x86_64-linux-gnu/src\" -v -p 1 github.com/hashicorp/raft github.com/hashicorp/raft/bench
github.com/hashicorp/golang-lru/simplelru
github.com/hashicorp/go-immutable-radix
github.com/armon/go-metrics
github.com/hashicorp/go-msgpack/codec
github.com/hashicorp/raft
github.com/hashicorp/raft/bench
dh_auto_test -i -O--buildsystem=golang
cd obj-x86_64-linux-gnu && go test -vet=off -v -p 1 github.com/hashicorp/raft github.com/hashicorp/raft/bench
=== RUN TestCommitment_setVoters
--- PASS: TestCommitment_setVoters (0.00s)
=== RUN TestCommitment_match_max
--- PASS: TestCommitment_match_max (0.00s)
=== RUN TestCommitment_match_nonVoting
--- PASS: TestCommitment_match_nonVoting (0.00s)
=== RUN TestCommitment_recalculate
--- PASS: TestCommitment_recalculate (0.00s)
=== RUN TestCommitment_recalculate_startIndex
--- PASS: TestCommitment_recalculate_startIndex (0.00s)
=== RUN TestCommitment_noVoterSanity
--- PASS: TestCommitment_noVoterSanity (0.00s)
=== RUN TestCommitment_singleVoter
--- PASS: TestCommitment_singleVoter (0.00s)
=== RUN TestConfiguration_Configuration_Clone
--- PASS: TestConfiguration_Configuration_Clone (0.00s)
=== RUN TestConfiguration_configurations_Clone
--- PASS: TestConfiguration_configurations_Clone (0.00s)
=== RUN TestConfiguration_hasVote
--- PASS: TestConfiguration_hasVote (0.00s)
=== RUN TestConfiguration_checkConfiguration
--- PASS: TestConfiguration_checkConfiguration (0.00s)
=== RUN TestConfiguration_nextConfiguration_table
--- PASS: TestConfiguration_nextConfiguration_table (0.00s)
=== RUN TestConfiguration_nextConfiguration_prevIndex
--- PASS: TestConfiguration_nextConfiguration_prevIndex (0.00s)
=== RUN TestConfiguration_nextConfiguration_checkConfiguration
--- PASS: TestConfiguration_nextConfiguration_checkConfiguration (0.00s)
=== RUN TestConfiguration_encodeDecodePeers
--- PASS: TestConfiguration_encodeDecodePeers (0.00s)
=== RUN TestConfiguration_encodeDecodeConfiguration
--- PASS: TestConfiguration_encodeDecodeConfiguration (0.00s)
=== RUN TestDiscardSnapshotStoreImpl
--- PASS: TestDiscardSnapshotStoreImpl (0.00s)
=== RUN TestDiscardSnapshotSinkImpl
--- PASS: TestDiscardSnapshotSinkImpl (0.00s)
=== RUN TestFileSnapshotStoreImpl
--- PASS: TestFileSnapshotStoreImpl (0.00s)
=== RUN TestFileSnapshotSinkImpl
--- PASS: TestFileSnapshotSinkImpl (0.00s)
=== RUN TestFileSS_CreateSnapshotMissingParentDir
--- PASS: TestFileSS_CreateSnapshotMissingParentDir (0.14s)
raft_test.go:101: 21:34:33.261773 [INFO] snapshot: Creating new snapshot at /tmp/raft068757217/raft335529164/snapshots/3-10-1533504873261.tmp
=== RUN TestFileSS_CreateSnapshot
--- PASS: TestFileSS_CreateSnapshot (0.50s)
raft_test.go:101: 21:34:33.401289 [INFO] snapshot: Creating new snapshot at /tmp/raft997309883/snapshots/3-10-1533504873401.tmp
raft_test.go:101: 21:34:33.534238 [WARN] snapshot: Found temporary snapshot: 3-10-1533504873401.tmp
=== RUN TestFileSS_CancelSnapshot
--- PASS: TestFileSS_CancelSnapshot (0.13s)
raft_test.go:101: 21:34:33.899206 [INFO] snapshot: Creating new snapshot at /tmp/raft437327838/snapshots/3-10-1533504873899.tmp
=== RUN TestFileSS_Retention
--- PASS: TestFileSS_Retention (2.67s)
raft_test.go:101: 21:34:34.032449 [INFO] snapshot: Creating new snapshot at /tmp/raft011354021/snapshots/3-10-1533504874032.tmp
raft_test.go:101: 21:34:34.591751 [INFO] snapshot: Creating new snapshot at /tmp/raft011354021/snapshots/3-11-1533504874591.tmp
raft_test.go:101: 21:34:35.192120 [INFO] snapshot: Creating new snapshot at /tmp/raft011354021/snapshots/3-12-1533504875192.tmp
raft_test.go:101: 21:34:35.691391 [INFO] snapshot: reaping snapshot /tmp/raft011354021/snapshots/3-10-1533504874032
raft_test.go:101: 21:34:35.691859 [INFO] snapshot: Creating new snapshot at /tmp/raft011354021/snapshots/3-13-1533504875691.tmp
raft_test.go:101: 21:34:36.206487 [INFO] snapshot: reaping snapshot /tmp/raft011354021/snapshots/3-11-1533504874591
raft_test.go:101: 21:34:36.206936 [INFO] snapshot: Creating new snapshot at /tmp/raft011354021/snapshots/3-14-1533504876206.tmp
raft_test.go:101: 21:34:36.703417 [INFO] snapshot: reaping snapshot /tmp/raft011354021/snapshots/3-12-1533504875192
=== RUN TestFileSS_BadPerm
--- PASS: TestFileSS_BadPerm (0.00s)
=== RUN TestFileSS_MissingParentDir
--- PASS: TestFileSS_MissingParentDir (0.00s)
=== RUN TestFileSS_Ordering
--- PASS: TestFileSS_Ordering (0.87s)
raft_test.go:101: 21:34:36.705125 [INFO] snapshot: Creating new snapshot at /tmp/raft464535028/snapshots/5-130350-1533504876705.tmp
raft_test.go:101: 21:34:37.210217 [INFO] snapshot: Creating new snapshot at /tmp/raft464535028/snapshots/36-204917-1533504877210.tmp
=== RUN TestDeferFutureSuccess
--- PASS: TestDeferFutureSuccess (0.00s)
=== RUN TestDeferFutureError
--- PASS: TestDeferFutureError (0.00s)
=== RUN TestDeferFutureConcurrent
--- PASS: TestDeferFutureConcurrent (0.00s)
=== RUN TestInmemSnapshotStoreImpl
--- PASS: TestInmemSnapshotStoreImpl (0.00s)
=== RUN TestInmemSnapshotSinkImpl
--- PASS: TestInmemSnapshotSinkImpl (0.00s)
=== RUN TestInmemSS_CreateSnapshot
--- PASS: TestInmemSS_CreateSnapshot (0.00s)
=== RUN TestInmemTransportImpl
--- PASS: TestInmemTransportImpl (0.00s)
=== RUN TestRaft_Integ
--- SKIP: TestRaft_Integ (0.00s)
=== RUN TestLogCache
--- PASS: TestLogCache (0.00s)
=== RUN TestNetworkTransport_CloseStreams
--- PASS: TestNetworkTransport_CloseStreams (0.01s)
raft_test.go:101: 21:34:37.585661 [DEBUG] raft-net: 127.0.0.1:43803 accepted connection from: 127.0.0.1:45228
raft_test.go:101: 21:34:37.587586 [DEBUG] raft-net: 127.0.0.1:43803 accepted connection from: 127.0.0.1:45230
raft_test.go:101: 21:34:37.587635 [DEBUG] raft-net: 127.0.0.1:43803 accepted connection from: 127.0.0.1:45232
raft_test.go:101: 21:34:37.587679 [DEBUG] raft-net: 127.0.0.1:43803 accepted connection from: 127.0.0.1:45234
raft_test.go:101: 21:34:37.587715 [DEBUG] raft-net: 127.0.0.1:43803 accepted connection from: 127.0.0.1:45236
raft_test.go:101: 21:34:37.590433 [DEBUG] raft-net: 127.0.0.1:43803 accepted connection from: 127.0.0.1:45238
raft_test.go:101: 21:34:37.590479 [DEBUG] raft-net: 127.0.0.1:43803 accepted connection from: 127.0.0.1:45240
raft_test.go:101: 21:34:37.590522 [DEBUG] raft-net: 127.0.0.1:43803 accepted connection from: 127.0.0.1:45242
raft_test.go:101: 21:34:37.590552 [DEBUG] raft-net: 127.0.0.1:43803 accepted connection from: 127.0.0.1:45244
raft_test.go:101: 21:34:37.591003 [DEBUG] raft-net: 127.0.0.1:43803 accepted connection from: 127.0.0.1:45246
=== RUN TestNetworkTransport_StartStop
--- PASS: TestNetworkTransport_StartStop (0.00s)
=== RUN TestNetworkTransport_Heartbeat_FastPath
--- PASS: TestNetworkTransport_Heartbeat_FastPath (0.00s)
raft_test.go:101: 21:34:37.596801 [DEBUG] raft-net: 127.0.0.1:45387 accepted connection from: 127.0.0.1:42658
=== RUN TestNetworkTransport_AppendEntries
--- PASS: TestNetworkTransport_AppendEntries (0.00s)
raft_test.go:101: 21:34:37.599005 [DEBUG] raft-net: 127.0.0.1:37269 accepted connection from: 127.0.0.1:35250
raft_test.go:101: 21:34:37.599782 [DEBUG] raft-net: 127.0.0.1:39797 accepted connection from: 127.0.0.1:46418
=== RUN TestNetworkTransport_AppendEntriesPipeline
--- PASS: TestNetworkTransport_AppendEntriesPipeline (0.00s)
raft_test.go:101: 21:34:37.602850 [DEBUG] raft-net: 127.0.0.1:35029 accepted connection from: 127.0.0.1:51152
raft_test.go:101: 21:34:37.604563 [DEBUG] raft-net: 127.0.0.1:33943 accepted connection from: 127.0.0.1:42982
=== RUN TestNetworkTransport_AppendEntriesPipeline_CloseStreams
--- FAIL: TestNetworkTransport_AppendEntriesPipeline_CloseStreams (0.01s)
raft_test.go:101: 21:34:37.607625 [DEBUG] raft-net: 127.0.0.1:42603 accepted connection from: 127.0.0.1:54548
net_transport_test.go:430: expected an error due to the streams being closed
=== RUN TestNetworkTransport_RequestVote
--- PASS: TestNetworkTransport_RequestVote (0.00s)
raft_test.go:101: 21:34:37.622810 [DEBUG] raft-net: 127.0.0.1:46533 accepted connection from: 127.0.0.1:49862
raft_test.go:101: 21:34:37.623203 [DEBUG] raft-net: 127.0.0.1:39871 accepted connection from: 127.0.0.1:41336
=== RUN TestNetworkTransport_InstallSnapshot
--- PASS: TestNetworkTransport_InstallSnapshot (0.00s)
raft_test.go:101: 21:34:37.624322 [DEBUG] raft-net: 127.0.0.1:38327 accepted connection from: 127.0.0.1:47078
raft_test.go:101: 21:34:37.624703 [DEBUG] raft-net: 127.0.0.1:38457 accepted connection from: 127.0.0.1:59188
=== RUN TestNetworkTransport_EncodeDecode
--- PASS: TestNetworkTransport_EncodeDecode (0.00s)
=== RUN TestNetworkTransport_EncodeDecode_AddressProvider
--- PASS: TestNetworkTransport_EncodeDecode_AddressProvider (0.00s)
=== RUN TestNetworkTransport_PooledConn
--- PASS: TestNetworkTransport_PooledConn (0.00s)
raft_test.go:101: 21:34:37.626694 [DEBUG] raft-net: 127.0.0.1:36083 accepted connection from: 127.0.0.1:53178
raft_test.go:101: 21:34:37.627528 [DEBUG] raft-net: 127.0.0.1:36083 accepted connection from: 127.0.0.1:53180
raft_test.go:101: 21:34:37.627570 [DEBUG] raft-net: 127.0.0.1:36083 accepted connection from: 127.0.0.1:53182
raft_test.go:101: 21:34:37.627594 [DEBUG] raft-net: 127.0.0.1:36083 accepted connection from: 127.0.0.1:53184
raft_test.go:101: 21:34:37.627610 [DEBUG] raft-net: 127.0.0.1:36083 accepted connection from: 127.0.0.1:53186
=== RUN TestPeersJSON_BadConfiguration
--- PASS: TestPeersJSON_BadConfiguration (0.00s)
=== RUN TestPeersJSON_ReadPeersJSON
--- PASS: TestPeersJSON_ReadPeersJSON (0.00s)
=== RUN TestPeersJSON_ReadConfigJSON
--- PASS: TestPeersJSON_ReadConfigJSON (0.00s)
=== RUN TestRaft_ProtocolVersion_RejectRPC
testLoggerAdapter verbose: cluster: 21:34:37.630973 [DEBUG] Fully Connecting
testLoggerAdapter verbose: server-7333363b-f44c-0ac4-5583-33011bff02e1: 21:34:37.631290 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-7333363b-f44c-0ac4-5583-33011bff02e1 Address:7333363b-f44c-0ac4-5583-33011bff02e1} {Suffrage:Voter ID:server-a7bec59b-fd42-090d-6959-801a534d0671 Address:a7bec59b-fd42-090d-6959-801a534d0671} {Suffrage:Voter ID:server-4173eaa8-dcef-283e-3345-6e663b2d5437 Address:4173eaa8-dcef-283e-3345-6e663b2d5437}]
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.631546 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-7333363b-f44c-0ac4-5583-33011bff02e1 Address:7333363b-f44c-0ac4-5583-33011bff02e1} {Suffrage:Voter ID:server-a7bec59b-fd42-090d-6959-801a534d0671 Address:a7bec59b-fd42-090d-6959-801a534d0671} {Suffrage:Voter ID:server-4173eaa8-dcef-283e-3345-6e663b2d5437 Address:4173eaa8-dcef-283e-3345-6e663b2d5437}]
testLoggerAdapter verbose: server-4173eaa8-dcef-283e-3345-6e663b2d5437: 21:34:37.631782 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-7333363b-f44c-0ac4-5583-33011bff02e1 Address:7333363b-f44c-0ac4-5583-33011bff02e1} {Suffrage:Voter ID:server-a7bec59b-fd42-090d-6959-801a534d0671 Address:a7bec59b-fd42-090d-6959-801a534d0671} {Suffrage:Voter ID:server-4173eaa8-dcef-283e-3345-6e663b2d5437 Address:4173eaa8-dcef-283e-3345-6e663b2d5437}]
testLoggerAdapter verbose: cluster: 21:34:37.631916 [INFO] Starting stability test for raft state: Follower
testLoggerAdapter verbose: server-7333363b-f44c-0ac4-5583-33011bff02e1: 21:34:37.632074 [INFO] raft: Node at 7333363b-f44c-0ac4-5583-33011bff02e1 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.632096 [INFO] raft: Node at a7bec59b-fd42-090d-6959-801a534d0671 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: server-4173eaa8-dcef-283e-3345-6e663b2d5437: 21:34:37.632140 [INFO] raft: Node at 4173eaa8-dcef-283e-3345-6e663b2d5437 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.690712 [WARN] raft: Heartbeat timeout from "" reached, starting election
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.690807 [INFO] raft: Node at a7bec59b-fd42-090d-6959-801a534d0671 [Candidate] entering Candidate state in term 2
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.690883 [DEBUG] raft: Votes needed: 2
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.690912 [DEBUG] raft: Vote granted from server-a7bec59b-fd42-090d-6959-801a534d0671 in term 2. Tally: 1
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.691010 [DEBUG] raft: Vote granted from server-4173eaa8-dcef-283e-3345-6e663b2d5437 in term 2. Tally: 2
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.691031 [INFO] raft: Election won. Tally: 2
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.691053 [INFO] raft: Node at a7bec59b-fd42-090d-6959-801a534d0671 [Leader] entering Leader state
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.691089 [INFO] raft: Added peer server-7333363b-f44c-0ac4-5583-33011bff02e1, starting replication
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.691110 [INFO] raft: Added peer server-4173eaa8-dcef-283e-3345-6e663b2d5437, starting replication
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.691235 [INFO] raft: pipelining replication to peer {Voter server-4173eaa8-dcef-283e-3345-6e663b2d5437 4173eaa8-dcef-283e-3345-6e663b2d5437}
testLoggerAdapter verbose: cluster: 21:34:37.691334 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: cluster: 21:34:37.691368 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: cluster: 21:34:37.691388 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.691497 [INFO] raft: pipelining replication to peer {Voter server-7333363b-f44c-0ac4-5583-33011bff02e1 7333363b-f44c-0ac4-5583-33011bff02e1}
testLoggerAdapter verbose: cluster: 21:34:37.691582 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: cluster: 21:34:37.796756 [INFO] Stable state for Follower reached at 2018-08-05 21:34:37.691599967 +0000 UTC m=+4.431992423 (2 nodes), 59.41985ms from start of poll, 60.465526ms from cluster start. Timeout at 2018-08-05 21:34:37.796658813 +0000 UTC m=+4.537051171, 105.058748ms after stability
testLoggerAdapter verbose: cluster: 21:34:37.796820 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: cluster: 21:34:37.902153 [INFO] Stable state for Leader reached at 2018-08-05 21:34:37.796832499 +0000 UTC m=+4.537224859 (1 nodes), 1.845µs from start of poll, 165.697962ms from cluster start. Timeout at 2018-08-05 21:34:37.902067048 +0000 UTC m=+4.642459569, 105.23471ms after stability
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.902321 [INFO] raft: aborting pipeline replication to peer {Voter server-4173eaa8-dcef-283e-3345-6e663b2d5437 4173eaa8-dcef-283e-3345-6e663b2d5437}
testLoggerAdapter verbose: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.902369 [INFO] raft: aborting pipeline replication to peer {Voter server-7333363b-f44c-0ac4-5583-33011bff02e1 7333363b-f44c-0ac4-5583-33011bff02e1}
--- PASS: TestRaft_ProtocolVersion_RejectRPC (0.27s)
raft_test.go:97: cluster: 21:34:37.630973 [DEBUG] Fully Connecting
raft_test.go:97: server-7333363b-f44c-0ac4-5583-33011bff02e1: 21:34:37.631290 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-7333363b-f44c-0ac4-5583-33011bff02e1 Address:7333363b-f44c-0ac4-5583-33011bff02e1} {Suffrage:Voter ID:server-a7bec59b-fd42-090d-6959-801a534d0671 Address:a7bec59b-fd42-090d-6959-801a534d0671} {Suffrage:Voter ID:server-4173eaa8-dcef-283e-3345-6e663b2d5437 Address:4173eaa8-dcef-283e-3345-6e663b2d5437}]
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.631546 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-7333363b-f44c-0ac4-5583-33011bff02e1 Address:7333363b-f44c-0ac4-5583-33011bff02e1} {Suffrage:Voter ID:server-a7bec59b-fd42-090d-6959-801a534d0671 Address:a7bec59b-fd42-090d-6959-801a534d0671} {Suffrage:Voter ID:server-4173eaa8-dcef-283e-3345-6e663b2d5437 Address:4173eaa8-dcef-283e-3345-6e663b2d5437}]
raft_test.go:97: server-4173eaa8-dcef-283e-3345-6e663b2d5437: 21:34:37.631782 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-7333363b-f44c-0ac4-5583-33011bff02e1 Address:7333363b-f44c-0ac4-5583-33011bff02e1} {Suffrage:Voter ID:server-a7bec59b-fd42-090d-6959-801a534d0671 Address:a7bec59b-fd42-090d-6959-801a534d0671} {Suffrage:Voter ID:server-4173eaa8-dcef-283e-3345-6e663b2d5437 Address:4173eaa8-dcef-283e-3345-6e663b2d5437}]
raft_test.go:97: cluster: 21:34:37.631916 [INFO] Starting stability test for raft state: Follower
raft_test.go:97: server-7333363b-f44c-0ac4-5583-33011bff02e1: 21:34:37.632074 [INFO] raft: Node at 7333363b-f44c-0ac4-5583-33011bff02e1 [Follower] entering Follower state (Leader: "")
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.632096 [INFO] raft: Node at a7bec59b-fd42-090d-6959-801a534d0671 [Follower] entering Follower state (Leader: "")
raft_test.go:97: server-4173eaa8-dcef-283e-3345-6e663b2d5437: 21:34:37.632140 [INFO] raft: Node at 4173eaa8-dcef-283e-3345-6e663b2d5437 [Follower] entering Follower state (Leader: "")
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.690712 [WARN] raft: Heartbeat timeout from "" reached, starting election
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.690807 [INFO] raft: Node at a7bec59b-fd42-090d-6959-801a534d0671 [Candidate] entering Candidate state in term 2
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.690883 [DEBUG] raft: Votes needed: 2
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.690912 [DEBUG] raft: Vote granted from server-a7bec59b-fd42-090d-6959-801a534d0671 in term 2. Tally: 1
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.691010 [DEBUG] raft: Vote granted from server-4173eaa8-dcef-283e-3345-6e663b2d5437 in term 2. Tally: 2
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.691031 [INFO] raft: Election won. Tally: 2
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.691053 [INFO] raft: Node at a7bec59b-fd42-090d-6959-801a534d0671 [Leader] entering Leader state
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.691089 [INFO] raft: Added peer server-7333363b-f44c-0ac4-5583-33011bff02e1, starting replication
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.691110 [INFO] raft: Added peer server-4173eaa8-dcef-283e-3345-6e663b2d5437, starting replication
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.691235 [INFO] raft: pipelining replication to peer {Voter server-4173eaa8-dcef-283e-3345-6e663b2d5437 4173eaa8-dcef-283e-3345-6e663b2d5437}
raft_test.go:97: cluster: 21:34:37.691334 [DEBUG] Resetting stability timeout
raft_test.go:97: cluster: 21:34:37.691368 [DEBUG] Resetting stability timeout
raft_test.go:97: cluster: 21:34:37.691388 [DEBUG] Resetting stability timeout
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.691497 [INFO] raft: pipelining replication to peer {Voter server-7333363b-f44c-0ac4-5583-33011bff02e1 7333363b-f44c-0ac4-5583-33011bff02e1}
raft_test.go:97: cluster: 21:34:37.691582 [DEBUG] Resetting stability timeout
raft_test.go:97: cluster: 21:34:37.796756 [INFO] Stable state for Follower reached at 2018-08-05 21:34:37.691599967 +0000 UTC m=+4.431992423 (2 nodes), 59.41985ms from start of poll, 60.465526ms from cluster start. Timeout at 2018-08-05 21:34:37.796658813 +0000 UTC m=+4.537051171, 105.058748ms after stability
raft_test.go:97: cluster: 21:34:37.796820 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: cluster: 21:34:37.902153 [INFO] Stable state for Leader reached at 2018-08-05 21:34:37.796832499 +0000 UTC m=+4.537224859 (1 nodes), 1.845µs from start of poll, 165.697962ms from cluster start. Timeout at 2018-08-05 21:34:37.902067048 +0000 UTC m=+4.642459569, 105.23471ms after stability
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.902321 [INFO] raft: aborting pipeline replication to peer {Voter server-4173eaa8-dcef-283e-3345-6e663b2d5437 4173eaa8-dcef-283e-3345-6e663b2d5437}
raft_test.go:97: server-a7bec59b-fd42-090d-6959-801a534d0671: 21:34:37.902369 [INFO] raft: aborting pipeline replication to peer {Voter server-7333363b-f44c-0ac4-5583-33011bff02e1 7333363b-f44c-0ac4-5583-33011bff02e1}
=== RUN TestRaft_ProtocolVersion_Upgrade_1_2
testLoggerAdapter verbose: cluster: 21:34:37.903769 [DEBUG] Fully Connecting
testLoggerAdapter verbose: e2d7d56f-5c15-9fda-8f5c-58649d49e7a2: 21:34:37.904016 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 Address:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2} {Suffrage:Voter ID:e6a27847-1561-0356-4b8e-83d498cf019d Address:e6a27847-1561-0356-4b8e-83d498cf019d}]
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.904188 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 Address:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2} {Suffrage:Voter ID:e6a27847-1561-0356-4b8e-83d498cf019d Address:e6a27847-1561-0356-4b8e-83d498cf019d}]
testLoggerAdapter verbose: cluster: 21:34:37.904493 [DEBUG] Fully Connecting
testLoggerAdapter verbose: 5e697909-978f-4783-0601-42a9c3a56df9: 21:34:37.904575 [INFO] raft: Initial configuration (index=0): []
testLoggerAdapter verbose: cluster: 21:34:37.904644 [DEBUG] Fully Connecting
testLoggerAdapter verbose: cluster: 21:34:37.904670 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: e2d7d56f-5c15-9fda-8f5c-58649d49e7a2: 21:34:37.904722 [INFO] raft: Node at e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.904768 [INFO] raft: Node at e6a27847-1561-0356-4b8e-83d498cf019d [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: 5e697909-978f-4783-0601-42a9c3a56df9: 21:34:37.904813 [INFO] raft: Node at 5e697909-978f-4783-0601-42a9c3a56df9 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961367 [WARN] raft: Heartbeat timeout from "" reached, starting election
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961476 [INFO] raft: Node at e6a27847-1561-0356-4b8e-83d498cf019d [Candidate] entering Candidate state in term 2
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961521 [DEBUG] raft: Votes needed: 2
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961546 [DEBUG] raft: Vote granted from e6a27847-1561-0356-4b8e-83d498cf019d in term 2. Tally: 1
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961693 [DEBUG] raft: Vote granted from e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 in term 2. Tally: 2
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961720 [INFO] raft: Election won. Tally: 2
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961745 [INFO] raft: Node at e6a27847-1561-0356-4b8e-83d498cf019d [Leader] entering Leader state
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961768 [INFO] raft: Added peer e2d7d56f-5c15-9fda-8f5c-58649d49e7a2, starting replication
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961897 [INFO] raft: pipelining replication to peer {Voter e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 e2d7d56f-5c15-9fda-8f5c-58649d49e7a2}
testLoggerAdapter verbose: cluster: 21:34:37.961938 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: cluster: 21:34:37.961971 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: cluster: 21:34:37.962001 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: 5e697909-978f-4783-0601-42a9c3a56df9: 21:34:37.998468 [WARN] raft: no known peers, aborting election
testLoggerAdapter verbose: cluster: 21:34:38.067227 [INFO] Stable state for Leader reached at 2018-08-05 21:34:37.962046175 +0000 UTC m=+4.702438631 (1 nodes), 57.357732ms from start of poll, 58.239831ms from cluster start. Timeout at 2018-08-05 21:34:38.067178511 +0000 UTC m=+4.807570929, 105.132298ms after stability
testLoggerAdapter verbose: cluster: 21:34:38.067515 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: cluster: 21:34:38.173010 [INFO] Stable state for Leader reached at 2018-08-05 21:34:38.067696606 +0000 UTC m=+4.808088989 (1 nodes), 865ns from start of poll, 163.890189ms from cluster start. Timeout at 2018-08-05 21:34:38.172913591 +0000 UTC m=+4.913306110, 105.217121ms after stability
testLoggerAdapter verbose: cluster: 21:34:38.173450 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: cluster: 21:34:38.278925 [INFO] Stable state for Leader reached at 2018-08-05 21:34:38.173837282 +0000 UTC m=+4.914229710 (1 nodes), 1.543µs from start of poll, 270.03091ms from cluster start. Timeout at 2018-08-05 21:34:38.278906342 +0000 UTC m=+5.019298694, 105.068984ms after stability
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.279139 [INFO] raft: Updating configuration with AddStaging (5e697909-978f-4783-0601-42a9c3a56df9, 5e697909-978f-4783-0601-42a9c3a56df9) to [{Suffrage:Voter ID:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 Address:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2} {Suffrage:Voter ID:e6a27847-1561-0356-4b8e-83d498cf019d Address:e6a27847-1561-0356-4b8e-83d498cf019d} {Suffrage:Voter ID:5e697909-978f-4783-0601-42a9c3a56df9 Address:5e697909-978f-4783-0601-42a9c3a56df9}]
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.279261 [INFO] raft: Added peer 5e697909-978f-4783-0601-42a9c3a56df9, starting replication
testLoggerAdapter verbose: 5e697909-978f-4783-0601-42a9c3a56df9: 21:34:38.279377 [WARN] raft: Failed to get previous log: 3 log not found (last: 0)
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.279466 [WARN] raft: AppendEntries to {Voter 5e697909-978f-4783-0601-42a9c3a56df9 5e697909-978f-4783-0601-42a9c3a56df9} rejected, sending older logs (next: 1)
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.279573 [INFO] raft: pipelining replication to peer {Voter 5e697909-978f-4783-0601-42a9c3a56df9 5e697909-978f-4783-0601-42a9c3a56df9}
testLoggerAdapter verbose: cluster: 21:34:38.279707 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: cluster: 21:34:38.385043 [INFO] Stable state for Leader reached at 2018-08-05 21:34:38.279781244 +0000 UTC m=+5.020173593 (1 nodes), 421ns from start of poll, 375.974793ms from cluster start. Timeout at 2018-08-05 21:34:38.384952813 +0000 UTC m=+5.125345252, 105.171659ms after stability
testLoggerAdapter verbose: cluster: 21:34:38.385538 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: cluster: 21:34:38.491049 [INFO] Stable state for Leader reached at 2018-08-05 21:34:38.385881068 +0000 UTC m=+5.126273496 (1 nodes), 1.388µs from start of poll, 482.074696ms from cluster start. Timeout at 2018-08-05 21:34:38.491029942 +0000 UTC m=+5.231422315, 105.148819ms after stability
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.491277 [INFO] raft: Updating configuration with RemoveServer (5e697909-978f-4783-0601-42a9c3a56df9, ) to [{Suffrage:Voter ID:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 Address:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2} {Suffrage:Voter ID:e6a27847-1561-0356-4b8e-83d498cf019d Address:e6a27847-1561-0356-4b8e-83d498cf019d}]
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.491398 [INFO] raft: Removed peer 5e697909-978f-4783-0601-42a9c3a56df9, stopping replication after 4
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.491499 [INFO] raft: aborting pipeline replication to peer {Voter 5e697909-978f-4783-0601-42a9c3a56df9 5e697909-978f-4783-0601-42a9c3a56df9}
testLoggerAdapter verbose: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.491637 [INFO] raft: aborting pipeline replication to peer {Voter e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 e2d7d56f-5c15-9fda-8f5c-58649d49e7a2}
--- PASS: TestRaft_ProtocolVersion_Upgrade_1_2 (0.59s)
raft_test.go:97: cluster: 21:34:37.903769 [DEBUG] Fully Connecting
raft_test.go:97: e2d7d56f-5c15-9fda-8f5c-58649d49e7a2: 21:34:37.904016 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 Address:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2} {Suffrage:Voter ID:e6a27847-1561-0356-4b8e-83d498cf019d Address:e6a27847-1561-0356-4b8e-83d498cf019d}]
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.904188 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 Address:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2} {Suffrage:Voter ID:e6a27847-1561-0356-4b8e-83d498cf019d Address:e6a27847-1561-0356-4b8e-83d498cf019d}]
raft_test.go:97: cluster: 21:34:37.904493 [DEBUG] Fully Connecting
raft_test.go:97: 5e697909-978f-4783-0601-42a9c3a56df9: 21:34:37.904575 [INFO] raft: Initial configuration (index=0): []
raft_test.go:97: cluster: 21:34:37.904644 [DEBUG] Fully Connecting
raft_test.go:97: cluster: 21:34:37.904670 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: e2d7d56f-5c15-9fda-8f5c-58649d49e7a2: 21:34:37.904722 [INFO] raft: Node at e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 [Follower] entering Follower state (Leader: "")
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.904768 [INFO] raft: Node at e6a27847-1561-0356-4b8e-83d498cf019d [Follower] entering Follower state (Leader: "")
raft_test.go:97: 5e697909-978f-4783-0601-42a9c3a56df9: 21:34:37.904813 [INFO] raft: Node at 5e697909-978f-4783-0601-42a9c3a56df9 [Follower] entering Follower state (Leader: "")
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961367 [WARN] raft: Heartbeat timeout from "" reached, starting election
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961476 [INFO] raft: Node at e6a27847-1561-0356-4b8e-83d498cf019d [Candidate] entering Candidate state in term 2
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961521 [DEBUG] raft: Votes needed: 2
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961546 [DEBUG] raft: Vote granted from e6a27847-1561-0356-4b8e-83d498cf019d in term 2. Tally: 1
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961693 [DEBUG] raft: Vote granted from e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 in term 2. Tally: 2
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961720 [INFO] raft: Election won. Tally: 2
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961745 [INFO] raft: Node at e6a27847-1561-0356-4b8e-83d498cf019d [Leader] entering Leader state
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961768 [INFO] raft: Added peer e2d7d56f-5c15-9fda-8f5c-58649d49e7a2, starting replication
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:37.961897 [INFO] raft: pipelining replication to peer {Voter e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 e2d7d56f-5c15-9fda-8f5c-58649d49e7a2}
raft_test.go:97: cluster: 21:34:37.961938 [DEBUG] Resetting stability timeout
raft_test.go:97: cluster: 21:34:37.961971 [DEBUG] Resetting stability timeout
raft_test.go:97: cluster: 21:34:37.962001 [DEBUG] Resetting stability timeout
raft_test.go:97: 5e697909-978f-4783-0601-42a9c3a56df9: 21:34:37.998468 [WARN] raft: no known peers, aborting election
raft_test.go:97: cluster: 21:34:38.067227 [INFO] Stable state for Leader reached at 2018-08-05 21:34:37.962046175 +0000 UTC m=+4.702438631 (1 nodes), 57.357732ms from start of poll, 58.239831ms from cluster start. Timeout at 2018-08-05 21:34:38.067178511 +0000 UTC m=+4.807570929, 105.132298ms after stability
raft_test.go:97: cluster: 21:34:38.067515 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: cluster: 21:34:38.173010 [INFO] Stable state for Leader reached at 2018-08-05 21:34:38.067696606 +0000 UTC m=+4.808088989 (1 nodes), 865ns from start of poll, 163.890189ms from cluster start. Timeout at 2018-08-05 21:34:38.172913591 +0000 UTC m=+4.913306110, 105.217121ms after stability
raft_test.go:97: cluster: 21:34:38.173450 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: cluster: 21:34:38.278925 [INFO] Stable state for Leader reached at 2018-08-05 21:34:38.173837282 +0000 UTC m=+4.914229710 (1 nodes), 1.543µs from start of poll, 270.03091ms from cluster start. Timeout at 2018-08-05 21:34:38.278906342 +0000 UTC m=+5.019298694, 105.068984ms after stability
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.279139 [INFO] raft: Updating configuration with AddStaging (5e697909-978f-4783-0601-42a9c3a56df9, 5e697909-978f-4783-0601-42a9c3a56df9) to [{Suffrage:Voter ID:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 Address:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2} {Suffrage:Voter ID:e6a27847-1561-0356-4b8e-83d498cf019d Address:e6a27847-1561-0356-4b8e-83d498cf019d} {Suffrage:Voter ID:5e697909-978f-4783-0601-42a9c3a56df9 Address:5e697909-978f-4783-0601-42a9c3a56df9}]
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.279261 [INFO] raft: Added peer 5e697909-978f-4783-0601-42a9c3a56df9, starting replication
raft_test.go:97: 5e697909-978f-4783-0601-42a9c3a56df9: 21:34:38.279377 [WARN] raft: Failed to get previous log: 3 log not found (last: 0)
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.279466 [WARN] raft: AppendEntries to {Voter 5e697909-978f-4783-0601-42a9c3a56df9 5e697909-978f-4783-0601-42a9c3a56df9} rejected, sending older logs (next: 1)
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.279573 [INFO] raft: pipelining replication to peer {Voter 5e697909-978f-4783-0601-42a9c3a56df9 5e697909-978f-4783-0601-42a9c3a56df9}
raft_test.go:97: cluster: 21:34:38.279707 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: cluster: 21:34:38.385043 [INFO] Stable state for Leader reached at 2018-08-05 21:34:38.279781244 +0000 UTC m=+5.020173593 (1 nodes), 421ns from start of poll, 375.974793ms from cluster start. Timeout at 2018-08-05 21:34:38.384952813 +0000 UTC m=+5.125345252, 105.171659ms after stability
raft_test.go:97: cluster: 21:34:38.385538 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: cluster: 21:34:38.491049 [INFO] Stable state for Leader reached at 2018-08-05 21:34:38.385881068 +0000 UTC m=+5.126273496 (1 nodes), 1.388µs from start of poll, 482.074696ms from cluster start. Timeout at 2018-08-05 21:34:38.491029942 +0000 UTC m=+5.231422315, 105.148819ms after stability
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.491277 [INFO] raft: Updating configuration with RemoveServer (5e697909-978f-4783-0601-42a9c3a56df9, ) to [{Suffrage:Voter ID:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 Address:e2d7d56f-5c15-9fda-8f5c-58649d49e7a2} {Suffrage:Voter ID:e6a27847-1561-0356-4b8e-83d498cf019d Address:e6a27847-1561-0356-4b8e-83d498cf019d}]
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.491398 [INFO] raft: Removed peer 5e697909-978f-4783-0601-42a9c3a56df9, stopping replication after 4
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.491499 [INFO] raft: aborting pipeline replication to peer {Voter 5e697909-978f-4783-0601-42a9c3a56df9 5e697909-978f-4783-0601-42a9c3a56df9}
raft_test.go:97: e6a27847-1561-0356-4b8e-83d498cf019d: 21:34:38.491637 [INFO] raft: aborting pipeline replication to peer {Voter e2d7d56f-5c15-9fda-8f5c-58649d49e7a2 e2d7d56f-5c15-9fda-8f5c-58649d49e7a2}
=== RUN TestRaft_ProtocolVersion_Upgrade_2_3
testLoggerAdapter verbose: cluster: 21:34:38.493007 [DEBUG] Fully Connecting
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.493189 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 Address:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3} {Suffrage:Voter ID:b428a04a-5ed2-ff80-71d1-f2b3e96972c5 Address:b428a04a-5ed2-ff80-71d1-f2b3e96972c5}]
testLoggerAdapter verbose: b428a04a-5ed2-ff80-71d1-f2b3e96972c5: 21:34:38.493324 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 Address:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3} {Suffrage:Voter ID:b428a04a-5ed2-ff80-71d1-f2b3e96972c5 Address:b428a04a-5ed2-ff80-71d1-f2b3e96972c5}]
testLoggerAdapter verbose: cluster: 21:34:38.493418 [INFO] Starting stability test for raft state: Follower
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.493524 [INFO] raft: Node at bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: b428a04a-5ed2-ff80-71d1-f2b3e96972c5: 21:34:38.493665 [INFO] raft: Node at b428a04a-5ed2-ff80-71d1-f2b3e96972c5 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.554394 [WARN] raft: Heartbeat timeout from "" reached, starting election
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.554836 [INFO] raft: Node at bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 [Candidate] entering Candidate state in term 2
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.555044 [DEBUG] raft: Votes needed: 2
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.555246 [DEBUG] raft: Vote granted from bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 in term 2. Tally: 1
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.555516 [DEBUG] raft: Vote granted from b428a04a-5ed2-ff80-71d1-f2b3e96972c5 in term 2. Tally: 2
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.555711 [INFO] raft: Election won. Tally: 2
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.555904 [INFO] raft: Node at bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 [Leader] entering Leader state
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.556092 [INFO] raft: Added peer b428a04a-5ed2-ff80-71d1-f2b3e96972c5, starting replication
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.556380 [INFO] raft: pipelining replication to peer {Voter b428a04a-5ed2-ff80-71d1-f2b3e96972c5 b428a04a-5ed2-ff80-71d1-f2b3e96972c5}
testLoggerAdapter verbose: cluster: 21:34:38.556590 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: cluster: 21:34:38.556786 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: cluster: 21:34:38.556989 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: cluster: 21:34:38.662314 [INFO] Stable state for Follower reached at 2018-08-05 21:34:38.557174987 +0000 UTC m=+5.297567395 (1 nodes), 63.67302ms from start of poll, 64.086991ms from cluster start. Timeout at 2018-08-05 21:34:38.662286461 +0000 UTC m=+5.402678833, 105.111438ms after stability
testLoggerAdapter verbose: cluster: 21:34:38.662663 [DEBUG] Fully Connecting
testLoggerAdapter verbose: server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2: 21:34:38.662787 [INFO] raft: Initial configuration (index=0): []
testLoggerAdapter verbose: cluster: 21:34:38.662866 [DEBUG] Fully Connecting
testLoggerAdapter verbose: cluster: 21:34:38.662937 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2: 21:34:38.663029 [INFO] raft: Node at f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2: 21:34:38.737871 [WARN] raft: no known peers, aborting election
testLoggerAdapter verbose: cluster: 21:34:38.768139 [INFO] Stable state for Leader reached at 2018-08-05 21:34:38.663007668 +0000 UTC m=+5.403400023 (1 nodes), 13.461µs from start of poll, 169.919619ms from cluster start. Timeout at 2018-08-05 21:34:38.768118469 +0000 UTC m=+5.508510840, 105.110817ms after stability
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.768360 [INFO] raft: Updating configuration with AddStaging (server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2, f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2) to [{Suffrage:Voter ID:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 Address:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3} {Suffrage:Voter ID:b428a04a-5ed2-ff80-71d1-f2b3e96972c5 Address:b428a04a-5ed2-ff80-71d1-f2b3e96972c5} {Suffrage:Voter ID:server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2 Address:f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2}]
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.768519 [INFO] raft: Added peer server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2, starting replication
testLoggerAdapter verbose: server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2: 21:34:38.768632 [WARN] raft: Failed to get previous log: 3 log not found (last: 0)
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.768723 [WARN] raft: AppendEntries to {Voter server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2 f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2} rejected, sending older logs (next: 1)
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.768829 [INFO] raft: pipelining replication to peer {Voter server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2 f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2}
testLoggerAdapter verbose: cluster: 21:34:38.768975 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: cluster: 21:34:38.874139 [INFO] Stable state for Leader reached at 2018-08-05 21:34:38.769049289 +0000 UTC m=+5.509441638 (1 nodes), 407ns from start of poll, 275.961234ms from cluster start. Timeout at 2018-08-05 21:34:38.874117273 +0000 UTC m=+5.614509626, 105.067988ms after stability
testLoggerAdapter verbose: cluster: 21:34:38.874324 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: cluster: 21:34:38.979542 [INFO] Stable state for Leader reached at 2018-08-05 21:34:38.874408976 +0000 UTC m=+5.614801325 (1 nodes), 443ns from start of poll, 381.320921ms from cluster start. Timeout at 2018-08-05 21:34:38.979511588 +0000 UTC m=+5.719903959, 105.102634ms after stability
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.979581 [INFO] raft: Updating configuration with RemoveServer (b428a04a-5ed2-ff80-71d1-f2b3e96972c5, ) to [{Suffrage:Voter ID:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 Address:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3} {Suffrage:Voter ID:server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2 Address:f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2}]
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.979612 [INFO] raft: Removed peer b428a04a-5ed2-ff80-71d1-f2b3e96972c5, stopping replication after 4
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.979639 [INFO] raft: aborting pipeline replication to peer {Voter b428a04a-5ed2-ff80-71d1-f2b3e96972c5 b428a04a-5ed2-ff80-71d1-f2b3e96972c5}
testLoggerAdapter verbose: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.979700 [INFO] raft: aborting pipeline replication to peer {Voter server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2 f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2}
--- PASS: TestRaft_ProtocolVersion_Upgrade_2_3 (0.49s)
raft_test.go:97: cluster: 21:34:38.493007 [DEBUG] Fully Connecting
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.493189 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 Address:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3} {Suffrage:Voter ID:b428a04a-5ed2-ff80-71d1-f2b3e96972c5 Address:b428a04a-5ed2-ff80-71d1-f2b3e96972c5}]
raft_test.go:97: b428a04a-5ed2-ff80-71d1-f2b3e96972c5: 21:34:38.493324 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 Address:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3} {Suffrage:Voter ID:b428a04a-5ed2-ff80-71d1-f2b3e96972c5 Address:b428a04a-5ed2-ff80-71d1-f2b3e96972c5}]
raft_test.go:97: cluster: 21:34:38.493418 [INFO] Starting stability test for raft state: Follower
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.493524 [INFO] raft: Node at bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 [Follower] entering Follower state (Leader: "")
raft_test.go:97: b428a04a-5ed2-ff80-71d1-f2b3e96972c5: 21:34:38.493665 [INFO] raft: Node at b428a04a-5ed2-ff80-71d1-f2b3e96972c5 [Follower] entering Follower state (Leader: "")
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.554394 [WARN] raft: Heartbeat timeout from "" reached, starting election
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.554836 [INFO] raft: Node at bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 [Candidate] entering Candidate state in term 2
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.555044 [DEBUG] raft: Votes needed: 2
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.555246 [DEBUG] raft: Vote granted from bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 in term 2. Tally: 1
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.555516 [DEBUG] raft: Vote granted from b428a04a-5ed2-ff80-71d1-f2b3e96972c5 in term 2. Tally: 2
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.555711 [INFO] raft: Election won. Tally: 2
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.555904 [INFO] raft: Node at bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 [Leader] entering Leader state
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.556092 [INFO] raft: Added peer b428a04a-5ed2-ff80-71d1-f2b3e96972c5, starting replication
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.556380 [INFO] raft: pipelining replication to peer {Voter b428a04a-5ed2-ff80-71d1-f2b3e96972c5 b428a04a-5ed2-ff80-71d1-f2b3e96972c5}
raft_test.go:97: cluster: 21:34:38.556590 [DEBUG] Resetting stability timeout
raft_test.go:97: cluster: 21:34:38.556786 [DEBUG] Resetting stability timeout
raft_test.go:97: cluster: 21:34:38.556989 [DEBUG] Resetting stability timeout
raft_test.go:97: cluster: 21:34:38.662314 [INFO] Stable state for Follower reached at 2018-08-05 21:34:38.557174987 +0000 UTC m=+5.297567395 (1 nodes), 63.67302ms from start of poll, 64.086991ms from cluster start. Timeout at 2018-08-05 21:34:38.662286461 +0000 UTC m=+5.402678833, 105.111438ms after stability
raft_test.go:97: cluster: 21:34:38.662663 [DEBUG] Fully Connecting
raft_test.go:97: server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2: 21:34:38.662787 [INFO] raft: Initial configuration (index=0): []
raft_test.go:97: cluster: 21:34:38.662866 [DEBUG] Fully Connecting
raft_test.go:97: cluster: 21:34:38.662937 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2: 21:34:38.663029 [INFO] raft: Node at f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2 [Follower] entering Follower state (Leader: "")
raft_test.go:97: server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2: 21:34:38.737871 [WARN] raft: no known peers, aborting election
raft_test.go:97: cluster: 21:34:38.768139 [INFO] Stable state for Leader reached at 2018-08-05 21:34:38.663007668 +0000 UTC m=+5.403400023 (1 nodes), 13.461µs from start of poll, 169.919619ms from cluster start. Timeout at 2018-08-05 21:34:38.768118469 +0000 UTC m=+5.508510840, 105.110817ms after stability
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.768360 [INFO] raft: Updating configuration with AddStaging (server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2, f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2) to [{Suffrage:Voter ID:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 Address:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3} {Suffrage:Voter ID:b428a04a-5ed2-ff80-71d1-f2b3e96972c5 Address:b428a04a-5ed2-ff80-71d1-f2b3e96972c5} {Suffrage:Voter ID:server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2 Address:f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2}]
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.768519 [INFO] raft: Added peer server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2, starting replication
raft_test.go:97: server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2: 21:34:38.768632 [WARN] raft: Failed to get previous log: 3 log not found (last: 0)
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.768723 [WARN] raft: AppendEntries to {Voter server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2 f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2} rejected, sending older logs (next: 1)
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.768829 [INFO] raft: pipelining replication to peer {Voter server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2 f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2}
raft_test.go:97: cluster: 21:34:38.768975 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: cluster: 21:34:38.874139 [INFO] Stable state for Leader reached at 2018-08-05 21:34:38.769049289 +0000 UTC m=+5.509441638 (1 nodes), 407ns from start of poll, 275.961234ms from cluster start. Timeout at 2018-08-05 21:34:38.874117273 +0000 UTC m=+5.614509626, 105.067988ms after stability
raft_test.go:97: cluster: 21:34:38.874324 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: cluster: 21:34:38.979542 [INFO] Stable state for Leader reached at 2018-08-05 21:34:38.874408976 +0000 UTC m=+5.614801325 (1 nodes), 443ns from start of poll, 381.320921ms from cluster start. Timeout at 2018-08-05 21:34:38.979511588 +0000 UTC m=+5.719903959, 105.102634ms after stability
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.979581 [INFO] raft: Updating configuration with RemoveServer (b428a04a-5ed2-ff80-71d1-f2b3e96972c5, ) to [{Suffrage:Voter ID:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3 Address:bc2e52a2-c0f6-421c-e3be-a73b04a27cf3} {Suffrage:Voter ID:server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2 Address:f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2}]
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.979612 [INFO] raft: Removed peer b428a04a-5ed2-ff80-71d1-f2b3e96972c5, stopping replication after 4
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.979639 [INFO] raft: aborting pipeline replication to peer {Voter b428a04a-5ed2-ff80-71d1-f2b3e96972c5 b428a04a-5ed2-ff80-71d1-f2b3e96972c5}
raft_test.go:97: bc2e52a2-c0f6-421c-e3be-a73b04a27cf3: 21:34:38.979700 [INFO] raft: aborting pipeline replication to peer {Voter server-f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2 f6cd9dec-cfb5-2f1b-d901-144b6e1f57d2}
=== RUN TestTCPTransport_BadAddr
--- PASS: TestTCPTransport_BadAddr (0.00s)
=== RUN TestTCPTransport_WithAdvertise
--- PASS: TestTCPTransport_WithAdvertise (0.00s)
=== RUN TestTransport_StartStop
--- PASS: TestTransport_StartStop (0.00s)
=== RUN TestTransport_AppendEntries
--- PASS: TestTransport_AppendEntries (0.00s)
=== RUN TestTransport_AppendEntriesPipeline
--- PASS: TestTransport_AppendEntriesPipeline (0.00s)
=== RUN TestTransport_RequestVote
--- PASS: TestTransport_RequestVote (0.00s)
=== RUN TestTransport_InstallSnapshot
--- PASS: TestTransport_InstallSnapshot (0.00s)
=== RUN TestTransport_EncodeDecode
--- PASS: TestTransport_EncodeDecode (0.00s)
=== RUN TestRandomTimeout
--- PASS: TestRandomTimeout (0.00s)
=== RUN TestNewSeed
--- PASS: TestNewSeed (0.00s)
=== RUN TestRandomTimeout_NoTime
--- PASS: TestRandomTimeout_NoTime (0.00s)
=== RUN TestMin
--- PASS: TestMin (0.00s)
=== RUN TestMax
--- PASS: TestMax (0.00s)
=== RUN TestGenerateUUID
--- PASS: TestGenerateUUID (0.00s)
=== RUN TestBackoff
--- PASS: TestBackoff (0.00s)
FAIL
FAIL github.com/hashicorp/raft 5.730s
? github.com/hashicorp/raft/bench [no test files]
dh_auto_test: cd obj-x86_64-linux-gnu && go test -vet=off -v -p 1 github.com/hashicorp/raft github.com/hashicorp/raft/bench returned exit code 1
make: *** [debian/rules:9: build-indep] Error 1
dpkg-buildpackage: error: debian/rules build-indep subprocess returned exit status 2
--------------------------------------------------------------------------------
I suspect of a race condition or something alike, because this failure
does not seem to happen in reproducible builds. However, it fails
for me approximately half of the time, so if you could not reproduce it,
I would gladly offer a test machine where this happens (please contact
me privately for details).
If this is really a bug in one of the build-depends, please use reassign and affects,
so that this is still visible in the BTS web page for this package.
Thanks.
More information about the Pkg-go-maintainers
mailing list