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

kv/kvserver: TestStoreRangeSplitRaceUninitializedRHS failed [skipped] #50809

Closed
cockroach-teamcity opened this issue Jun 30, 2020 · 6 comments · Fixed by #57029
Closed

kv/kvserver: TestStoreRangeSplitRaceUninitializedRHS failed [skipped] #50809

cockroach-teamcity opened this issue Jun 30, 2020 · 6 comments · Fixed by #57029
Assignees
@tbg
Labels
branch-master Failures and bugs on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Milestone
20.2

Comments

@cockroach-teamcity
Copy link
Member

(kv/kvserver).TestStoreRangeSplitRaceUninitializedRHS failed on master@0b65365fce6a9bdde6c611c92031877ade88a8b2:

Error types: (1) *contextutil.TimeoutError (2) context.deadlineExceededError
W200630 06:44:22.106836 368001 kv/kvserver/node_liveness.go:538  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 150ms
(1) operation "node liveness heartbeat" timed out after 150ms
Wraps: (2) context deadline exceeded
Error types: (1) *contextutil.TimeoutError (2) context.deadlineExceededError
W200630 06:44:22.123928 368205 kv/kvserver/node_liveness.go:538  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 150ms
(1) operation "node liveness heartbeat" timed out after 150ms
Wraps: (2) aborted during DistSender.Send: context deadline exceeded
Error types: (1) *contextutil.TimeoutError (2) *roachpb.internalError
E200630 06:44:22.161498 387578 kv/kvserver/replica_range_lease.go:339  [s1,r5/1:{/Systemtse-a��}] heartbeat failed on epoch increment
W200630 06:44:22.309647 368001 kv/kvserver/node_liveness.go:538  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 150ms
(1) operation "node liveness heartbeat" timed out after 150ms
Wraps: (2) aborted during DistSender.Send: context deadline exceeded
Error types: (1) *contextutil.TimeoutError (2) *roachpb.internalError
W200630 06:44:22.321225 368205 kv/kvserver/node_liveness.go:538  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 150ms
(1) operation "node liveness heartbeat" timed out after 150ms
Wraps: (2) aborted during DistSender.Send: context deadline exceeded
Error types: (1) *contextutil.TimeoutError (2) *roachpb.internalError
I200630 06:44:22.560846 387980 kv/kvserver/replica_command.go:413  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf7" [r43] (manual)
I200630 06:44:22.666342 387980 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=2209eaa7] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593499462.561514588,0 encountered previous write with future timestamp 1593499462.561514588,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200630 06:44:22.691763 387980 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=2209eaa7] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593499462.562763929,0 encountered previous write with future timestamp 1593499462.562763929,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200630 06:44:22.704542 387980 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=2209eaa7] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593499462.562763929,1 encountered previous write with future timestamp 1593499462.562763929,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200630 06:44:22.729960 387980 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=2209eaa7] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593499462.562763929,2 encountered previous write with future timestamp 1593499462.562763929,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200630 06:44:22.763078 387980 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=2209eaa7] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593499462.562763929,3 encountered previous write with future timestamp 1593499462.562763929,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200630 06:44:22.807223 387980 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=2209eaa7] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593499462.562763929,4 encountered previous write with future timestamp 1593499462.562763929,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
W200630 06:44:22.899552 367878 kv/kvserver/store_rebalancer.go:223  [s1,store-rebalancer] StorePool missing descriptor for local store
I200630 06:44:22.984716 388249 kv/kvserver/replica_command.go:413  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf6" [r44] (manual)
I200630 06:44:23.229653 388249 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=a516945f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593499462.985206828,0 encountered previous write with future timestamp 1593499462.985206828,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200630 06:44:23.276346 388249 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=a516945f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593499462.986198305,0 encountered previous write with future timestamp 1593499462.986198305,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200630 06:44:23.297203 388249 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=a516945f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593499462.986198305,1 encountered previous write with future timestamp 1593499462.986198305,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200630 06:44:23.348812 388249 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=a516945f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593499462.986198305,2 encountered previous write with future timestamp 1593499462.986198305,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
W200630 06:44:23.367335 368198 kv/kvserver/store_rebalancer.go:223  [s2,store-rebalancer] StorePool missing descriptor for local store
I200630 06:44:23.398408 388249 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=a516945f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593499462.986198305,3 encountered previous write with future timestamp 1593499462.986198305,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200630 06:44:23.415034 388249 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=a516945f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593499462.986198305,4 encountered previous write with future timestamp 1593499462.986198305,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200630 06:44:23.723157 388400 util/stop/stopper.go:539  quiescing
I200630 06:44:23.728868 388399 util/stop/stopper.go:539  quiescing
I200630 06:44:23.729607 368107 kv/kvserver/queue.go:582  [s2,r5/2:{/Systemtse-a��}] rate limited in MaybeAdd (split): node unavailable; try another peer
W200630 06:44:23.729859 388515 kv/kvserver/intentresolver/intent_resolver.go:539  failed to cleanup transaction intents: failed to resolve intents: node unavailable; try another peer
I200630 06:44:23.730348 368107 kv/kvserver/queue.go:582  [s2,r5/2:{/Systemtse-a��}] rate limited in MaybeAdd (replicate): node unavailable; try another peer
W200630 06:44:23.754751 368363 kv/kvserver/raft_transport.go:294  unable to accept Raft message from (n2,s2):2: no handler registered for (n1,s1):1
W200630 06:44:23.756233 368363 kv/kvserver/raft_transport.go:294  unable to accept Raft message from (n2,s2):2: no handler registered for (n1,s1):1
W200630 06:44:23.758384 368354 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 1: node unavailable; try another peer:
I200630 06:44:23.772860 388398 util/stop/stopper.go:539  quiescing
W200630 06:44:23.776950 368404 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 2: rpc error: code = Unavailable desc = transport is closing:
W200630 06:44:23.777818 368255 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 2: EOF:
W200630 06:44:23.781477 368072 gossip/gossip.go:1518  [n2] no incoming or outgoing connections
W200630 06:44:23.801344 368319 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 1: EOF:
I200630 06:44:23.806269 388398 util/stop/stopper.go:539  quiescing
I200630 06:44:23.808064 388398 util/stop/stopper.go:539  quiescing
--- FAIL: TestStoreRangeSplitRaceUninitializedRHS (58.04s)
More

