[pkg-go] Bug#923820: golang-github-hashicorp-raft: FTBFS randomly (failing tests)
Santiago Vila
sanvila at debian.org
Tue Mar 5 19:09:41 GMT 2019
Package: src:golang-github-hashicorp-raft
Version: 1.0.0+git20180823.82694fb-3
Severity: important
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_autoreconf -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=all=\"-trimpath=/<<BUILDDIR>>/golang-github-hashicorp-raft-1.0.0\+git20180823.82694fb/obj-x86_64-linux-gnu/src\" -asmflags=all=\"-trimpath=/<<BUILDDIR>>/golang-github-hashicorp-raft-1.0.0\+git20180823.82694fb/obj-x86_64-linux-gnu/src\" -v -p 2 github.com/hashicorp/raft github.com/hashicorp/raft/bench
errors
internal/cpu
internal/race
runtime/internal/atomic
runtime/internal/sys
internal/bytealg
sync/atomic
unicode
runtime
unicode/utf8
container/list
math
internal/testlog
math/bits
strconv
crypto/internal/subtle
crypto/subtle
encoding
unicode/utf16
github.com/hashicorp/golang-lru/simplelru
vendor/golang_org/x/net/dns/dnsmessage
internal/nettrace
runtime/cgo
crypto/rc4
vendor/golang_org/x/crypto/cryptobyte/asn1
vendor/golang_org/x/crypto/curve25519
sync
io
syscall
bytes
bufio
reflect
time
internal/poll
internal/syscall/unix
os
crypto/cipher
fmt
crypto/aes
encoding/binary
math/rand
strings
context
encoding/base64
sort
math/big
encoding/json
github.com/hashicorp/go-immutable-radix
log
internal/singleflight
net
crypto/rand
compress/flate
hash
hash/crc32
compress/gzip
crypto
crypto/des
crypto/elliptic
crypto/internal/randutil
crypto/sha512
encoding/asn1
crypto/ecdsa
crypto/hmac
crypto/md5
crypto/rsa
crypto/sha1
crypto/sha256
crypto/dsa
encoding/hex
crypto/x509/pkix
encoding/pem
vendor/golang_org/x/crypto/cryptobyte
path/filepath
net/url
io/ioutil
vendor/golang_org/x/crypto/internal/chacha20
crypto/x509
vendor/golang_org/x/crypto/poly1305
vendor/golang_org/x/crypto/chacha20poly1305
vendor/golang_org/x/text/transform
vendor/golang_org/x/text/unicode/bidi
vendor/golang_org/x/text/secure/bidirule
crypto/tls
vendor/golang_org/x/text/unicode/norm
vendor/golang_org/x/net/idna
net/textproto
vendor/golang_org/x/net/http/httpproxy
vendor/golang_org/x/net/http2/hpack
vendor/golang_org/x/net/http/httpguts
mime
mime/quotedprintable
net/http/httptrace
net/http/internal
mime/multipart
path
os/signal
net/http
encoding/gob
html
text/template/parse
text/template
html/template
hash/crc64
flag
runtime/debug
runtime/trace
testing
github.com/armon/go-metrics
net/rpc
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 2 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.01s)
raft_test.go:101: 14:42:53.497855 [INFO] snapshot: Creating new snapshot at /tmp/raft336792914/raft632769673/snapshots/3-10-1551796973497.tmp
=== RUN TestFileSS_CreateSnapshot
--- PASS: TestFileSS_CreateSnapshot (0.03s)
raft_test.go:101: 14:42:53.505077 [INFO] snapshot: Creating new snapshot at /tmp/raft828889172/snapshots/3-10-1551796973505.tmp
raft_test.go:101: 14:42:53.516811 [WARN] snapshot: Found temporary snapshot: 3-10-1551796973505.tmp
=== RUN TestFileSS_CancelSnapshot
--- PASS: TestFileSS_CancelSnapshot (0.01s)
raft_test.go:101: 14:42:53.539396 [INFO] snapshot: Creating new snapshot at /tmp/raft432728995/snapshots/3-10-1551796973539.tmp
=== RUN TestFileSS_Retention
--- PASS: TestFileSS_Retention (0.10s)
raft_test.go:101: 14:42:53.548698 [INFO] snapshot: Creating new snapshot at /tmp/raft753930918/snapshots/3-10-1551796973548.tmp
raft_test.go:101: 14:42:53.566476 [INFO] snapshot: Creating new snapshot at /tmp/raft753930918/snapshots/3-11-1551796973566.tmp
raft_test.go:101: 14:42:53.583945 [INFO] snapshot: Creating new snapshot at /tmp/raft753930918/snapshots/3-12-1551796973583.tmp
raft_test.go:101: 14:42:53.606177 [INFO] snapshot: reaping snapshot /tmp/raft753930918/snapshots/3-10-1551796973548
raft_test.go:101: 14:42:53.606439 [INFO] snapshot: Creating new snapshot at /tmp/raft753930918/snapshots/3-13-1551796973606.tmp
raft_test.go:101: 14:42:53.625713 [INFO] snapshot: reaping snapshot /tmp/raft753930918/snapshots/3-11-1551796973566
raft_test.go:101: 14:42:53.626053 [INFO] snapshot: Creating new snapshot at /tmp/raft753930918/snapshots/3-14-1551796973626.tmp
raft_test.go:101: 14:42:53.646385 [INFO] snapshot: reaping snapshot /tmp/raft753930918/snapshots/3-12-1551796973583
=== RUN TestFileSS_BadPerm
--- PASS: TestFileSS_BadPerm (0.00s)
=== RUN TestFileSS_MissingParentDir
--- PASS: TestFileSS_MissingParentDir (0.00s)
=== RUN TestFileSS_Ordering
--- PASS: TestFileSS_Ordering (0.04s)
raft_test.go:101: 14:42:53.649218 [INFO] snapshot: Creating new snapshot at /tmp/raft949332305/snapshots/5-130350-1551796973649.tmp
raft_test.go:101: 14:42:53.666795 [INFO] snapshot: Creating new snapshot at /tmp/raft949332305/snapshots/36-204917-1551796973666.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
--- FAIL: TestNetworkTransport_CloseStreams (0.00s)
raft_test.go:101: 14:42:53.687952 [DEBUG] raft-net: 127.0.0.1:36945 accepted connection from: 127.0.0.1:54658
raft_test.go:101: 14:42:53.688023 [DEBUG] raft-net: 127.0.0.1:36945 accepted connection from: 127.0.0.1:54660
net_transport_test.go:103: Expected 3 pooled conns!
=== RUN TestNetworkTransport_StartStop
--- PASS: TestNetworkTransport_StartStop (0.00s)
=== RUN TestNetworkTransport_Heartbeat_FastPath
--- PASS: TestNetworkTransport_Heartbeat_FastPath (0.00s)
raft_test.go:101: 14:42:53.689919 [DEBUG] raft-net: 127.0.0.1:46871 accepted connection from: 127.0.0.1:58178
=== RUN TestNetworkTransport_AppendEntries
--- PASS: TestNetworkTransport_AppendEntries (0.00s)
raft_test.go:101: 14:42:53.690948 [DEBUG] raft-net: 127.0.0.1:41693 accepted connection from: 127.0.0.1:42094
raft_test.go:101: 14:42:53.691617 [DEBUG] raft-net: 127.0.0.1:39305 accepted connection from: 127.0.0.1:36312
=== RUN TestNetworkTransport_AppendEntriesPipeline
--- PASS: TestNetworkTransport_AppendEntriesPipeline (0.00s)
raft_test.go:101: 14:42:53.693086 [DEBUG] raft-net: 127.0.0.1:45111 accepted connection from: 127.0.0.1:52416
raft_test.go:101: 14:42:53.694312 [DEBUG] raft-net: 127.0.0.1:43045 accepted connection from: 127.0.0.1:54840
=== RUN TestNetworkTransport_AppendEntriesPipeline_CloseStreams
--- SKIP: TestNetworkTransport_AppendEntriesPipeline_CloseStreams (0.00s)
net_transport_test.go:333: Disabled unreliable test
=== RUN TestNetworkTransport_RequestVote
--- PASS: TestNetworkTransport_RequestVote (0.00s)
raft_test.go:101: 14:42:53.696533 [DEBUG] raft-net: 127.0.0.1:38531 accepted connection from: 127.0.0.1:59972
raft_test.go:101: 14:42:53.697247 [DEBUG] raft-net: 127.0.0.1:44473 accepted connection from: 127.0.0.1:57680
=== RUN TestNetworkTransport_InstallSnapshot
--- PASS: TestNetworkTransport_InstallSnapshot (0.00s)
raft_test.go:101: 14:42:53.698306 [DEBUG] raft-net: 127.0.0.1:45791 accepted connection from: 127.0.0.1:54116
raft_test.go:101: 14:42:53.699077 [DEBUG] raft-net: 127.0.0.1:37143 accepted connection from: 127.0.0.1:59450
=== 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: 14:42:53.700730 [DEBUG] raft-net: 127.0.0.1:42333 accepted connection from: 127.0.0.1:60614
raft_test.go:101: 14:42:53.700789 [DEBUG] raft-net: 127.0.0.1:42333 accepted connection from: 127.0.0.1:60616
raft_test.go:101: 14:42:53.700838 [DEBUG] raft-net: 127.0.0.1:42333 accepted connection from: 127.0.0.1:60618
raft_test.go:101: 14:42:53.700912 [DEBUG] raft-net: 127.0.0.1:42333 accepted connection from: 127.0.0.1:60620
raft_test.go:101: 14:42:53.700960 [DEBUG] raft-net: 127.0.0.1:42333 accepted connection from: 127.0.0.1:60622
=== 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: 14:42:53.704718 [DEBUG] Fully Connecting
testLoggerAdapter verbose: server-e9bf31b7-0c29-2fa4-a812-32f541d39919: 14:42:53.705083 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-e9bf31b7-0c29-2fa4-a812-32f541d39919 Address:e9bf31b7-0c29-2fa4-a812-32f541d39919} {Suffrage:Voter ID:server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58 Address:4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58} {Suffrage:Voter ID:server-41fbe837-9e02-2356-06a1-146e3d478db4 Address:41fbe837-9e02-2356-06a1-146e3d478db4}]
testLoggerAdapter verbose: server-e9bf31b7-0c29-2fa4-a812-32f541d39919: 14:42:53.705338 [INFO] raft: Node at e9bf31b7-0c29-2fa4-a812-32f541d39919 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58: 14:42:53.705646 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-e9bf31b7-0c29-2fa4-a812-32f541d39919 Address:e9bf31b7-0c29-2fa4-a812-32f541d39919} {Suffrage:Voter ID:server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58 Address:4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58} {Suffrage:Voter ID:server-41fbe837-9e02-2356-06a1-146e3d478db4 Address:41fbe837-9e02-2356-06a1-146e3d478db4}]
testLoggerAdapter verbose: server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58: 14:42:53.705824 [INFO] raft: Node at 4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.706172 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-e9bf31b7-0c29-2fa4-a812-32f541d39919 Address:e9bf31b7-0c29-2fa4-a812-32f541d39919} {Suffrage:Voter ID:server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58 Address:4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58} {Suffrage:Voter ID:server-41fbe837-9e02-2356-06a1-146e3d478db4 Address:41fbe837-9e02-2356-06a1-146e3d478db4}]
testLoggerAdapter verbose: cluster: 14:42:53.706288 [INFO] Starting stability test for raft state: Follower
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.706363 [INFO] raft: Node at 41fbe837-9e02-2356-06a1-146e3d478db4 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.763960 [WARN] raft: Heartbeat timeout from "" reached, starting election
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764013 [INFO] raft: Node at 41fbe837-9e02-2356-06a1-146e3d478db4 [Candidate] entering Candidate state in term 2
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764103 [DEBUG] raft: Votes needed: 2
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764131 [DEBUG] raft: Vote granted from server-41fbe837-9e02-2356-06a1-146e3d478db4 in term 2. Tally: 1
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764231 [DEBUG] raft: Vote granted from server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58 in term 2. Tally: 2
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764256 [INFO] raft: Election won. Tally: 2
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764283 [INFO] raft: Node at 41fbe837-9e02-2356-06a1-146e3d478db4 [Leader] entering Leader state
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764322 [INFO] raft: Added peer server-e9bf31b7-0c29-2fa4-a812-32f541d39919, starting replication
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764352 [INFO] raft: Added peer server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58, starting replication
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764501 [INFO] raft: pipelining replication to peer {Voter server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58 4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58}
testLoggerAdapter verbose: cluster: 14:42:53.764550 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: cluster: 14:42:53.764598 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: cluster: 14:42:53.764627 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764737 [INFO] raft: pipelining replication to peer {Voter server-e9bf31b7-0c29-2fa4-a812-32f541d39919 e9bf31b7-0c29-2fa4-a812-32f541d39919}
testLoggerAdapter verbose: cluster: 14:42:53.764809 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: cluster: 14:42:53.870012 [INFO] Stable state for Follower reached at 2019-03-05 14:42:53.76483352 +0000 UTC m=+0.275679840 (2 nodes), 58.114701ms from start of poll, 60.019274ms from cluster start. Timeout at 2019-03-05 14:42:53.869918599 +0000 UTC m=+0.380764883, 105.085043ms after stability
testLoggerAdapter verbose: cluster: 14:42:53.870071 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: cluster: 14:42:53.975270 [INFO] Stable state for Leader reached at 2019-03-05 14:42:53.870097131 +0000 UTC m=+0.380943397 (1 nodes), 1.006µs from start of poll, 165.282831ms from cluster start. Timeout at 2019-03-05 14:42:53.975220551 +0000 UTC m=+0.486066858, 105.123461ms after stability
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.975455 [INFO] raft: aborting pipeline replication to peer {Voter server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58 4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58}
testLoggerAdapter verbose: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.975529 [INFO] raft: aborting pipeline replication to peer {Voter server-e9bf31b7-0c29-2fa4-a812-32f541d39919 e9bf31b7-0c29-2fa4-a812-32f541d39919}
--- PASS: TestRaft_ProtocolVersion_RejectRPC (0.27s)
raft_test.go:97: cluster: 14:42:53.704718 [DEBUG] Fully Connecting
raft_test.go:97: server-e9bf31b7-0c29-2fa4-a812-32f541d39919: 14:42:53.705083 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-e9bf31b7-0c29-2fa4-a812-32f541d39919 Address:e9bf31b7-0c29-2fa4-a812-32f541d39919} {Suffrage:Voter ID:server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58 Address:4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58} {Suffrage:Voter ID:server-41fbe837-9e02-2356-06a1-146e3d478db4 Address:41fbe837-9e02-2356-06a1-146e3d478db4}]
raft_test.go:97: server-e9bf31b7-0c29-2fa4-a812-32f541d39919: 14:42:53.705338 [INFO] raft: Node at e9bf31b7-0c29-2fa4-a812-32f541d39919 [Follower] entering Follower state (Leader: "")
raft_test.go:97: server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58: 14:42:53.705646 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-e9bf31b7-0c29-2fa4-a812-32f541d39919 Address:e9bf31b7-0c29-2fa4-a812-32f541d39919} {Suffrage:Voter ID:server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58 Address:4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58} {Suffrage:Voter ID:server-41fbe837-9e02-2356-06a1-146e3d478db4 Address:41fbe837-9e02-2356-06a1-146e3d478db4}]
raft_test.go:97: server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58: 14:42:53.705824 [INFO] raft: Node at 4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58 [Follower] entering Follower state (Leader: "")
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.706172 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:server-e9bf31b7-0c29-2fa4-a812-32f541d39919 Address:e9bf31b7-0c29-2fa4-a812-32f541d39919} {Suffrage:Voter ID:server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58 Address:4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58} {Suffrage:Voter ID:server-41fbe837-9e02-2356-06a1-146e3d478db4 Address:41fbe837-9e02-2356-06a1-146e3d478db4}]
raft_test.go:97: cluster: 14:42:53.706288 [INFO] Starting stability test for raft state: Follower
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.706363 [INFO] raft: Node at 41fbe837-9e02-2356-06a1-146e3d478db4 [Follower] entering Follower state (Leader: "")
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.763960 [WARN] raft: Heartbeat timeout from "" reached, starting election
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764013 [INFO] raft: Node at 41fbe837-9e02-2356-06a1-146e3d478db4 [Candidate] entering Candidate state in term 2
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764103 [DEBUG] raft: Votes needed: 2
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764131 [DEBUG] raft: Vote granted from server-41fbe837-9e02-2356-06a1-146e3d478db4 in term 2. Tally: 1
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764231 [DEBUG] raft: Vote granted from server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58 in term 2. Tally: 2
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764256 [INFO] raft: Election won. Tally: 2
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764283 [INFO] raft: Node at 41fbe837-9e02-2356-06a1-146e3d478db4 [Leader] entering Leader state
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764322 [INFO] raft: Added peer server-e9bf31b7-0c29-2fa4-a812-32f541d39919, starting replication
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764352 [INFO] raft: Added peer server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58, starting replication
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764501 [INFO] raft: pipelining replication to peer {Voter server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58 4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58}
raft_test.go:97: cluster: 14:42:53.764550 [DEBUG] Resetting stability timeout
raft_test.go:97: cluster: 14:42:53.764598 [DEBUG] Resetting stability timeout
raft_test.go:97: cluster: 14:42:53.764627 [DEBUG] Resetting stability timeout
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.764737 [INFO] raft: pipelining replication to peer {Voter server-e9bf31b7-0c29-2fa4-a812-32f541d39919 e9bf31b7-0c29-2fa4-a812-32f541d39919}
raft_test.go:97: cluster: 14:42:53.764809 [DEBUG] Resetting stability timeout
raft_test.go:97: cluster: 14:42:53.870012 [INFO] Stable state for Follower reached at 2019-03-05 14:42:53.76483352 +0000 UTC m=+0.275679840 (2 nodes), 58.114701ms from start of poll, 60.019274ms from cluster start. Timeout at 2019-03-05 14:42:53.869918599 +0000 UTC m=+0.380764883, 105.085043ms after stability
raft_test.go:97: cluster: 14:42:53.870071 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: cluster: 14:42:53.975270 [INFO] Stable state for Leader reached at 2019-03-05 14:42:53.870097131 +0000 UTC m=+0.380943397 (1 nodes), 1.006µs from start of poll, 165.282831ms from cluster start. Timeout at 2019-03-05 14:42:53.975220551 +0000 UTC m=+0.486066858, 105.123461ms after stability
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.975455 [INFO] raft: aborting pipeline replication to peer {Voter server-4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58 4b4a8374-ca55-4a8e-f9cd-abab2a6d3e58}
raft_test.go:97: server-41fbe837-9e02-2356-06a1-146e3d478db4: 14:42:53.975529 [INFO] raft: aborting pipeline replication to peer {Voter server-e9bf31b7-0c29-2fa4-a812-32f541d39919 e9bf31b7-0c29-2fa4-a812-32f541d39919}
=== RUN TestRaft_ProtocolVersion_Upgrade_1_2
testLoggerAdapter verbose: cluster: 14:42:53.977211 [DEBUG] Fully Connecting
testLoggerAdapter verbose: c760f3bc-e06f-09cd-a9b7-7c9d91565825: 14:42:53.977505 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:c760f3bc-e06f-09cd-a9b7-7c9d91565825 Address:c760f3bc-e06f-09cd-a9b7-7c9d91565825} {Suffrage:Voter ID:8e737df6-5549-5b69-ed79-8dc588b75e24 Address:8e737df6-5549-5b69-ed79-8dc588b75e24}]
testLoggerAdapter verbose: c760f3bc-e06f-09cd-a9b7-7c9d91565825: 14:42:53.977664 [INFO] raft: Node at c760f3bc-e06f-09cd-a9b7-7c9d91565825 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:53.977820 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:c760f3bc-e06f-09cd-a9b7-7c9d91565825 Address:c760f3bc-e06f-09cd-a9b7-7c9d91565825} {Suffrage:Voter ID:8e737df6-5549-5b69-ed79-8dc588b75e24 Address:8e737df6-5549-5b69-ed79-8dc588b75e24}]
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:53.977962 [INFO] raft: Node at 8e737df6-5549-5b69-ed79-8dc588b75e24 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: cluster: 14:42:53.978236 [DEBUG] Fully Connecting
testLoggerAdapter verbose: 0d7482e3-22ba-e121-8fee-aeb323589b1e: 14:42:53.978375 [INFO] raft: Initial configuration (index=0): []
testLoggerAdapter verbose: cluster: 14:42:53.978511 [DEBUG] Fully Connecting
testLoggerAdapter verbose: cluster: 14:42:53.978752 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: 0d7482e3-22ba-e121-8fee-aeb323589b1e: 14:42:53.978592 [INFO] raft: Node at 0d7482e3-22ba-e121-8fee-aeb323589b1e [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.029912 [WARN] raft: Heartbeat timeout from "" reached, starting election
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.030198 [INFO] raft: Node at 8e737df6-5549-5b69-ed79-8dc588b75e24 [Candidate] entering Candidate state in term 2
testLoggerAdapter verbose: cluster: 14:42:54.030305 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.030378 [DEBUG] raft: Votes needed: 2
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.030506 [DEBUG] raft: Vote granted from 8e737df6-5549-5b69-ed79-8dc588b75e24 in term 2. Tally: 1
testLoggerAdapter verbose: cluster: 14:42:54.030602 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.030608 [DEBUG] raft: Vote granted from c760f3bc-e06f-09cd-a9b7-7c9d91565825 in term 2. Tally: 2
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.030723 [INFO] raft: Election won. Tally: 2
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.030813 [INFO] raft: Node at 8e737df6-5549-5b69-ed79-8dc588b75e24 [Leader] entering Leader state
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.030883 [INFO] raft: Added peer c760f3bc-e06f-09cd-a9b7-7c9d91565825, starting replication
testLoggerAdapter verbose: cluster: 14:42:54.030882 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.031150 [INFO] raft: pipelining replication to peer {Voter c760f3bc-e06f-09cd-a9b7-7c9d91565825 c760f3bc-e06f-09cd-a9b7-7c9d91565825}
testLoggerAdapter verbose: 0d7482e3-22ba-e121-8fee-aeb323589b1e: 14:42:54.049754 [WARN] raft: no known peers, aborting election
testLoggerAdapter verbose: cluster: 14:42:54.136378 [INFO] Stable state for Leader reached at 2019-03-05 14:42:54.031075969 +0000 UTC m=+0.541922293 (1 nodes), 52.23243ms from start of poll, 53.764649ms from cluster start. Timeout at 2019-03-05 14:42:54.13625646 +0000 UTC m=+0.647102758, 105.180465ms after stability
testLoggerAdapter verbose: cluster: 14:42:54.136447 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: cluster: 14:42:54.241833 [INFO] Stable state for Leader reached at 2019-03-05 14:42:54.136577497 +0000 UTC m=+0.647423764 (1 nodes), 1.129µs from start of poll, 159.26612ms from cluster start. Timeout at 2019-03-05 14:42:54.241749416 +0000 UTC m=+0.752595723, 105.171959ms after stability
testLoggerAdapter verbose: cluster: 14:42:54.241948 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: cluster: 14:42:54.347283 [INFO] Stable state for Leader reached at 2019-03-05 14:42:54.242033502 +0000 UTC m=+0.752879769 (1 nodes), 1.384µs from start of poll, 264.722125ms from cluster start. Timeout at 2019-03-05 14:42:54.347174279 +0000 UTC m=+0.858020585, 105.140816ms after stability
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.357543 [INFO] raft: Updating configuration with AddStaging (0d7482e3-22ba-e121-8fee-aeb323589b1e, 0d7482e3-22ba-e121-8fee-aeb323589b1e) to [{Suffrage:Voter ID:c760f3bc-e06f-09cd-a9b7-7c9d91565825 Address:c760f3bc-e06f-09cd-a9b7-7c9d91565825} {Suffrage:Voter ID:8e737df6-5549-5b69-ed79-8dc588b75e24 Address:8e737df6-5549-5b69-ed79-8dc588b75e24} {Suffrage:Voter ID:0d7482e3-22ba-e121-8fee-aeb323589b1e Address:0d7482e3-22ba-e121-8fee-aeb323589b1e}]
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.357750 [INFO] raft: Added peer 0d7482e3-22ba-e121-8fee-aeb323589b1e, starting replication
testLoggerAdapter verbose: 0d7482e3-22ba-e121-8fee-aeb323589b1e: 14:42:54.357997 [WARN] raft: Failed to get previous log: 3 log not found (last: 0)
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.358110 [WARN] raft: AppendEntries to {Voter 0d7482e3-22ba-e121-8fee-aeb323589b1e 0d7482e3-22ba-e121-8fee-aeb323589b1e} rejected, sending older logs (next: 1)
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.358326 [INFO] raft: pipelining replication to peer {Voter 0d7482e3-22ba-e121-8fee-aeb323589b1e 0d7482e3-22ba-e121-8fee-aeb323589b1e}
testLoggerAdapter verbose: cluster: 14:42:59.363600 [ERR] peer mismatch: {Servers:[{Suffrage:Voter ID:c760f3bc-e06f-09cd-a9b7-7c9d91565825 Address:c760f3bc-e06f-09cd-a9b7-7c9d91565825} {Suffrage:Voter ID:8e737df6-5549-5b69-ed79-8dc588b75e24 Address:8e737df6-5549-5b69-ed79-8dc588b75e24}]} {Servers:[{Suffrage:Voter ID:c760f3bc-e06f-09cd-a9b7-7c9d91565825 Address:c760f3bc-e06f-09cd-a9b7-7c9d91565825} {Suffrage:Voter ID:8e737df6-5549-5b69-ed79-8dc588b75e24 Address:8e737df6-5549-5b69-ed79-8dc588b75e24} {Suffrage:Voter ID:0d7482e3-22ba-e121-8fee-aeb323589b1e Address:0d7482e3-22ba-e121-8fee-aeb323589b1e}]}
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:59.363721 [INFO] raft: aborting pipeline replication to peer {Voter 0d7482e3-22ba-e121-8fee-aeb323589b1e 0d7482e3-22ba-e121-8fee-aeb323589b1e}
testLoggerAdapter verbose: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:59.363770 [INFO] raft: aborting pipeline replication to peer {Voter c760f3bc-e06f-09cd-a9b7-7c9d91565825 c760f3bc-e06f-09cd-a9b7-7c9d91565825}
--- FAIL: TestRaft_ProtocolVersion_Upgrade_1_2 (5.39s)
raft_test.go:97: cluster: 14:42:53.977211 [DEBUG] Fully Connecting
raft_test.go:97: c760f3bc-e06f-09cd-a9b7-7c9d91565825: 14:42:53.977505 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:c760f3bc-e06f-09cd-a9b7-7c9d91565825 Address:c760f3bc-e06f-09cd-a9b7-7c9d91565825} {Suffrage:Voter ID:8e737df6-5549-5b69-ed79-8dc588b75e24 Address:8e737df6-5549-5b69-ed79-8dc588b75e24}]
raft_test.go:97: c760f3bc-e06f-09cd-a9b7-7c9d91565825: 14:42:53.977664 [INFO] raft: Node at c760f3bc-e06f-09cd-a9b7-7c9d91565825 [Follower] entering Follower state (Leader: "")
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:53.977820 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:c760f3bc-e06f-09cd-a9b7-7c9d91565825 Address:c760f3bc-e06f-09cd-a9b7-7c9d91565825} {Suffrage:Voter ID:8e737df6-5549-5b69-ed79-8dc588b75e24 Address:8e737df6-5549-5b69-ed79-8dc588b75e24}]
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:53.977962 [INFO] raft: Node at 8e737df6-5549-5b69-ed79-8dc588b75e24 [Follower] entering Follower state (Leader: "")
raft_test.go:97: cluster: 14:42:53.978236 [DEBUG] Fully Connecting
raft_test.go:97: 0d7482e3-22ba-e121-8fee-aeb323589b1e: 14:42:53.978375 [INFO] raft: Initial configuration (index=0): []
raft_test.go:97: cluster: 14:42:53.978511 [DEBUG] Fully Connecting
raft_test.go:97: cluster: 14:42:53.978752 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: 0d7482e3-22ba-e121-8fee-aeb323589b1e: 14:42:53.978592 [INFO] raft: Node at 0d7482e3-22ba-e121-8fee-aeb323589b1e [Follower] entering Follower state (Leader: "")
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.029912 [WARN] raft: Heartbeat timeout from "" reached, starting election
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.030198 [INFO] raft: Node at 8e737df6-5549-5b69-ed79-8dc588b75e24 [Candidate] entering Candidate state in term 2
raft_test.go:97: cluster: 14:42:54.030305 [DEBUG] Resetting stability timeout
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.030378 [DEBUG] raft: Votes needed: 2
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.030506 [DEBUG] raft: Vote granted from 8e737df6-5549-5b69-ed79-8dc588b75e24 in term 2. Tally: 1
raft_test.go:97: cluster: 14:42:54.030602 [DEBUG] Resetting stability timeout
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.030608 [DEBUG] raft: Vote granted from c760f3bc-e06f-09cd-a9b7-7c9d91565825 in term 2. Tally: 2
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.030723 [INFO] raft: Election won. Tally: 2
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.030813 [INFO] raft: Node at 8e737df6-5549-5b69-ed79-8dc588b75e24 [Leader] entering Leader state
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.030883 [INFO] raft: Added peer c760f3bc-e06f-09cd-a9b7-7c9d91565825, starting replication
raft_test.go:97: cluster: 14:42:54.030882 [DEBUG] Resetting stability timeout
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.031150 [INFO] raft: pipelining replication to peer {Voter c760f3bc-e06f-09cd-a9b7-7c9d91565825 c760f3bc-e06f-09cd-a9b7-7c9d91565825}
raft_test.go:97: 0d7482e3-22ba-e121-8fee-aeb323589b1e: 14:42:54.049754 [WARN] raft: no known peers, aborting election
raft_test.go:97: cluster: 14:42:54.136378 [INFO] Stable state for Leader reached at 2019-03-05 14:42:54.031075969 +0000 UTC m=+0.541922293 (1 nodes), 52.23243ms from start of poll, 53.764649ms from cluster start. Timeout at 2019-03-05 14:42:54.13625646 +0000 UTC m=+0.647102758, 105.180465ms after stability
raft_test.go:97: cluster: 14:42:54.136447 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: cluster: 14:42:54.241833 [INFO] Stable state for Leader reached at 2019-03-05 14:42:54.136577497 +0000 UTC m=+0.647423764 (1 nodes), 1.129µs from start of poll, 159.26612ms from cluster start. Timeout at 2019-03-05 14:42:54.241749416 +0000 UTC m=+0.752595723, 105.171959ms after stability
raft_test.go:97: cluster: 14:42:54.241948 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: cluster: 14:42:54.347283 [INFO] Stable state for Leader reached at 2019-03-05 14:42:54.242033502 +0000 UTC m=+0.752879769 (1 nodes), 1.384µs from start of poll, 264.722125ms from cluster start. Timeout at 2019-03-05 14:42:54.347174279 +0000 UTC m=+0.858020585, 105.140816ms after stability
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.357543 [INFO] raft: Updating configuration with AddStaging (0d7482e3-22ba-e121-8fee-aeb323589b1e, 0d7482e3-22ba-e121-8fee-aeb323589b1e) to [{Suffrage:Voter ID:c760f3bc-e06f-09cd-a9b7-7c9d91565825 Address:c760f3bc-e06f-09cd-a9b7-7c9d91565825} {Suffrage:Voter ID:8e737df6-5549-5b69-ed79-8dc588b75e24 Address:8e737df6-5549-5b69-ed79-8dc588b75e24} {Suffrage:Voter ID:0d7482e3-22ba-e121-8fee-aeb323589b1e Address:0d7482e3-22ba-e121-8fee-aeb323589b1e}]
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.357750 [INFO] raft: Added peer 0d7482e3-22ba-e121-8fee-aeb323589b1e, starting replication
raft_test.go:97: 0d7482e3-22ba-e121-8fee-aeb323589b1e: 14:42:54.357997 [WARN] raft: Failed to get previous log: 3 log not found (last: 0)
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.358110 [WARN] raft: AppendEntries to {Voter 0d7482e3-22ba-e121-8fee-aeb323589b1e 0d7482e3-22ba-e121-8fee-aeb323589b1e} rejected, sending older logs (next: 1)
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:54.358326 [INFO] raft: pipelining replication to peer {Voter 0d7482e3-22ba-e121-8fee-aeb323589b1e 0d7482e3-22ba-e121-8fee-aeb323589b1e}
raft_test.go:97: cluster: 14:42:59.363600 [ERR] peer mismatch: {Servers:[{Suffrage:Voter ID:c760f3bc-e06f-09cd-a9b7-7c9d91565825 Address:c760f3bc-e06f-09cd-a9b7-7c9d91565825} {Suffrage:Voter ID:8e737df6-5549-5b69-ed79-8dc588b75e24 Address:8e737df6-5549-5b69-ed79-8dc588b75e24}]} {Servers:[{Suffrage:Voter ID:c760f3bc-e06f-09cd-a9b7-7c9d91565825 Address:c760f3bc-e06f-09cd-a9b7-7c9d91565825} {Suffrage:Voter ID:8e737df6-5549-5b69-ed79-8dc588b75e24 Address:8e737df6-5549-5b69-ed79-8dc588b75e24} {Suffrage:Voter ID:0d7482e3-22ba-e121-8fee-aeb323589b1e Address:0d7482e3-22ba-e121-8fee-aeb323589b1e}]}
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:59.363721 [INFO] raft: aborting pipeline replication to peer {Voter 0d7482e3-22ba-e121-8fee-aeb323589b1e 0d7482e3-22ba-e121-8fee-aeb323589b1e}
raft_test.go:97: 8e737df6-5549-5b69-ed79-8dc588b75e24: 14:42:59.363770 [INFO] raft: aborting pipeline replication to peer {Voter c760f3bc-e06f-09cd-a9b7-7c9d91565825 c760f3bc-e06f-09cd-a9b7-7c9d91565825}
=== RUN TestRaft_ProtocolVersion_Upgrade_2_3
testLoggerAdapter verbose: cluster: 14:42:59.365227 [DEBUG] Fully Connecting
testLoggerAdapter verbose: 9d94fb5a-9471-86d8-5bc8-e95123778240: 14:42:59.365493 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:9d94fb5a-9471-86d8-5bc8-e95123778240 Address:9d94fb5a-9471-86d8-5bc8-e95123778240} {Suffrage:Voter ID:49f3a5a1-4a36-c407-9df4-ed03443291ad Address:49f3a5a1-4a36-c407-9df4-ed03443291ad}]
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.365670 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:9d94fb5a-9471-86d8-5bc8-e95123778240 Address:9d94fb5a-9471-86d8-5bc8-e95123778240} {Suffrage:Voter ID:49f3a5a1-4a36-c407-9df4-ed03443291ad Address:49f3a5a1-4a36-c407-9df4-ed03443291ad}]
testLoggerAdapter verbose: cluster: 14:42:59.365707 [INFO] Starting stability test for raft state: Follower
testLoggerAdapter verbose: 9d94fb5a-9471-86d8-5bc8-e95123778240: 14:42:59.365781 [INFO] raft: Node at 9d94fb5a-9471-86d8-5bc8-e95123778240 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.365832 [INFO] raft: Node at 49f3a5a1-4a36-c407-9df4-ed03443291ad [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417322 [WARN] raft: Heartbeat timeout from "" reached, starting election
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417419 [INFO] raft: Node at 49f3a5a1-4a36-c407-9df4-ed03443291ad [Candidate] entering Candidate state in term 2
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417488 [DEBUG] raft: Votes needed: 2
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417517 [DEBUG] raft: Vote granted from 49f3a5a1-4a36-c407-9df4-ed03443291ad in term 2. Tally: 1
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417593 [DEBUG] raft: Vote granted from 9d94fb5a-9471-86d8-5bc8-e95123778240 in term 2. Tally: 2
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417620 [INFO] raft: Election won. Tally: 2
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417649 [INFO] raft: Node at 49f3a5a1-4a36-c407-9df4-ed03443291ad [Leader] entering Leader state
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417679 [INFO] raft: Added peer 9d94fb5a-9471-86d8-5bc8-e95123778240, starting replication
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417805 [INFO] raft: pipelining replication to peer {Voter 9d94fb5a-9471-86d8-5bc8-e95123778240 9d94fb5a-9471-86d8-5bc8-e95123778240}
testLoggerAdapter verbose: cluster: 14:42:59.417843 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: cluster: 14:42:59.417874 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: cluster: 14:42:59.417903 [DEBUG] Resetting stability timeout
testLoggerAdapter verbose: cluster: 14:42:59.523135 [INFO] Stable state for Follower reached at 2019-03-05 14:42:59.41792494 +0000 UTC m=+5.928771252 (1 nodes), 52.191005ms from start of poll, 52.663544ms from cluster start. Timeout at 2019-03-05 14:42:59.523059523 +0000 UTC m=+6.033905831, 105.134579ms after stability
testLoggerAdapter verbose: cluster: 14:42:59.523564 [DEBUG] Fully Connecting
testLoggerAdapter verbose: server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2: 14:42:59.523683 [INFO] raft: Initial configuration (index=0): []
testLoggerAdapter verbose: cluster: 14:42:59.523734 [DEBUG] Fully Connecting
testLoggerAdapter verbose: cluster: 14:42:59.523763 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2: 14:42:59.523867 [INFO] raft: Node at fbe6104b-a7ca-0bb6-379a-64f780f21fe2 [Follower] entering Follower state (Leader: "")
testLoggerAdapter verbose: server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2: 14:42:59.577668 [WARN] raft: no known peers, aborting election
testLoggerAdapter verbose: cluster: 14:42:59.628934 [INFO] Stable state for Leader reached at 2019-03-05 14:42:59.523790262 +0000 UTC m=+6.034636528 (1 nodes), 610ns from start of poll, 158.52882ms from cluster start. Timeout at 2019-03-05 14:42:59.628882527 +0000 UTC m=+6.139728811, 105.092283ms after stability
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.629028 [INFO] raft: Updating configuration with AddStaging (server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2, fbe6104b-a7ca-0bb6-379a-64f780f21fe2) to [{Suffrage:Voter ID:9d94fb5a-9471-86d8-5bc8-e95123778240 Address:9d94fb5a-9471-86d8-5bc8-e95123778240} {Suffrage:Voter ID:49f3a5a1-4a36-c407-9df4-ed03443291ad Address:49f3a5a1-4a36-c407-9df4-ed03443291ad} {Suffrage:Voter ID:server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2 Address:fbe6104b-a7ca-0bb6-379a-64f780f21fe2}]
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.629110 [INFO] raft: Added peer server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2, starting replication
testLoggerAdapter verbose: server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2: 14:42:59.629190 [WARN] raft: Failed to get previous log: 3 log not found (last: 0)
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.629232 [WARN] raft: AppendEntries to {Voter server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2 fbe6104b-a7ca-0bb6-379a-64f780f21fe2} rejected, sending older logs (next: 1)
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.629333 [INFO] raft: pipelining replication to peer {Voter server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2 fbe6104b-a7ca-0bb6-379a-64f780f21fe2}
testLoggerAdapter verbose: cluster: 14:42:59.629484 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: cluster: 14:42:59.734769 [INFO] Stable state for Leader reached at 2019-03-05 14:42:59.629511909 +0000 UTC m=+6.140358176 (1 nodes), 719ns from start of poll, 264.250468ms from cluster start. Timeout at 2019-03-05 14:42:59.734709831 +0000 UTC m=+6.245556096, 105.19792ms after stability
testLoggerAdapter verbose: cluster: 14:42:59.734844 [INFO] Starting stability test for raft state: Leader
testLoggerAdapter verbose: cluster: 14:42:59.840115 [INFO] Stable state for Leader reached at 2019-03-05 14:42:59.734870788 +0000 UTC m=+6.245717055 (1 nodes), 1.039µs from start of poll, 369.609347ms from cluster start. Timeout at 2019-03-05 14:42:59.840006979 +0000 UTC m=+6.350853287, 105.136232ms after stability
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.840232 [INFO] raft: Updating configuration with RemoveServer (9d94fb5a-9471-86d8-5bc8-e95123778240, ) to [{Suffrage:Voter ID:49f3a5a1-4a36-c407-9df4-ed03443291ad Address:49f3a5a1-4a36-c407-9df4-ed03443291ad} {Suffrage:Voter ID:server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2 Address:fbe6104b-a7ca-0bb6-379a-64f780f21fe2}]
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.840332 [INFO] raft: Removed peer 9d94fb5a-9471-86d8-5bc8-e95123778240, stopping replication after 4
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.840436 [INFO] raft: aborting pipeline replication to peer {Voter 9d94fb5a-9471-86d8-5bc8-e95123778240 9d94fb5a-9471-86d8-5bc8-e95123778240}
testLoggerAdapter verbose: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.840633 [INFO] raft: aborting pipeline replication to peer {Voter server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2 fbe6104b-a7ca-0bb6-379a-64f780f21fe2}
--- PASS: TestRaft_ProtocolVersion_Upgrade_2_3 (0.48s)
raft_test.go:97: cluster: 14:42:59.365227 [DEBUG] Fully Connecting
raft_test.go:97: 9d94fb5a-9471-86d8-5bc8-e95123778240: 14:42:59.365493 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:9d94fb5a-9471-86d8-5bc8-e95123778240 Address:9d94fb5a-9471-86d8-5bc8-e95123778240} {Suffrage:Voter ID:49f3a5a1-4a36-c407-9df4-ed03443291ad Address:49f3a5a1-4a36-c407-9df4-ed03443291ad}]
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.365670 [INFO] raft: Initial configuration (index=1): [{Suffrage:Voter ID:9d94fb5a-9471-86d8-5bc8-e95123778240 Address:9d94fb5a-9471-86d8-5bc8-e95123778240} {Suffrage:Voter ID:49f3a5a1-4a36-c407-9df4-ed03443291ad Address:49f3a5a1-4a36-c407-9df4-ed03443291ad}]
raft_test.go:97: cluster: 14:42:59.365707 [INFO] Starting stability test for raft state: Follower
raft_test.go:97: 9d94fb5a-9471-86d8-5bc8-e95123778240: 14:42:59.365781 [INFO] raft: Node at 9d94fb5a-9471-86d8-5bc8-e95123778240 [Follower] entering Follower state (Leader: "")
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.365832 [INFO] raft: Node at 49f3a5a1-4a36-c407-9df4-ed03443291ad [Follower] entering Follower state (Leader: "")
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417322 [WARN] raft: Heartbeat timeout from "" reached, starting election
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417419 [INFO] raft: Node at 49f3a5a1-4a36-c407-9df4-ed03443291ad [Candidate] entering Candidate state in term 2
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417488 [DEBUG] raft: Votes needed: 2
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417517 [DEBUG] raft: Vote granted from 49f3a5a1-4a36-c407-9df4-ed03443291ad in term 2. Tally: 1
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417593 [DEBUG] raft: Vote granted from 9d94fb5a-9471-86d8-5bc8-e95123778240 in term 2. Tally: 2
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417620 [INFO] raft: Election won. Tally: 2
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417649 [INFO] raft: Node at 49f3a5a1-4a36-c407-9df4-ed03443291ad [Leader] entering Leader state
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417679 [INFO] raft: Added peer 9d94fb5a-9471-86d8-5bc8-e95123778240, starting replication
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.417805 [INFO] raft: pipelining replication to peer {Voter 9d94fb5a-9471-86d8-5bc8-e95123778240 9d94fb5a-9471-86d8-5bc8-e95123778240}
raft_test.go:97: cluster: 14:42:59.417843 [DEBUG] Resetting stability timeout
raft_test.go:97: cluster: 14:42:59.417874 [DEBUG] Resetting stability timeout
raft_test.go:97: cluster: 14:42:59.417903 [DEBUG] Resetting stability timeout
raft_test.go:97: cluster: 14:42:59.523135 [INFO] Stable state for Follower reached at 2019-03-05 14:42:59.41792494 +0000 UTC m=+5.928771252 (1 nodes), 52.191005ms from start of poll, 52.663544ms from cluster start. Timeout at 2019-03-05 14:42:59.523059523 +0000 UTC m=+6.033905831, 105.134579ms after stability
raft_test.go:97: cluster: 14:42:59.523564 [DEBUG] Fully Connecting
raft_test.go:97: server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2: 14:42:59.523683 [INFO] raft: Initial configuration (index=0): []
raft_test.go:97: cluster: 14:42:59.523734 [DEBUG] Fully Connecting
raft_test.go:97: cluster: 14:42:59.523763 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2: 14:42:59.523867 [INFO] raft: Node at fbe6104b-a7ca-0bb6-379a-64f780f21fe2 [Follower] entering Follower state (Leader: "")
raft_test.go:97: server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2: 14:42:59.577668 [WARN] raft: no known peers, aborting election
raft_test.go:97: cluster: 14:42:59.628934 [INFO] Stable state for Leader reached at 2019-03-05 14:42:59.523790262 +0000 UTC m=+6.034636528 (1 nodes), 610ns from start of poll, 158.52882ms from cluster start. Timeout at 2019-03-05 14:42:59.628882527 +0000 UTC m=+6.139728811, 105.092283ms after stability
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.629028 [INFO] raft: Updating configuration with AddStaging (server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2, fbe6104b-a7ca-0bb6-379a-64f780f21fe2) to [{Suffrage:Voter ID:9d94fb5a-9471-86d8-5bc8-e95123778240 Address:9d94fb5a-9471-86d8-5bc8-e95123778240} {Suffrage:Voter ID:49f3a5a1-4a36-c407-9df4-ed03443291ad Address:49f3a5a1-4a36-c407-9df4-ed03443291ad} {Suffrage:Voter ID:server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2 Address:fbe6104b-a7ca-0bb6-379a-64f780f21fe2}]
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.629110 [INFO] raft: Added peer server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2, starting replication
raft_test.go:97: server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2: 14:42:59.629190 [WARN] raft: Failed to get previous log: 3 log not found (last: 0)
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.629232 [WARN] raft: AppendEntries to {Voter server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2 fbe6104b-a7ca-0bb6-379a-64f780f21fe2} rejected, sending older logs (next: 1)
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.629333 [INFO] raft: pipelining replication to peer {Voter server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2 fbe6104b-a7ca-0bb6-379a-64f780f21fe2}
raft_test.go:97: cluster: 14:42:59.629484 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: cluster: 14:42:59.734769 [INFO] Stable state for Leader reached at 2019-03-05 14:42:59.629511909 +0000 UTC m=+6.140358176 (1 nodes), 719ns from start of poll, 264.250468ms from cluster start. Timeout at 2019-03-05 14:42:59.734709831 +0000 UTC m=+6.245556096, 105.19792ms after stability
raft_test.go:97: cluster: 14:42:59.734844 [INFO] Starting stability test for raft state: Leader
raft_test.go:97: cluster: 14:42:59.840115 [INFO] Stable state for Leader reached at 2019-03-05 14:42:59.734870788 +0000 UTC m=+6.245717055 (1 nodes), 1.039µs from start of poll, 369.609347ms from cluster start. Timeout at 2019-03-05 14:42:59.840006979 +0000 UTC m=+6.350853287, 105.136232ms after stability
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.840232 [INFO] raft: Updating configuration with RemoveServer (9d94fb5a-9471-86d8-5bc8-e95123778240, ) to [{Suffrage:Voter ID:49f3a5a1-4a36-c407-9df4-ed03443291ad Address:49f3a5a1-4a36-c407-9df4-ed03443291ad} {Suffrage:Voter ID:server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2 Address:fbe6104b-a7ca-0bb6-379a-64f780f21fe2}]
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.840332 [INFO] raft: Removed peer 9d94fb5a-9471-86d8-5bc8-e95123778240, stopping replication after 4
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.840436 [INFO] raft: aborting pipeline replication to peer {Voter 9d94fb5a-9471-86d8-5bc8-e95123778240 9d94fb5a-9471-86d8-5bc8-e95123778240}
raft_test.go:97: 49f3a5a1-4a36-c407-9df4-ed03443291ad: 14:42:59.840633 [INFO] raft: aborting pipeline replication to peer {Voter server-fbe6104b-a7ca-0bb6-379a-64f780f21fe2 fbe6104b-a7ca-0bb6-379a-64f780f21fe2}
=== 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.01s)
=== 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.01s)
=== RUN TestBackoff
--- PASS: TestBackoff (0.00s)
FAIL
FAIL github.com/hashicorp/raft 6.375s
? github.com/hashicorp/raft/bench [no test files]
dh_auto_test: cd obj-x86_64-linux-gnu && go test -vet=off -v -p 2 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
--------------------------------------------------------------------------------
The build was made in one of my autobuilders with "dpkg-buildpackage -A".
The failure happens randomly, i.e. sometimes it fails, sometimes it does not,
so I don't have a "recipe" to reproduce it as such, but the "randomness"
is reproducible in my autobuilders (i.e. when I build it a lot of times,
there are always some failed builds).
I've put several failed build logs here for reference:
https://people.debian.org/~sanvila/build-logs/golang-github-hashicorp-raft/
If you need a test machine to reproduce this, please contact me
privately and I could provide ssh access to a machine where it happens
(caveat: randomly and maybe with low probability).
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