rpc: re-work connection maintenance

[tbg]

This commit simplifies the rpc package.

The main aim is to make the code and the logging it produces somewhat
clearer and to pave the way for an ultimate merging of nodedialer with
rpc as well as adoption of the util/circuit package (async-based
circuit breaker).

rpc.Context hadn't aged well. Back in the day, it was a connection
pool that held on to connections even when they failed. The heartbeat
loop would run forever and its latest outcome would reflect the health
of the connection. We relied on gRPC to reconnect the transport as
necessary.

At some point we realized that leaving the connection management to
gRPC could cause correctness issues. For example, if a node is de-
commissioned and brought up again, gRPC might reconnect to it but
now we have a connection that claims to be for node X but is actually
for node Y. Similarly, we want to be able to vet that the remote
node's cluster version is compatible with ours before letting any
messages cross the connection.

To achieve this, we added onlyOnceDialer - a dialer that fails
all but the first attempt to actually connect, and in particular
from that point on connections were never long lived once they
hit a failure state.

Still, the code and testing around the heartbeat loop continued
to nurture this illusion. I found that quite unappealing as it
was sure to throw off whoever would ultimately work on this code.

So, while my original impetus was to produce better log messages
from rpc.Context when there were connection issues, I took
the opportunity to simplify the architecture of the code to
reflect what it actually does.

In doing so, a few heartbeat-related metrics were removed, as they made
limited sense in a world where failing connections get torn down (i.e.
our world).

Connection state logging is now a lot nicer. Previously, one would very
frequently see the onlyOnceDialer's error "cannot reuse client
connection" which, if one is not familar with the concept of the
onlyOnceDialer is completely opaque, and for those few in the know is an
unhelpful error - you wanted the error that occurred during dialing.

I paid special attention to the "failfast" behavior. If connections
don't stay in the pool when they are unhealthy, what prevents us from
dialing down nodes in a tight loop? I realized that we got lucky with
our use of onlyOnceDialer because it would always prompt gRPC to do
one retry, and at a 1s backoff. So, the connection would stay in the
pool for at least a second, meaning that this was the maximum frequency
at which we'd try to connect to a down node.

My cleanups to onlyOnceDialer in pursuit of better logging elimitated
this (desirable) property. Instead we now skip the log messages should
they become too frequent. I claim that this is acceptable for now since
the vast majority of callers go through a node.Diaelr, which has a
circuit breaker (letting callers through at most once per second).

We previously configured gRPC with a 20s dial timeout. That means that
if a remote is unreachable, we'd spend 20s just trying to dial it,
possibly tying up callers that could be trying a reachable node in the
meantime. That seemed wildly too large; I am reducing it to 5s here
which is still generous (but there's a TLS handshake in here so better
not make it too tight).

We previously tried to re-use connections that were keyed with a NodeID
for dial attempts that didn't provide a NodeID. This caused some issues
over the years and was now removed; the extra RPC connections are
unlikely to cause any issues.

The internal connection map is now a plain map with an RWMutex. This is
just easier and gets the job done. The code has simplified as a result
and it's clearer that it's correct (which it repeatedly was not in the
past).

I implemented redactability for gRPC's status.Status-style errors,
so they format nicer and at least we get to see the error code (the
error message is already flattened when gRPC hands us the error,
sadly).

There are various other improvements to errors and formatting. The
following are excerpts from the health channel when shutting down
another node in a local cluster:

Connection is first established:

[n3,rnode=1,raddr=‹127.0.0.1:26257›,class=system,rpc] 3 connection is now ready

n1 goes down, i.e. existing connection is interrupted (this error comes
from onlyOnceDialer):

[n3,rnode=1,raddr=‹127.0.0.1:26257›,class=system,rpc] 35 closing
connection after: ‹rpc error: code = Unavailable desc = connection
error: desc = "transport: Error while dialing connection interrupted
(did the remote node shut down or are there networking issues?)"›

Reconnection attempts; these logs are spaced 1-2s apart:

[n3,rnode=1,raddr=‹127.0.0.1:26257›,class=system,rpc] 37 unable to
connect (is the peer up and reachable?): initial connection heartbeat
failed: ‹rpc error: code = Unavailable desc = connection error: desc =
"transport: Error while dialing dial tcp 127.0.0.1:26257: connect:
connection refused"›