Parameters:

  • TAGS=
  • GOFLAGS=-race -parallel=2
make stressrace TESTS=TestStoreRangeSplitRaceUninitializedRHS PKG=./pkg/kv/kvserver TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

See this test on roachdash
powered by pkg/cmd/internal/issues
@cockroach-teamcity cockroach-teamcity added branch-master Failures and bugs on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Jun 30, 2020
@cockroach-teamcity cockroach-teamcity added this to the 20.2 milestone Jun 30, 2020
@cockroach-teamcity
Copy link
Member Author

(kv/kvserver).TestStoreRangeSplitRaceUninitializedRHS failed on master@9e0a39fb605df4f03014be44fac297971a6b61f5:

I200703 02:30:47.755190 403516 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=cc70b169] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743447.519256739,4 encountered previous write with future timestamp 1593743447.519256739,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:48.017197 403778 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xfa" [r40] (manual)
I200703 02:30:48.133082 403778 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=dfc561d2] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.031454235,0 encountered previous write with future timestamp 1593743448.031454235,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:48.146736 403778 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=dfc561d2] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.069571184,0 encountered previous write with future timestamp 1593743448.069571184,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:48.161285 403778 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=dfc561d2] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.069571184,1 encountered previous write with future timestamp 1593743448.069571184,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:48.177733 403778 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=dfc561d2] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.069571184,2 encountered previous write with future timestamp 1593743448.069571184,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:48.335868 403778 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=dfc561d2] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.069571184,3 encountered previous write with future timestamp 1593743448.069571184,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:48.374188 403778 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=dfc561d2] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.069571184,4 encountered previous write with future timestamp 1593743448.069571184,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:48.549566 403884 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf9" [r41] (manual)
I200703 02:30:48.631674 403884 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=d7189321] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.550203406,0 encountered previous write with future timestamp 1593743448.550203406,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:48.644989 403884 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=d7189321] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.551400425,0 encountered previous write with future timestamp 1593743448.551400425,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:48.656862 403884 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=d7189321] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.551400425,1 encountered previous write with future timestamp 1593743448.551400425,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:48.684693 403884 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=d7189321] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.551400425,2 encountered previous write with future timestamp 1593743448.551400425,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:48.708050 403884 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=d7189321] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.551400425,3 encountered previous write with future timestamp 1593743448.551400425,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:48.727165 403884 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=d7189321] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.551400425,4 encountered previous write with future timestamp 1593743448.551400425,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:48.869327 404141 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf8" [r42] (manual)
I200703 02:30:48.961618 404141 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=b6a32335] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.869887760,0 encountered previous write with future timestamp 1593743448.869887760,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:48.999645 404141 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=b6a32335] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.871195690,0 encountered previous write with future timestamp 1593743448.871195690,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.017198 404141 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=b6a32335] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.871195690,1 encountered previous write with future timestamp 1593743448.871195690,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.042252 404141 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=b6a32335] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.871195690,2 encountered previous write with future timestamp 1593743448.871195690,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.057743 404141 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=b6a32335] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.871195690,3 encountered previous write with future timestamp 1593743448.871195690,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.072632 404141 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=b6a32335] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743448.871195690,4 encountered previous write with future timestamp 1593743448.871195690,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.284564 404265 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf7" [r43] (manual)
I200703 02:30:49.371697 404265 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=03a6ad5f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743449.285688066,0 encountered previous write with future timestamp 1593743449.285688066,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.385125 404265 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=03a6ad5f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743449.286862850,0 encountered previous write with future timestamp 1593743449.286862850,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.397812 404265 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=03a6ad5f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743449.286862850,1 encountered previous write with future timestamp 1593743449.286862850,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.418534 404265 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=03a6ad5f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743449.286862850,2 encountered previous write with future timestamp 1593743449.286862850,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.444303 404265 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=03a6ad5f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743449.286862850,3 encountered previous write with future timestamp 1593743449.286862850,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.469842 404265 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=03a6ad5f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743449.286862850,4 encountered previous write with future timestamp 1593743449.286862850,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.638392 404586 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf6" [r44] (manual)
I200703 02:30:49.751753 404586 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0c03dafd] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743449.638966945,0 encountered previous write with future timestamp 1593743449.638966945,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.774930 404586 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0c03dafd] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743449.640225327,0 encountered previous write with future timestamp 1593743449.640225327,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.802251 404586 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0c03dafd] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743449.640225327,1 encountered previous write with future timestamp 1593743449.640225327,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.817955 404586 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0c03dafd] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743449.640225327,2 encountered previous write with future timestamp 1593743449.640225327,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.836337 404586 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0c03dafd] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743449.640225327,3 encountered previous write with future timestamp 1593743449.640225327,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:49.865081 404586 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0c03dafd] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593743449.640225327,4 encountered previous write with future timestamp 1593743449.640225327,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200703 02:30:50.037722 404624 util/stop/stopper.go:539  quiescing
I200703 02:30:50.039727 404623 util/stop/stopper.go:539  quiescing
W200703 02:30:50.041219 404730 kv/kvserver/intentresolver/intent_resolver.go:539  failed to cleanup transaction intents: failed to resolve intents: node unavailable; try another peer
I200703 02:30:50.061239 381393 kv/kvserver/queue.go:582  [s2,r5/2:{/Systemtse-a��}] rate limited in MaybeAdd (split): node unavailable; try another peer
I200703 02:30:50.061931 381393 kv/kvserver/queue.go:582  [s2,r5/2:{/Systemtse-a��}] rate limited in MaybeAdd (replicate): node unavailable; try another peer
I200703 02:30:50.116252 404622 util/stop/stopper.go:539  quiescing
W200703 02:30:50.125666 381657 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 2: EOF:
W200703 02:30:50.128175 381599 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 1: rpc error: code = Canceled desc = grpc: the client connection is closing:
W200703 02:30:50.128522 381611 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 2: EOF:
W200703 02:30:50.128417 381370 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 1: EOF:
W200703 02:30:50.131567 381576 gossip/gossip.go:1504  [n2] no incoming or outgoing connections
I200703 02:30:50.132650 404622 util/stop/stopper.go:539  quiescing
I200703 02:30:50.134696 404622 util/stop/stopper.go:539  quiescing
--- FAIL: TestStoreRangeSplitRaceUninitializedRHS (46.47s)
More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestStoreRangeSplitRaceUninitializedRHS PKG=./pkg/kv/kvserver TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

