Skip to content

Instantly share code, notes, and snippets.

@tbg

tbg/-

Created August 4, 2015 06:01
Show Gist options
  • Save tbg/3380546a93f8851e5bbd to your computer and use it in GitHub Desktop.
Save tbg/3380546a93f8851e5bbd to your computer and use it in GitHub Desktop.
go test -tags '' -i ./storage
go test -tags '' -run TestRaftAfterRemoveRange -cpu 1 ./storage -timeout 10s -v --verbosity=1
=== RUN TestRaftAfterRemoveRange
I0804 02:01:20.668546 93859 storage/engine/rocksdb.go:99 opening in-memory rocksdb instance
W0804 02:01:20.678905 93859 rpc/tls.go:41 listening via tcp to 127.0.0.1:0 without TLS
I0804 02:01:20.681252 93859 multiraft/multiraft.go:454 node 100000001 starting
I0804 02:01:20.682832 93859 storage/range.go:986 gossiping cluster id from store 1, range 1
I0804 02:01:20.684805 93859 raft/raft.go:390 100000001 became follower at term 5
I0804 02:01:20.684892 93859 raft/raft.go:207 newRaft 100000001 [peers: [100000001], term: 5, commit: 10, applied: 10, lastindex: 10, lastterm: 5]
I0804 02:01:20.684960 93859 raft/raft.go:464 100000001 is starting a new election at term 5
I0804 02:01:20.684986 93859 raft/raft.go:403 100000001 became candidate at term 6
I0804 02:01:20.685009 93859 raft/raft.go:447 100000001 received vote from 100000001 at term 6
I0804 02:01:20.685044 93859 raft/raft.go:426 100000001 became leader at term 6
I0804 02:01:20.688925 93859 storage/range_command.go:932 range 1: new leader lease replica 1:1 19:00:00.000 +1.000s
I0804 02:01:20.689051 93859 storage/range.go:1053 gossiping accounting config from store 1, range 1
I0804 02:01:20.689114 93859 storage/range.go:1053 gossiping permissions config from store 1, range 1
I0804 02:01:20.689158 93859 storage/range.go:1053 gossiping user config from store 1, range 1
I0804 02:01:20.689204 93859 storage/range.go:1053 gossiping zones config from store 1, range 1
I0804 02:01:20.689319 93859 storage/range.go:994 gossiping sentinel from store 1, range 1
I0804 02:01:20.689353 93859 storage/range.go:998 gossiping first range from store 1, range 1
I0804 02:01:20.689457 93859 storage/engine/rocksdb.go:99 opening in-memory rocksdb instance
W0804 02:01:20.689835 93859 rpc/tls.go:41 listening via tcp to 127.0.0.1:0 without TLS
I0804 02:01:20.690023 93859 multiraft/multiraft.go:454 node 200000002 starting
I0804 02:01:20.690092 93859 storage/engine/rocksdb.go:99 opening in-memory rocksdb instance
W0804 02:01:20.690358 93859 rpc/tls.go:41 listening via tcp to 127.0.0.1:0 without TLS
I0804 02:01:20.690537 93859 multiraft/multiraft.go:454 node 300000003 starting
I0804 02:01:20.692547 93859 storage/range_command.go:994 initiating a split of range=1 ["" - "\xff\xff") at key "b"
W0804 02:01:20.697198 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00\x00k\x00\x01rdsc" "" "range_command.go:1038" id=b18e3666 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:01:20.697327 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00\x00k\x00\x01rtn-" "" "range_command.go:1038" id=b18e3666 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:01:20.697399 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1038" id=b18e3666 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:01:20.697451 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rtn-" "" "range_command.go:1038" id=b18e3666 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:01:20.697498 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00meta1\xff\xff" "" "range_command.go:1038" id=b18e3666 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:01:20.697541 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00meta2b" "" "range_command.go:1038" id=b18e3666 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:01:20.697583 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00meta2\xff\xff" "" "range_command.go:1038" id=b18e3666 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:01:20.697623 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00range-tree-root" "" "range_command.go:1038" id=b18e3666 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:01:20.698557 93859 raft/raft.go:390 100000001 became follower at term 5
I0804 02:01:20.698597 93859 raft/raft.go:207 newRaft 100000001 [peers: [100000001], term: 5, commit: 10, applied: 10, lastindex: 10, lastterm: 5]
I0804 02:01:20.698626 93859 raft/raft.go:464 100000001 is starting a new election at term 5
I0804 02:01:20.698637 93859 raft/raft.go:403 100000001 became candidate at term 6
I0804 02:01:20.698644 93859 raft/raft.go:447 100000001 received vote from 100000001 at term 6
I0804 02:01:20.698661 93859 raft/raft.go:426 100000001 became leader at term 6
I0804 02:01:20.698883 93859 storage/range_command.go:932 range 2: new leader lease replica 1:1 19:00:00.000 +1.000s
W0804 02:01:20.699630 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=ef8418cc 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:01:20.699686 93859 storage/range_command.go:1264 TODO(tschottdorf): changeReplicasTrigger
W0804 02:01:20.700971 93859 rpc/tls.go:57 connecting via tcp to 127.0.0.1:49283 without TLS
I0804 02:01:20.701694 93859 multiraft/multiraft.go:513 node 200000002: got message for unknown group 2; creating it
I0804 02:01:20.701800 93859 raft/raft.go:390 200000002 became follower at term 0
I0804 02:01:20.701832 93859 raft/raft.go:207 newRaft 200000002 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I0804 02:01:20.701841 93859 raft/raft.go:390 200000002 became follower at term 1
I0804 02:01:20.701885 93859 raft/raft.go:479 200000002 [term: 1] received a MsgApp message with higher term from 100000001 [term: 6]
I0804 02:01:20.701894 93859 raft/raft.go:390 200000002 became follower at term 6
W0804 02:01:20.702009 93859 rpc/tls.go:57 connecting via tcp to 127.0.0.1:49282 without TLS
I0804 02:01:20.702611 93859 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:01:20.702642 93859 raft/raft.go:260 100000001 paused sending replication messages to 200000002 [next = 1, match = 0, state = ProgressStateSnapshot, waiting = true, pendingSnapshot = 14]
I0804 02:01:20.702760 93859 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:01:20.702873 93859 raft/raft.go:698 200000002 [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 14, term: 6]
I0804 02:01:20.702905 93859 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:01:20.702929 93859 raft/raft.go:710 200000002 restored progress of 100000001 [next = 15, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0804 02:01:20.702945 93859 raft/raft.go:710 200000002 restored progress of 200000002 [next = 15, match = 14, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0804 02:01:20.702964 93859 raft/raft.go:675 200000002 [commit: 0] restored snapshot [index: 14, term: 6]
W0804 02:01:20.707211 93859 storage/store.go:1291 conflicting intents on ["\x00\x00meta2\xff\xff"]: resolved? true
W0804 02:01:20.708573 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=b0331b2a 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:01:20.708606 93859 storage/range_command.go:1264 TODO(tschottdorf): changeReplicasTrigger
W0804 02:01:20.709064 93859 rpc/tls.go:57 connecting via tcp to 127.0.0.1:49284 without TLS
W0804 02:01:20.709429 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=b0331b2a 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:01:20.709458 93859 storage/range_command.go:1264 TODO(tschottdorf): changeReplicasTrigger
I0804 02:01:20.710340 93859 multiraft/multiraft.go:513 node 300000003: got message for unknown group 2; creating it
I0804 02:01:20.710435 93859 raft/raft.go:390 300000003 became follower at term 0
I0804 02:01:20.710462 93859 raft/raft.go:207 newRaft 300000003 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]
I0804 02:01:20.710470 93859 raft/raft.go:390 300000003 became follower at term 1
I0804 02:01:20.710491 93859 raft/raft.go:479 300000003 [term: 1] received a MsgApp message with higher term from 100000001 [term: 6]
I0804 02:01:20.710498 93859 raft/raft.go:390 300000003 became follower at term 6
I0804 02:01:20.710783 93859 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:01:20.710797 93859 raft/raft.go:260 100000001 paused sending replication messages to 300000003 [next = 1, match = 0, state = ProgressStateSnapshot, waiting = true, pendingSnapshot = 19]
I0804 02:01:20.710883 93859 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:01:20.711357 93859 raft/raft.go:698 300000003 [commit: 0, lastindex: 0, lastterm: 0] starts to restore snapshot [index: 19, term: 6]
I0804 02:01:20.711370 93859 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:01:20.711381 93859 raft/raft.go:710 300000003 restored progress of 100000001 [next = 20, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0804 02:01:20.711389 93859 raft/raft.go:710 300000003 restored progress of 200000002 [next = 20, match = 0, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0804 02:01:20.711397 93859 raft/raft.go:710 300000003 restored progress of 300000003 [next = 20, match = 19, state = ProgressStateProbe, waiting = false, pendingSnapshot = 0]
I0804 02:01:20.711403 93859 raft/raft.go:675 300000003 [commit: 0] restored snapshot [index: 19, term: 6]
W0804 02:01:20.713686 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=f6dabea4 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:01:20.713711 93859 storage/range_command.go:1264 TODO(tschottdorf): changeReplicasTrigger
W0804 02:01:20.714424 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=f6dabea4 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:01:20.714448 93859 storage/range_command.go:1264 TODO(tschottdorf): changeReplicasTrigger
W0804 02:01:20.715633 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=f6dabea4 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:01:20.715667 93859 storage/range_command.go:1264 TODO(tschottdorf): changeReplicasTrigger
W0804 02:01:20.717333 93859 storage/store.go:1291 conflicting intents on ["\x00\x00meta2\xff\xff"]: resolved? true
W0804 02:01:20.718137 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=cf0e8d79 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:01:20.718172 93859 storage/range_command.go:1264 TODO(tschottdorf): changeReplicasTrigger
W0804 02:01:20.718827 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00\x00kb\x00\x01rdsc" "" "range_command.go:1344" id=cf0e8d79 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:01:20.718851 93859 storage/range_command.go:1264 TODO(tschottdorf): changeReplicasTrigger
W0804 02:01:20.718971 93859 storage/client_raft_test.go:868 _______________________
W0804 02:01:20.719706 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00\x00k\x00\x01rdsc" "" "range_command.go:1344" id=cd04a15b 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:01:20.719774 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00meta1\xff\xff" "" "range_command.go:1344" id=cd04a15b 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:01:20.719805 93859 storage/range_command.go:346 resolving on EndTransaction: {"\x00\x00meta2b" "" "range_command.go:1344" id=cd04a15b 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:01:20.719832 93859 storage/range_command.go:1264 TODO(tschottdorf): changeReplicasTrigger
W0804 02:01:21.810561 93859 rpc/server.go:351 rpc: server cannot decode request: read tcp 127.0.0.1:49286: use of closed network connection
W0804 02:01:21.810623 93859 rpc/server.go:351 rpc: server cannot decode request: read tcp 127.0.0.1:49285: use of closed network connection
W0804 02:01:21.810682 93859 rpc/server.go:351 rpc: server cannot decode request: read tcp 127.0.0.1:49287: use of closed network connection
--- FAIL: TestRaftAfterRemoveRange (1.14s)
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.257s
make: *** [test] Error 1
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment