{"action":"closed","issue":{"url":"https://api.github.com/repos/cockroachdb/cockroach/issues/12258","repository_url":"https://api.github.com/repos/cockroachdb/cockroach","labels_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/12258/labels{/name}","comments_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/12258/comments","events_url":"https://api.github.com/repos/cockroachdb/cockroach/issues/12258/events","html_url":"https://github.com/cockroachdb/cockroach/issues/12258","id":194813483,"number":12258,"title":"storage: Double-applied command in TestSplitSnapshotRace_SplitWins","user":{"login":"bdarnell","id":160562,"avatar_url":"https://avatars.githubusercontent.com/u/160562?v=3","gravatar_id":"","url":"https://api.github.com/users/bdarnell","html_url":"https://github.com/bdarnell","followers_url":"https://api.github.com/users/bdarnell/followers","following_url":"https://api.github.com/users/bdarnell/following{/other_user}","gists_url":"https://api.github.com/users/bdarnell/gists{/gist_id}","starred_url":"https://api.github.com/users/bdarnell/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/bdarnell/subscriptions","organizations_url":"https://api.github.com/users/bdarnell/orgs","repos_url":"https://api.github.com/users/bdarnell/repos","events_url":"https://api.github.com/users/bdarnell/events{/privacy}","received_events_url":"https://api.github.com/users/bdarnell/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":{"login":"bdarnell","id":160562,"avatar_url":"https://avatars.githubusercontent.com/u/160562?v=3","gravatar_id":"","url":"https://api.github.com/users/bdarnell","html_url":"https://github.com/bdarnell","followers_url":"https://api.github.com/users/bdarnell/followers","following_url":"https://api.github.com/users/bdarnell/following{/other_user}","gists_url":"https://api.github.com/users/bdarnell/gists{/gist_id}","starred_url":"https://api.github.com/users/bdarnell/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/bdarnell/subscriptions","organizations_url":"https://api.github.com/users/bdarnell/orgs","repos_url":"https://api.github.com/users/bdarnell/repos","events_url":"https://api.github.com/users/bdarnell/events{/privacy}","received_events_url":"https://api.github.com/users/bdarnell/received_events","type":"User","site_admin":false},"assignees":[{"login":"bdarnell","id":160562,"avatar_url":"https://avatars.githubusercontent.com/u/160562?v=3","gravatar_id":"","url":"https://api.github.com/users/bdarnell","html_url":"https://github.com/bdarnell","followers_url":"https://api.github.com/users/bdarnell/followers","following_url":"https://api.github.com/users/bdarnell/following{/other_user}","gists_url":"https://api.github.com/users/bdarnell/gists{/gist_id}","starred_url":"https://api.github.com/users/bdarnell/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/bdarnell/subscriptions","organizations_url":"https://api.github.com/users/bdarnell/orgs","repos_url":"https://api.github.com/users/bdarnell/repos","events_url":"https://api.github.com/users/bdarnell/events{/privacy}","received_events_url":"https://api.github.com/users/bdarnell/received_events","type":"User","site_admin":false}],"milestone":null,"comments":1,"created_at":"2016-12-11T05:08:17Z","updated_at":"2016-12-14T12:35:21Z","closed_at":"2016-12-14T12:35:21Z","body":"Found while investigating #10698 and #11709. Those issues relate to a replica not getting GC'd when it should, but while stressing the tests I saw a more worrying failure (at commit e71bf9d675):\r\n\r\n```\r\n--- FAIL: TestSplitSnapshotRace_SplitWins (46.82s)\r\n\tsoon.go:43: storage/client_split_test.go:1001, condition failed to evaluate within 45s: expected [0 0 0 2 5 5], got [0 0 0 2 8 8]\r\n```\r\n\r\nThat means that an `Increment(3)` command is getting applied twice. Since it happened on both of the live replicas, it's probably a reproposal and a failure of our replay protection. \r\n\r\nThe full log follows (well, most of it. The same messages repeat for the remaining 45s)\r\n```\r\nI161211 12:51:34.016433 1 rand.go:76  Random seed: 5032174770022480193\r\nI161211 12:51:34.017890 19 storage/engine/rocksdb.go:340  opening in memory rocksdb instance\r\nI161211 12:51:34.019090 19 gossip/gossip.go:248  [n?] initial resolvers: []\r\nW161211 12:51:34.019121 19 gossip/gossip.go:1124  [n?] no resolvers found; use --join to specify a connected node\r\nI161211 12:51:34.019164 19 base/node_id.go:62  NodeID set to 1\r\nI161211 12:51:34.022058 19 storage/store.go:1240  [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available\r\nI161211 12:51:34.022166 19 gossip/gossip.go:290  [n1] NodeDescriptor set to node_id:1 address:<network_field:\"tcp\" address_field:\"127.0.0.1:64516\" > attrs:<> locality:<> \r\nI161211 12:51:34.023165 66 storage/replica_proposal.go:360  [s1,r1/1:/M{in-ax},@c420206000] new range lease repl={1 1 1} start=0.000000000,0 exp=0.900000123,7 pro=0.000000123,8 following repl={0 0 0} start=0.000000000,0 exp=0.000000000,0 [physicalTime=1970-01-01 00:00:00.000000123 +0000 UTC]\r\nI161211 12:51:34.026603 19 storage/engine/rocksdb.go:340  opening in memory rocksdb instance\r\nI161211 12:51:34.028202 19 gossip/gossip.go:248  [n?] initial resolvers: [127.0.0.1:64516]\r\nW161211 12:51:34.028248 19 gossip/gossip.go:1126  [n?] no incoming or outgoing connections\r\nI161211 12:51:34.028311 19 base/node_id.go:62  NodeID set to 2\r\nI161211 12:51:34.030249 19 storage/store.go:1240  [n2,s2]: failed initial metrics computation: [n2,s2]: system config not yet available\r\nI161211 12:51:34.030310 19 gossip/gossip.go:290  [n2] NodeDescriptor set to node_id:2 address:<network_field:\"tcp\" address_field:\"127.0.0.1:64518\" > attrs:<> locality:<> \r\nI161211 12:51:34.030706 64 gossip/client.go:125  [n2] started gossip client to 127.0.0.1:64516\r\nI161211 12:51:34.107997 19 storage/engine/rocksdb.go:340  opening in memory rocksdb instance\r\nI161211 12:51:34.110682 19 gossip/gossip.go:248  [n?] initial resolvers: [127.0.0.1:64516]\r\nW161211 12:51:34.110731 19 gossip/gossip.go:1126  [n?] no incoming or outgoing connections\r\nI161211 12:51:34.110846 19 base/node_id.go:62  NodeID set to 3\r\nI161211 12:51:34.113138 19 storage/store.go:1240  [n3,s3]: failed initial metrics computation: [n3,s3]: system config not yet available\r\nI161211 12:51:34.113187 19 gossip/gossip.go:290  [n3] NodeDescriptor set to node_id:3 address:<network_field:\"tcp\" address_field:\"127.0.0.1:64520\" > attrs:<> locality:<> \r\nI161211 12:51:34.113234 30 gossip/client.go:125  [n3] started gossip client to 127.0.0.1:64516\r\nI161211 12:51:34.115367 19 storage/engine/rocksdb.go:340  opening in memory rocksdb instance\r\nI161211 12:51:34.116170 19 gossip/gossip.go:248  [n?] initial resolvers: [127.0.0.1:64516]\r\nW161211 12:51:34.116182 19 gossip/gossip.go:1126  [n?] no incoming or outgoing connections\r\nI161211 12:51:34.116208 19 base/node_id.go:62  NodeID set to 4\r\nI161211 12:51:34.117580 19 storage/store.go:1240  [n4,s4]: failed initial metrics computation: [n4,s4]: system config not yet available\r\nI161211 12:51:34.117624 19 gossip/gossip.go:290  [n4] NodeDescriptor set to node_id:4 address:<network_field:\"tcp\" address_field:\"127.0.0.1:64522\" > attrs:<> locality:<> \r\nI161211 12:51:34.117660 220 gossip/client.go:125  [n4] started gossip client to 127.0.0.1:64516\r\nI161211 12:51:34.119796 19 storage/engine/rocksdb.go:340  opening in memory rocksdb instance\r\nI161211 12:51:34.120718 19 gossip/gossip.go:248  [n?] initial resolvers: [127.0.0.1:64516]\r\nW161211 12:51:34.120731 19 gossip/gossip.go:1126  [n?] no incoming or outgoing connections\r\nI161211 12:51:34.120758 19 base/node_id.go:62  NodeID set to 5\r\nI161211 12:51:34.123903 19 storage/store.go:1240  [n5,s5]: failed initial metrics computation: [n5,s5]: system config not yet available\r\nI161211 12:51:34.123965 19 gossip/gossip.go:290  [n5] NodeDescriptor set to node_id:5 address:<network_field:\"tcp\" address_field:\"127.0.0.1:64524\" > attrs:<> locality:<> \r\nI161211 12:51:34.125761 312 gossip/client.go:125  [n5] started gossip client to 127.0.0.1:64516\r\nI161211 12:51:34.126472 317 gossip/server.go:263  [n1] refusing gossip from node 5 (max 3 conns); forwarding to 3 ({tcp 127.0.0.1:64520})\r\nI161211 12:51:34.126621 317 gossip/server.go:263  [n1] refusing gossip from node 5 (max 3 conns); forwarding to 3 ({tcp 127.0.0.1:64520})\r\nI161211 12:51:34.127480 317 gossip/server.go:263  [n1] refusing gossip from node 5 (max 3 conns); forwarding to 3 ({tcp 127.0.0.1:64520})\r\nI161211 12:51:34.127596 317 gossip/server.go:263  [n1] refusing gossip from node 5 (max 3 conns); forwarding to 3 ({tcp 127.0.0.1:64520})\r\nI161211 12:51:34.127700 312 gossip/client.go:130  [n5] closing client to node 1 (127.0.0.1:64516): received forward from node 1 to 3 (127.0.0.1:64520)\r\nI161211 12:51:34.128013 320 gossip/client.go:125  [n5] started gossip client to 127.0.0.1:64520\r\nI161211 12:51:34.201028 19 storage/engine/rocksdb.go:340  opening in memory rocksdb instance\r\nI161211 12:51:34.201857 19 gossip/gossip.go:248  [n?] initial resolvers: [127.0.0.1:64516]\r\nW161211 12:51:34.201872 19 gossip/gossip.go:1126  [n?] no incoming or outgoing connections\r\nI161211 12:51:34.201905 19 base/node_id.go:62  NodeID set to 6\r\nI161211 12:51:34.203197 19 storage/store.go:1240  [n6,s6]: failed initial metrics computation: [n6,s6]: system config not yet available\r\nI161211 12:51:34.203219 402 gossip/client.go:125  [n6] started gossip client to 127.0.0.1:64516\r\nI161211 12:51:34.203240 19 gossip/gossip.go:290  [n6] NodeDescriptor set to node_id:6 address:<network_field:\"tcp\" address_field:\"127.0.0.1:64526\" > attrs:<> locality:<> \r\nI161211 12:51:34.203397 357 gossip/server.go:263  [n1] refusing gossip from node 6 (max 3 conns); forwarding to 2 ({tcp 127.0.0.1:64518})\r\nI161211 12:51:34.203535 357 gossip/server.go:263  [n1] refusing gossip from node 6 (max 3 conns); forwarding to 2 ({tcp 127.0.0.1:64518})\r\nI161211 12:51:34.203747 402 gossip/client.go:130  [n6] closing client to node 1 (127.0.0.1:64516): received forward from node 1 to 2 (127.0.0.1:64518)\r\nI161211 12:51:34.203868 435 gossip/client.go:125  [n6] started gossip client to 127.0.0.1:64518\r\nI161211 12:51:34.206290 19 storage/replica_command.go:2389  [s1,r1/1:/M{in-ax},@c420206000] initiating a split of this range at key /System/Max [r2]\r\nE161211 12:51:34.208751 25 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.208969 25 storage/queue.go:613  [replicate,s1,r2/1:/{System/Max-Max},@c420177400] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.209057 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nI161211 12:51:34.209458 19 storage/replica_raftstorage.go:468  [s1,r2/1:/{System/Max-Max},@c420177400] generated preemptive snapshot 8dedd60e at index 11\r\nI161211 12:51:34.210481 19 storage/store.go:3255  [s1,r2/1:/{System/Max-Max},@c420177400] streamed snapshot: kv pairs: 30, log entries: 1\r\nI161211 12:51:34.210825 385 storage/replica_raftstorage.go:633  [s2,r2/?:{-},@c4202f0500] applying preemptive snapshot at index 11 (id=8dedd60e, encoded size=3539, 1 rocksdb batches, 1 log entries)\r\nI161211 12:51:34.211104 385 storage/replica_raftstorage.go:641  [s2,r2/?:/{System/Max-Max},@c4202f0500] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\r\nI161211 12:51:34.211728 19 storage/replica_command.go:3290  [s1,r2/1:/{System/Max-Max},@c420177400] change replicas: 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 \r\nE161211 12:51:34.212050 368 storage/queue.go:613  [replicate,s1,r2/1:/{System/Max-Max},@c420177400] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.212107 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nW161211 12:51:34.212464 469 storage/stores.go:218  range not contained in one range: [/Meta2/Max,\"\\x05\\x00\"), but have [/Min,/System/Max)\r\nI161211 12:51:34.213196 473 storage/replica.go:2334  [s1,r2/1:/{System/Max-Max},@c420177400] proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:2}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]\r\nI161211 12:51:34.213953 19 storage/replica_raftstorage.go:468  [s1,r2/1:/{System/Max-Max},@c420177400] generated preemptive snapshot f91dd110 at index 13\r\nI161211 12:51:34.214247 490 storage/raft_transport.go:437  raft transport stream to node 1 established\r\nI161211 12:51:34.214324 19 storage/store.go:3255  [s1,r2/1:/{System/Max-Max},@c420177400] streamed snapshot: kv pairs: 32, log entries: 3\r\nI161211 12:51:34.214523 505 storage/replica_raftstorage.go:633  [s3,r2/?:{-},@c420a74000] applying preemptive snapshot at index 13 (id=f91dd110, encoded size=4430, 1 rocksdb batches, 3 log entries)\r\nI161211 12:51:34.214734 505 storage/replica_raftstorage.go:641  [s3,r2/?:/{System/Max-Max},@c420a74000] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\r\nI161211 12:51:34.215160 19 storage/replica_command.go:3290  [s1,r2/1:/{System/Max-Max},@c420177400] change replicas: 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 \r\nI161211 12:51:34.216351 521 storage/replica.go:2334  [s1,r2/1:/{System/Max-Max},@c420177400] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:3}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3}]\r\nI161211 12:51:34.217379 19 storage/replica_raftstorage.go:468  [s1,r2/1:/{System/Max-Max},@c420177400] generated preemptive snapshot db7da2f8 at index 17\r\nI161211 12:51:34.217760 19 storage/store.go:3255  [s1,r2/1:/{System/Max-Max},@c420177400] streamed snapshot: kv pairs: 33, log entries: 7\r\nI161211 12:51:34.218004 525 storage/replica_raftstorage.go:633  [s4,r2/?:{-},@c420b22000] applying preemptive snapshot at index 17 (id=db7da2f8, encoded size=5648, 1 rocksdb batches, 7 log entries)\r\nI161211 12:51:34.218314 525 storage/replica_raftstorage.go:641  [s4,r2/?:/{System/Max-Max},@c420b22000] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\r\nI161211 12:51:34.218854 19 storage/replica_command.go:3290  [s1,r2/1:/{System/Max-Max},@c420177400] change replicas: 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 \r\nI161211 12:51:34.220350 480 storage/replica.go:2334  [s1,r2/1:/{System/Max-Max},@c420177400] proposing ADD_REPLICA {NodeID:4 StoreID:4 ReplicaID:4}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3} {NodeID:4 StoreID:4 ReplicaID:4}]\r\nI161211 12:51:34.229422 19 storage/replica_command.go:3290  [s1,r2/1:/{System/Max-Max},@c420177400] change replicas: 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 \r\nI161211 12:51:34.230997 563 storage/replica.go:2334  [s1,r2/1:/{System/Max-Max},@c420177400] proposing REMOVE_REPLICA {NodeID:1 StoreID:1 ReplicaID:1}: [{NodeID:4 StoreID:4 ReplicaID:4} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3}]\r\nI161211 12:51:34.232728 26 storage/store.go:2069  [replicaGC,s1,r2/1:/{System/Max-Max},@c420177400] removing replica\r\nW161211 12:51:34.233087 492 storage/store.go:3121  [s2] got error from range 2, replica {1 1 1}: raft group deleted\r\nE161211 12:51:34.233326 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.233826 19 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nE161211 12:51:34.234258 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.234702 19 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nE161211 12:51:34.235442 19 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nE161211 12:51:34.235600 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.236091 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.236594 19 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nE161211 12:51:34.237382 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.237885 19 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nE161211 12:51:34.238480 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.239105 19 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nI161211 12:51:34.239191 19 util/stop/stopper.go:396  stop has been called, stopping or quiescing all running tasks\r\nE161211 12:51:34.240280 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.240841 19 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nE161211 12:51:34.241599 19 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nE161211 12:51:34.241752 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.242160 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.242693 19 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nE161211 12:51:34.242775 19 storage/client_test.go:1113  node unavailable; try another peer\r\nE161211 12:51:34.243696 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.243810 19 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nE161211 12:51:34.244992 19 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nE161211 12:51:34.245141 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nW161211 12:51:34.274427 532 storage/raft_transport.go:258  unable to accept Raft message from {NodeID:1 StoreID:1 ReplicaID:0}: no handler registered for {NodeID:4 StoreID:4 ReplicaID:0}\r\nW161211 12:51:34.274753 547 storage/store.go:3117  [s1] raft error: node 4 claims to not contain store 4 for replica {4 4 0}: store 4 was not found\r\nW161211 12:51:34.274802 481 storage/raft_transport.go:443  raft transport stream to node 4 failed: store 4 was not found\r\nE161211 12:51:34.294969 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.307698 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.385046 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.385664 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.393789 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nW161211 12:51:34.431959 492 storage/store.go:3121  [s2] got error from range 2, replica {1 1 1}: raft group deleted\r\nE161211 12:51:34.474889 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.486323 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nI161211 12:51:34.513744 681 storage/raft_transport.go:437  raft transport stream to node 4 established\r\nW161211 12:51:34.513859 708 storage/raft_transport.go:258  unable to accept Raft message from {NodeID:3 StoreID:3 ReplicaID:3}: no handler registered for {NodeID:4 StoreID:4 ReplicaID:4}\r\nW161211 12:51:34.513952 695 storage/store.go:3117  [s3] raft error: node 4 claims to not contain store 4 for replica {4 4 4}: store 4 was not found\r\nI161211 12:51:34.532075 682 storage/raft_transport.go:437  raft transport stream to node 4 established\r\nW161211 12:51:34.532238 684 storage/raft_transport.go:258  unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:2}: no handler registered for {NodeID:4 StoreID:4 ReplicaID:4}\r\nW161211 12:51:34.532351 710 storage/store.go:3117  [s2] raft error: node 4 claims to not contain store 4 for replica {4 4 4}: store 4 was not found\r\nE161211 12:51:34.564468 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.564809 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.572751 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.658159 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.665895 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.747869 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.748602 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.752374 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nI161211 12:51:34.831896 731 storage/raft_transport.go:437  raft transport stream to node 4 established\r\nW161211 12:51:34.832073 733 storage/raft_transport.go:258  unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:2}: no handler registered for {NodeID:4 StoreID:4 ReplicaID:4}\r\nW161211 12:51:34.832208 760 storage/store.go:3117  [s2] raft error: node 4 claims to not contain store 4 for replica {4 4 4}: store 4 was not found\r\nW161211 12:51:34.832291 733 storage/raft_transport.go:258  unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:2}: no handler registered for {NodeID:4 StoreID:4 ReplicaID:4}\r\nI161211 12:51:34.833063 104 storage/replica_proposal.go:360  [s2,r2/2:/{System/Max-Max},@c4202f0500] new range lease repl={2 2 2} start=0.900000123,8 exp=2.700000125,21 pro=1.800000125,22 following repl={1 1 1} start=0.000000000,0 exp=0.900000123,7 pro=0.000000123,8 [physicalTime=1970-01-01 00:00:03.600000127 +0000 UTC]\r\nE161211 12:51:34.834728 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nI161211 12:51:34.836503 632 storage/replica_command.go:2389  [s2,r2/2:/{System/Max-Max},@c4202f0500] initiating a split of this range at key \"m\" [r11]\r\nE161211 12:51:34.845472 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.924618 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:34.925579 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nI161211 12:51:34.933687 819 storage/raft_transport.go:437  raft transport stream to node 4 established\r\nE161211 12:51:34.934634 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nW161211 12:51:34.935209 836 storage/raft_transport.go:258  unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:0}: no handler registered for {NodeID:4 StoreID:4 ReplicaID:0}\r\nW161211 12:51:34.935372 821 storage/store.go:3117  [s2] raft error: node 4 claims to not contain store 4 for replica {4 4 0}: store 4 was not found\r\nI161211 12:51:34.952597 19 storage/replica_raftstorage.go:468  [s2,r11/2:{\"m\"-/Max},@c4202f0a00] generated preemptive snapshot 69389f96 at index 10\r\nI161211 12:51:34.953099 19 storage/store.go:3255  [s2,r11/2:{\"m\"-/Max},@c4202f0a00] streamed snapshot: kv pairs: 29, log entries: 0\r\nI161211 12:51:34.953312 809 storage/replica_raftstorage.go:633  [s5,r11/?:{-},@c420176a00] applying preemptive snapshot at index 10 (id=69389f96, encoded size=3536, 1 rocksdb batches, 0 log entries)\r\nI161211 12:51:34.953540 809 storage/replica_raftstorage.go:641  [s5,r11/?:{\"m\"-/Max},@c420176a00] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\r\nI161211 12:51:34.954005 19 storage/replica_command.go:3290  [s2,r11/2:{\"m\"-/Max},@c4202f0a00] change replicas: 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 \r\nI161211 12:51:34.954526 855 storage/raft_transport.go:437  raft transport stream to node 4 established\r\nW161211 12:51:34.955040 823 storage/raft_transport.go:258  unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:2}: no handler registered for {NodeID:4 StoreID:4 ReplicaID:1}\r\nW161211 12:51:34.955183 857 storage/store.go:3117  [s2] raft error: node 4 claims to not contain store 4 for replica {4 4 1}: store 4 was not found\r\nI161211 12:51:34.955384 824 storage/raft_transport.go:437  raft transport stream to node 4 established\r\nW161211 12:51:34.955559 859 storage/raft_transport.go:258  unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:2}: no handler registered for {NodeID:4 StoreID:4 ReplicaID:1}\r\nW161211 12:51:34.955663 811 storage/store.go:3117  [s2] raft error: node 4 claims to not contain store 4 for replica {4 4 1}: store 4 was not found\r\nI161211 12:51:34.957018 827 storage/replica.go:2334  [s2,r11/2:{\"m\"-/Max},@c4202f0a00] proposing ADD_REPLICA {NodeID:5 StoreID:5 ReplicaID:4}: [{NodeID:4 StoreID:4 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3} {NodeID:5 StoreID:5 ReplicaID:4}]\r\nE161211 12:51:35.014456 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nI161211 12:51:35.014966 19 storage/replica_raftstorage.go:468  [s2,r11/2:{\"m\"-/Max},@c4202f0a00] generated preemptive snapshot 75ac0864 at index 15\r\nI161211 12:51:35.015330 19 storage/store.go:3255  [s2,r11/2:{\"m\"-/Max},@c4202f0a00] streamed snapshot: kv pairs: 30, log entries: 5\r\nI161211 12:51:35.015534 882 storage/replica_raftstorage.go:633  [s6,r11/?:{-},@c420a74500] applying preemptive snapshot at index 15 (id=75ac0864, encoded size=5036, 1 rocksdb batches, 5 log entries)\r\nI161211 12:51:35.015770 882 storage/replica_raftstorage.go:641  [s6,r11/?:{\"m\"-/Max},@c420a74500] applied preemptive snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]\r\nI161211 12:51:35.016112 19 storage/replica_command.go:3290  [s2,r11/2:{\"m\"-/Max},@c4202f0a00] change replicas: 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 \r\nI161211 12:51:35.017365 885 storage/replica.go:2334  [s2,r11/2:{\"m\"-/Max},@c4202f0a00] proposing ADD_REPLICA {NodeID:6 StoreID:6 ReplicaID:5}: [{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}]\r\nI161211 12:51:35.020308 19 storage/replica_command.go:3290  [s2,r11/2:{\"m\"-/Max},@c4202f0a00] change replicas: 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 \r\nI161211 12:51:35.021605 874 storage/replica.go:2334  [s2,r11/2:{\"m\"-/Max},@c4202f0a00] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:3}: [{NodeID:4 StoreID:4 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:6 StoreID:6 ReplicaID:5} {NodeID:5 StoreID:5 ReplicaID:4}]\r\nI161211 12:51:35.023168 19 storage/replica_command.go:3290  [s2,r11/2:{\"m\"-/Max},@c4202f0a00] change replicas: 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 \r\nI161211 12:51:35.024161 503 storage/store.go:3113  [s3,r11/3:{\"m\"-/Max},@c420176500] added to replica GC queue (peer suggestion)\r\nI161211 12:51:35.025178 140 storage/store.go:2069  [replicaGC,s3,r11/3:{\"m\"-/Max},@c420176500] removing replica\r\nI161211 12:51:35.026179 914 storage/replica.go:2334  [s2,r11/2:{\"m\"-/Max},@c4202f0a00] proposing REMOVE_REPLICA {NodeID:2 StoreID:2 ReplicaID:2}: [{NodeID:4 StoreID:4 ReplicaID:1} {NodeID:5 StoreID:5 ReplicaID:4} {NodeID:6 StoreID:6 ReplicaID:5}]\r\nE161211 12:51:35.026486 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:35.028515 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:35.029213 913 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nE161211 12:51:35.030231 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nI161211 12:51:35.030760 938 storage/raft_transport.go:437  raft transport stream to node 4 established\r\nI161211 12:51:35.030922 888 storage/store.go:3113  [s2,r11/2:{\"m\"-/Max},@c4202f0a00] added to replica GC queue (peer suggestion)\r\nE161211 12:51:35.030967 913 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nW161211 12:51:35.030986 925 storage/raft_transport.go:258  unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:0}: no handler registered for {NodeID:4 StoreID:4 ReplicaID:0}\r\nW161211 12:51:35.031072 923 storage/store.go:3117  [s2] raft error: node 4 claims to not contain store 4 for replica {4 4 0}: store 4 was not found\r\nE161211 12:51:35.031540 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:35.032220 913 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nE161211 12:51:35.032324 913 storage/client_test.go:1113  node unavailable; try another peer\r\nE161211 12:51:35.033541 913 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nE161211 12:51:35.033785 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:35.034305 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:35.034748 913 storage/client_test.go:1126  heartbeat failed on epoch increment\r\nE161211 12:51:35.108553 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:35.109217 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:35.111679 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nI161211 12:51:35.180557 988 storage/raft_transport.go:437  raft transport stream to node 4 established\r\nW161211 12:51:35.180762 945 storage/raft_transport.go:258  unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:0}: no handler registered for {NodeID:4 StoreID:4 ReplicaID:0}\r\nW161211 12:51:35.180882 990 storage/store.go:3117  [s2] raft error: node 4 claims to not contain store 4 for replica {4 4 0}: store 4 was not found\r\nE161211 12:51:35.198523 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:35.205817 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nI161211 12:51:35.282018 1002 storage/raft_transport.go:437  raft transport stream to node 4 established\r\nW161211 12:51:35.282279 1004 storage/raft_transport.go:258  unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:0}: no handler registered for {NodeID:4 StoreID:4 ReplicaID:0}\r\nW161211 12:51:35.282487 1027 storage/store.go:3117  [s2] raft error: node 4 claims to not contain store 4 for replica {4 4 0}: store 4 was not found\r\nE161211 12:51:35.285013 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:35.285640 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nE161211 12:51:35.292169 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nI161211 12:51:35.304920 1045 storage/raft_transport.go:437  raft transport stream to node 4 established\r\nW161211 12:51:35.305160 1047 storage/raft_transport.go:258  unable to accept Raft message from {NodeID:6 StoreID:6 ReplicaID:5}: no handler registered for {NodeID:4 StoreID:4 ReplicaID:1}\r\nW161211 12:51:35.305334 1035 storage/store.go:3117  [s6] raft error: node 4 claims to not contain store 4 for replica {4 4 1}: store 4 was not found\r\nE161211 12:51:35.374976 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nI161211 12:51:35.380884 1037 storage/raft_transport.go:437  raft transport stream to node 4 established\r\nW161211 12:51:35.381128 1062 storage/raft_transport.go:258  unable to accept Raft message from {NodeID:2 StoreID:2 ReplicaID:0}: no handler registered for {NodeID:4 StoreID:4 ReplicaID:0}\r\nW161211 12:51:35.381264 1021 storage/store.go:3117  [s2] raft error: node 4 claims to not contain store 4 for replica {4 4 0}: store 4 was not found\r\nE161211 12:51:35.385969 368 storage/queue.go:613  [replicate,s1,r1/1:/{Min-System/Max},@c420206000] purgatory: 0 of 0 stores with an attribute matching []; likely not enough nodes in cluster\r\nI161211 12:51:35.425583 1024 storage/raft_transport.go:437  raft transport stream to node 4 established\r\n```"}}
{"actor":{"display_login":"bdarnell"}}