See this test on roachdash
powered by pkg/cmd/internal/issues

rytaft added a commit to rytaft/cockroach that referenced this issue Jul 3, 2020
@rytaft
partitionccl,kvserver: skip some flaky tests
ede3219 
This commit skips 2 tests as part of the test-infra-team flaky
test cleanup:

TestInitialPartitioning
TestStoreRangeSplitRaceUninitializedRHS

Informs cockroachdb#49909
Informs cockroachdb#50809

Release note: None
@rytaft rytaft mentioned this issue Jul 3, 2020
Merged
@cockroach-teamcity
Copy link
Member Author

(kv/kvserver).TestStoreRangeSplitRaceUninitializedRHS failed on master@456a07cfc1e53b87abc7709052e54efb1450e758:

Wraps: (2) context deadline exceeded
Error types: (1) *contextutil.TimeoutError (2) context.deadlineExceededError
W200704 06:01:56.013964 360658 kv/kvserver/node_liveness.go:538  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 150ms
(1) operation "node liveness heartbeat" timed out after 150ms
Wraps: (2) context deadline exceeded
Error types: (1) *contextutil.TimeoutError (2) *roachpb.internalError
E200704 06:01:56.049599 375173 kv/kvserver/replica_range_lease.go:339  [s1,r5/1:{/Systemtse-a��}] heartbeat failed on epoch increment
I200704 06:01:56.058206 360440 kv/kvserver/node_liveness.go:528  [liveness-hb] heartbeat failed on epoch increment; retrying
I200704 06:01:56.170985 360440 kv/kvserver/node_liveness.go:897  [liveness-hb] retrying liveness update after kvserver.errRetryLiveness: result is ambiguous (context deadline exceeded)
W200704 06:01:56.171633 360440 kv/kvserver/node_liveness.go:538  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 150ms
(1) operation "node liveness heartbeat" timed out after 150ms
Wraps: (2) context deadline exceeded
Error types: (1) *contextutil.TimeoutError (2) context.deadlineExceededError
E200704 06:01:56.185359 375309 kv/kvserver/replica_range_lease.go:383  [s2,r39/2:a�{�-�}] mismatch incrementing epoch for liveness(nid:1 epo:1 exp:1593842515.993867656,0); actual is liveness(nid:1 epo:1 exp:1593842516.358652523,0)
I200704 06:01:56.473758 374842 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=2347666b] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842514.710813107,1 encountered previous write with future timestamp 1593842514.710813107,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:56.521864 374842 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=2347666b] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842514.710813107,2 encountered previous write with future timestamp 1593842514.710813107,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:56.566485 374842 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=2347666b] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842514.710813107,3 encountered previous write with future timestamp 1593842514.710813107,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:56.619079 374842 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=2347666b] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842514.710813107,4 encountered previous write with future timestamp 1593842514.710813107,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:57.121862 375595 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf7" [r43] (manual)
I200704 06:01:57.310386 375595 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=326491e3] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842517.122572725,0 encountered previous write with future timestamp 1593842517.122572725,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:57.354297 360440 kv/kvserver/node_liveness.go:897  [liveness-hb] retrying liveness update after kvserver.errRetryLiveness: result is ambiguous (context deadline exceeded)
W200704 06:01:57.354958 360440 kv/kvserver/node_liveness.go:538  [liveness-hb] failed node liveness heartbeat: operation "node liveness heartbeat" timed out after 150ms
(1) operation "node liveness heartbeat" timed out after 150ms
Wraps: (2) context deadline exceeded
Error types: (1) *contextutil.TimeoutError (2) context.deadlineExceededError
I200704 06:01:57.486849 375595 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=326491e3] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842517.124141996,0 encountered previous write with future timestamp 1593842517.124141996,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:57.588192 375595 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=326491e3] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842517.124141996,1 encountered previous write with future timestamp 1593842517.124141996,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:57.633537 375595 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=326491e3] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842517.124141996,2 encountered previous write with future timestamp 1593842517.124141996,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:57.670833 375595 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=326491e3] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842517.124141996,3 encountered previous write with future timestamp 1593842517.124141996,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:57.705158 360439 gossip/gossip.go:1518  [n1] node has connected to cluster via gossip
I200704 06:01:57.708394 375595 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=326491e3] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842517.124141996,4 encountered previous write with future timestamp 1593842517.124141996,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:58.027514 375955 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf6" [r44] (manual)
I200704 06:01:58.156526 375955 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0ef38a65] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842518.035624219,1 encountered previous write with future timestamp 1593842518.035624219,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:58.223407 375955 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0ef38a65] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842518.036631225,0 encountered previous write with future timestamp 1593842518.036631225,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:58.239587 375955 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0ef38a65] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842518.036631225,1 encountered previous write with future timestamp 1593842518.036631225,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:58.393398 375955 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0ef38a65] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842518.036631225,2 encountered previous write with future timestamp 1593842518.036631225,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:58.424905 375955 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0ef38a65] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842518.036631225,3 encountered previous write with future timestamp 1593842518.036631225,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:58.476991 375955 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0ef38a65] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593842518.036631225,4 encountered previous write with future timestamp 1593842518.036631225,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200704 06:01:58.882569 376243 util/stop/stopper.go:539  quiescing
I200704 06:01:58.883265 376244 util/stop/stopper.go:539  quiescing
W200704 06:01:58.890204 376229 kv/kvserver/intentresolver/intent_resolver.go:539  failed to cleanup transaction intents: failed to resolve intents: node unavailable; try another peer
I200704 06:01:59.052722 376242 util/stop/stopper.go:539  quiescing
W200704 06:01:59.056287 360764 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 2: EOF:
W200704 06:01:59.057607 360791 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 1: rpc error: code = Canceled desc = grpc: the client connection is closing:
W200704 06:01:59.058695 360727 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 1: EOF:
W200704 06:01:59.059252 360439 gossip/gossip.go:1504  [n1] no incoming or outgoing connections
W200704 06:01:59.059484 360720 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 2: EOF:
I200704 06:01:59.071664 376242 util/stop/stopper.go:539  quiescing
I200704 06:01:59.073548 376242 util/stop/stopper.go:539  quiescing
--- FAIL: TestStoreRangeSplitRaceUninitializedRHS (41.77s)
More

