A replica's subscription connection can stall in ConnectedEstablishing, costing the whole ConnectTimeout

[mgravell]

A cluster replica's subscription connection can stay in ConnectedEstablishing, and under RESP2 that burns the whole ConnectTimeout.

Seen once in CI on the #3238 branch (job log), against the in-process test server. Not reproduced locally in ~47 runs, including 22 full-suite runs and 10 under deliberate CPU contention on a 24-core box. Filing what the log shows rather than leaving it in a PR comment.

Symptom

Connect took the full 10s timeout. Every node was reachable; one node's interactive connection was fine and only its subscription connection never finished establishing:

Not all available tasks completed cleanly (from ReconfigureAsync#1838, timeout 9994ms), ...
  Server[0] (127.0.0.1:6379) Status: RanToCompletion
  Server[1] (127.0.0.1:6380) Status: RanToCompletion
  Server[2] (127.0.0.1:6381) Status: WaitingForActivation
Endpoint summary:
  127.0.0.1:6379: Endpoint is (Interactive: ConnectedEstablished, Subscription: ConnectedEstablished)
  127.0.0.1:6380: Endpoint is (Interactive: ConnectedEstablished, Subscription: ConnectedEstablished)
  127.0.0.1:6381: Endpoint is (Interactive: ConnectedEstablished, Subscription: ConnectedEstablishing)
Task summary:
  127.0.0.1:6381: Did not respond (Task.Status: WaitingForActivation)

6381 is a replica; 6379 and 6380 are primaries. Its interactive handshake completed normally, including the tracer:

127.0.0.1:6381: Auto-configured (HELLO) role: replica
Response from 127.0.0.1:6381/Interactive / ECHO: BulkString: 16 bytes

Why that stalls the connect rather than degrading

ServerEndPoint.OnFullyEstablished only completes the OnConnectedAsync waiters once the second leg is up:

if (IsConnected && (IsSubscriberConnected || !SupportsSubscriptions || isResp3))
{
    CompletePendingConnectionMonitors(source);
}

Under RESP2 with subscriptions available, an interactive connection that is fully established is therefore not enough. The waiter never completes, and ReconfigureAsync waits out ConnectTimeout before reporting the node DidNotRespond — the same presentation as #3232, from a different cause.

What the counters say

Both of that node's connections finish with exactly one message written and awaiting a response, and the server logs nothing further for it for the whole 10 seconds:

127.0.0.1:6381: int ops=12, qu=0, qs=1, qc=0, wr=0, socks=1; sub ops=4, qu=0, qs=1, qc=0, wr=0, socks=1

Its subscription connection also issued one fewer CLIENT command than the healthy peers' did (3 vs 4) before its ECHO, which the server answered.

The run was heavily loaded — POOL grew from 24 to 38 threads and completed ~48k work items inside the stalled window, the rest of the suite running in parallel.

Open questions

• Is this specific to a replica, or to any node whose subscription connection loses the race? RequiresReadMode (serverType == Cluster && IsReplica) is the one write-path behaviour that is replica-only, and it would prepend READONLY — but the test server logs unknown commands and none was logged, so it does not appear to have been sent.
• Is it the in-process server's pipe scheduling under load rather than the client? The test server is a fake; a real replica answers everything. This has only ever been seen against the fake.
• Whichever it is, the consequence is worth its own look: one slow-to-establish subscription connection costs the entire connect its timeout, and the node is then reported as unresponsive when it is in fact connected and usable on the interactive leg.

Note

The in-process test server only gained the ability to model a replica in #3238 (AddReplicaNode, plus replicas in CLUSTER SLOTS and consistent role in HELLO/INFO/ROLE), so no earlier test could have hit this. The test that surfaced it now connects with withPubSub: false, since its subject is discovery rather than subscriptions — which means nothing currently covers this path.