-

go test -tags ''  -i ./storage
go test -tags ''  -run TestRaftAfterRemoveRange -cpu 1 ./storage -timeout 10s -v --verbosity=1
=== RUN TestRaftAfterRemoveRange
I0804 02:03:00.493796 94286 storage/engine/rocksdb.go:99  opening in-memory rocksdb instance
W0804 02:03:00.503873 94286 rpc/tls.go:41  listening via tcp to 127.0.0.1:0 without TLS
I0804 02:03:00.506259 94286 multiraft/multiraft.go:454  node 100000001 starting
I0804 02:03:00.507684 94286 storage/range.go:986  gossiping cluster id  from store 1, range 1
I0804 02:03:00.509799 94286 raft/raft.go:390  100000001 became follower at term 5
I0804 02:03:00.509884 94286 raft/raft.go:207  newRaft 100000001 [peers: [100000001], term: 5, commit: 10, applied: 10, lastindex: 10, lastterm: 5]
I0804 02:03:00.509950 94286 raft/raft.go:464  100000001 is starting a new election at term 5
I0804 02:03:00.509976 94286 raft/raft.go:403  100000001 became candidate at term 6
I0804 02:03:00.509999 94286 raft/raft.go:447  100000001 received vote from 100000001 at term 6
I0804 02:03:00.510034 94286 raft/raft.go:426  100000001 became leader at term 6
I0804 02:03:00.514642 94286 storage/range_command.go:932  range 1: new leader lease replica 1:1 19:00:00.000 +1.000s
I0804 02:03:00.514765 94286 storage/range.go:1053  gossiping accounting config from store 1, range 1
I0804 02:03:00.514829 94286 storage/range.go:1053  gossiping permissions config from store 1, range 1
I0804 02:03:00.514874 94286 storage/range.go:1053  gossiping user config from store 1, range 1
I0804 02:03:00.514923 94286 storage/range.go:1053  gossiping zones config from store 1, range 1
I0804 02:03:00.515046 94286 storage/range.go:994  gossiping sentinel from store 1, range 1
I0804 02:03:00.515081 94286 storage/range.go:998  gossiping first range from store 1, range 1
I0804 02:03:00.515188 94286 storage/engine/rocksdb.go:99  opening in-memory rocksdb instance
W0804 02:03:00.515554 94286 rpc/tls.go:41  listening via tcp to 127.0.0.1:0 without TLS
I0804 02:03:00.515740 94286 multiraft/multiraft.go:454  node 200000002 starting
I0804 02:03:00.515808 94286 storage/engine/rocksdb.go:99  opening in-memory rocksdb instance
W0804 02:03:00.516132 94286 rpc/tls.go:41  listening via tcp to 127.0.0.1:0 without TLS
I0804 02:03:00.516325 94286 multiraft/multiraft.go:454  node 300000003 starting
I0804 02:03:00.518320 94286 storage/range_command.go:994  initiating a split of range=1 ["" - "\xff\xff") at key "b"
W0804 02:03:00.522505 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00\x00k\x00\x01rdsc" "" "range_command.go:1038" id=934e5419 key="b" rw=false pri=93.43629810 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,20 orig=0.000000000,20 max=0.000000000,20 }
W0804 02:03:00.522581 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00\x00k\x00\x01rtn-" "" "range_command.go:1038" id=934e5419 key="b" rw=false pri=93.43629810 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,20 orig=0.000000000,20 max=0.000000000,20 }
W0804 02:03:00.522624 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1038" id=934e5419 key="b" rw=false pri=93.43629810 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,20 orig=0.000000000,20 max=0.000000000,20 }
W0804 02:03:00.522661 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rtn-" "" "range_command.go:1038" id=934e5419 key="b" rw=false pri=93.43629810 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,20 orig=0.000000000,20 max=0.000000000,20 }
W0804 02:03:00.522697 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00meta1\xff\xff" "" "range_command.go:1038" id=934e5419 key="b" rw=false pri=93.43629810 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,20 orig=0.000000000,20 max=0.000000000,20 }
W0804 02:03:00.522730 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00meta2b" "" "range_command.go:1038" id=934e5419 key="b" rw=false pri=93.43629810 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,20 orig=0.000000000,20 max=0.000000000,20 }
W0804 02:03:00.522762 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00meta2\xff\xff" "" "range_command.go:1038" id=934e5419 key="b" rw=false pri=93.43629810 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,20 orig=0.000000000,20 max=0.000000000,20 }
W0804 02:03:00.522795 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00range-tree-root" "" "range_command.go:1038" id=934e5419 key="b" rw=false pri=93.43629810 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,20 orig=0.000000000,20 max=0.000000000,20 }
I0804 02:03:00.523556 94286 raft/raft.go:390  100000001 became follower at term 5
I0804 02:03:00.523588 94286 raft/raft.go:207  newRaft 100000001 [peers: [100000001], term: 5, commit: 10, applied: 10, lastindex: 10, lastterm: 5]
I0804 02:03:00.523609 94286 raft/raft.go:464  100000001 is starting a new election at term 5
I0804 02:03:00.523617 94286 raft/raft.go:403  100000001 became candidate at term 6
I0804 02:03:00.523623 94286 raft/raft.go:447  100000001 received vote from 100000001 at term 6
I0804 02:03:00.523635 94286 raft/raft.go:426  100000001 became leader at term 6
I0804 02:03:00.523820 94286 storage/range_command.go:932  range 2: new leader lease replica 1:1 19:00:00.000 +1.000s
W0804 02:03:00.524400 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=68b52065 key="b" rw=false pri=79.68131233 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,44 orig=0.000000000,44 max=0.000000000,44 }
W0804 02:03:00.524439 94286 storage/range_command.go:1264  TODO(tschottdorf): changeReplicasTrigger
W0804 02:03:00.525599 94286 rpc/tls.go:57  connecting via tcp to 127.0.0.1:49313 without TLS
I0804 02:03:00.526176 94286 multiraft/multiraft.go:513  node 200000002: got message for unknown group 2; creating it
I0804 02:03:00.526265 94286 raft/raft.go:390  200000002 became follower at term 0
I0804 02:03:00.526291 94286 raft/raft.go:207  newRaft 200000002 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I0804 02:03:00.526298 94286 raft/raft.go:390  200000002 became follower at term 1
I0804 02:03:00.526335 94286 raft/raft.go:479  200000002 [term: 1] received a MsgApp message with higher term from 100000001 [term: 6]
I0804 02:03:00.526341 94286 raft/raft.go:390  200000002 became follower at term 6
W0804 02:03:00.526444 94286 rpc/tls.go:57  connecting via tcp to 127.0.0.1:49312 without TLS
I0804 02:03:00.527732 94286 raft/raft.go:258  100000001 [firstindex: 11, commit: 14] sent snapshot[index: 14, term: 6] to 200000002 [next = 1, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0804 02:03:00.527760 94286 raft/raft.go:260  100000001 paused sending replication messages to 200000002 [next = 1, match = 0, state = ProgressStateSnapshot, waiting = true, pendingSnapshot = 14]
I0804 02:03:00.527867 94286 raft/raft.go:565  100000001 snapshot succeeded, resumed sending replication messages to 200000002 [next = 15, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0804 02:03:00.527960 94286 raft/raft.go:698  200000002 [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 14, term: 6]
I0804 02:03:00.527986 94286 raft/log.go:250  log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 14, term: 6]
I0804 02:03:00.528006 94286 raft/raft.go:710  200000002 restored progress of 100000001 [next = 15, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0804 02:03:00.528018 94286 raft/raft.go:710  200000002 restored progress of 200000002 [next = 15, match = 14, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0804 02:03:00.528034 94286 raft/raft.go:675  200000002 [commit: 0] restored snapshot [index: 14, term: 6]
W0804 02:03:00.531222 94286 storage/store.go:1291  conflicting intents on ["\x00\x00meta2\xff\xff"]: resolved? true
W0804 02:03:00.532163 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=85d13391 key="b" rw=false pri=24.74269645 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,54 orig=0.000000000,54 max=0.000000000,54 }
W0804 02:03:00.532187 94286 storage/range_command.go:1264  TODO(tschottdorf): changeReplicasTrigger
W0804 02:03:00.532554 94286 rpc/tls.go:57  connecting via tcp to 127.0.0.1:49314 without TLS
W0804 02:03:00.532886 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=85d13391 key="b" rw=false pri=24.74269645 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,54 orig=0.000000000,54 max=0.000000000,54 }
W0804 02:03:00.532908 94286 storage/range_command.go:1264  TODO(tschottdorf): changeReplicasTrigger
I0804 02:03:00.533677 94286 multiraft/multiraft.go:513  node 300000003: got message for unknown group 2; creating it
I0804 02:03:00.533776 94286 raft/raft.go:390  300000003 became follower at term 0
I0804 02:03:00.533809 94286 raft/raft.go:207  newRaft 300000003 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I0804 02:03:00.533815 94286 raft/raft.go:390  300000003 became follower at term 1
I0804 02:03:00.533833 94286 raft/raft.go:479  300000003 [term: 1] received a MsgApp message with higher term from 100000001 [term: 6]
I0804 02:03:00.533848 94286 raft/raft.go:390  300000003 became follower at term 6
I0804 02:03:00.534128 94286 raft/raft.go:258  100000001 [firstindex: 11, commit: 19] sent snapshot[index: 19, term: 6] to 300000003 [next = 1, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0804 02:03:00.534149 94286 raft/raft.go:260  100000001 paused sending replication messages to 300000003 [next = 1, match = 0, state = ProgressStateSnapshot, waiting = true, pendingSnapshot = 19]
I0804 02:03:00.534227 94286 raft/raft.go:565  100000001 snapshot succeeded, resumed sending replication messages to 300000003 [next = 20, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0804 02:03:00.534704 94286 raft/raft.go:698  300000003 [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 19, term: 6]
I0804 02:03:00.534735 94286 raft/log.go:250  log [committed=0, applied=0, unstable.offset=1, len(unstable.Entries)=0] starts to restore snapshot [index: 19, term: 6]
I0804 02:03:00.534745 94286 raft/raft.go:710  300000003 restored progress of 100000001 [next = 20, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0804 02:03:00.534752 94286 raft/raft.go:710  300000003 restored progress of 200000002 [next = 20, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0804 02:03:00.534759 94286 raft/raft.go:710  300000003 restored progress of 300000003 [next = 20, match = 19, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0804 02:03:00.534765 94286 raft/raft.go:675  300000003 [commit: 0] restored snapshot [index: 19, term: 6]
W0804 02:03:00.536921 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=f3969200 key="b" rw=false pri=72.14923784 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,85 orig=0.000000000,85 max=0.000000000,85 }
W0804 02:03:00.536945 94286 storage/range_command.go:1264  TODO(tschottdorf): changeReplicasTrigger
W0804 02:03:00.537585 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=f3969200 key="b" rw=false pri=72.14923784 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,85 orig=0.000000000,85 max=0.000000000,85 }
W0804 02:03:00.537619 94286 storage/range_command.go:1264  TODO(tschottdorf): changeReplicasTrigger
W0804 02:03:00.538859 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=f3969200 key="b" rw=false pri=72.14923784 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,85 orig=0.000000000,85 max=0.000000000,85 }
W0804 02:03:00.538884 94286 storage/range_command.go:1264  TODO(tschottdorf): changeReplicasTrigger
W0804 02:03:00.540502 94286 storage/store.go:1291  conflicting intents on ["\x00\x00meta2\xff\xff"]: resolved? true
W0804 02:03:00.541418 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=e999fc5a key="b" rw=false pri=21.13950850 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,94 orig=0.000000000,94 max=0.000000000,94 }
W0804 02:03:00.541453 94286 storage/range_command.go:1264  TODO(tschottdorf): changeReplicasTrigger
W0804 02:03:00.542143 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=e999fc5a key="b" rw=false pri=21.13950850 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,94 orig=0.000000000,94 max=0.000000000,94 }
W0804 02:03:00.542166 94286 storage/range_command.go:1264  TODO(tschottdorf): changeReplicasTrigger
W0804 02:03:00.542282 94286 storage/client_raft_test.go:868  _______________________
W0804 02:03:00.542975 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00\x00k\x00\x01rdsc" "" "range_command.go:1344" id=35d1c8e3 key="" rw=false pri=57.16429183 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,122 orig=0.000000000,122 max=0.000000000,122 }
W0804 02:03:00.543022 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00meta1\xff\xff" "" "range_command.go:1344" id=35d1c8e3 key="" rw=false pri=57.16429183 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,122 orig=0.000000000,122 max=0.000000000,122 }
W0804 02:03:00.543064 94286 storage/range_command.go:346  resolving on EndTransaction: {"\x00\x00meta2b" "" "range_command.go:1344" id=35d1c8e3 key="" rw=false pri=57.16429183 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,122 orig=0.000000000,122 max=0.000000000,122 }
W0804 02:03:00.543081 94286 storage/range_command.go:1264  TODO(tschottdorf): changeReplicasTrigger
W0804 02:03:01.642085 94286 rpc/server.go:351  rpc: server cannot decode request: read tcp 127.0.0.1:49316: use of closed network connection
W0804 02:03:01.642185 94286 rpc/server.go:351  rpc: server cannot decode request: read tcp 127.0.0.1:49315: use of closed network connection
W0804 02:03:01.642283 94286 rpc/server.go:351  rpc: server cannot decode request: read tcp 127.0.0.1:49317: use of closed network connection
--- FAIL: TestRaftAfterRemoveRange (1.15s)
	testing.go:150: storage/client_test.go:320: condition failed to evaluate within 1s: storage/client_test.go:316: range not found on store 1
FAIL
exit status 1
FAIL	github.com/cockroachdb/cockroach/storage	1.271s
make: *** [test] Error 1