Parameters:

  • TAGS=
  • GOFLAGS=-race -parallel=2
make stressrace TESTS=TestStoreRangeSplitRaceUninitializedRHS PKG=./pkg/kv/kvserver TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

See this test on roachdash
powered by pkg/cmd/internal/issues

@cockroach-teamcity
Copy link
Member Author

(kv/kvserver).TestStoreRangeSplitRaceUninitializedRHS failed on master@3e0de239121813ea4d47873388a2828a66d9edf7:

I200705 05:59:08.923371 392877 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xfa" [r40] (manual)
I200705 05:59:09.155224 392877 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0a5bb391] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928748.923797843,0 encountered previous write with future timestamp 1593928748.923797843,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:09.184645 392877 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0a5bb391] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928748.924681291,0 encountered previous write with future timestamp 1593928748.924681291,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:09.196765 392877 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0a5bb391] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928748.924681291,1 encountered previous write with future timestamp 1593928748.924681291,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:09.208592 392877 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0a5bb391] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928748.924681291,2 encountered previous write with future timestamp 1593928748.924681291,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:09.233625 392877 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0a5bb391] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928748.924681291,3 encountered previous write with future timestamp 1593928748.924681291,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:09.248044 392877 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=0a5bb391] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928748.924681291,4 encountered previous write with future timestamp 1593928748.924681291,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:09.543871 393173 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf9" [r41] (manual)
I200705 05:59:09.678967 393173 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=7c8c4b6e] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928749.544445887,0 encountered previous write with future timestamp 1593928749.544445887,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:09.734576 393173 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=7c8c4b6e] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928749.547262021,0 encountered previous write with future timestamp 1593928749.547262021,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:09.760805 393173 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=7c8c4b6e] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928749.547262021,1 encountered previous write with future timestamp 1593928749.547262021,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:09.772182 393173 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=7c8c4b6e] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928749.547262021,2 encountered previous write with future timestamp 1593928749.547262021,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:09.811072 393173 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=7c8c4b6e] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928749.547262021,3 encountered previous write with future timestamp 1593928749.547262021,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:09.832262 393173 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=7c8c4b6e] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928749.547262021,4 encountered previous write with future timestamp 1593928749.547262021,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:10.001637 393335 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf8" [r42] (manual)
I200705 05:59:10.077581 393335 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=41170154] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928750.002133110,0 encountered previous write with future timestamp 1593928750.002133110,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:10.099457 393335 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=41170154] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928750.003277716,0 encountered previous write with future timestamp 1593928750.003277716,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:10.115742 393335 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=41170154] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928750.003277716,1 encountered previous write with future timestamp 1593928750.003277716,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:10.129656 393335 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=41170154] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928750.003277716,2 encountered previous write with future timestamp 1593928750.003277716,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:10.157297 393335 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=41170154] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928750.003277716,3 encountered previous write with future timestamp 1593928750.003277716,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:10.169719 393335 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=41170154] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928750.003277716,4 encountered previous write with future timestamp 1593928750.003277716,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
W200705 05:59:10.338802 367141 kv/kvserver/store_rebalancer.go:223  [s1,store-rebalancer] StorePool missing descriptor for local store
I200705 05:59:10.407374 393524 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf7" [r43] (manual)
I200705 05:59:10.710223 393524 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=ea4c0c7f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928750.407913521,0 encountered previous write with future timestamp 1593928750.407913521,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:10.726255 393524 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=ea4c0c7f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928750.408983303,0 encountered previous write with future timestamp 1593928750.408983303,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:10.758643 393524 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=ea4c0c7f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928750.408983303,1 encountered previous write with future timestamp 1593928750.408983303,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:10.823956 393524 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=ea4c0c7f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928750.408983303,2 encountered previous write with future timestamp 1593928750.408983303,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:10.876334 393524 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=ea4c0c7f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928750.408983303,3 encountered previous write with future timestamp 1593928750.408983303,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:10.898300 393524 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=ea4c0c7f] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928750.408983303,4 encountered previous write with future timestamp 1593928750.408983303,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:11.086559 393737 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf6" [r44] (manual)
I200705 05:59:11.501395 393737 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=03eb3bfc] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928751.086988548,0 encountered previous write with future timestamp 1593928751.086988548,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:11.584956 393737 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=03eb3bfc] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928751.088142222,0 encountered previous write with future timestamp 1593928751.088142222,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:11.675869 393737 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=03eb3bfc] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928751.088142222,1 encountered previous write with future timestamp 1593928751.088142222,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:11.686586 393737 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=03eb3bfc] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928751.088142222,2 encountered previous write with future timestamp 1593928751.088142222,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:11.706883 393737 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=03eb3bfc] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928751.088142222,3 encountered previous write with future timestamp 1593928751.088142222,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:11.726254 393737 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=03eb3bfc] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1593928751.088142222,4 encountered previous write with future timestamp 1593928751.088142222,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200705 05:59:11.918325 393932 util/stop/stopper.go:539  quiescing
I200705 05:59:11.918916 393931 util/stop/stopper.go:539  quiescing
W200705 05:59:11.920479 394021 kv/kvserver/intentresolver/intent_resolver.go:539  failed to cleanup transaction intents: failed to resolve intents: node unavailable; try another peer
I200705 05:59:11.940091 367323 kv/kvserver/queue.go:582  [s2,r5/2:{/Systemtse-a��}] rate limited in MaybeAdd (split): node unavailable; try another peer
I200705 05:59:11.940584 367323 kv/kvserver/queue.go:582  [s2,r5/2:{/Systemtse-a��}] rate limited in MaybeAdd (replicate): node unavailable; try another peer
I200705 05:59:11.990662 393930 util/stop/stopper.go:539  quiescing
W200705 05:59:11.993529 367463 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 2: rpc error: code = Canceled desc = grpc: the client connection is closing:
W200705 05:59:11.997551 367459 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 1: EOF:
W200705 05:59:11.997916 367476 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 1: EOF:
W200705 05:59:11.998136 367179 gossip/gossip.go:1504  [n2] no incoming or outgoing connections
W200705 05:59:11.998716 367401 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 2: EOF:
I200705 05:59:12.000616 393930 util/stop/stopper.go:539  quiescing
I200705 05:59:12.002414 393930 util/stop/stopper.go:539  quiescing
--- FAIL: TestStoreRangeSplitRaceUninitializedRHS (69.75s)
More

