: TestTableReader failed under stress

[cockroach-teamcity]

SHA: https://github.com/cockroachdb/cockroach/commits/cdcd15f77105c95024f184af2aac63c80dc7b184

Stress build found a failed test:

I161104 07:45:12.631349 775 gossip/gossip.go:237  [n?] initial resolvers: []
W161104 07:45:12.631803 775 gossip/gossip.go:1055  [n?] no resolvers found; use --join to specify a connected node
W161104 07:45:12.637236 775 server/status/runtime.go:116  Could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I161104 07:45:12.639130 775 storage/engine/rocksdb.go:340  opening in memory rocksdb instance
I161104 07:45:12.640496 775 server/config.go:443  1 storage engine initialized
I161104 07:45:12.652220 775 server/node.go:421  [n?] store [n0,s0] not bootstrapped
I161104 07:45:12.675323 850 storage/replica_proposal.go:292  [s1,r1/1:/M{in-ax}] new range lease replica {1 1 1} 1970-01-01 00:00:00 +0000 UTC 410623h45m21.670719559s following replica {0 0 0} 1970-01-01 00:00:00 +0000 UTC 0s [physicalTime=2016-11-04 07:45:12.67510465 +0000 UTC]
I161104 07:45:12.701830 775 util/stop/stopper.go:396  stop has been called, stopping or quiescing all running tasks
I161104 07:45:12.703674 775 server/node.go:350  [n?] **** cluster {c0c287cc-b0f3-431e-ad2c-2f5cffcf31d6} has been created
I161104 07:45:12.703938 775 server/node.go:351  [n?] **** add additional nodes by specifying --join=127.0.0.1:33136
I161104 07:45:12.715767 775 base/node_id.go:62  [n1] NodeID set to 1
I161104 07:45:12.733933 775 server/node.go:434  [n1] initialized store [n1,s1]: {Capacity:536870912 Available:536870912 RangeCount:0 LeaseCount:0}
I161104 07:45:12.734528 775 server/node.go:319  [n1] node ID 1 initialized
I161104 07:45:12.734972 775 gossip/gossip.go:280  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:33136" > attrs:<> locality:<> 
I161104 07:45:12.735863 775 storage/stores.go:296  [n1] read 0 node addresses from persistent storage
I161104 07:45:12.736326 775 server/node.go:564  [n1] connecting to gossip network to verify cluster ID...
I161104 07:45:12.736682 775 server/node.go:585  [n1] node connected via gossip and verified as part of cluster {"c0c287cc-b0f3-431e-ad2c-2f5cffcf31d6"}
I161104 07:45:12.737014 775 server/node.go:369  [n1] node=1: started with [[]=] engine(s) and attributes []
I161104 07:45:12.737326 775 server/server.go:606  [n1] starting https server at 127.0.0.1:51233
I161104 07:45:12.737573 775 server/server.go:607  [n1] starting grpc/postgres server at 127.0.0.1:33136
I161104 07:45:12.737820 775 server/server.go:608  [n1] advertising CockroachDB node at 127.0.0.1:33136
I161104 07:45:12.745782 808 storage/split_queue.go:103  [n1,split,s1,r1/1:/M{in-ax}] splitting at keys [/Table/11/0 /Table/12/0 /Table/13/0 /Table/14/0]
I161104 07:45:12.785217 808 storage/replica_command.go:2361  [n1,split,s1,r1/1:/M{in-ax}] initiating a split of this range at key /Table/11 [r2]
I161104 07:45:13.154713 900 sql/event_log.go:95  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:33136} Attrs: Locality:} ClusterID:{UUID:c0c287cc-b0f3-431e-ad2c-2f5cffcf31d6} StartedAt:1478245512736887526}
I161104 07:45:13.446062 808 storage/replica_command.go:2361  [n1,split,s1,r1/1:/{Min-Table/11}] initiating a split of this range at key /Table/12 [r3]
W161104 07:45:13.016808 808 util/hlc/hlc.go:145  backward time jump detected (-0.434156 seconds)
E161104 07:45:13.042421 808 internal/client/txn.go:331  [n1,split,s1,r1/1:/{Min-Table/11}] failure aborting transaction: storage/store.go:2233: rejecting command with timestamp in the future: 1478245513447151680 (406.408532ms ahead); abort caused by: storage/store.go:2233: rejecting command with timestamp in the future: 1478245513447151680 (411.455801ms ahead)
E161104 07:45:13.043557 808 storage/queue.go:568  [n1,split] on [n1,s1,r1/1:/{Min-Table/11}]: unable to split [n1,s1,r1/1:/{Min-Table/11}] at key "/Table/12/0": storage/replica_command.go:2441: split at key /Table/12 failed: storage/store.go:2233: rejecting command with timestamp in the future: 1478245513447151680 (411.455801ms ahead)
I161104 07:45:13.046216 808 storage/split_queue.go:103  [n1,split,s1,r2/1:/{Table/11-Max}] splitting at keys [/Table/12/0 /Table/13/0 /Table/14/0]
E161104 07:45:13.048278 808 storage/queue.go:568  [n1,split] on [n1,s1,r2/1:/{Table/11-Max}]: unable to split [n1,s1,r2/1:/{Table/11-Max}] at key "/Table/12/0": storage/store.go:2233: rejecting command with timestamp in the future: 1478245513450406007 (402.816334ms ahead)
I161104 07:45:23.286856 775 util/stop/stopper.go:396  stop has been called, stopping or quiescing all running tasks
I161104 07:45:23.287186 775 util/stop/stopper.go:468  quiescing; tasks left:
1      storage/queue.go:477
1      server/node.go:855
E161104 07:45:23.291421 812 storage/queue.go:568  [n1,timeSeriesMaintenance] on [n1,s1,r1/1:/{Min-Table/11}]: node unavailable; try another peer
	test_server_shim.go:124: had 2 ranges at startup, expected 5


ERROR: exit status 1

Makefile:128: recipe for target 'stress' failed
make: *** [stress] Error 1

[tamird]

Possibly #10409. @petermattis?

[petermattis]

Sounds like #10409. I can't get this to fail using make stress right now (after my fix for #10409) went in. Closing for now. I'll take a look if this rears its ugly head again.