tamird
commented
8 years ago This one is pretty scary and reproduces very easily in GCE with:
make stress STRESSFLAGS='-p 100 -stderr -maxfails 1' PKG=./storage TESTS=TestReplicateRestartAfterTruncationWithRemoveAndReAdd611 runs so far, 0 failures, over 5s
1167 runs so far, 0 failures, over 10s
1699 runs so far, 0 failures, over 15s
I161004 19:52:15.537426 1 rand.go:76 Random seed: -5025832341681872018
I161004 19:52:15.609866 25 storage/engine/rocksdb.go:360 opening in memory rocksdb instance
I161004 19:52:15.611986 25 gossip/gossip.go:234 initial resolvers: []
W161004 19:52:15.612017 25 gossip/gossip.go:1045 no resolvers found; use --join to specify a connected node
I161004 19:52:15.612102 25 gossip/gossip.go:268 NodeID set to 1
I161004 19:52:15.620763 25 gossip/gossip.go:268 NodeID set to 1
I161004 19:52:15.622814 25 storage/store.go:1040 [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I161004 19:52:15.622997 25 gossip/gossip.go:282 NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:45150" > attrs:<>
I161004 19:52:15.625251 101 storage/replica_trigger.go:252 [s1,r1:/M{in-ax}] new range lease replica {1 1 1} 1970-01-01 00:00:00 +0000 UTC 900ms following replica {0 0 0} 1970-01-01 00:00:00 +0000 UTC 0s [physicalTime=1970-01-01 00:00:00 +0000 UTC]
I161004 19:52:15.625903 25 storage/engine/rocksdb.go:360 opening in memory rocksdb instance
I161004 19:52:15.626877 25 gossip/gossip.go:234 initial resolvers: [127.0.0.1:45150]
W161004 19:52:15.626922 25 gossip/gossip.go:1047 no incoming or outgoing connections
I161004 19:52:15.626989 25 gossip/gossip.go:268 NodeID set to 2
I161004 19:52:15.627852 25 gossip/gossip.go:268 NodeID set to 2
I161004 19:52:15.628093 25 storage/store.go:1040 [n2,s2]: failed initial metrics computation: [n2,s2]: system config not yet available
I161004 19:52:15.628145 25 gossip/gossip.go:282 NodeDescriptor set to node_id:2 address:<network_field:"tcp" address_field:"127.0.0.1:34704" > attrs:<>
I161004 19:52:15.773880 25 storage/engine/rocksdb.go:360 opening in memory rocksdb instance
I161004 19:52:15.774910 25 gossip/gossip.go:234 initial resolvers: [127.0.0.1:45150]
W161004 19:52:15.797089 25 gossip/gossip.go:1047 no incoming or outgoing connections
I161004 19:52:15.797149 25 gossip/gossip.go:268 NodeID set to 3
I161004 19:52:15.798368 25 gossip/gossip.go:268 NodeID set to 3
I161004 19:52:15.798687 25 storage/store.go:1040 [n3,s3]: failed initial metrics computation: [n3,s3]: system config not yet available
I161004 19:52:15.798739 25 gossip/gossip.go:282 NodeDescriptor set to node_id:3 address:<network_field:"tcp" address_field:"127.0.0.1:45056" > attrs:<>
I161004 19:52:15.798945 56 gossip/client.go:125 node 2: started gossip client to 127.0.0.1:45150
I161004 19:52:15.799759 267 gossip/client.go:125 node 3: started gossip client to 127.0.0.1:45150
I161004 19:52:15.802885 25 storage/replica_raftstorage.go:443 [s1,r1:/M{in-ax}] generated snapshot a424e808 for range 1 at index 12 in 63.962µs.
I161004 19:52:15.810006 25 storage/store.go:2747 streamed snapshot: kv pairs: 31, log entries: 2
I161004 19:52:15.814200 86 storage/replica_raftstorage.go:573 [s2] [n2,s2,r1:{-}]: with replicaID [?], applying preemptive snapshot at index 12 (id=a424e808, encoded size=16, 1 rocksdb batches, 2 log entries)
I161004 19:52:15.814911 86 storage/replica_raftstorage.go:576 [s2] [n2,s2,r1:/M{in-ax}]: with replicaID [?], applied preemptive snapshot in 0.001s
I161004 19:52:15.821376 25 storage/replica_command.go:3236 change replicas: read existing descriptor range_id:1 start_key:"" end_key:"\377\377" replicas:<node_id:1 store_id:1 replica_id:1 > next_replica_id:2
I161004 19:52:15.823488 434 storage/replica.go:1712 [s1,r1:/M{in-ax}] proposing ADD_REPLICA {NodeID:2 StoreID:2 ReplicaID:2} for range 1: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2}]
I161004 19:52:15.864750 87 storage/raft_transport.go:418 raft transport stream to node 1 established
I161004 19:52:15.865283 25 storage/replica_raftstorage.go:443 [s1,r1:/M{in-ax}] generated snapshot 73e739d1 for range 1 at index 14 in 164.209µs.
I161004 19:52:15.866326 25 storage/store.go:2747 streamed snapshot: kv pairs: 34, log entries: 4
I161004 19:52:15.866846 451 storage/replica_raftstorage.go:573 [s3] [n3,s3,r1:{-}]: with replicaID [?], applying preemptive snapshot at index 14 (id=73e739d1, encoded size=16, 1 rocksdb batches, 4 log entries)
I161004 19:52:15.868005 451 storage/replica_raftstorage.go:576 [s3] [n3,s3,r1:/M{in-ax}]: with replicaID [?], applied preemptive snapshot in 0.001s
I161004 19:52:15.874809 25 storage/replica_command.go:3236 change replicas: read existing descriptor range_id:1 start_key:"" 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
I161004 19:52:15.903020 453 storage/replica.go:1712 [s1,r1:/M{in-ax}] proposing ADD_REPLICA {NodeID:3 StoreID:3 ReplicaID:3} for range 1: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:2 StoreID:2 ReplicaID:2} {NodeID:3 StoreID:3 ReplicaID:3}]
I161004 19:52:15.924549 482 storage/raft_transport.go:418 raft transport stream to node 1 established
E161004 19:52:15.925325 25 storage/client_test.go:950 engine 1: missing key "a"
E161004 19:52:15.925368 25 storage/client_test.go:950 engine 2: missing key "a"
I161004 19:52:15.928355 25 util/stop/stopper.go:353 stop has been called, stopping or quiescing all running tasks
I161004 19:52:15.929785 25 storage/replica_command.go:3236 change replicas: read existing descriptor range_id:1 start_key:"" 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
W161004 19:52:15.931219 410 storage/store.go:2636 [s1] got error from range 1, replica {2 2 2}: storage/raft_transport.go:247: unable to accept Raft message from {NodeID:1 StoreID:1 ReplicaID:1}: no handler registered for {NodeID:2 StoreID:2 ReplicaID:2}
W161004 19:52:15.931534 410 storage/store.go:2636 [s1] got error from range 1, replica {2 2 2}: storage/raft_transport.go:247: unable to accept Raft message from {NodeID:1 StoreID:1 ReplicaID:1}: no handler registered for {NodeID:2 StoreID:2 ReplicaID:2}
I161004 19:52:15.936671 488 storage/replica.go:1712 [s1,r1:/M{in-ax}] proposing REMOVE_REPLICA {NodeID:2 StoreID:2 ReplicaID:2} for range 1: [{NodeID:1 StoreID:1 ReplicaID:1} {NodeID:3 StoreID:3 ReplicaID:3}]
W161004 19:52:15.939282 410 storage/store.go:2636 [s1] got error from range 1, replica {2 2 2}: storage/raft_transport.go:247: unable to accept Raft message from {NodeID:1 StoreID:1 ReplicaID:1}: no handler registered for {NodeID:2 StoreID:2 ReplicaID:2}
W161004 19:52:15.939335 410 storage/store.go:2636 [s1] got error from range 1, replica {2 2 2}: storage/raft_transport.go:247: unable to accept Raft message from {NodeID:1 StoreID:1 ReplicaID:1}: no handler registered for {NodeID:2 StoreID:2 ReplicaID:2}
I161004 19:52:15.944480 25 gossip/gossip.go:268 NodeID set to 2
I161004 19:52:15.954336 25 storage/replica_raftstorage.go:443 [s1,r1:/M{in-ax}] generated snapshot a1061e88 for range 1 at index 22 in 54.207µs.
I161004 19:52:15.958691 25 storage/store.go:2747 streamed snapshot: kv pairs: 42, log entries: 3
I161004 19:52:15.958991 595 storage/replica_raftstorage.go:573 [s2] [n2,s2,r1:/M{in-ax}]: with replicaID 2, applying Raft snapshot at index 22 (id=a1061e88, encoded size=16, 1 rocksdb batches, 3 log entries)
E161004 19:52:15.971105 610 raft/raft.go:1091 [s2,r1:/M{in-ax}] 2 state.commit 22 is out of range [10, 17]
panic: 2 state.commit 22 is out of range [10, 17] [recovered]
panic: 2 state.commit 22 is out of range [10, 17]
goroutine 610 [running]:
panic(0x1615840, 0xc420d0cb70)
/home/tamird/go/src/runtime/panic.go:500 +0x1a1
github.com/cockroachdb/cockroach/util/stop.(*Stopper).Recover(0xc4205c2630)
/home/tamird/src/github.com/cockroachdb/cockroach/util/stop/stopper.go:180 +0x6e
panic(0x1615840, 0xc420d0cb70)
/home/tamird/go/src/runtime/panic.go:458 +0x243
github.com/cockroachdb/cockroach/storage.(*raftLogger).Panicf(0xc420d860e0, 0x180283d, 0x2b, 0xc420cfab00, 0x4, 0x4)
/home/tamird/src/github.com/cockroachdb/cockroach/storage/raft.go:111 +0x107
github.com/coreos/etcd/raft.(*raft).loadState(0xc420346b40, 0x6, 0x0, 0x16, 0x0, 0x0, 0x0)
/home/tamird/src/github.com/coreos/etcd/raft/raft.go:1091 +0x1db
github.com/coreos/etcd/raft.newRaft(0xc420de1498, 0x40)
/home/tamird/src/github.com/coreos/etcd/raft/raft.go:289 +0xc9b
github.com/coreos/etcd/raft.NewRawNode(0xc420de1498, 0x0, 0x0, 0x0, 0xc420d90000, 0x16, 0x0)
/home/tamird/src/github.com/coreos/etcd/raft/rawnode.go:79 +0x71
github.com/cockroachdb/cockroach/storage.(*Replica).withRaftGroupLocked(0xc42009e700, 0x0, 0xc420de17e0, 0x0, 0x0)
/home/tamird/src/github.com/cockroachdb/cockroach/storage/replica.go:414 +0x28a
github.com/cockroachdb/cockroach/storage.defaultProposeRaftCommandLocked(0xc42009e700, 0xc420dae000, 0x0, 0x0)
/home/tamird/src/github.com/cockroachdb/cockroach/storage/replica.go:1747 +0x1ed
github.com/cockroachdb/cockroach/storage.(*Replica).proposePendingCmdLocked(0xc42009e700, 0xc420dae000, 0xc420d920c0, 0xc420d860c0)
/home/tamird/src/github.com/cockroachdb/cockroach/storage/replica.go:1686 +0x77
github.com/cockroachdb/cockroach/storage.(*Replica).proposeRaftCommand(0xc42009e700, 0x7f961d71c000, 0xc420d920c0, 0x311cdad160001, 0xe, 0x0, 0x0, 0x1, 0x0, 0x0, ...)
/home/tamird/src/github.com/cockroachdb/cockroach/storage/replica.go:1665 +0x1f6
github.com/cockroachdb/cockroach/storage.(*Replica).addWriteCmd(0xc42009e700, 0x7f961d71c000, 0xc420d920c0, 0x311cdad160001, 0xe, 0x0, 0x0, 0x1, 0x0, 0x0, ...)
/home/tamird/src/github.com/cockroachdb/cockroach/storage/replica.go:1551 +0x17a
github.com/cockroachdb/cockroach/storage.(*Replica).Send(0xc42009e700, 0x7f961d71c000, 0xc420d920c0, 0x311cdad160001, 0xe, 0x0, 0x0, 0x1, 0x0, 0x0, ...)
/home/tamird/src/github.com/cockroachdb/cockroach/storage/replica.go:1075 +0x277
github.com/cockroachdb/cockroach/storage.(*pendingLeaseRequest).InitOrJoinRequest.func1(0x7f961d71c000, 0xc420b95f50)
/home/tamird/src/github.com/cockroachdb/cockroach/storage/replica_range_lease.go:127 +0x174
github.com/cockroachdb/cockroach/util/stop.(*Stopper).RunAsyncTask.func1(0xc4205c2630, 0x1f100b8, 0x1e, 0x91, 0x19866d8, 0xc420d92000, 0x7f961d71c000, 0xc420b95f50)
/home/tamird/src/github.com/cockroachdb/cockroach/util/stop/stopper.go:239 +0xc6
created by github.com/cockroachdb/cockroach/util/stop.(*Stopper).RunAsyncTask
/home/tamird/src/github.com/cockroachdb/cockroach/util/stop/stopper.go:240 +0x227
ERROR: exit status 2
2146 runs completed, 1 failures, over 19s
FAIL
Makefile:146: recipe for target 'stress' failed
make: *** [stress] Error 1Assigning @petermattis as the newest raft whisperer.
petermattis
tbg
bdarnell
Binary: cockroach/static-tests.tar.gz sha: https://github.com/cockroachdb/cockroach/commits/087bda1d10e970964d6885ce7b505766d113cabe
Stress build found a failed test:
Run Details:
Please assign, take a look and update the issue accordingly.