Parameters:

  • TAGS=
  • GOFLAGS=-race -parallel=2
make stressrace TESTS=TestStoreRangeSplitRaceUninitializedRHS PKG=./pkg/kv/kvserver TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

See this test on roachdash
powered by pkg/cmd/internal/issues

@cockroach-teamcity
Copy link
Member Author

(kv/kvserver).TestStoreRangeSplitRaceUninitializedRHS failed on master@f61d73fe1e4773372f3800b715143305a3342ee7:

I200706 06:07:49.612534 395887 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=c35cbca4] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015669.444642434,0 encountered previous write with future timestamp 1594015669.444642434,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:49.639417 395887 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=c35cbca4] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015669.459182911,0 encountered previous write with future timestamp 1594015669.459182911,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:49.675478 395887 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=c35cbca4] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015669.459182911,1 encountered previous write with future timestamp 1594015669.459182911,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:49.721790 395887 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=c35cbca4] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015669.459182911,2 encountered previous write with future timestamp 1594015669.459182911,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:49.758826 395887 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=c35cbca4] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015669.459182911,3 encountered previous write with future timestamp 1594015669.459182911,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:49.772123 395887 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=c35cbca4] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015669.459182911,4 encountered previous write with future timestamp 1594015669.459182911,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:49.961213 396091 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf8" [r42] (manual)
I200706 06:07:50.374238 396091 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=ca28b969] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015669.961800757,0 encountered previous write with future timestamp 1594015669.961800757,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:50.400957 396091 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=ca28b969] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015669.964425580,0 encountered previous write with future timestamp 1594015669.964425580,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:50.420570 396091 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=ca28b969] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015669.964425580,1 encountered previous write with future timestamp 1594015669.964425580,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:50.466434 396091 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=ca28b969] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015669.964425580,2 encountered previous write with future timestamp 1594015669.964425580,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:50.488178 396091 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=ca28b969] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015669.964425580,3 encountered previous write with future timestamp 1594015669.964425580,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:50.546079 396091 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=ca28b969] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015669.964425580,4 encountered previous write with future timestamp 1594015669.964425580,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:51.020224 396459 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf7" [r43] (manual)
I200706 06:07:51.182041 396459 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=aec1bb1a] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015671.025028700,0 encountered previous write with future timestamp 1594015671.025028700,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:51.233500 396459 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=aec1bb1a] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015671.026611395,0 encountered previous write with future timestamp 1594015671.026611395,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:51.286878 396459 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=aec1bb1a] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015671.026611395,1 encountered previous write with future timestamp 1594015671.026611395,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:51.323346 396459 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=aec1bb1a] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015671.026611395,2 encountered previous write with future timestamp 1594015671.026611395,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:51.344553 396459 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=aec1bb1a] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015671.026611395,3 encountered previous write with future timestamp 1594015671.026611395,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:51.365875 396459 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=aec1bb1a] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015671.026611395,4 encountered previous write with future timestamp 1594015671.026611395,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:51.838029 396732 kv/kvserver/replica_command.go:414  [s1,r5/1:{/Systemtse-a��}] initiating a split of this range at key "a\x87\xf6" [r44] (manual)
I200706 06:07:52.094651 396732 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=68df91b5] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015671.838634818,0 encountered previous write with future timestamp 1594015671.838634818,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:52.244299 396732 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=68df91b5] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015671.853865648,0 encountered previous write with future timestamp 1594015671.853865648,0 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:52.258721 396732 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=68df91b5] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015671.853865648,1 encountered previous write with future timestamp 1594015671.853865648,1 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:52.383369 396732 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=68df91b5] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015671.853865648,2 encountered previous write with future timestamp 1594015671.853865648,2 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:52.427216 396732 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=68df91b5] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015671.853865648,3 encountered previous write with future timestamp 1594015671.853865648,3 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:52.450607 396732 kv/kvserver/replica_evaluate.go:454  [s1,r5/1:{/Systemtse-a��},txn=68df91b5] test injecting error: ReadWithinUncertaintyIntervalError: read at time 1594015671.853865648,4 encountered previous write with future timestamp 1594015671.853865648,4 within uncertainty interval `t <= <nil>`; observed timestamps: []
I200706 06:07:52.791476 397047 util/stop/stopper.go:539  quiescing
I200706 06:07:52.792188 397048 util/stop/stopper.go:539  quiescing
W200706 06:07:52.793020 397044 kv/kvserver/intentresolver/intent_resolver.go:539  failed to cleanup transaction intents: failed to resolve intents: node unavailable; try another peer
I200706 06:07:52.813053 373679 kv/kvserver/queue.go:582  [s2,r40/2:a�{�-�}] rate limited in MaybeAdd (replicate): node unavailable; try another peer
W200706 06:07:52.813260 373881 kv/kvserver/raft_transport.go:294  unable to accept Raft message from (n2,s2):2: no handler registered for (n1,s1):1
W200706 06:07:52.814692 373881 kv/kvserver/raft_transport.go:294  unable to accept Raft message from (n2,s2):2: no handler registered for (n1,s1):1
W200706 06:07:52.817690 373840 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 1: node unavailable; try another peer:
W200706 06:07:52.818916 373881 kv/kvserver/raft_transport.go:294  unable to accept Raft message from (n2,s2):2: no handler registered for (n1,s1):1
I200706 06:07:52.828953 397046 util/stop/stopper.go:539  quiescing
W200706 06:07:52.828840 373744 kv/kvserver/raft_transport.go:294  unable to accept Raft message from (n1,s1):1: no handler registered for (n2,s2):2
W200706 06:07:52.830440 373744 kv/kvserver/raft_transport.go:294  unable to accept Raft message from (n1,s1):1: no handler registered for (n2,s2):2
W200706 06:07:52.831423 373744 kv/kvserver/raft_transport.go:294  unable to accept Raft message from (n1,s1):1: no handler registered for (n2,s2):2
W200706 06:07:52.832176 373744 kv/kvserver/raft_transport.go:294  unable to accept Raft message from (n1,s1):1: no handler registered for (n2,s2):2
W200706 06:07:52.834758 373742 kv/kvserver/raft_transport.go:466  no handler found for store 1 in response range_id:43 from_replica:<node_id:2 store_id:2 replica_id:2 > to_replica:<node_id:1 store_id:1 replica_id:1 > union:<error:<message:"store 2 was not found" transaction_restart:NONE origin_node:0 detail:<store_not_found:<store_id:2 > > now:<> > > 
W200706 06:07:52.836050 373742 kv/kvserver/raft_transport.go:466  no handler found for store 1 in response range_id:43 from_replica:<node_id:2 store_id:2 replica_id:2 > to_replica:<node_id:1 store_id:1 replica_id:1 > union:<error:<message:"store 2 was not found" transaction_restart:NONE origin_node:0 detail:<store_not_found:<store_id:2 > > now:<> > > 
W200706 06:07:52.836798 373656 gossip/gossip.go:1504  [n2] no incoming or outgoing connections
W200706 06:07:52.836975 373742 kv/kvserver/raft_transport.go:466  no handler found for store 1 in response range_id:43 from_replica:<node_id:2 store_id:2 replica_id:2 > to_replica:<node_id:1 store_id:1 replica_id:1 > union:<error:<message:"store 2 was not found" transaction_restart:NONE origin_node:0 detail:<store_not_found:<store_id:2 > > now:<> > > 
W200706 06:07:52.838160 373634 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 2: EOF:
W200706 06:07:52.840520 395098 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 1: rpc error: code = Unavailable desc = transport is closing:
W200706 06:07:52.841006 373851 kv/kvserver/raft_transport.go:637  while processing outgoing Raft queue to node 2: rpc error: code = Canceled desc = grpc: the client connection is closing:
I200706 06:07:52.843769 397046 util/stop/stopper.go:539  quiescing
I200706 06:07:52.846207 397046 util/stop/stopper.go:539  quiescing
--- FAIL: TestStoreRangeSplitRaceUninitializedRHS (88.52s)
More

