Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

stress: failed test in cockroach/storage/storage.test: TestSplitSnapshotRace_SnapshotWins #8635

Closed
cockroach-teamcity opened this issue Aug 18, 2016 · 1 comment
Closed

stress: failed test in cockroach/storage/storage.test: TestSplitSnapshotRace_SnapshotWins #8635

cockroach-teamcity opened this issue Aug 18, 2016 · 1 comment
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Milestone
Q3

Comments

@cockroach-teamcity
Copy link
Member

Binary: cockroach/static-tests.tar.gz sha: https://github.com/cockroachdb/cockroach/commits/f6cb86c1aa5a39cae56a972c6043837601912a75

Stress build found a failed test:

=== RUN   TestSplitSnapshotRace_SnapshotWins
I160818 04:49:59.432716 storage/engine/rocksdb.go:354  opening in memory rocksdb instance
W160818 04:49:59.433656 gossip/gossip.go:1035  not connected to cluster; use --join to specify a connected node
I160818 04:49:59.437742 storage/store.go:2662  store=1:1: system config not yet available
I160818 04:49:59.445559 storage/replica_trigger.go:308  store=1:1 range=1 [/Min-/Max): new range lease replica {1 1 1} 1970-01-01 00:00:00 +0000 UTC 900ms following replica {0 0 0} 1970-01-01 00:00:00 +0000 UTC 0s [physicalTime=1970-01-01 00:00:00 +0000 UTC]
I160818 04:49:59.446023 storage/engine/rocksdb.go:354  opening in memory rocksdb instance
W160818 04:49:59.446936 gossip/gossip.go:1035  not connected to cluster; use --join to specify a connected node
I160818 04:49:59.447901 storage/store.go:2662  store=2:2: system config not yet available
I160818 04:49:59.448447 storage/engine/rocksdb.go:354  opening in memory rocksdb instance
I160818 04:49:59.448492 gossip/client.go:74  node 2: starting client to 127.0.0.1:36233
W160818 04:49:59.449338 gossip/gossip.go:1035  not connected to cluster; use --join to specify a connected node
I160818 04:49:59.450798 storage/store.go:2662  store=3:3: system config not yet available
I160818 04:49:59.450872 gossip/client.go:74  node 3: starting client to 127.0.0.1:36233
I160818 04:49:59.453475 storage/engine/rocksdb.go:354  opening in memory rocksdb instance
W160818 04:49:59.462440 gossip/gossip.go:1035  not connected to cluster; use --join to specify a connected node
I160818 04:49:59.464006 storage/store.go:2662  store=4:4: system config not yet available
I160818 04:49:59.464039 gossip/client.go:74  node 4: starting client to 127.0.0.1:36233
I160818 04:49:59.464186 storage/engine/rocksdb.go:354  opening in memory rocksdb instance
W160818 04:49:59.465242 gossip/gossip.go:1035  not connected to cluster; use --join to specify a connected node
I160818 04:49:59.466116 storage/store.go:2662  store=5:5: system config not yet available
I160818 04:49:59.466171 gossip/client.go:74  node 5: starting client to 127.0.0.1:36233
I160818 04:49:59.466308 storage/engine/rocksdb.go:354  opening in memory rocksdb instance
I160818 04:49:59.466693 gossip/server.go:241  node 1: refusing gossip from node 5 (max 3 conns); forwarding to 3 ({tcp 127.0.0.1:40826})
I160818 04:49:59.466807 gossip/server.go:241  node 1: refusing gossip from node 5 (max 3 conns); forwarding to 4 ({tcp 127.0.0.1:46142})
I160818 04:49:59.467022 gossip/server.go:241  node 1: refusing gossip from node 5 (max 3 conns); forwarding to 3 ({tcp 127.0.0.1:40826})
I160818 04:49:59.467062 gossip/client.go:98  node 5: closing client to node 1 (127.0.0.1:36233): received forward from node 1 to 3 (127.0.0.1:40826)
W160818 04:49:59.467097 gossip/gossip.go:1035  not connected to cluster; use --join to specify a connected node
I160818 04:49:59.467125 gossip/client.go:74  node 5: starting client to 127.0.0.1:40826
I160818 04:49:59.467200 gossip/server.go:241  node 1: refusing gossip from node 5 (max 3 conns); forwarding to 4 ({tcp 127.0.0.1:46142})
I160818 04:49:59.467883 storage/store.go:2662  store=6:6: system config not yet available
I160818 04:49:59.469867 gossip/client.go:74  node 6: starting client to 127.0.0.1:36233
I160818 04:49:59.470788 gossip/server.go:241  node 1: refusing gossip from node 6 (max 3 conns); forwarding to 3 ({tcp 127.0.0.1:40826})
I160818 04:49:59.470931 gossip/server.go:241  node 1: refusing gossip from node 6 (max 3 conns); forwarding to 2 ({tcp 127.0.0.1:39245})
I160818 04:49:59.471096 gossip/client.go:98  node 6: closing client to node 1 (127.0.0.1:36233): received forward from node 1 to 3 (127.0.0.1:40826)
I160818 04:49:59.471156 gossip/client.go:74  node 6: starting client to 127.0.0.1:40826
I160818 04:49:59.471205 gossip/server.go:241  node 1: refusing gossip from node 6 (max 3 conns); forwarding to 4 ({tcp 127.0.0.1:46142})
I160818 04:49:59.472630 storage/replica_command.go:2216  store=1:1 range=1 [/Min-/Max): initiating a split of this range at key /System/Max
E160818 04:49:59.475480 storage/queue.go:508  [replicate] (purgatory) on store=1:1 range=1 [/Min-/System/Max): 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster
E160818 04:49:59.475669 storage/queue.go:508  [replicate] (purgatory) on store=1:1 range=2 [/System/Max-/Max): 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster
I160818 04:49:59.476067 storage/replica_raftstorage.go:493  generated snapshot for range 2 at index 11 in 125.93µs. encoded size=2453, 25 KV pairs, 1 log entries
I160818 04:49:59.476822 storage/replica_raftstorage.go:620  store=2:2 range=2 [/Min-/Min): with replicaID [?], applying preemptive snapshot for range 2 at index 11 (encoded size=2453, 25 KV pairs, 1 log entries)
I160818 04:49:59.477161 storage/replica_raftstorage.go:623  store=2:2 range=2 [/System/Max-/Max): with replicaID [?], applied preemptive snapshot for range 2 in 300.969µs
I160818 04:49:59.477925 storage/replica_command.go:3059  store=1:1 range=2 [/System/Max-/Max): change replicas of 2: read existing descriptor range_id:2 start_key:"\005" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2 
W160818 04:49:59.478177 storage/stores.go:207  range not contained in one range: [/Meta2/Max,"\x05\x00"), but have [/Min,/System/Max)
I160818 04:49:59.478769 storage/replica.go:2150  store=1:1 range=1 [/Min-/System/Max): applied part of replica change txn: Noop [/Min,/Min), Noop [/Min,/Min), Put [/Meta2/Max,/Min), pErr=<nil>
I160818 04:49:59.479462 storage/replica.go:2150  store=1:1 range=2 [/System/Max-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"\x05"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
W160818 04:49:59.480435 storage/intent_resolver.go:303  store=1:1 range=1 [/Min-/System/Max): failed to push during intent resolution: failed to push "change-replica" id=0e0b6217 key=/Local/Range/"\x05"/RangeDescriptor rw=true pri=0.01702774 iso=SERIALIZABLE stat=PENDING epo=0 ts=0.000000000,90 orig=0.000000000,90 max=0.000000000,90 wto=false rop=false
I160818 04:49:59.480560 storage/replica.go:1500  store=1:1 range=2 [/System/Max-/Max): proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:2} for range 2: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I160818 04:49:59.480873 storage/replica.go:2150  store=1:1 range=2 [/System/Max-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.483307 storage/replica_raftstorage.go:493  generated snapshot for range 2 at index 14 in 202.651µs. encoded size=3486, 27 KV pairs, 4 log entries
W160818 04:49:59.483545 storage/intent_resolver.go:344  could not GC completed transaction: end key /Local/Range/"\x05"/"rdsc\x00" must be greater than start /Local/Range/"\x05"/RangeDescriptor
I160818 04:49:59.483786 storage/replica_command.go:3059  store=1:1 range=2 [/System/Max-/Max): change replicas of 2: read existing descriptor range_id:2 start_key:"\005" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > next_replica_id:3 
I160818 04:49:59.484235 storage/replica_raftstorage.go:620  store=3:3 range=2 [/Min-/Min): with replicaID [?], applying preemptive snapshot for range 2 at index 14 (encoded size=3486, 27 KV pairs, 4 log entries)
I160818 04:49:59.484380 storage/replica.go:2150  store=1:1 range=1 [/Min-/System/Max): applied part of replica change txn: Noop [/Min,/Min), Noop [/Min,/Min), Put [/Meta2/Max,/Min), pErr=<nil>
I160818 04:49:59.484662 storage/replica_raftstorage.go:623  store=3:3 range=2 [/System/Max-/Max): with replicaID [?], applied preemptive snapshot for range 2 in 381.679µs
I160818 04:49:59.486987 storage/replica.go:2150  store=2:2 range=2 [/System/Max-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"\x05"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.487388 storage/replica.go:2150  store=2:2 range=2 [/System/Max-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.492185 storage/replica.go:2150  store=1:1 range=2 [/System/Max-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"\x05"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.492726 storage/replica.go:1500  store=1:1 range=2 [/System/Max-/Max): proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:3} for range 2: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3}]
I160818 04:49:59.493335 storage/replica.go:2150  store=2:2 range=2 [/System/Max-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"\x05"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.494532 storage/replica.go:2150  store=1:1 range=2 [/System/Max-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.494858 storage/replica.go:2150  store=2:2 range=2 [/System/Max-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.495278 storage/replica_raftstorage.go:493  generated snapshot for range 2 at index 16 in 153.006µs. encoded size=4349, 29 KV pairs, 6 log entries
I160818 04:49:59.495676 storage/replica_command.go:3059  store=1:1 range=2 [/System/Max-/Max): change replicas of 2: read existing descriptor range_id:2 start_key:"\005" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > replicas:<node_id:3 store_id:3 replica_id:3 > next_replica_id:4 
W160818 04:49:59.495884 storage/intent_resolver.go:344  could not GC completed transaction: end key /Local/Range/"\x05"/"rdsc\x00" must be greater than start /Local/Range/"\x05"/RangeDescriptor
I160818 04:49:59.496211 storage/replica.go:2150  store=1:1 range=1 [/Min-/System/Max): applied part of replica change txn: Noop [/Min,/Min), Noop [/Min,/Min), Put [/Meta2/Max,/Min), pErr=<nil>
I160818 04:49:59.496484 storage/replica_raftstorage.go:620  store=4:4 range=2 [/Min-/Min): with replicaID [?], applying preemptive snapshot for range 2 at index 16 (encoded size=4349, 29 KV pairs, 6 log entries)
I160818 04:49:59.496947 storage/replica_raftstorage.go:623  store=4:4 range=2 [/System/Max-/Max): with replicaID [?], applied preemptive snapshot for range 2 in 423.753µs
I160818 04:49:59.497489 storage/replica.go:2150  store=1:1 range=2 [/System/Max-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"\x05"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.497738 storage/replica.go:2150  store=2:2 range=2 [/System/Max-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"\x05"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.497997 storage/replica.go:1500  store=1:1 range=2 [/System/Max-/Max): proposing ADD_REPLICA {NodeID:4 StoreID:4 ReplicaID:4} for range 2: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3} {NodeID:4 StoreID:4 ReplicaID:4}]
I160818 04:49:59.498183 storage/replica.go:2150  store=3:3 range=2 [/System/Max-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"\x05"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.498486 storage/replica.go:2150  store=3:3 range=2 [/System/Max-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.498660 storage/replica.go:2150  store=1:1 range=2 [/System/Max-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.498866 storage/replica.go:2150  store=3:3 range=2 [/System/Max-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"\x05"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.499221 storage/replica.go:2150  store=2:2 range=2 [/System/Max-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.500209 storage/replica.go:2150  store=3:3 range=2 [/System/Max-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), pErr=<nil>
W160818 04:49:59.500321 storage/intent_resolver.go:344  could not GC completed transaction: end key /Local/Range/"\x05"/"rdsc\x00" must be greater than start /Local/Range/"\x05"/RangeDescriptor
I160818 04:49:59.501562 storage/replica_command.go:3059  store=1:1 range=2 [/System/Max-/Max): change replicas of 2: read existing descriptor range_id:2 start_key:"\005" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > replicas:<node_id:3 store_id:3 replica_id:3 > replicas:<node_id:4 store_id:4 replica_id:4 > next_replica_id:5 
I160818 04:49:59.502250 storage/replica.go:2150  store=1:1 range=1 [/Min-/System/Max): applied part of replica change txn: Noop [/Min,/Min), Noop [/Min,/Min), Put [/Meta2/Max,/Min), pErr=<nil>
I160818 04:49:59.503418 storage/replica.go:2150  store=1:1 range=2 [/System/Max-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"\x05"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.503835 storage/replica.go:1500  store=1:1 range=2 [/System/Max-/Max): proposing REMOVE_REPLICA {NodeID:1 StoreID:1 ReplicaID:1} for range 2: [{NodeID:4 StoreID:4 ReplicaID:4} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3}]
I160818 04:49:59.503935 storage/replica.go:2150  store=2:2 range=2 [/System/Max-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"\x05"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.504545 storage/replica.go:2150  store=3:3 range=2 [/System/Max-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"\x05"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.504839 storage/replica.go:2150  store=1:1 range=2 [/System/Max-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.505554 storage/replica.go:2150  store=3:3 range=2 [/System/Max-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), pErr=<nil>
E160818 04:49:59.505635 storage/client_test.go:863  engine 4: missing key "a"
I160818 04:49:59.505805 storage/replica.go:2150  store=2:2 range=2 [/System/Max-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"\x05"/RangeDescriptor,/Min), pErr=<nil>
E160818 04:49:59.505961 storage/client_test.go:863  engine 5: missing key "a"
E160818 04:49:59.506105 storage/client_test.go:863  engine 4: missing key "a"
E160818 04:49:59.506128 storage/client_test.go:863  engine 5: missing key "a"
E160818 04:49:59.506215 storage/client_test.go:863  engine 0: missing key "a"
E160818 04:49:59.506289 storage/client_test.go:863  engine 4: missing key "a"
E160818 04:49:59.506306 storage/client_test.go:863  engine 5: missing key "a"
E160818 04:49:59.506348 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:49:59.506391 storage/client_test.go:863  engine 4: missing key "z"
E160818 04:49:59.506410 storage/client_test.go:863  engine 5: missing key "z"
W160818 04:49:59.506728 storage/intent_resolver.go:344  could not GC completed transaction: end key /Local/Range/"\x05"/"rdsc\x00" must be greater than start /Local/Range/"\x05"/RangeDescriptor
W160818 04:49:59.506883 storage/store.go:2382  store=2:2: got unknown raft error: raft group deleted
W160818 04:49:59.508311 storage/store.go:2382  store=2:2: got unknown raft error: raft group deleted
W160818 04:49:59.508977 storage/raft_transport.go:371  range=2: outgoing raft transport stream to 4 closed by the remote: rpc error: code = 2 desc = unable to accept Raft message from {NodeID:4 StoreID:4 ReplicaID:4}: no store registered for {NodeID:1 StoreID:1 ReplicaID:1}
W160818 04:49:59.749041 storage/store.go:2382  store=2:2: got unknown raft error: raft group deleted
W160818 04:49:59.849348 storage/raft_transport.go:371  range=2: outgoing raft transport stream to 4 closed by the remote: rpc error: code = 2 desc = unable to accept Raft message from {NodeID:4 StoreID:4 ReplicaID:4}: no store registered for {NodeID:2 StoreID:2 ReplicaID:2}
W160818 04:49:59.850512 storage/raft_transport.go:371  range=2: outgoing raft transport stream to 4 closed by the remote: rpc error: code = 2 desc = unable to accept Raft message from {NodeID:4 StoreID:4 ReplicaID:4}: no store registered for {NodeID:2 StoreID:2 ReplicaID:2}
I160818 04:49:59.850986 storage/replica_trigger.go:308  store=2:2 range=2 [/System/Max-/Max): new range lease replica {2 2 2} 1970-01-01 00:00:00.9 +0000 UTC 7.2s following replica {1 1 1} 1970-01-01 00:00:00 +0000 UTC 900ms [physicalTime=1970-01-01 00:00:07.2 +0000 UTC]
I160818 04:49:59.852679 storage/replica_command.go:2216  store=2:2 range=2 [/System/Max-/Max): initiating a split of this range at key "m"
W160818 04:49:59.857004 storage/intent_resolver.go:344  could not GC completed transaction: end key /Local/Range/"\x05"/"rdsc\x00" must be greater than start /Local/Range/"\x05"/RangeDescriptor
W160818 04:49:59.949079 storage/raft_transport.go:371  range=2: outgoing raft transport stream to 4 closed by the remote: rpc error: code = 2 desc = unable to accept Raft message from {NodeID:4 StoreID:4 ReplicaID:4}: no store registered for {NodeID:2 StoreID:2 ReplicaID:2}
W160818 04:49:59.949754 storage/raft_transport.go:371  range=11: outgoing raft transport stream to 4 closed by the remote: rpc error: code = 2 desc = unable to accept Raft message from {NodeID:4 StoreID:4 ReplicaID:1}: no store registered for {NodeID:2 StoreID:2 ReplicaID:2}
I160818 04:49:59.951402 storage/replica_raftstorage.go:493  generated snapshot for range 11 at index 13 in 139.875µs. encoded size=2714, 24 KV pairs, 3 log entries
I160818 04:49:59.951779 storage/replica_command.go:3059  store=2:2 range=11 ["m"-/Max): change replicas of 11: read existing descriptor range_id:11 start_key:"m" end_key:"\377\377" replicas:<node_id:4 store_id:4 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > replicas:<node_id:3 store_id:3 replica_id:3 > next_replica_id:4 
I160818 04:49:59.952111 storage/replica_raftstorage.go:620  store=5:5 range=11 [/Min-/Min): with replicaID [?], applying preemptive snapshot for range 11 at index 13 (encoded size=2714, 24 KV pairs, 3 log entries)
I160818 04:49:59.952502 storage/replica_raftstorage.go:623  store=5:5 range=11 ["m"-/Max): with replicaID [?], applied preemptive snapshot for range 11 in 351.979µs
I160818 04:49:59.952625 storage/replica.go:2150  store=1:1 range=1 [/Min-/System/Max): applied part of replica change txn: Noop [/Min,/Min), Noop [/Min,/Min), Put [/Meta2/Max,/Min), pErr=<nil>
I160818 04:49:59.953616 storage/replica.go:2150  store=2:2 range=11 ["m"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"m"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"m"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.954018 storage/replica.go:1500  store=2:2 range=11 ["m"-/Max): proposing ADD_REPLICA {NodeID:5 StoreID:5 ReplicaID:4} for range 11: [{NodeID:4 StoreID:4 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3} {NodeID:5 StoreID:5 ReplicaID:4}]
I160818 04:49:59.954548 storage/replica.go:2150  store=3:3 range=11 ["m"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"m"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"m"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.954966 storage/replica.go:2150  store=2:2 range=11 ["m"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"m"/RangeDescriptor,/Min), pErr=<nil>
W160818 04:49:59.956220 storage/intent_resolver.go:344  could not GC completed transaction: end key /Local/Range/"m"/"rdsc\x00" must be greater than start /Local/Range/"m"/RangeDescriptor
I160818 04:49:59.957519 storage/replica.go:2150  store=5:5 range=11 ["m"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"m"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"m"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.957660 storage/replica.go:2150  store=5:5 range=11 ["m"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"m"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.958391 storage/replica.go:2150  store=3:3 range=11 ["m"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"m"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.959266 storage/replica_raftstorage.go:493  generated snapshot for range 11 at index 16 in 157.508µs. encoded size=3818, 26 KV pairs, 6 log entries
I160818 04:49:59.959636 storage/replica_command.go:3059  store=2:2 range=11 ["m"-/Max): change replicas of 11: read existing descriptor range_id:11 start_key:"m" end_key:"\377\377" replicas:<node_id:4 store_id:4 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > replicas:<node_id:3 store_id:3 replica_id:3 > replicas:<node_id:5 store_id:5 replica_id:4 > next_replica_id:5 
I160818 04:49:59.960458 storage/replica.go:2150  store=1:1 range=1 [/Min-/System/Max): applied part of replica change txn: Noop [/Min,/Min), Noop [/Min,/Min), Put [/Meta2/Max,/Min), pErr=<nil>
I160818 04:49:59.961518 storage/replica_raftstorage.go:620  store=6:6 range=11 [/Min-/Min): with replicaID [?], applying preemptive snapshot for range 11 at index 16 (encoded size=3818, 26 KV pairs, 6 log entries)
I160818 04:49:59.961871 storage/replica_raftstorage.go:623  store=6:6 range=11 ["m"-/Max): with replicaID [?], applied preemptive snapshot for range 11 in 327.142µs
I160818 04:49:59.963106 storage/replica.go:2150  store=2:2 range=11 ["m"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"m"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"m"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.963449 storage/replica.go:1500  store=2:2 range=11 ["m"-/Max): proposing ADD_REPLICA {NodeID:6 StoreID:6 ReplicaID:5} for range 11: [{NodeID:4 StoreID:4 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3} {NodeID:5 StoreID:5 ReplicaID:4} {NodeID:6 StoreID:6 ReplicaID:5}]
I160818 04:49:59.963496 storage/replica.go:2150  store=3:3 range=11 ["m"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"m"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"m"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.963845 storage/replica.go:2150  store=5:5 range=11 ["m"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"m"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"m"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.964497 storage/replica.go:2150  store=2:2 range=11 ["m"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"m"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.965225 storage/replica.go:2150  store=5:5 range=11 ["m"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"m"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.965361 storage/replica.go:2150  store=3:3 range=11 ["m"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"m"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.967181 storage/replica_command.go:3059  store=2:2 range=11 ["m"-/Max): change replicas of 11: read existing descriptor range_id:11 start_key:"m" end_key:"\377\377" replicas:<node_id:4 store_id:4 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > replicas:<node_id:3 store_id:3 replica_id:3 > replicas:<node_id:5 store_id:5 replica_id:4 > replicas:<node_id:6 store_id:6 replica_id:5 > next_replica_id:6 
I160818 04:49:59.967401 storage/replica.go:2150  store=6:6 range=11 ["m"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"m"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"m"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.967607 storage/replica.go:2150  store=6:6 range=11 ["m"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"m"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.967988 storage/replica.go:2150  store=1:1 range=1 [/Min-/System/Max): applied part of replica change txn: Noop [/Min,/Min), Noop [/Min,/Min), Put [/Meta2/Max,/Min), pErr=conflicting intents on [/Meta2/Max]: resolved? false
W160818 04:49:59.969522 storage/intent_resolver.go:344  could not GC completed transaction: end key /Local/Range/"m"/"rdsc\x00" must be greater than start /Local/Range/"m"/RangeDescriptor
I160818 04:49:59.970728 storage/replica.go:2150  store=1:1 range=1 [/Min-/System/Max): applied part of replica change txn: Noop [/Min,/Min), Noop [/Min,/Min), Put [/Meta2/Max,/Min), pErr=<nil>
I160818 04:49:59.971884 storage/replica.go:2150  store=2:2 range=11 ["m"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"m"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"m"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.972384 storage/replica.go:1500  store=2:2 range=11 ["m"-/Max): proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:3} for range 11: [{NodeID:4 StoreID:4 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:6 StoreID:6 ReplicaID:5} {NodeID:5 StoreID:5 ReplicaID:4}]
I160818 04:49:59.974118 storage/replica.go:2150  store=6:6 range=11 ["m"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"m"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"m"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.974223 storage/replica.go:2150  store=5:5 range=11 ["m"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"m"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"m"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.974332 storage/replica.go:2150  store=3:3 range=11 ["m"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"m"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"m"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.974577 storage/replica.go:2150  store=2:2 range=11 ["m"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"m"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.974732 storage/replica.go:2150  store=6:6 range=11 ["m"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"m"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.974824 storage/replica.go:2150  store=3:3 range=11 ["m"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"m"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.974908 storage/replica.go:2150  store=5:5 range=11 ["m"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"m"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.975015 storage/store.go:2371  store=3:3 range=11 ["m"-/Max): replica {3 3 3} too old, adding to replica GC queue
I160818 04:49:59.975059 storage/store.go:2371  store=3:3 range=11 ["m"-/Max): replica {3 3 3} too old, adding to replica GC queue
I160818 04:49:59.975133 storage/store.go:2371  store=3:3 range=11 ["m"-/Max): replica {3 3 3} too old, adding to replica GC queue
W160818 04:49:59.975553 storage/intent_resolver.go:344  could not GC completed transaction: end key /Local/Range/"m"/"rdsc\x00" must be greater than start /Local/Range/"m"/RangeDescriptor
I160818 04:49:59.977602 storage/replica_command.go:3059  store=2:2 range=11 ["m"-/Max): change replicas of 11: read existing descriptor range_id:11 start_key:"m" end_key:"\377\377" replicas:<node_id:4 store_id:4 replica_id:1 > replicas:<node_id:2 store_id:2 replica_id:2 > replicas:<node_id:6 store_id:6 replica_id:5 > replicas:<node_id:5 store_id:5 replica_id:4 > next_replica_id:6 
I160818 04:49:59.978090 storage/replica.go:2150  store=1:1 range=1 [/Min-/System/Max): applied part of replica change txn: Noop [/Min,/Min), Noop [/Min,/Min), Put [/Meta2/Max,/Min), pErr=<nil>
I160818 04:49:59.979101 storage/replica.go:2150  store=2:2 range=11 ["m"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"m"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"m"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.979419 storage/replica.go:2150  store=6:6 range=11 ["m"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"m"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"m"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.979468 storage/replica.go:1500  store=2:2 range=11 ["m"-/Max): proposing REMOVE_REPLICA {NodeID:2 StoreID:2 ReplicaID:2} for range 11: [{NodeID:4 StoreID:4 ReplicaID:1} {NodeID:5 StoreID:5 ReplicaID:4} {NodeID:6 StoreID:6 ReplicaID:5}]
I160818 04:49:59.979789 storage/replica.go:2150  store=5:5 range=11 ["m"-/Max): applied part of replica change txn: BeginTransaction [/Local/Range/"m"/RangeDescriptor,/Min), ConditionalPut [/Local/Range/"m"/RangeDescriptor,/Min), Noop [/Min,/Min), pErr=<nil>
I160818 04:49:59.980347 storage/replica.go:2150  store=2:2 range=11 ["m"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"m"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.980998 storage/replica.go:2150  store=5:5 range=11 ["m"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"m"/RangeDescriptor,/Min), pErr=<nil>
I160818 04:49:59.981843 storage/replica.go:2150  store=6:6 range=11 ["m"-/Max): applied part of replica change txn: EndTransaction [/Local/Range/"m"/RangeDescriptor,/Min), pErr=<nil>
W160818 04:49:59.983234 storage/intent_resolver.go:344  could not GC completed transaction: end key /Local/Range/"m"/"rdsc\x00" must be greater than start /Local/Range/"m"/RangeDescriptor
I160818 04:50:00.049211 storage/store.go:2371  store=2:2 range=11 ["m"-/Max): replica {2 2 2} too old, adding to replica GC queue
I160818 04:50:00.049260 storage/store.go:2371  store=2:2 range=11 ["m"-/Max): replica {2 2 2} too old, adding to replica GC queue
W160818 04:50:00.049421 storage/raft_transport.go:371  range=2: outgoing raft transport stream to 4 closed by the remote: rpc error: code = 2 desc = unable to accept Raft message from {NodeID:4 StoreID:4 ReplicaID:1}: no store registered for {NodeID:2 StoreID:2 ReplicaID:2}
I160818 04:50:00.148805 storage/store.go:2371  store=2:2 range=11 ["m"-/Max): replica {2 2 2} too old, adding to replica GC queue
I160818 04:50:00.148855 storage/store.go:2371  store=2:2 range=11 ["m"-/Max): replica {2 2 2} too old, adding to replica GC queue
W160818 04:50:00.149150 storage/raft_transport.go:371  range=11: outgoing raft transport stream to 4 closed by the remote: rpc error: code = 2 desc = unable to accept Raft message from {NodeID:4 StoreID:4 ReplicaID:4}: no store registered for {NodeID:2 StoreID:2 ReplicaID:2}
I160818 04:50:00.249069 storage/store.go:2371  store=2:2 range=11 ["m"-/Max): replica {2 2 2} too old, adding to replica GC queue
I160818 04:50:00.249136 storage/store.go:2371  store=2:2 range=11 ["m"-/Max): replica {2 2 2} too old, adding to replica GC queue
W160818 04:50:00.249180 storage/raft_transport.go:371  range=2: outgoing raft transport stream to 4 closed by the remote: rpc error: code = 2 desc = unable to accept Raft message from {NodeID:4 StoreID:4 ReplicaID:1}: no store registered for {NodeID:2 StoreID:2 ReplicaID:2}
W160818 04:50:00.268850 storage/raft_transport.go:371  range=11: outgoing raft transport stream to 4 closed by the remote: rpc error: code = 2 desc = unable to accept Raft message from {NodeID:4 StoreID:4 ReplicaID:1}: no store registered for {NodeID:6 StoreID:6 ReplicaID:5}
W160818 04:50:00.269700 storage/raft_transport.go:371  range=11: outgoing raft transport stream to 4 closed by the remote: rpc error: code = 2 desc = unable to accept Raft message from {NodeID:4 StoreID:4 ReplicaID:1}: no store registered for {NodeID:6 StoreID:6 ReplicaID:5}
I160818 04:50:00.271063 storage/replica_trigger.go:308  store=5:5 range=11 ["m"-/Max): new range lease replica {5 5 4} 1970-01-01 00:00:17.1 +0000 UTC 7.2s following replica {2 2 2} 1970-01-01 00:00:00.9 +0000 UTC 16.2s [physicalTime=1970-01-01 00:00:27 +0000 UTC]
E160818 04:50:00.274520 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.274581 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.274714 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.274769 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.274907 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.274949 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.275099 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.275136 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.275267 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.275320 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.275427 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.275479 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.275600 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.275629 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.275650 storage/client_test.go:863  engine 2: missing key "z"
I160818 04:50:00.580304 storage/replica_raftstorage.go:493  generated snapshot for range 11 at index 32 in 245.772µs. encoded size=8146, 33 KV pairs, 22 log entries
I160818 04:50:00.581155 storage/replica_raftstorage.go:620  store=4:4 range=11 [/Min-/Min): with replicaID 1, applying Raft snapshot for range 11 at index 32 (encoded size=8146, 33 KV pairs, 22 log entries)
I160818 04:50:00.581489 storage/replica_trigger.go:308  store=6:6 range=11 ["m"-/Max): new range lease replica {6 6 5} 1970-01-01 00:00:27.9 +0000 UTC 1.8s following replica {5 5 4} 1970-01-01 00:00:17.1 +0000 UTC 10.8s [physicalTime=1970-01-01 00:00:28.8 +0000 UTC]
I160818 04:50:00.582022 storage/replica_raftstorage.go:623  store=4:4 range=11 ["m"-/Max): with replicaID 1, applied Raft snapshot for range 11 in 829.172µs
E160818 04:50:00.587208 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.587253 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.587281 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.587421 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.587456 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.587485 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.587606 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.587625 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.587641 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.587706 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.587723 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.587740 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.587812 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.587829 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.587844 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.587905 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.587922 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.587937 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.587997 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.588024 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.588051 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.588126 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.588154 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.588166 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.588259 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.588277 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.588292 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.588384 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.588404 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.588420 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.588486 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.588504 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.588526 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.588585 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.588601 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.588617 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.588677 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.588694 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.588708 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.588777 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.588798 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.588813 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.588892 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.588942 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.588989 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.589249 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.589341 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.589373 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.589530 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.589557 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.589582 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.589819 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.589848 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.589872 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.590187 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.590227 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.590254 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.590643 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.590673 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.590699 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.591423 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.591463 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.591501 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.592722 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.592763 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.592809 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.595100 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.595128 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.595149 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.599573 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.599612 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.599640 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.608550 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.608609 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.608642 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.625714 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.625754 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.625816 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.659674 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.659715 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.659744 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.727173 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.727212 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.727235 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:00.861714 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:00.861804 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:00.861849 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:01.130553 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:01.130615 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:01.130645 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:01.667818 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:01.667854 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:01.667872 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:02.668155 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:02.668186 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:02.668201 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:03.668407 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:03.668438 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:03.668453 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:04.668678 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:04.668719 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:04.668741 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:05.669024 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:05.669068 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:05.669095 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:06.669357 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:06.669398 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:06.669455 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:07.669768 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:07.669806 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:07.669830 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:08.670113 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:08.670153 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:08.670180 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:09.670504 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:09.670550 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:09.670576 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:10.670838 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:10.670879 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:10.670905 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:11.671173 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:11.671231 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:11.671266 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:12.671568 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:12.671601 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:12.671633 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:13.671937 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:13.671982 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:13.672014 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:14.672308 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:14.672353 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:14.672374 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:15.672618 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:15.672660 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:15.672676 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:16.672940 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:16.672973 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:16.672988 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:17.673304 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:17.673340 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:17.673357 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:18.673725 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:18.673764 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:18.673787 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:19.674066 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:19.674117 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:19.674144 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:20.674440 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:20.674475 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:20.674496 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:21.674917 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:21.674957 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:21.674973 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:22.675241 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:22.675274 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:22.675296 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:23.675572 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:23.675618 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:23.675645 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:24.675903 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:24.675950 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:24.675967 storage/client_test.go:863  engine 2: missing key "z"
I160818 04:50:24.868953 gossip/gossip.go:1003  node has connected to cluster via gossip
E160818 04:50:25.676246 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:25.676279 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:25.676296 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:26.676571 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:26.676601 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:26.676625 storage/client_test.go:863  engine 2: missing key "z"
I160818 04:50:27.240543 gossip/gossip.go:1003  node has connected to cluster via gossip
E160818 04:50:27.676875 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:27.676903 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:27.676925 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:28.677157 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:28.677194 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:28.677219 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:29.677500 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:29.677531 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:29.677561 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:30.677812 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:30.677851 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:30.677881 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:31.678148 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:31.678190 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:31.678220 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:32.678451 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:32.678480 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:32.678507 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:33.678840 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:33.678879 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:33.678909 storage/client_test.go:863  engine 2: missing key "z"
I160818 04:50:33.943278 gossip/gossip.go:1003  node has connected to cluster via gossip
E160818 04:50:34.679186 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:34.679225 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:34.679283 storage/client_test.go:863  engine 2: missing key "z"
I160818 04:50:35.297383 gossip/gossip.go:1003  node has connected to cluster via gossip
E160818 04:50:35.679543 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:35.679582 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:35.679616 storage/client_test.go:863  engine 2: missing key "z"
I160818 04:50:35.705294 gossip/gossip.go:1003  node has connected to cluster via gossip
E160818 04:50:36.679846 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:36.679881 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:36.679908 storage/client_test.go:863  engine 2: missing key "z"
I160818 04:50:36.720048 gossip/gossip.go:1003  node has connected to cluster via gossip
E160818 04:50:37.680650 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:37.680702 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:37.680727 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:38.680969 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:38.680998 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:38.681012 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:39.681267 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:39.681312 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:39.681346 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:40.681633 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:40.681668 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:40.681707 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:41.681987 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:41.682043 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:41.682070 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:42.682287 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:42.682326 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:42.682361 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:43.682612 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:43.682641 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:43.682663 storage/client_test.go:863  engine 2: missing key "z"
E160818 04:50:44.682916 storage/client_test.go:863  engine 0: missing key "z"
E160818 04:50:44.682966 storage/client_test.go:863  engine 1: missing key "z"
E160818 04:50:44.683000 storage/client_test.go:863  engine 2: missing key "z"
I160818 04:50:45.684002 http2_server.go:276  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:44397->127.0.0.1:51924: use of closed network connection
I160818 04:50:45.684098 http2_server.go:276  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:45963->127.0.0.1:37632: use of closed network connection
I160818 04:50:45.684104 http2_server.go:276  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:40826->127.0.0.1:56138: use of closed network connection
I160818 04:50:45.684113 http2_server.go:276  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:39245->127.0.0.1:33728: use of closed network connection
I160818 04:50:45.684146 http2_server.go:276  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:46142->127.0.0.1:54348: use of closed network connection
I160818 04:50:45.684152 http2_server.go:276  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:36233->127.0.0.1:47682: use of closed network connection
--- FAIL: TestSplitSnapshotRace_SnapshotWins (46.25s)
    testing.go:117: storage/client_split_test.go:1050, condition failed to evaluate within 45s: expected [0 0 0 2 25 25], got [0 0 0 25 25 25]

Run Details:

0 runs so far, 0 failures, over 5s
0 runs so far, 0 failures, over 10s
0 runs so far, 0 failures, over 15s
0 runs so far, 0 failures, over 20s
0 runs so far, 0 failures, over 25s
0 runs so far, 0 failures, over 30s
0 runs so far, 0 failures, over 35s
16 runs so far, 0 failures, over 40s
16 runs so far, 0 failures, over 45s
16 runs so far, 0 failures, over 50s
16 runs so far, 0 failures, over 55s
16 runs so far, 0 failures, over 1m0s
16 runs so far, 0 failures, over 1m5s
17 runs so far, 0 failures, over 1m10s
19 runs so far, 0 failures, over 1m15s
32 runs so far, 0 failures, over 1m20s
32 runs so far, 0 failures, over 1m25s
32 runs so far, 0 failures, over 1m30s
32 runs so far, 0 failures, over 1m35s
32 runs so far, 0 failures, over 1m40s
33 runs so far, 0 failures, over 1m45s
34 runs so far, 0 failures, over 1m50s
48 runs so far, 0 failures, over 1m55s
48 runs so far, 0 failures, over 2m0s
48 runs so far, 0 failures, over 2m5s
48 runs so far, 0 failures, over 2m10s
48 runs so far, 0 failures, over 2m15s
50 runs so far, 0 failures, over 2m20s
50 runs so far, 0 failures, over 2m25s
61 runs so far, 0 failures, over 2m30s
64 runs so far, 0 failures, over 2m35s
64 runs so far, 0 failures, over 2m40s
64 runs so far, 0 failures, over 2m45s
65 runs so far, 0 failures, over 2m50s
66 runs so far, 0 failures, over 2m55s
66 runs so far, 0 failures, over 3m0s
71 runs so far, 0 failures, over 3m5s
80 runs so far, 0 failures, over 3m10s
80 runs so far, 0 failures, over 3m15s
80 runs so far, 0 failures, over 3m20s
81 runs so far, 0 failures, over 3m25s
81 runs so far, 0 failures, over 3m30s
81 runs so far, 0 failures, over 3m35s
83 runs so far, 0 failures, over 3m40s
95 runs so far, 0 failures, over 3m45s
95 runs so far, 0 failures, over 3m50s
95 runs so far, 0 failures, over 3m55s
97 runs completed, 1 failures, over 3m58s
FAIL

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added this to the Q3 milestone Aug 18, 2016
@cockroach-teamcity cockroach-teamcity added C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Aug 18, 2016
@tamird
Copy link
Contributor

tamird commented Aug 19, 2016

#8416.

@tamird tamird closed this as completed Aug 19, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
Q3
Development

No branches or pull requests
2 participants
@tamird @cockroach-teamcity