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

teamcity: failed tests on master: testrace/TestBackupRestoreSystemJobs #15263

Closed
cockroach-teamcity opened this issue Apr 22, 2017 · 2 comments
Closed

teamcity: failed tests on master: testrace/TestBackupRestoreSystemJobs #15263

cockroach-teamcity opened this issue Apr 22, 2017 · 2 comments
Assignees
@a-robinson
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.

Comments

@cockroach-teamcity
Copy link
Member

The following tests appear to have failed:

#231100:

--- FAIL: testrace/TestBackupRestoreSystemJobs (0.000s)
Test ended in panic.

------- Stdout: -------
W170422 00:02:45.449743 7241 server/status/runtime.go:111  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I170422 00:02:45.453366 7241 server/config.go:413  1 storage engine initialized
I170422 00:02:45.454478 7241 server/node.go:451  [n?] store [n0,s0] not bootstrapped
I170422 00:02:45.486389 7241 server/node.go:386  [n?] **** cluster cd635c97-d0cf-4dd4-9979-49659c05e36b has been created
I170422 00:02:45.486494 7241 server/node.go:387  [n?] **** add additional nodes by specifying --join=127.0.0.1:50910
I170422 00:02:45.508706 7209 storage/split_queue.go:92  [split,n1,s1,r1/1:/M{in-ax}] splitting at key /System/""
I170422 00:02:45.514879 7241 server/node.go:464  [n1] initialized store [n1,s1]: {Capacity:536870912 Available:536870912 RangeCount:1 LeaseCount:1}
I170422 00:02:45.515177 7241 server/node.go:348  [n1] node ID 1 initialized
I170422 00:02:45.515460 7241 gossip/gossip.go:297  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:50910" > attrs:<> locality:<> 
I170422 00:02:45.516324 7241 storage/stores.go:296  [n1] read 0 node addresses from persistent storage
I170422 00:02:45.516600 7241 server/node.go:605  [n1] connecting to gossip network to verify cluster ID...
I170422 00:02:45.517062 7241 server/node.go:630  [n1] node connected via gossip and verified as part of cluster "cd635c97-d0cf-4dd4-9979-49659c05e36b"
I170422 00:02:45.518677 7241 server/node.go:402  [n1] node=1: started with [[]=] engine(s) and attributes []
I170422 00:02:45.531792 7209 storage/replica_command.go:2626  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I170422 00:02:45.559996 7241 sql/executor.go:326  [n1] creating distSQLPlanner with address {tcp 127.0.0.1:50910}
E170422 00:02:45.578665 7210 storage/queue.go:634  [replicate,n1,s1,r1/1:/{Min-System/}] range requires a replication change, but lacks a quorum of live replicas (0/1)
I170422 00:02:45.580237 7209 storage/split_queue.go:92  [split,n1,s1,r2/1:/{System/-Max}] splitting at key /System/tsd
I170422 00:02:45.580451 7209 storage/replica_command.go:2626  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/tsd [r3]
I170422 00:02:45.643442 7241 server/server.go:730  [n1] starting https server at 127.0.0.1:48948
I170422 00:02:45.643604 7241 server/server.go:731  [n1] starting grpc/postgres server at 127.0.0.1:50910
I170422 00:02:45.643669 7241 server/server.go:732  [n1] advertising CockroachDB node at 127.0.0.1:50910
E170422 00:02:45.707906 7210 storage/queue.go:634  [replicate,n1,s1,r2/1:/System/{-tsd}] range requires a replication change, but lacks a quorum of live replicas (0/1)
I170422 00:02:45.714137 7209 storage/split_queue.go:92  [split,n1,s1,r3/1:/{System/tsd-Max}] splitting at key /System/"tse"
I170422 00:02:45.714318 7209 storage/replica_command.go:2626  [split,n1,s1,r3/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r4]
E170422 00:02:45.736700 7210 storage/queue.go:634  [replicate,n1,s1,r1/1:/{Min-System/}] range requires a replication change, but lacks a quorum of live replicas (0/1)
I170422 00:02:45.829313 7241 sql/event_log.go:101  [n1] Event: "alter_table", target: 12, info: {TableName:eventlog Statement:ALTER TABLE system.eventlog ALTER COLUMN uniqueID SET DEFAULT uuid_v4() User:node MutationID:0 CascadeDroppedViews:[]}
I170422 00:02:45.858526 7241 sql/lease.go:372  [n1] publish: descID=12 (eventlog) version=2 mtime=2017-04-22 00:02:45.858410076 +0000 UTC
I170422 00:02:45.888224 7209 storage/split_queue.go:92  [split,n1,s1,r4/1:/{System/tse-Max}] splitting at key /Table/0/0
I170422 00:02:45.888423 7209 storage/replica_command.go:2626  [split,n1,s1,r4/1:/{System/tse-Max}] initiating a split of this range at key /Table/0 [r5]
I170422 00:02:45.974108 7209 storage/split_queue.go:92  [split,n1,s1,r5/1:/{Table/0-Max}] splitting at key /Table/11/0
I170422 00:02:45.974369 7209 storage/replica_command.go:2626  [split,n1,s1,r5/1:/{Table/0-Max}] initiating a split of this range at key /Table/11 [r6]
I170422 00:02:46.038401 7209 storage/split_queue.go:92  [split,n1,s1,r6/1:/{Table/11-Max}] splitting at key /Table/12/0
I170422 00:02:46.038578 7209 storage/replica_command.go:2626  [split,n1,s1,r6/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r7]
I170422 00:02:46.045669 7241 server/server.go:841  [n1] done ensuring all necessary migrations have run
I170422 00:02:46.045797 7241 server/server.go:843  [n1] serving sql connections
I170422 00:02:46.118241 7612 sql/event_log.go:101  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:50910} Attrs: Locality:} ClusterID:cd635c97-d0cf-4dd4-9979-49659c05e36b StartedAt:1492819365517133680 LastUp:1492819365517133680}
I170422 00:02:46.200751 7209 storage/split_queue.go:92  [split,n1,s1,r7/1:/{Table/12-Max}] splitting at key /Table/13/0
I170422 00:02:46.200968 7209 storage/replica_command.go:2626  [split,n1,s1,r7/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r8]
I170422 00:02:46.267568 7209 storage/split_queue.go:92  [split,n1,s1,r8/1:/{Table/13-Max}] splitting at key /Table/14/0
I170422 00:02:46.267782 7209 storage/replica_command.go:2626  [split,n1,s1,r8/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r9]
I170422 00:02:46.397513 7209 storage/split_queue.go:92  [split,n1,s1,r9/1:/{Table/14-Max}] splitting at key /Table/15/0
I170422 00:02:46.397679 7209 storage/replica_command.go:2626  [split,n1,s1,r9/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r10]
W170422 00:02:46.552804 7241 server/status/runtime.go:111  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
W170422 00:02:46.554725 7241 gossip/gossip.go:1189  [n?] no incoming or outgoing connections
I170422 00:02:46.579707 7241 server/config.go:413  1 storage engine initialized
I170422 00:02:46.580945 7241 server/node.go:451  [n?] store [n0,s0] not bootstrapped
I170422 00:02:46.581665 7241 storage/stores.go:296  [n?] read 0 node addresses from persistent storage
I170422 00:02:46.581819 7241 server/node.go:605  [n?] connecting to gossip network to verify cluster ID...
I170422 00:02:46.623967 7828 gossip/client.go:131  [n?] started gossip client to 127.0.0.1:50910
I170422 00:02:46.625310 7938 gossip/server.go:234  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:38844}
I170422 00:02:46.628928 7896 storage/stores.go:312  [n?] wrote 1 node addresses to persistent storage
I170422 00:02:46.629734 7241 server/node.go:630  [n?] node connected via gossip and verified as part of cluster "cd635c97-d0cf-4dd4-9979-49659c05e36b"
I170422 00:02:46.637071 7241 kv/dist_sender.go:367  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I170422 00:02:46.645128 7241 server/node.go:341  [n?] new node allocated ID 2
I170422 00:02:46.645450 7241 gossip/gossip.go:297  [n2] NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:38844" > attrs:<> locality:<> 
I170422 00:02:46.646361 7241 server/node.go:402  [n2] node=2: started with [[]=] engine(s) and attributes []
I170422 00:02:46.648657 7241 sql/executor.go:326  [n2] creating distSQLPlanner with address {tcp 127.0.0.1:38844}
I170422 00:02:46.658601 7940 storage/stores.go:312  [n1] wrote 1 node addresses to persistent storage
I170422 00:02:46.698980 7802 server/node.go:586  [n2] bootstrapped store [n2,s2]
I170422 00:02:46.706661 7241 server/server.go:730  [n2] starting https server at 127.0.0.1:42353
I170422 00:02:46.706775 7241 server/server.go:731  [n2] starting grpc/postgres server at 127.0.0.1:38844
I170422 00:02:46.706814 7241 server/server.go:732  [n2] advertising CockroachDB node at 127.0.0.1:38844
I170422 00:02:46.716138 7574 storage/replica_raftstorage.go:415  [replicate,n1,s1,r6/1:/Table/1{1-2}] generated preemptive snapshot e14a2d79 at index 25
I170422 00:02:46.721915 7241 server/server.go:841  [n2] done ensuring all necessary migrations have run
I170422 00:02:46.726398 7241 server/server.go:843  [n2] serving sql connections
I170422 00:02:46.824880 8100 sql/event_log.go:101  [n2] Event: "node_join", target: 2, info: {Descriptor:{NodeID:2 Address:{NetworkField:tcp AddressField:127.0.0.1:38844} Attrs: Locality:} ClusterID:cd635c97-d0cf-4dd4-9979-49659c05e36b StartedAt:1492819366646066006 LastUp:1492819366646066006}
W170422 00:02:46.846692 7241 server/status/runtime.go:111  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
W170422 00:02:46.848481 7241 gossip/gossip.go:1189  [n?] no incoming or outgoing connections
I170422 00:02:46.851354 7241 server/config.go:413  1 storage engine initialized
I170422 00:02:46.852459 7241 server/node.go:451  [n?] store [n0,s0] not bootstrapped
I170422 00:02:46.852583 7241 storage/stores.go:296  [n?] read 0 node addresses from persistent storage
I170422 00:02:46.852694 7241 server/node.go:605  [n?] connecting to gossip network to verify cluster ID...
I170422 00:02:46.859063 7574 storage/store.go:3337  [replicate,n1,s1,r6/1:/Table/1{1-2}] streamed snapshot: kv pairs: 10, log entries: 15, 20ms
I170422 00:02:46.864862 8146 storage/replica_raftstorage.go:595  [n2,s2,r6/?:{-}] applying preemptive snapshot at index 25 (id=e14a2d79, encoded size=12769, 1 rocksdb batches, 15 log entries)
I170422 00:02:46.866725 8146 storage/replica_raftstorage.go:603  [n2,s2,r6/?:/Table/1{1-2}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I170422 00:02:46.870436 7574 storage/replica_command.go:3521  [replicate,n1,s1,r6/1:/Table/1{1-2}] change replicas (ADD_REPLICA {2 2 2}): read existing descriptor r6:/Table/1{1-2} [r1(n1,s1), next=2]
I170422 00:02:46.888148 8152 storage/replica.go:2582  [n1,s1,r6/1:/Table/1{1-2}] proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:2}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I170422 00:02:46.897522 7574 storage/replica_raftstorage.go:415  [replicate,n1,s1,r8/1:/Table/1{3-4}] generated preemptive snapshot 93730072 at index 25
I170422 00:02:46.907276 8167 storage/raft_transport.go:436  [n2] raft transport stream to node 1 established
I170422 00:02:46.914874 7574 storage/store.go:3337  [replicate,n1,s1,r8/1:/Table/1{3-4}] streamed snapshot: kv pairs: 73, log entries: 15, 11ms
I170422 00:02:46.917429 8124 storage/replica_raftstorage.go:595  [n2,s2,r8/?:{-}] applying preemptive snapshot at index 25 (id=93730072, encoded size=20778, 1 rocksdb batches, 15 log entries)
I170422 00:02:46.919070 8124 storage/replica_raftstorage.go:603  [n2,s2,r8/?:/Table/1{3-4}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170422 00:02:46.922604 7574 storage/replica_command.go:3521  [replicate,n1,s1,r8/1:/Table/1{3-4}] change replicas (ADD_REPLICA {2 2 2}): read existing descriptor r8:/Table/1{3-4} [r1(n1,s1), next=2]
I170422 00:02:46.945548 7839 gossip/client.go:131  [n?] started gossip client to 127.0.0.1:50910
I170422 00:02:46.947403 8180 storage/replica.go:2582  [n1,s1,r8/1:/Table/1{3-4}] proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:2}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I170422 00:02:46.948435 8135 gossip/server.go:234  [n1] received initial cluster-verification connection from {tcp 127.0.0.1:46327}
I170422 00:02:46.955412 8140 storage/stores.go:312  [n?] wrote 1 node addresses to persistent storage
I170422 00:02:46.956080 8140 storage/stores.go:312  [n?] wrote 2 node addresses to persistent storage
I170422 00:02:46.956908 7241 server/node.go:630  [n?] node connected via gossip and verified as part of cluster "cd635c97-d0cf-4dd4-9979-49659c05e36b"
I170422 00:02:46.959173 7574 storage/replica_raftstorage.go:415  [replicate,n1,s1,r7/1:/Table/1{2-3}] generated preemptive snapshot 331c5074 at index 23
I170422 00:02:46.962743 7574 storage/store.go:3337  [replicate,n1,s1,r7/1:/Table/1{2-3}] streamed snapshot: kv pairs: 24, log entries: 13, 3ms
I170422 00:02:46.964494 8183 storage/replica_raftstorage.go:595  [n2,s2,r7/?:{-}] applying preemptive snapshot at index 23 (id=331c5074, encoded size=13305, 1 rocksdb batches, 13 log entries)
I170422 00:02:46.966042 8183 storage/replica_raftstorage.go:603  [n2,s2,r7/?:/Table/1{2-3}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170422 00:02:46.968658 7241 kv/dist_sender.go:367  [n?] unable to determine this node's attributes for replica selection; node is most likely bootstrapping
I170422 00:02:46.970467 7574 storage/replica_command.go:3521  [replicate,n1,s1,r7/1:/Table/1{2-3}] change replicas (ADD_REPLICA {2 2 2}): read existing descriptor r7:/Table/1{2-3} [r1(n1,s1), next=2]
I170422 00:02:46.973190 7241 server/node.go:341  [n?] new node allocated ID 3
I170422 00:02:46.973534 7241 gossip/gossip.go:297  [n3] NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:46327" > attrs:<> locality:<> 
I170422 00:02:46.974301 7241 server/node.go:402  [n3] node=3: started with [[]=] engine(s) and attributes []
I170422 00:02:46.984421 8171 storage/stores.go:312  [n1] wrote 2 node addresses to persistent storage
I170422 00:02:46.986431 7241 sql/executor.go:326  [n3] creating distSQLPlanner with address {tcp 127.0.0.1:46327}
I170422 00:02:46.987375 8172 storage/stores.go:312  [n2] wrote 2 node addresses to persistent storage
I170422 00:02:47.022622 8327 storage/replica.go:2582  [n1,s1,r7/1:/Table/1{2-3}] proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:2}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I170422 00:02:47.022991 7241 server/server.go:730  [n3] starting https server at 127.0.0.1:60751
I170422 00:02:47.023106 7241 server/server.go:731  [n3] starting grpc/postgres server at 127.0.0.1:46327
I170422 00:02:47.023152 7241 server/server.go:732  [n3] advertising CockroachDB node at 127.0.0.1:46327
I170422 00:02:47.028001 7574 storage/replica_raftstorage.go:415  [replicate,n1,s1,r3/1:/System/ts{d-e}] generated preemptive snapshot 8f59632c at index 26
I170422 00:02:47.036362 7241 server/server.go:841  [n3] done ensuring all necessary migrations have run
I170422 00:02:47.036524 7241 server/server.go:843  [n3] serving sql connections
I170422 00:02:47.039727 8216 server/node.go:586  [n3] bootstrapped store [n3,s3]
I170422 00:02:47.108076 7574 storage/store.go:3337  [replicate,n1,s1,r3/1:/System/ts{d-e}] streamed snapshot: kv pairs: 600, log entries: 16, 78ms
I170422 00:02:47.110226 8158 storage/replica_raftstorage.go:595  [n2,s2,r3/?:{-}] applying preemptive snapshot at index 26 (id=8f59632c, encoded size=138050, 1 rocksdb batches, 16 log entries)
I170422 00:02:47.114218 8158 storage/replica_raftstorage.go:603  [n2,s2,r3/?:/System/ts{d-e}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=1ms commit=1ms]
I170422 00:02:47.119537 7574 storage/replica_command.go:3521  [replicate,n1,s1,r3/1:/System/ts{d-e}] change replicas (ADD_REPLICA {2 2 2}): read existing descriptor r3:/System/ts{d-e} [r1(n1,s1), next=2]
I170422 00:02:47.147849 8386 sql/event_log.go:101  [n3] Event: "node_join", target: 3, info: {Descriptor:{NodeID:3 Address:{NetworkField:tcp AddressField:127.0.0.1:46327} Attrs: Locality:} ClusterID:cd635c97-d0cf-4dd4-9979-49659c05e36b StartedAt:1492819366974063610 LastUp:1492819366974063610}
I170422 00:02:47.173656 8440 storage/replica.go:2582  [n1,s1,r3/1:/System/ts{d-e}] proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:2}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I170422 00:02:47.178331 7574 storage/replica_raftstorage.go:415  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot 80a71f08 at index 53
I170422 00:02:47.269310 7574 storage/store.go:3337  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot: kv pairs: 36, log entries: 43, 6ms
I170422 00:02:47.270442 8422 storage/replica_raftstorage.go:595  [n3,s3,r1/?:{-}] applying preemptive snapshot at index 53 (id=80a71f08, encoded size=25139, 1 rocksdb batches, 43 log entries)
I170422 00:02:47.273681 8422 storage/replica_raftstorage.go:603  [n3,s3,r1/?:/{Min-System/}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I170422 00:02:47.286007 7574 storage/replica_command.go:3521  [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA {3 3 2}): read existing descriptor r1:/{Min-System/} [r1(n1,s1), next=2]
I170422 00:02:47.304850 8396 storage/replica.go:2582  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:2}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:3 StoreID:3 ReplicaID:2}]
I170422 00:02:47.308543 7574 storage/replica_raftstorage.go:415  [replicate,n1,s1,r2/1:/System/{-tsd}] generated preemptive snapshot 38edaf09 at index 39
I170422 00:02:47.314049 7574 storage/store.go:3337  [replicate,n1,s1,r2/1:/System/{-tsd}] streamed snapshot: kv pairs: 32, log entries: 29, 5ms
I170422 00:02:47.342711 8485 storage/raft_transport.go:436  [n3] raft transport stream to node 1 established
I170422 00:02:47.368722 8461 storage/replica_raftstorage.go:595  [n3,s3,r2/?:{-}] applying preemptive snapshot at index 39 (id=38edaf09, encoded size=116055, 1 rocksdb batches, 29 log entries)
I170422 00:02:47.373005 8461 storage/replica_raftstorage.go:603  [n3,s3,r2/?:/System/{-tsd}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=3ms commit=0ms]
I170422 00:02:47.376290 7574 storage/replica_command.go:3521  [replicate,n1,s1,r2/1:/System/{-tsd}] change replicas (ADD_REPLICA {3 3 2}): read existing descriptor r2:/System/{-tsd} [r1(n1,s1), next=2]
I170422 00:02:47.401972 8530 storage/replica.go:2582  [n1,s1,r2/1:/System/{-tsd}] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:2}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:3 StoreID:3 ReplicaID:2}]
I170422 00:02:47.405794 7210 storage/replica_raftstorage.go:415  [replicate,n1,s1,r3/1:/System/ts{d-e}] generated preemptive snapshot f1dafd17 at index 30
I170422 00:02:47.445225 7210 storage/store.go:3337  [replicate,n1,s1,r3/1:/System/ts{d-e}] streamed snapshot: kv pairs: 827, log entries: 20, 39ms
I170422 00:02:47.450018 8517 storage/replica_raftstorage.go:595  [n3,s3,r3/?:{-}] applying preemptive snapshot at index 30 (id=f1dafd17, encoded size=188655, 1 rocksdb batches, 20 log entries)
I170422 00:02:47.454431 8517 storage/replica_raftstorage.go:603  [n3,s3,r3/?:/System/ts{d-e}] applied preemptive snapshot in 4ms [clear=0ms batch=0ms entries=2ms commit=1ms]
I170422 00:02:47.461661 7210 storage/replica_command.go:3521  [replicate,n1,s1,r3/1:/System/ts{d-e}] change replicas (ADD_REPLICA {3 3 3}): read existing descriptor r3:/System/ts{d-e} [r1(n1,s1), r2(n2,s2), next=3]
I170422 00:02:47.492764 8549 storage/replica.go:2582  [n1,s1,r3/1:/System/ts{d-e}] 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}]
I170422 00:02:47.499107 7574 storage/replica_raftstorage.go:415  [replicate,n1,s1,r4/1:/{System/tse-Table/0}] generated preemptive snapshot e2dae4be at index 24
I170422 00:02:47.506574 7574 storage/store.go:3337  [replicate,n1,s1,r4/1:/{System/tse-Table/0}] streamed snapshot: kv pairs: 11, log entries: 14, 7ms
I170422 00:02:47.513479 8551 storage/replica_raftstorage.go:595  [n3,s3,r4/?:{-}] applying preemptive snapshot at index 24 (id=e2dae4be, encoded size=10967, 1 rocksdb batches, 14 log entries)
I170422 00:02:47.514992 8551 storage/replica_raftstorage.go:603  [n3,s3,r4/?:/{System/tse-Table/0}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170422 00:02:47.518379 7574 storage/replica_command.go:3521  [replicate,n1,s1,r4/1:/{System/tse-Table/0}] change replicas (ADD_REPLICA {3 3 2}): read existing descriptor r4:/{System/tse-Table/0} [r1(n1,s1), next=2]
I170422 00:02:47.552770 8382 storage/replica.go:2582  [n1,s1,r4/1:/{System/tse-Table/0}] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:2}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:3 StoreID:3 ReplicaID:2}]
I170422 00:02:47.559885 7574 storage/replica_raftstorage.go:415  [replicate,n1,s1,r10/1:/{Table/15-Max}] generated preemptive snapshot e60c79f4 at index 11
I170422 00:02:47.564484 7574 storage/store.go:3337  [replicate,n1,s1,r10/1:/{Table/15-Max}] streamed snapshot: kv pairs: 8, log entries: 1, 4ms
I170422 00:02:47.566878 8553 storage/replica_raftstorage.go:595  [n2,s2,r10/?:{-}] applying preemptive snapshot at index 11 (id=e60c79f4, encoded size=476, 1 rocksdb batches, 1 log entries)
I170422 00:02:47.568545 8553 storage/replica_raftstorage.go:603  [n2,s2,r10/?:/{Table/15-Max}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170422 00:02:47.575398 7574 storage/replica_command.go:3521  [replicate,n1,s1,r10/1:/{Table/15-Max}] change replicas (ADD_REPLICA {2 2 2}): read existing descriptor r10:/{Table/15-Max} [r1(n1,s1), next=2]
I170422 00:02:47.603600 8527 storage/replica.go:2582  [n1,s1,r10/1:/{Table/15-Max}] proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:2}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I170422 00:02:47.607023 7574 storage/replica_raftstorage.go:415  [replicate,n1,s1,r9/1:/Table/1{4-5}] generated preemptive snapshot a68cd28e at index 19
I170422 00:02:47.611155 7574 storage/store.go:3337  [replicate,n1,s1,r9/1:/Table/1{4-5}] streamed snapshot: kv pairs: 9, log entries: 9, 2ms
I170422 00:02:47.614589 8610 storage/replica_raftstorage.go:595  [n3,s3,r9/?:{-}] applying preemptive snapshot at index 19 (id=a68cd28e, encoded size=5767, 1 rocksdb batches, 9 log entries)
I170422 00:02:47.616728 8610 storage/replica_raftstorage.go:603  [n3,s3,r9/?:/Table/1{4-5}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I170422 00:02:47.621327 7574 storage/replica_command.go:3521  [replicate,n1,s1,r9/1:/Table/1{4-5}] change replicas (ADD_REPLICA {3 3 2}): read existing descriptor r9:/Table/1{4-5} [r1(n1,s1), next=2]
I170422 00:02:47.648290 8629 storage/replica.go:2582  [n1,s1,r9/1:/Table/1{4-5}] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:2}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:3 StoreID:3 ReplicaID:2}]
I170422 00:02:47.652205 7574 storage/replica_raftstorage.go:415  [replicate,n1,s1,r5/1:/Table/{0-11}] generated preemptive snapshot 6082b40a at index 22
I170422 00:02:47.659473 7574 storage/store.go:3337  [replicate,n1,s1,r5/1:/Table/{0-11}] streamed snapshot: kv pairs: 38, log entries: 12, 6ms
I170422 00:02:47.663292 8572 storage/replica_raftstorage.go:595  [n2,s2,r5/?:{-}] applying preemptive snapshot at index 22 (id=6082b40a, encoded size=14887, 1 rocksdb batches, 12 log entries)
I170422 00:02:47.666288 8572 storage/replica_raftstorage.go:603  [n2,s2,r5/?:/Table/{0-11}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=0ms commit=1ms]
I170422 00:02:47.675675 7574 storage/replica_command.go:3521  [replicate,n1,s1,r5/1:/Table/{0-11}] change replicas (ADD_REPLICA {2 2 2}): read existing descriptor r5:/Table/{0-11} [r1(n1,s1), next=2]
I170422 00:02:47.714460 8660 storage/replica.go:2582  [n1,s1,r5/1:/Table/{0-11}] proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:2}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I170422 00:02:47.717809 7574 storage/queue.go:699  [n1,replicate] purgatory is now empty
I170422 00:02:47.725001 7210 storage/replica_raftstorage.go:415  [replicate,n1,s1,r4/1:/{System/tse-Table/0}] generated preemptive snapshot 809aba27 at index 27
I170422 00:02:47.731860 7210 storage/store.go:3337  [replicate,n1,s1,r4/1:/{System/tse-Table/0}] streamed snapshot: kv pairs: 12, log entries: 17, 6ms
I170422 00:02:47.733916 8616 storage/replica_raftstorage.go:595  [n2,s2,r4/?:{-}] applying preemptive snapshot at index 27 (id=809aba27, encoded size=13097, 1 rocksdb batches, 17 log entries)
I170422 00:02:47.737897 8616 storage/replica_raftstorage.go:603  [n2,s2,r4/?:/{System/tse-Table/0}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I170422 00:02:47.741539 7210 storage/replica_command.go:3521  [replicate,n1,s1,r4/1:/{System/tse-Table/0}] change replicas (ADD_REPLICA {2 2 3}): read existing descriptor r4:/{System/tse-Table/0} [r1(n1,s1), r2(n3,s3), next=3]
I170422 00:02:47.778128 8599 storage/replica.go:2582  [n1,s1,r4/1:/{System/tse-Table/0}] proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:3}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:3 StoreID:3 ReplicaID:2} {NodeID:2 StoreID:2 ReplicaID:3}]
I170422 00:02:47.786994 7210 storage/replica_raftstorage.go:415  [replicate,n1,s1,r5/1:/Table/{0-11}] generated preemptive snapshot 8dbec808 at index 25
I170422 00:02:47.793991 7210 storage/store.go:3337  [replicate,n1,s1,r5/1:/Table/{0-11}] streamed snapshot: kv pairs: 39, log entries: 15, 6ms
I170422 00:02:47.796092 8600 storage/replica_raftstorage.go:595  [n3,s3,r5/?:{-}] applying preemptive snapshot at index 25 (id=8dbec808, encoded size=16960, 1 rocksdb batches, 15 log entries)
I170422 00:02:47.801963 8600 storage/replica_raftstorage.go:603  [n3,s3,r5/?:/Table/{0-11}] applied preemptive snapshot in 6ms [clear=4ms batch=0ms entries=0ms commit=0ms]
I170422 00:02:47.811946 7210 storage/replica_command.go:3521  [replicate,n1,s1,r5/1:/Table/{0-11}] change replicas (ADD_REPLICA {3 3 3}): read existing descriptor r5:/Table/{0-11} [r1(n1,s1), r2(n2,s2), next=3]
I170422 00:02:47.856421 8601 storage/replica.go:2582  [n1,s1,r5/1:/Table/{0-11}] 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}]
I170422 00:02:47.864228 7210 storage/replica_raftstorage.go:415  [replicate,n1,s1,r10/1:/{Table/15-Max}] generated preemptive snapshot b2a0ca7c at index 14
I170422 00:02:47.869997 7210 storage/store.go:3337  [replicate,n1,s1,r10/1:/{Table/15-Max}] streamed snapshot: kv pairs: 9, log entries: 4, 5ms
I170422 00:02:47.876638 8576 storage/replica_raftstorage.go:595  [n3,s3,r10/?:{-}] applying preemptive snapshot at index 14 (id=b2a0ca7c, encoded size=2553, 1 rocksdb batches, 4 log entries)
I170422 00:02:47.878194 8576 storage/replica_raftstorage.go:603  [n3,s3,r10/?:/{Table/15-Max}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170422 00:02:47.883527 7210 storage/replica_command.go:3521  [replicate,n1,s1,r10/1:/{Table/15-Max}] change replicas (ADD_REPLICA {3 3 3}): read existing descriptor r10:/{Table/15-Max} [r1(n1,s1), r2(n2,s2), next=3]
I170422 00:02:47.931204 8608 storage/replica.go:2582  [n1,s1,r10/1:/{Table/15-Max}] 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}]
I170422 00:02:47.948333 7210 storage/replica_raftstorage.go:415  [replicate,n1,s1,r9/1:/Table/1{4-5}] generated preemptive snapshot a280e518 at index 22
I170422 00:02:47.953571 7210 storage/store.go:3337  [replicate,n1,s1,r9/1:/Table/1{4-5}] streamed snapshot: kv pairs: 10, log entries: 12, 4ms
I170422 00:02:47.955434 8700 storage/replica_raftstorage.go:595  [n2,s2,r9/?:{-}] applying preemptive snapshot at index 22 (id=a280e518, encoded size=7840, 1 rocksdb batches, 12 log entries)
I170422 00:02:47.969083 8700 storage/replica_raftstorage.go:603  [n2,s2,r9/?:/Table/1{4-5}] applied preemptive snapshot in 13ms [clear=0ms batch=0ms entries=0ms commit=9ms]
I170422 00:02:47.972457 7210 storage/replica_command.go:3521  [replicate,n1,s1,r9/1:/Table/1{4-5}] change replicas (ADD_REPLICA {2 2 3}): read existing descriptor r9:/Table/1{4-5} [r1(n1,s1), r2(n3,s3), next=3]
I170422 00:02:47.997591 8724 storage/replica.go:2582  [n1,s1,r9/1:/Table/1{4-5}] proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:3}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:3 StoreID:3 ReplicaID:2} {NodeID:2 StoreID:2 ReplicaID:3}]
I170422 00:02:48.008754 7210 storage/replica_raftstorage.go:415  [replicate,n1,s1,r7/1:/Table/1{2-3}] generated preemptive snapshot 6624d079 at index 30
I170422 00:02:48.016735 7210 storage/store.go:3337  [replicate,n1,s1,r7/1:/Table/1{2-3}] streamed snapshot: kv pairs: 31, log entries: 20, 7ms
I170422 00:02:48.018636 8739 storage/replica_raftstorage.go:595  [n3,s3,r7/?:{-}] applying preemptive snapshot at index 30 (id=6624d079, encoded size=19469, 1 rocksdb batches, 20 log entries)
I170422 00:02:48.020618 8739 storage/replica_raftstorage.go:603  [n3,s3,r7/?:/Table/1{2-3}] applied preemptive snapshot in 2ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I170422 00:02:48.023460 7210 storage/replica_command.go:3521  [replicate,n1,s1,r7/1:/Table/1{2-3}] change replicas (ADD_REPLICA {3 3 3}): read existing descriptor r7:/Table/1{2-3} [r1(n1,s1), r2(n2,s2), next=3]
I170422 00:02:48.061196 8654 storage/replica.go:2582  [n1,s1,r7/1:/Table/1{2-3}] 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}]
I170422 00:02:48.074619 7210 storage/replica_raftstorage.go:415  [replicate,n1,s1,r6/1:/Table/1{1-2}] generated preemptive snapshot c827020e at index 28
I170422 00:02:48.083438 7210 storage/store.go:3337  [replicate,n1,s1,r6/1:/Table/1{1-2}] streamed snapshot: kv pairs: 11, log entries: 18, 4ms
I170422 00:02:48.093003 8773 storage/replica_raftstorage.go:595  [n3,s3,r6/?:{-}] applying preemptive snapshot at index 28 (id=c827020e, encoded size=14842, 1 rocksdb batches, 18 log entries)
I170422 00:02:48.094670 8773 storage/replica_raftstorage.go:603  [n3,s3,r6/?:/Table/1{1-2}] applied preemptive snapshot in 1ms [clear=0ms batch=0ms entries=1ms commit=0ms]
I170422 00:02:48.119980 7210 storage/replica_command.go:3521  [replicate,n1,s1,r6/1:/Table/1{1-2}] change replicas (ADD_REPLICA {3 3 3}): read existing descriptor r6:/Table/1{1-2} [r1(n1,s1), r2(n2,s2), next=3]
I170422 00:02:48.155487 8802 storage/replica.go:2582  [n1,s1,r6/1:/Table/1{1-2}] 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}]
I170422 00:02:48.167416 7210 storage/replica_raftstorage.go:415  [replicate,n1,s1,r2/1:/System/{-tsd}] generated preemptive snapshot 5a48b30f at index 42
I170422 00:02:48.180202 7210 storage/store.go:3337  [replicate,n1,s1,r2/1:/System/{-tsd}] streamed snapshot: kv pairs: 33, log entries: 32, 11ms
I170422 00:02:48.183361 8729 storage/replica_raftstorage.go:595  [n2,s2,r2/?:{-}] applying preemptive snapshot at index 42 (id=5a48b30f, encoded size=118140, 1 rocksdb batches, 32 log entries)
I170422 00:02:48.186382 8729 storage/replica_raftstorage.go:603  [n2,s2,r2/?:/System/{-tsd}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I170422 00:02:48.193631 7210 storage/replica_command.go:3521  [replicate,n1,s1,r2/1:/System/{-tsd}] change replicas (ADD_REPLICA {2 2 3}): read existing descriptor r2:/System/{-tsd} [r1(n1,s1), r2(n3,s3), next=3]
I170422 00:02:48.235879 8684 storage/replica.go:2582  [n1,s1,r2/1:/System/{-tsd}] proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:3}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:3 StoreID:3 ReplicaID:2} {NodeID:2 StoreID:2 ReplicaID:3}]
I170422 00:02:48.241571 7210 storage/replica_raftstorage.go:415  [replicate,n1,s1,r8/1:/Table/1{3-4}] generated preemptive snapshot 1678e242 at index 63
I170422 00:02:48.257499 7210 storage/store.go:3337  [replicate,n1,s1,r8/1:/Table/1{3-4}] streamed snapshot: kv pairs: 160, log entries: 53, 15ms
I170422 00:02:48.261241 8818 storage/replica_raftstorage.go:595  [n3,s3,r8/?:{-}] applying preemptive snapshot at index 63 (id=1678e242, encoded size=65565, 1 rocksdb batches, 53 log entries)
I170422 00:02:48.264464 8818 storage/replica_raftstorage.go:603  [n3,s3,r8/?:/Table/1{3-4}] applied preemptive snapshot in 3ms [clear=0ms batch=0ms entries=2ms commit=0ms]
I170422 00:02:48.275686 7210 storage/replica_command.go:3521  [replicate,n1,s1,r8/1:/Table/1{3-4}] change replicas (ADD_REPLICA {3 3 3}): read existing descriptor r8:/Table/1{3-4} [r1(n1,s1), r2(n2,s2), next=3]
I170422 00:02:48.313271 8792 storage/replica.go:2582  [n1,s1,r8/1:/Table/1{3-4}] 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}]
I170422 00:02:48.339275 7210 storage/replica_raftstorage.go:415  [replicate,n1,s1,r1/1:/{Min-System/}] generated preemptive snapshot fe2d7b04 at index 84
I170422 00:02:48.348503 7210 storage/store.go:3337  [replicate,n1,s1,r1/1:/{Min-System/}] streamed snapshot: kv pairs: 53, log entries: 74, 6ms
I170422 00:02:48.350762 8820 storage/replica_raftstorage.go:595  [n2,s2,r1/?:{-}] applying preemptive snapshot at index 84 (id=fe2d7b04, encoded size=41402, 1 rocksdb batches, 74 log entries)
I170422 00:02:48.357444 8820 storage/replica_raftstorage.go:603  [n2,s2,r1/?:/{Min-System/}] applied preemptive snapshot in 6ms [clear=0ms batch=0ms entries=3ms commit=2ms]
I170422 00:02:48.361153 7210 storage/replica_command.go:3521  [replicate,n1,s1,r1/1:/{Min-System/}] change replicas (ADD_REPLICA {2 2 3}): read existing descriptor r1:/{Min-System/} [r1(n1,s1), r2(n3,s3), next=3]
I170422 00:02:48.385220 8797 storage/replica.go:2582  [n1,s1,r1/1:/{Min-System/}] proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:3}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:3 StoreID:3 ReplicaID:2} {NodeID:2 StoreID:2 ReplicaID:3}]
I170422 00:02:48.856146 7209 storage/split_queue.go:92  [split,n1,s1,r10/1:/{Table/15-Max}] splitting at key /Table/50/0
I170422 00:02:48.856361 7209 storage/replica_command.go:2626  [split,n1,s1,r10/1:/{Table/15-Max}] initiating a split of this range at key /Table/50 [r11]
I170422 00:02:48.857945 8866 sql/event_log.go:101  [client=127.0.0.1:47920,user=root,n1] Event: "create_database", target: 50, info: {DatabaseName:bench Statement:CREATE DATABASE bench User:root}
I170422 00:02:49.025671 7209 storage/split_queue.go:92  [split,n1,s1,r11/1:/{Table/50-Max}] splitting at key /Table/51/0
I170422 00:02:49.025866 7209 storage/replica_command.go:2626  [split,n1,s1,r11/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r12]
I170422 00:02:49.027123 8866 sql/event_log.go:101  [client=127.0.0.1:47920,user=root,n1] Event: "create_table", target: 51, info: {TableName:bench.bank Statement:CREATE TABLE bench.bank (id INT PRIMARY KEY, balance INT, payload STRING, FAMILY (id, balance, payload)) User:root}
I170422 00:02:49.256338 8866 sql/mon/mem_usage.go:509  [client=127.0.0.1:47920,user=root,n1] txn: memory usage increases to 49 KiB (+49680)
I170422 00:02:49.256870 8866 sql/mon/mem_usage.go:509  [client=127.0.0.1:47920,user=root,n1] txn: memory usage increases to 64 KiB (+140)
I170422 00:02:49.258222 8866 sql/mon/mem_usage.go:509  [client=127.0.0.1:47920,user=root,n1] txn: memory usage increases to 128 KiB (+140)
I170422 00:02:49.849026 9059 storage/replica_command.go:2626  [n1,s1,r12/1:/{Table/51-Max}] initiating a split of this range at key /Table/51/1/100 [r13]
I170422 00:02:49.950590 9064 storage/replica_command.go:2626  [n1,s1,r13/1:/{Table/51/1/1���-Max}] initiating a split of this range at key /Table/51/1/200 [r14]
I170422 00:02:50.097279 9095 storage/replica_command.go:2626  [n1,s1,r14/1:/{Table/51/1/2���-Max}] initiating a split of this range at key /Table/51/1/300 [r15]
I170422 00:02:50.190362 9140 storage/replica_command.go:2626  [n1,s1,r15/1:/{Table/51/1/3���-Max}] initiating a split of this range at key /Table/51/1/400 [r16]
I170422 00:02:50.330372 9121 storage/replica_command.go:2626  [n1,s1,r16/1:/{Table/51/1/4���-Max}] initiating a split of this range at key /Table/51/1/500 [r17]
I170422 00:02:50.404779 9179 storage/replica_command.go:2626  [n1,s1,r17/1:/{Table/51/1/5���-Max}] initiating a split of this range at key /Table/51/1/600 [r18]
I170422 00:02:50.504871 9169 storage/replica_command.go:2626  [n1,s1,r18/1:/{Table/51/1/6���-Max}] initiating a split of this range at key /Table/51/1/700 [r19]
I170422 00:02:50.521497 7213 storage/replica_raftstorage.go:415  [raftsnapshot,n1,s1,r18/1:/{Table/51/1/6���-Max}] generated Raft snapshot 70f9d29f at index 10
E170422 00:02:50.533141 7213 storage/queue.go:634  [raftsnapshot,n1,s1,r18/1:/{Table/51/1/6���-Max}] snapshot failed: r18: remote couldn't accept snapshot with error: [n3,s3],r18: cannot apply snapshot: snapshot intersects existing range [n3,s3,r17/3:/{Table/51/1/5���-Max}]
I170422 00:02:50.599245 9295 storage/replica_command.go:2626  [n1,s1,r19/1:/{Table/51/1/7���-Max}] initiating a split of this range at key /Table/51/1/800 [r20]
I170422 00:02:50.628382 7213 storage/replica_raftstorage.go:415  [raftsnapshot,n1,s1,r19/1:/{Table/51/1/7���-Max}] generated Raft snapshot 5a5bb739 at index 11
E170422 00:02:50.660409 7213 storage/queue.go:634  [raftsnapshot,n1,s1,r19/1:/{Table/51/1/7���-Max}] snapshot failed: r19: remote couldn't accept snapshot with error: [n3,s3],r19: cannot apply snapshot: snapshot intersects existing range [n3,s3,r17/3:/{Table/51/1/5���-Max}]
I170422 00:02:50.702610 9296 storage/replica_command.go:2626  [n1,s1,r20/1:/{Table/51/1/8���-Max}] initiating a split of this range at key /Table/51/1/900 [r21]
I170422 00:02:50.728235 7213 storage/replica_raftstorage.go:415  [raftsnapshot,n1,s1,r20/1:/{Table/51/1/8���-Max}] generated Raft snapshot c54144bc at index 10
E170422 00:02:50.736498 7213 storage/queue.go:634  [raftsnapshot,n1,s1,r20/1:/{Table/51/1/8���-Max}] snapshot failed: r20: remote couldn't accept snapshot with error: [n3,s3],r20: cannot apply snapshot: snapshot intersects existing range [n3,s3,r17/3:/{Table/51/1/5���-Max}]
I170422 00:02:50.927628 9281 ccl/storageccl/export.go:76  [n1,s1,r5/1:/Table/{0-11}] export [/Table/4/1,/Table/4/2)
I170422 00:02:50.929074 9373 ccl/storageccl/export.go:76  [n1,s1,r15/1:/Table/51/1/{300-400}] export [/Table/51/1/300,/Table/51/1/400)
I170422 00:02:50.929194 9374 ccl/storageccl/export.go:76  [n1,s1,r12/1:/Table/51{-/1/100}] export [/Table/51/1,/Table/51/1/100)
I170422 00:02:50.929876 9375 ccl/storageccl/export.go:76  [n1,s1,r14/1:/Table/51/1/{200-300}] export [/Table/51/1/200,/Table/51/1/300)
I170422 00:02:50.931616 9361 ccl/storageccl/export.go:76  [n1,s1,r17/1:/Table/51/1/{500-600}] export [/Table/51/1/500,/Table/51/1/600)
I170422 00:02:50.936895 9378 ccl/storageccl/export.go:76  [n1,s1,r5/1:/Table/{0-11}] export [/Table/3/1,/Table/3/2)
I170422 00:02:50.961182 9359 ccl/storageccl/export.go:76  [n1,s1,r20/1:/Table/51/1/{800-900}] export [/Table/51/1/800,/Table/51/1/900)
I170422 00:02:50.962878 9394 ccl/storageccl/export.go:76  [n1,s1,r18/1:/Table/51/1/{600-700}] export [/Table/51/1/600,/Table/51/1/700)
I170422 00:02:50.963356 9360 ccl/storageccl/export.go:76  [n1,s1,r13/1:/Table/51/1/{100-200}] export [/Table/51/1/100,/Table/51/1/200)
I170422 00:02:50.979558 9395 ccl/storageccl/export.go:76  [n1,s1,r16/1:/Table/51/1/{400-500}] export [/Table/51/1/400,/Table/51/1/500)
I170422 00:02:50.983945 9262 ccl/storageccl/export.go:76  [n1,s1,r19/1:/Table/51/1/{700-800}] export [/Table/51/1/700,/Table/51/1/800)
I170422 00:02:50.998982 9327 ccl/storageccl/export.go:76  [n1,s1,r21/1:/{Table/51/1/9���-Max}] export [/Table/51/1/900,/Table/51/2)
I170422 00:02:51.113885 7213 storage/replica_raftstorage.go:415  [raftsnapshot,n1,s1,r21/1:/{Table/51/1/9���-Max}] generated Raft snapshot 9b0040ab at index 10
E170422 00:02:51.143322 7213 storage/queue.go:634  [raftsnapshot,n1,s1,r21/1:/{Table/51/1/9���-Max}] snapshot failed: r21: remote couldn't accept snapshot with error: [n3,s3],r21: cannot apply snapshot: snapshot intersects existing range [n3,s3,r17/3:/{Table/51/1/5���-Max}]
I170422 00:02:51.521003 7213 storage/replica_raftstorage.go:415  [raftsnapshot,n1,s1,r19/1:/Table/51/1/{700-800}] generated Raft snapshot 006b56cb at index 16
E170422 00:02:51.529103 7213 storage/queue.go:634  [raftsnapshot,n1,s1,r19/1:/Table/51/1/{700-800}] snapshot failed: r19: remote couldn't accept snapshot with error: [n3,s3],r19: cannot apply snapshot: snapshot intersects existing range [n3,s3,r18/3:/{Table/51/1/6���-Max}]
I170422 00:02:51.617841 7213 storage/replica_raftstorage.go:415  [raftsnapshot,n1,s1,r18/1:/Table/51/1/{600-700}] generated Raft snapshot 64bf375e at index 16
I170422 00:02:51.632916 7213 storage/store.go:3337  [raftsnapshot,n1,s1,r18/1:/Table/51/1/{600-700}] streamed snapshot: kv pairs: 109, log entries: 6, 6ms
I170422 00:02:51.633665 9785 storage/replica_raftstorage.go:595  [n3,s3,r18/3:/{Table/51/1/6���-Max}] applying Raft snapshot at index 16 (id=64bf375e, encoded size=18277, 1 rocksdb batches, 6 log entries)
I170422 00:02:51.635360 9785 storage/replica_raftstorage.go:603  [n3,s3,r18/3:/Table/51/1/{600-700}] applied Raft snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170422 00:02:51.816243 7213 storage/replica_raftstorage.go:415  [raftsnapshot,n1,s1,r20/1:/Table/51/1/{800-900}] generated Raft snapshot 0a095090 at index 16
I170422 00:02:51.838779 7213 storage/store.go:3337  [raftsnapshot,n1,s1,r20/1:/Table/51/1/{800-900}] streamed snapshot: kv pairs: 109, log entries: 6, 21ms
I170422 00:02:51.840335 9814 storage/replica_raftstorage.go:595  [n3,s3,r20/3:{-}] applying Raft snapshot at index 16 (id=0a095090, encoded size=18277, 1 rocksdb batches, 6 log entries)
I170422 00:02:51.842165 9814 storage/replica_raftstorage.go:603  [n3,s3,r20/3:/Table/51/1/{800-900}] applied Raft snapshot in 2ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170422 00:02:52.215535 7213 storage/replica_raftstorage.go:415  [raftsnapshot,n1,s1,r21/1:/{Table/51/1/9���-Max}] generated Raft snapshot 6f2fd506 at index 11
I170422 00:02:52.220884 7213 storage/store.go:3337  [raftsnapshot,n1,s1,r21/1:/{Table/51/1/9���-Max}] streamed snapshot: kv pairs: 108, log entries: 1, 5ms
I170422 00:02:52.221752 10017 storage/replica_raftstorage.go:595  [n3,s3,r21/3:{-}] applying Raft snapshot at index 11 (id=6f2fd506, encoded size=14096, 1 rocksdb batches, 1 log entries)
I170422 00:02:52.223281 10017 storage/replica_raftstorage.go:603  [n3,s3,r21/3:/{Table/51/1/9���-Max}] applied Raft snapshot in 1ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I170422 00:02:52.336628 9427 sql/event_log.go:101  [client=127.0.0.1:47964,user=root,n1] Event: "create_database", target: 52, info: {DatabaseName:bench2 Statement:CREATE DATABASE bench2 User:root}
I170422 00:02:52.339866 7209 storage/split_queue.go:92  [split,n1,s1,r21/1:/{Table/51/1/9���-Max}] splitting at key /Table/52/0
I170422 00:02:52.340069 7209 storage/replica_command.go:2626  [split,n1,s1,r21/1:/{Table/51/1/9���-Max}] initiating a split of this range at key /Table/52 [r22]
I170422 00:02:52.518769 7213 storage/replica_raftstorage.go:415  [raftsnapshot,n1,s1,r19/1:/Table/51/1/{700-800}] generated Raft snapshot e993c81e at index 16
I170422 00:02:52.519284 8866 ccl/sqlccl/restore.go:487  [client=127.0.0.1:47920,user=root,n1] presplitting 10 ranges
I170422 00:02:52.522804 10124 storage/replica_command.go:2626  [n1,s1,r22/1:/{Table/52-Max}] initiating a split of this range at key /Table/53/1/500 [r23]
I170422 00:02:52.535969 7213 storage/store.go:3337  [raftsnapshot,n1,s1,r19/1:/Table/51/1/{700-800}] streamed snapshot: kv pairs: 109, log entries: 6, 16ms
I170422 00:02:52.536982 10153 storage/replica_raftstorage.go:595  [n3,s3,r19/3:{-}] applying Raft snapshot at index 16 (id=e993c81e, encoded size=18277, 1 rocksdb batches, 6 log entries)
I170422 00:02:52.540259 10153 storage/replica_raftstorage.go:603  [n3,s3,r19/3:/Table/51/1/{700-800}] applied Raft snapshot in 3ms [clear=0ms batch=0ms entries=0ms commit=2ms]
I170422 00:02:52.608964 10096 storage/replica_command.go:2626  [n1,s1,r23/1:/{Table/53/1/5���-Max}] initiating a split of this range at key /Table/53/1/800 [r24]
I170422 00:02:52.616818 10161 storage/replica_command.go:2626  [n1,s1,r22/1:/Table/5{2-3/1/500}] initiating a split of this range at key /Table/53/1/200 [r25]
I170422 00:02:52.806657 9984 storage/replica_command.go:2626  [n1,s1,r22/1:/Table/5{2-3/1/200}] initiating a split of this range at key /Table/53/1/100 [r26]
I170422 00:02:52.808816 10279 storage/replica_command.go:2626  [n1,s1,r25/1:/Table/53/1/{200-500}] initiating a split of this range at key /Table/53/1/400 [r27]
I170422 00:02:52.823360 10250 storage/replica_command.go:2626  [n1,s1,r23/1:/Table/53/1/{500-800}] initiating a split of this range at key /Table/53/1/700 [r28]
I170422 00:02:52.842247 10308 storage/replica_command.go:2626  [n1,s1,r24/1:/{Table/53/1/8���-Max}] initiating a split of this range at key /Table/53/1/900 [r29]
I170422 00:02:53.033473 10299 storage/replica_command.go:2626  [n1,s1,r23/1:/Table/53/1/{500-700}] initiating a split of this range at key /Table/53/1/600 [r30]
I170422 00:02:53.117331 10376 storage/replica_command.go:2626  [n1,s1,r22/1:/Table/5{2-3/1/100}] initiating a split of this range at key /Table/53/1 [r31]
I170422 00:02:53.148117 10304 storage/replica_command.go:2626  [n1,s1,r25/1:/Table/53/1/{200-400}] initiating a split of this range at key /Table/53/1/300 [r32]
I170422 00:02:53.360054 10568 storage/replica_command.go:3521  [n1,s1,r30/1:/Table/53/1/{600-700}] change replicas (REMOVE_REPLICA {3 3 3}): read existing descriptor r30:/Table/53/1/{600-700} [r1(n1,s1), r2(n2,s2), r3(n3,s3), next=4]
I170422 00:02:53.361422 10581 storage/replica_command.go:3521  [n1,s1,r31/1:/Table/53/1{-/100}] change replicas (REMOVE_REPLICA {3 3 3}): read existing descriptor r31:/Table/53/1{-/100} [r1(n1,s1), r2(n2,s2), r3(n3,s3), next=4]
I170422 00:02:53.386844 10615 storage/replica_command.go:3521  [n2,s2,r24/2:/Table/53/1/{800-900}] change replicas (REMOVE_REPLICA {3 3 3}): read existing descriptor r24:/Table/53/1/{800-900} [r1(n1,s1), r2(n2,s2), r3(n3,s3), next=4]
I170422 00:02:53.409981 10570 storage/replica_command.go:3521  [n1,s1,r25/1:/Table/53/1/{200-300}] change replicas (REMOVE_REPLICA {3 3 3}): read existing descriptor r25:/Table/53/1/{200-300} [r1(n1,s1), r2(n2,s2), r3(n3,s3), next=4]
I170422 00:02:53.418158 10574 storage/replica_command.go:3521  [n1,s1,r26/1:/Table/53/1/{100-200}] change replicas (REMOVE_REPLICA {3 3 3}): read existing descriptor r26:/Table/53/1/{100-200} [r1(n1,s1), r2(n2,s2), r3(n3,s3), next=4]
I170422 00:02:53.444733 10620 storage/replica_command.go:3521  [n2,s2,r27/2:/Table/53/1/{400-500}] change replicas (REMOVE_REPLICA {3 3 3}): read existing descriptor r27:/Table/53/1/{400-500} [r1(n1,s1), r2(n2,s2), r3(n3,s3), next=4]
I170422 00:02:53.456182 10585 storage/replica_command.go:3521  [n2,s2,r23/2:/Table/53/1/{500-600}] change replicas (REMOVE_REPLICA {3 3 3}): read existing descriptor r23:/Table/53/1/{500-600} [r1(n1,s1), r2(n2,s2), r3(n3,s3), next=4]
I170422 00:02:53.462435 10645 storage/replica_command.go:3521  [n2,s2,r29/2:/{Table/53/1/9���-Max}] change replicas (REMOVE_REPLICA {3 3 3}): read existing descriptor r29:/{Table/53/1/900-Max} [r1(n1,s1), r2(n2,s2), r3(n3,s3), next=4]
I170422 00:02:53.473865 10648 storage/replica_command.go:3521  [n2,s2,r32/2:/Table/53/1/{300-400}] change replicas (REMOVE_REPLICA {3 3 3}): read existing descriptor r32:/Table/53/1/{300-400} [r1(n1,s1), r2(n2,s2), r3(n3,s3), next=4]
I170422 00:02:53.514131 10491 storage/raft_transport.go:436  [n2] raft transport stream to node 3 established
I170422 00:02:53.531047 10665 storage/replica_command.go:3521  [n2,s2,r28/2:/Table/53/1/{700-800}] change replicas (REMOVE_REPLICA {3 3 3}): read existing descriptor r28:/Table/53/1/{700-800} [r1(n1,s1), r2(n2,s2), r3(n3,s3), next=4]
I170422 00:02:53.605187 10786 storage/replica.go:2582  [n1,s1,r31/1:/Table/53/1{-/100}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:3}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I170422 00:02:53.608974 10641 storage/replica.go:2582  [n1,s1,r25/1:/Table/53/1/{200-300}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:3}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I170422 00:02:53.669637 10779 storage/replica.go:2582  [n1,s1,r30/1:/Table/53/1/{600-700}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:3}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I170422 00:02:53.680514 8487 storage/store.go:3155  [n3,s3,r31/3:/Table/53/1{-/100}] added to replica GC queue (peer suggestion)
I170422 00:02:53.691400 10734 storage/replica.go:2582  [n1,s1,r26/1:/Table/53/1/{100-200}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:3}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I170422 00:02:53.734835 10606 storage/raft_transport.go:436  [n3] raft transport stream to node 2 established
I170422 00:02:53.816712 10867 storage/replica.go:2582  [n2,s2,r23/2:/Table/53/1/{500-600}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:3}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
W170422 00:02:53.824429 10867 storage/replica.go:2272  [n2,s2,r23/2:/Table/53/1/{500-600}] context cancellation after 0.0s of attempting command [txn: 009b33fb], EndTransaction [/Local/Range/"\xbd\x89\xf7\x01\xf4"/RangeDescriptor,/Min)
E170422 00:02:53.826749 10585 internal/client/txn.go:439  [n2,s2,r23/2:/Table/53/1/{500-600}] failure aborting transaction: context canceled; abort caused by: result is ambiguous (context canceled)
I170422 00:02:53.848012 10845 storage/replica.go:2582  [n2,s2,r32/2:/Table/53/1/{300-400}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:3}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I170422 00:02:53.850264 10844 storage/replica.go:2582  [n2,s2,r29/2:/{Table/53/1/9���-Max}] proposing REMOVE_REPLICA {NodeID:3 StoreID:3 ReplicaID:3}: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
E170422 00:02:53.851610 10615 internal/client/txn.go:439  [n2,s2,r24/2:/Table/53/1/{800-900}] failure aborting transaction: context canceled; abort caused by: context canceled
E170422 00:02:53.855029 10620 internal/client/txn.go:439  [n2,s2,r27/2:/Table/53/1/{400-500}] failure aborting transaction: context canceled; abort caused by: context canceled
I170422 00:02:53.864178 10851 storage/store.go:3155  [n3,s3,r23/3:/Table/53/1/{500-600}] added to replica GC queue (peer suggestion)
W170422 00:02:53.913858 10845 storage/replica.go:2272  [n2,s2,r32/2:/Table/53/1/{300-400}] context cancellation after 0.1s of attempting command [txn: fd49e7bf], EndTransaction [/Local/Range/"\xbd\x89\xf7\x01,"/RangeDescriptor,/Min)
E170422 00:02:53.914883 10648 internal/client/txn.go:439  [n2,s2,r32/2:/Table/53/1/{300-400}] failure aborting transaction: context canceled; abort caused by: result is ambiguous (context canceled)
E170422 00:02:53.923682 10665 internal/client/txn.go:439  [n2,s2,r28/2:/Table/53/1/{700-800}] failure aborting transaction: context canceled; abort caused by: context canceled
I170422 00:02:53.925347 8346 storage/store.go:2144  [replicaGC,n3,s3,r31/3:/Table/53/1{-/100}] removing replica
W170422 00:02:53.925798 10874 storage/replica.go:2272  [n1,s1,r1/1:/{Min-System/}] context cancellation after 0.0s of attempting command [txn: bff3916e], Put [/Meta2/Table/53/1/800,/Min)
I170422 00:02:53.929005 8346 storage/replica.go:662  [replicaGC,n3,s3,r31/3:/Table/53/1{-/100}] removed 9 (0+9) keys in 2ms [clear=2ms commit=0ms]
I170422 00:02:53.950717 10851 storage/store.go:3155  [n3,s3,r29/3:/{Table/53/1/9���-Max}] added to replica GC queue (peer suggestion)
I170422 00:02:53.982204 10863 ccl/storageccl/import.go:59  [n1,s1,r25/1:/Table/53/1/{200-300}] import [/Table/53/1/200,/Table/53/1/300)
I170422 00:02:53.982750 10913 ccl/storageccl/import.go:59  [n1,s1,r31/1:/Table/53/1{-/100}] import [/Table/53/1,/Table/53/1/100)
I170422 00:02:53.984493 10913 storage/engine/rocksdb.go:380  opening rocksdb instance at "/go/src/github.com/cockroachdb/cockroach/artifacts/TestBackupRestoreSystemJobs468384193/must-be-cleaned-up/import-sstreader711045500"
I170422 00:02:53.986793 10980 ccl/storageccl/import.go:59  [n1,s1,r26/1:/Table/53/1/{100-200}] import [/Table/53/1/100,/Table/53/1/200)
I170422 00:02:53.993821 10863 storage/engine/rocksdb.go:380  opening rocksdb instance at "/go/src/github.com/cockroachdb/cockroach/artifacts/TestBackupRestoreSystemJobs468384193/must-be-cleaned-up/import-sstreader148775505"
I170422 00:02:54.003245 10980 storage/engine/rocksdb.go:380  opening rocksdb instance at "/go/src/github.com/cockroachdb/cockroach/artifacts/TestBackupRestoreSystemJobs468384193/must-be-cleaned-up/import-sstreader311468203"
F170422 00:02:54.024863 10865 storage/replica.go:971  [n2,s2,r29/2:/{Table/53/1/9���-Max}] lease repl={3 3 3} start=1492819373.864055874,0 epo=1 pro=1492819373.864066474,0 owned by replica {NodeID:3 StoreID:3 ReplicaID:3} that no longer exists
goroutine 10865 [running]:
github.com/cockroachdb/cockroach/pkg/util/log.getStacks(0x3d64c01, 0x17b6377, 0x33a1100, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:837 +0xc4
github.com/cockroachdb/cockroach/pkg/util/log.(*loggingT).outputLogEntry(0x33a26c0, 0xc400000004, 0x2c6a933, 0x12, 0x3cb, 0xc424a86e40, 0xbd)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:709 +0x660
github.com/cockroachdb/cockroach/pkg/util/log.addStructured(0x2ba4c5b2bae8, 0xc423e2c2d0, 0x4, 0x2, 0x21a322e, 0x33, 0xc4243fbee8, 0x2, 0x2)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/structured.go:146 +0x313
github.com/cockroachdb/cockroach/pkg/util/log.logDepth(0x2ba4c5b2bae8, 0xc423e2c2d0, 0x1, 0x4, 0x21a322e, 0x33, 0xc4243fbee8, 0x2, 0x2)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:68 +0x9a
github.com/cockroachdb/cockroach/pkg/util/log.Fatalf(0x2ba4c5b2bae8, 0xc423e2c2d0, 0x21a322e, 0x33, 0xc4243fbee8, 0x2, 0x2)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/log.go:162 +0x90
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).redirectOnOrAcquireLease.func1(0xc42430f200, 0xc4243fc2d0, 0x14b78f4fb68dcea0, 0x0, 0x2ba4c5b2bae8, 0xc423e2c2d0, 0xc4243fc2b0, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:971 +0xe96
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).redirectOnOrAcquireLease(0xc42430f200, 0x2ba4c5b2bae8, 0xc423e2c2d0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x2)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:1039 +0x1ed
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).tryExecuteWriteBatch(0xc42430f200, 0x2ba4c5b2bae8, 0xc423e2c2d0, 0x14b78f4fb68ac28b, 0x0, 0x200000002, 0x2, 0x1d, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:2191 +0x1217
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).executeWriteBatch(0xc42430f200, 0x2ba4c5b2bae8, 0xc423e2c2d0, 0x14b78f4fb68ac28b, 0x0, 0x200000002, 0x2, 0x1d, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:2077 +0xa9
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).Send(0xc42430f200, 0x2ba4c5b2bae8, 0xc423e2c2d0, 0x14b78f4fb68ac28b, 0x0, 0x200000002, 0x2, 0x1d, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:1405 +0x28e
github.com/cockroachdb/cockroach/pkg/storage.(*Store).Send(0xc42252d800, 0x2ba4c5b2bae8, 0xc423e2c2a0, 0x14b78f4fb68ac28b, 0x0, 0x200000002, 0x2, 0x1d, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/store.go:2559 +0x9d3
github.com/cockroachdb/cockroach/pkg/storage.(*Stores).Send(0xc420542180, 0x2ba4c5b2bae8, 0xc423e2c270, 0x0, 0x0, 0x200000002, 0x2, 0x1d, 0x0, 0x0, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/stores.go:187 +0x24b
github.com/cockroachdb/cockroach/pkg/server.(*Node).batchInternal.func1(0x2ba4c5b2bae8, 0xc423e2c270, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/server/node.go:840 +0x20f
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr(0xc42208d0e0, 0x2ba4c5b2bae8, 0xc423e2c240, 0xc4243fd7e8, 0x0, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:272 +0x14f
github.com/cockroachdb/cockroach/pkg/server.(*Node).batchInternal(0xc422ef9080, 0x2ba4c5b2bae8, 0xc423e2c240, 0xc424a86b68, 0xc423e2c240, 0x1270100, 0x217e46e)
	/go/src/github.com/cockroachdb/cockroach/pkg/server/node.go:851 +0x1c1
github.com/cockroachdb/cockroach/pkg/server.(*Node).Batch(0xc422ef9080, 0x2ba4c5b2bae8, 0xc423e2c240, 0xc424a86b68, 0x1f, 0xc423e28060, 0x0)
	/go/src/github.com/cockroachdb/cockroach/pkg/server/node.go:868 +0xb8
github.com/cockroachdb/cockroach/pkg/kv.(*grpcTransport).SendNext.func1.1(0xc42422c9b0, 0xc424a86b40, 0x2ba4c5b2bae8, 0xc423e2c1e0, 0x79f607, 0xc423efd788, 0xc423efd780)
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/transport.go:252 +0x73d
github.com/cockroachdb/cockroach/pkg/kv.(*grpcTransport).SendNext.func1(0xc42422c9b0, 0xc424a86b40, 0x2ba4c5b2bae8, 0xc423e2c1e0, 0x2f738a0, 0x3d64ed8, 0xc421738ae0)
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/transport.go:265 +0xdd
created by github.com/cockroachdb/cockroach/pkg/kv.(*grpcTransport).SendNext
	/go/src/github.com/cockroachdb/cockroach/pkg/kv/transport.go:278 +0x236

goroutine 1 [chan receive]:
testing.(*T).Run(0xc4201d2340, 0x2177148, 0x1b, 0x21caad8, 0xc4204b5b01)
	/usr/local/go/src/testing/testing.go:698 +0x582
testing.runTests.func1(0xc4201d2340)
	/usr/local/go/src/testing/testing.go:882 +0xab
testing.tRunner(0xc4201d2340, 0xc4204b5d10)
	/usr/local/go/src/testing/testing.go:657 +0x108
testing.runTests(0xc42010b280, 0x2f423c0, 0x17, 0x17, 0x2c70cc9)
	/usr/local/go/src/testing/testing.go:888 +0x4e1
testing.(*M).Run(0xc4202d3f28, 0x3d64920)
	/usr/local/go/src/testing/testing.go:822 +0x1c4
github.com/cockroachdb/cockroach/pkg/ccl/sqlccl.TestMain(0xc4204b5f28)
	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/sqlccl/main_test.go:29 +0x18a
main.main()
	github.com/cockroachdb/cockroach/pkg/ccl/sqlccl/_test/_testmain.go:96 +0x210

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
	/usr/local/go/src/runtime/asm_amd64.s:2197 +0x1

goroutine 20 [chan receive]:
github.com/cockroachdb/cockroach/pkg/util/log.(*loggingT).flushDaemon(0x33a26c0)
	/go/src/github.com/cockroachdb/cockroach/pkg/util/log/clog.go:1003 +0x85
created by github.com/cockroachdb/cockroach/pkg/util/log.init.1
	/go/src/github.com/cockroachdb/c

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added O-robot Originated from a bot. C-test-failure Broken test (automatically or manually discovered). labels Apr 22, 2017
@benesch
Copy link
Contributor

benesch commented Apr 22, 2017

This seems like #15003 striking again.

@a-robinson a-robinson self-assigned this Apr 25, 2017
@a-robinson
Copy link
Contributor

Same as #15003

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@a-robinson a-robinson

Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@benesch @a-robinson @cockroach-teamcity