Parameters:

  • TAGS=
  • GOFLAGS=-race -parallel=2
make stressrace TESTS=TestStoreRangeSplitRaceUninitializedRHS PKG=./pkg/kv/kvserver TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

See this test on roachdash
powered by pkg/cmd/internal/issues

craig bot pushed a commit that referenced this issue Jul 6, 2020
@rytaft
Merge #50971
b2e4e2e 
50971: partitionccl,kvserver: skip some flaky tests r=rytaft a=rytaft

This commit skips 2 tests as part of the test-infra-team flaky
test cleanup:

TestInitialPartitioning
TestStoreRangeSplitRaceUninitializedRHS

Informs #49909
Informs #50809

Release note: None

Co-authored-by: Rebecca Taft <becca@cockroachlabs.com>
@knz knz changed the title kv/kvserver: TestStoreRangeSplitRaceUninitializedRHS failed kv/kvserver: TestStoreRangeSplitRaceUninitializedRHS failed [skipped] Jul 22, 2020
@knz knz unassigned tbg Jul 22, 2020
@knz
Copy link
Contributor

knz commented Jul 22, 2020

The failure is still current (but the test is now skipped)

cc @tbg @nvanbenschoten for triage

@knz
Copy link
Contributor

knz commented Aug 31, 2020