n3 is back up:

[n3,rnode=1,raddr=‹127.0.0.1:26257›,class=system,rpc] 49 connection is now ready

There are other connection errors in the logs that stem from operations
checking for a healthy connection, failing to get through circuit
breakers, etc., such as these:

[n3,intExec=‹claim-jobs›,range-lookup=/Table/15/4/‹NULL›] 33 unable
to connect to n1: failed to check for ready connection to n1 at
‹127.0.0.1:26257›: ‹connection not ready: TRANSIENT_FAILURE›

Epic: none

Release note (general change): Previously, CockroachDB employed a 20s
connection timeout for cluster-internal connections between nodes. This
has been reduced to 5s to potentially reduce the impact of network
issues.

Release note (general change): Previously, CockroachDB (mostly) shared a
TCP connection for the KV and Gossip subsystems. They now use their own
connection each, so the total number of outgoing and incoming TCP
connections at each node in the cluster will increase by 30 to 50
percent.

[cockroach-teamcity]

This change is 

[knz]

First commit LGTM.
2nd commit - I reviewed all I could but not in the right frame of mind to ascertain correctness of the "main" thing. I'd need to look at it further next week. Also will welcome Erik's opinion of course.

Reviewed 1 of 1 files at r1, 24 of 24 files at r2, all commit messages.
Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @erikgrinaker and @tbg)

---

