kv: dist sender can get into a bad loop if replicas are rebalanced

[spencerkimball]

In the case where the dist sender gets an RPC "black holed" to a replica which is then replaced, the dist sender will never get an updated set of replicas which includes the newly rebalanced replica, and will retry forever on NotLeaseHolderErrors.

[petermattis]

From a comment in #15163:

2017/04/30 19:43:17.558052	1049.859796	sql txn
19:43:17.558089	 .    37	... [client=127.0.0.1:33792,user=root,n11] executing 1/1: INSERT INTO blocks(block_id, writer_id, block_num, raw_bytes) VALUES (4058608034129001455, '36588123-f7ba-4b5e-9011-6e2e912bb530', 7335216, $1)
19:43:17.558164	 .    75	... [client=127.0.0.1:33792,user=root,n11] query not supported for distSQL: unsupported node *sql.insertNode
19:43:17.558216	 .    53	... txnID:e016abc1-0b3a-4473-9292-9c35448d2b6c
19:43:17.558254	 .    37	... [client=127.0.0.1:33792,user=root,n11] querying next range at /Table/51/1/4058608034129001455/"36588123-f7ba-4b5e-9011-6e2e912bb530"/7335216/0
19:43:17.558298	 .    44	... [client=127.0.0.1:33792,user=root,n11] sending batch 1 CPut, 1 BeginTxn, 1 EndTxn to r3187
19:43:17.558511	 .   213	... [client=127.0.0.1:33792,user=root,n11] application error: [NotLeaseHolderError] range 3187: replica (n11,s11):8 not lease holder; current lease is repl=(n6,s6):11 start=1493581019.136971047,0 epo=37 pro=1493581019.136989947,0
19:43:17.558515	 .     4	... [client=127.0.0.1:33792,user=root,n11] error, trying next peer
19:43:18.060190	 .501675	... [client=127.0.0.1:33792,user=root,n11] timeout, trying next peer
19:43:18.063872	 .  3682	... [client=127.0.0.1:33792,user=root,n11] application error: range 3187 was not found
19:43:18.063881	 .     9	... [client=127.0.0.1:33792,user=root,n11] error, trying next peer
19:43:18.064086	 .   205	... [client=127.0.0.1:33792,user=root,n11] application error: [NotLeaseHolderError] range 3187: replica (n11,s11):8 not lease holder; current lease is repl=(n6,s6):11 start=1493581019.136971047,0 epo=37 pro=1493581019.136989947,0
19:43:18.564253	 .500167	... [client=127.0.0.1:33792,user=root,n11] timeout, trying next peer
19:43:18.564588	 .   335	... [client=127.0.0.1:33792,user=root,n11] application error: [NotLeaseHolderError] range 3187: replica (n11,s11):8 not lease holder; current lease is repl=(n6,s6):11 start=1493581019.136971047,0 epo=37 pro=1493581019.136989947,0
...
<NotLeaseHolderError lines repeat>

@spencerkimball This looks exactly like what you're concerned about. r3187 was seeing a bunch of rebalancing activity around this time. I'm going to dig some more info from the logs to see if I can confirm that r3187 was rebalanced while this RPC was inflight.

[petermattis]

I170430 19:24:43.134285 20623974 storage/replica.go:2591  [n11,s11,r3187/8:/Table/51/1/40{58154…-60411…}] proposing REMOVE_REPLICA (n5,s5):6: [(n2,s2):10 (n11,s11):8]
I170430 19:36:20.830332 21146300 storage/replica.go:2591  [n11,s11,r3187/8:/Table/51/1/40{58154…-60411…}] proposing ADD_REPLICA (n6,s6):11: [(n2,s2):10 (n11,s11):8 (n6,s6):11]
I170430 19:36:58.445976 21179658 storage/replica.go:2591  [n11,s11,r3187/8:/Table/51/1/40{58154…-60411…}] proposing ADD_REPLICA (n4,s4):12: [(n2,s2):10 (n11,s11):8 (n6,s6):11 (n4,s4):12]
I170430 19:52:43.536551 25338571 storage/replica.go:2591  [n6,s6,r3187/11:/Table/51/1/40{58154…-60411…}] proposing REMOVE_REPLICA (n11,s11):8: [(n2,s2):10 (n4,s4):12 (n6,s6):11]
I170428 19:55:08.940116 18365095 storage/replica.go:2587  [n10,s10,r3187/1:/Table/51/1/40{58154…-60411…}] proposing ADD_REPLICA (n11,s11):4: [(n10,s10):1 (n6,s6):2 (n9,s9):3 (n11,s11):4]
I170428 19:55:09.374377 18365562 storage/replica.go:2587  [n10,s10,r3187/1:/Table/51/1/40{58154…-60411…}] proposing REMOVE_REPLICA (n9,s9):3: [(n10,s10):1 (n6,s6):2 (n11,s11):4]

There is an unusual amount of rebalancing activity for r3187 during the time period, though nothing that precisely overlaps the RPC. I could imagine that the RPC happened slightly after a lease transfer which would then hit an old entry in the range descriptor cache.

It is unfortunate that the log messages do not include the node ID that reported the NotLeaseHolderErrors. I'm going to add that.