Stressed this today: still repros with the same symptoms.

@knz knz added the release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. label Aug 31, 2020
@cockroach-teamcity cockroach-teamcity mentioned this issue Aug 31, 2020
Closed
@tbg tbg self-assigned this Sep 1, 2020
@thoszhang thoszhang removed branch-release-20.2 release-blocker Indicates a release-blocker. Use with branch-release-2x.x label to denote which branch is blocked. labels Oct 12, 2020
@lunevalex lunevalex mentioned this issue Nov 23, 2020
Merged
lunevalex added a commit to lunevalex/cockroach that referenced this issue Nov 24, 2020
@lunevalex
kvserver: replace the use of client_test code with TestCluster/TestSe…
451e94a 
…rver in client_split test

Fixes cockroachdb#50809
Makes progress on cockroachdb#8299

multiTestContext and test store code in client_test are deprecated in favor of running
tests via TestClusteri/TestServer. This is one PR out of many to remove the usage of
multiTestContext in the client_split test cases. This does not remove
all the usages of mtc in this file and just focuses on the simple ones.
The more complex cases that rely on lease expiration will be tackled in a future PR.

Release note: None
lunevalex added a commit to lunevalex/cockroach that referenced this issue Jan 8, 2021
@lunevalex
kvserver: replace the use of client_test code with TestCluster/TestSe…
96897ac 
…rver in client_split test