pkg/rpc/context.go line 1804 at r2 (raw file):

	target string, remoteNodeID roachpb.NodeID, class ConnectionClass,
) *Connection {
	ctx := rpcCtx.makeDialCtx(target, remoteNodeID, class)

Why did you move this? I put it there for the log.Fatal's benefit.

---

pkg/util/grpcutil/grpc_err_redaction.go line 28 at r2 (raw file):

func grpcSpecialCasePrintFn(err error, p errbase.Printer, isLeaf bool) (handled bool, next error) {
	if errors.GetTypeKey(err) != grpcErrTypeKey {

nit: I think the following is just as correct and will get you less overhead:

var refErr = status.Error(codes.Unavailable, "")
...
if errors.HasType(err, refErr)

Alternatively, you could just drop this check entirely and trust status.FromError - it only returns true in the 2nd return value if the status object could be recovered with the right type.

---

pkg/util/netutil/net.go line 212 at r2 (raw file):

// SafeFormatError implements errors.SafeFormatter.
func (e *InitialHeartbeatFailedError) SafeFormatError(p errors.Printer) (next error) {
	p.Printf("initial connection heartbeat failed")

nit: p.SafeString, less overhead.

---

pkg/rpc/context_test.go line 821 at r2 (raw file):

func TestHeartbeatHealth(t *testing.T) {
	defer leaktest.AfterTest(t)()
	// TODO why does this hide log.HEALTH even when -show-logs is active?

It was Andrei's request: #69765 / #70052.

You can define a custom log config for use with log.Scope if you want.

[knz]

Reviewed 5 of 25 files at r4, 8 of 9 files at r6, 7 of 7 files at r7, all commit messages.
Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @tbg)

---

pkg/rpc/context.go line 1804 at r2 (raw file):

Previously, tbg (Tobias Grieger) wrote…

Done.

I'm still confused - what's the obstacle to having ctx := rpcCtx.makeDialCtx(target, remoteNodeID, class) here and passing it as argument to grpcDialNodeInternal? Is it solely because you want to avoid creating a context.Context if rpcCtx.m.Get returns a valid connection?

---

pkg/rpc/context.go line 1871 at r7 (raw file):

	// callers that may pass a zero NodeID could coalesce onto the connection
	// with the "real" NodeID. This caused issues over the years[^1][^2] and
	// was never necessary anyway, so we don't do it anymore.

Does this mean we get 1 extra connection for those callers that use node ID 0?
If so, perhaps worth mentioning in the release note. This will double the number of node-node connections when the cluster goes from non-initialized to initialized at the point cockroach init is run.

---

pkg/rpc/context.go line 1943 at r7 (raw file):

		conn.err.Store(errDialRejected)
		close(conn.initialHeartbeatDone)
		_ = rpcCtx.m.Remove(k, conn) // ignoring error since it's just on shutdown anyway

nit: period at end of comment.

Also I'm not sure I agree - we're moving to a world where these things get instantiated and teared down dynamically (#84700) so we want clean shutdowns in every case.

---

pkg/util/netutil/net.go line 212 at r2 (raw file):

Previously, tbg (Tobias Grieger) wrote…

Does not exist on errors.Printer.

oh sorry I misread. that's cool.

[knz]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @tbg)

---

pkg/rpc/context.go line 1871 at r7 (raw file):

Previously, knz (Raphael 'kena' Poss) wrote…

Does this mean we get 1 extra connection for those callers that use node ID 0?
If so, perhaps worth mentioning in the release note. This will double the number of node-node connections when the cluster goes from non-initialized to initialized at the point cockroach init is run.

Also, gossip uses UnvalidatedDial (so with Node ID = 0). So it's not just in the non-init case we're doubling the connections. It's all the time.

(Technically, we'd be going to 2 conns per node-node pair, from system/normal classes, to 3: system/normal/gossip-other.)

[knz]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @tbg)

---

pkg/rpc/context.go line 1871 at r7 (raw file):

Previously, knz (Raphael 'kena' Poss) wrote…

Also, gossip uses UnvalidatedDial (so with Node ID = 0). So it's not just in the non-init case we're doubling the connections. It's all the time.

(Technically, we'd be going to 2 conns per node-node pair, from system/normal classes, to 3: system/normal/gossip-other.)

That incidentally brings me to a related question: does it matter whether the gossip connection uses the same TCP connection as the other RPCs? Is there something that gossip decides wrt connectivity that could be wrong / disruptive if the gossip connection succeeds, but the other RPC connection(s) fail?

[tbg]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @erikgrinaker, @knz, and @yuzefovich)

---

pkg/rpc/context.go line 1804 at r2 (raw file):

Previously, knz (Raphael 'kena' Poss) wrote…

I'm still confused - what's the obstacle to having ctx := rpcCtx.makeDialCtx(target, remoteNodeID, class) here and passing it as argument to grpcDialNodeInternal? Is it solely because you want to avoid creating a context.Context if rpcCtx.m.Get returns a valid connection?

The dialing API is currently such that you have methods like GRPCDialNode that give you a *Connection and are non-blocking, so they can never use the cancellation property of the Context (that happens when you call .Connect). I think it's a little clearer to pass the context only once, or you end up with (essentially) rpcCtx.GRPCDialNode(ctx).Connect(ctx).

---

pkg/rpc/context.go line 1871 at r7 (raw file):

Previously, knz (Raphael 'kena' Poss) wrote…

That incidentally brings me to a related question: does it matter whether the gossip connection uses the same TCP connection as the other RPCs? Is there something that gossip decides wrt connectivity that could be wrong / disruptive if the gossip connection succeeds, but the other RPC connection(s) fail?

Good point, will mention in the release note. It shouldn't matter to Gossip who it's sharing the connection with. If anything, having its own connection might be helpful sometimes. (And of course in async weird network partitions as always all bets are off).

---

pkg/rpc/context.go line 1943 at r7 (raw file):

Previously, knz (Raphael 'kena' Poss) wrote…

nit: period at end of comment.

Also I'm not sure I agree - we're moving to a world where these things get instantiated and teared down dynamically (#84700) so we want clean shutdowns in every case.

The shutdown here is clean, the error makes assertions. But I might as well check the error here too.

[tbg]

bors r=erikgrinaker

[erikgrinaker]

Linter failure:

=== RUN   TestLint/TestRoachVet
    lint_test.go:91:
        pkg/rpc/context_test.go:928:11: github.com/cockroachdb/errors.Errorf format %d reads arg #1, but call has 0 args
        pkg/rpc/context_test.go:951:11: github.com/cockroachdb/errors.Errorf format %d reads arg #1, but call has 0 args
    --- FAIL: TestLint/TestRoachVet (142.81s)

[tbg]

bors r-

[craig]

Canceled.

[tbg]

bors r=erikgrinaker

[craig]

Build succeeded:

• Bazel Essential CI (Cockroach)