Fixes cockroachdb#50809
Makes progress on cockroachdb#8299

multiTestContext and test store code in client_test are deprecated in favor of running
tests via TestClusteri/TestServer. This is one PR out of many to remove the usage of
multiTestContext in the client_split test cases. This does not remove
all the usages of mtc in this file and just focuses on the simple ones.
The more complex cases that rely on lease expiration will be tackled in a future PR.

Release note: None
craig bot pushed a commit that referenced this issue Jan 13, 2021
@lunevalex
Merge #57029
d1702fe 
57029: kvserver: replace the use of client_test code  with TestCluster/TestServer in client_split test r=lunevalex a=lunevalex

Fixes #50809
Makes progress on #8299

multiTestContext and test store code in client_test are deprecated in favor of running
tests via TestClusteri/TestServer. This is one PR out of many to remove the usage of
multiTestContext in the client_split test cases. This does not remove
all the usages of mtc in this file and just focuses on the simple ones.
The more complex cases that rely on lease expiration will be tackled in a future PR.

Release note: None

Co-authored-by: Alex Lunev <alexl@cockroachlabs.com>
@craig craig bot closed this as completed in a591707 Jan 13, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@tbg tbg

Labels
branch-master Failures and bugs on the master branch. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
20.2
5 participants
@dt @knz @thoszhang @tbg @cockroach-teamcity