2.12.14+ / 3.4.5: transactions on idle connections are torn down as "Dead socket detected … with 2 timeouts" when replies are slower than one heartbeat

Start with the awaiting-response and timeout logic in src/StackExchange.Redis/PhysicalConnection.cs and the dead-socket heuristic in src/StackExchange.Redis/PhysicalBridge.cs; src/StackExchange.Redis/ConnectionMultiplexer.cs contains the forced-heartbeat entry point used by the repro. Run the supplied C# transaction repro with proxy.py to add 64 ms of reply latency, then verify that transactions commit without a dead-socket teardown and that timeout accounting reflects actual command timing.

I've been looking to upgrade some of my services to a more modern version of se.redis. In my tests, I hit some exceptions which appear to be exacerbated by the environment (cross-region requests in a low traffic environment). The issue is summarized, code snippets to create a local repro and a suggested fix are defined below.

Summary

After moving from 2.12.8 to 2.12.14 or later (including 3.4.5), we see frequent Dead socket detected, no reads in N seconds with 2 timeouts, issuing disconnect teardowns, and the in-flight transaction fails with RedisConnectionException: SocketClosed on [0]:UNWATCH. Nothing else changed: same network, same server, same configuration. The clearest comparison is a local harness that only adds 64 ms of reply latency (our client↔server RTT):

Client	Transactions on pooled connections, 64 ms reply latency, 150 s
2.12.8	348 / 348 committed, 0 dead-socket teardowns
3.4.5	23 / 347 failed (6.6%), 23 dead-socket teardowns

It affects transactions with and without AddCondition(...). The trigger is a transaction written to a connection that has had no reads for more than 4 × SyncTimeout, whose reply arrives after the next heartbeat (≤ 1 s later), even though that is well inside the configured timeout. The failure rate is close to RTT / HeartbeatInterval. Cross-region latency therefore makes it frequent for us. With in-region latency, or connections that are rarely idle, it is probably rare enough to go unnoticed.

This appears unintended, but we would like the maintainers' view. Our analysis, detailed below with production snapshots of the awaiting-response queue:

• Sub-commands of an IMultiMessage (in a transaction: WATCH, the condition commands, MULTI, the queued operations) are added to the awaiting-response queue with no write timestamp (_writeTickCount == 0). On the next heartbeat they look overdue, by the process uptime.
• Since #2965 (https://github.com/StackExchange/StackExchange.Redis/pull/2965), overdue messages without an async result box count as "sync timeouts" (PhysicalConnection.cs#L1036-L1048). Fire-and-forget prefix commands such as SELECT count too.
• One such count, plus the stale LastReadSecondsAgo of an idle connection, satisfies the dead-socket heuristic. Yet no command has actually timed out: in production the teardown came a median of 40 ms after the WATCH was written.

The heuristic's own comment (PhysicalBridge.cs#L712-L715) describes the case it targets as "we've received NOTHING on the pipe in 4 timeouts worth of time and we're timing out commands". The second half of that condition is not really met here.

By code inspection, the same write path is used by script evaluation (the SCRIPT LOAD sent the first time a script is used on a connection) and by StringGetWithExpiry (PTTL); we have not tested those.

This may also explain #3085 and #3100, which were closed as resolved by 3.0:

• #3085 used CreateTransaction() on AWS Lambda. Lambda freezes between invocations, so its connections are idle when the next transaction is written.
• #3100 was a write-heavy client using EVAL, with high latency to the server.

We still see it on 3.4.5 (and 2.12.14 / 2.13.x); 2.12.8 is not affected.

Environment

StackExchange.Redis	3.4.5 (also reproduced on 2.12.14, 2.13.1, 2.13.17, 3.1.31, 3.4.0; not on 2.10.1, 2.12.1, 2.12.4, 2.12.8)
Runtime	.NET 10, Linux containers on AKS (East US)
Server	Azure Cache for Redis (classic), Premium P2, Redis 6.0.14, clustering enabled with 1 shard (primary + replica), update channel Stable, no zones
Server region	West US — the client and the cache are in different regions; client↔server RTT is about 64 ms
Transport	TLS 1.2 only (non-SSL port disabled); clients connect to the :6380 endpoint and are redirected to the cluster node ports (:15000 / :15001)
Server config	maxclients=15000, maxmemory-policy=noeviction, maxmemory-reserved=1330, maxfragmentationmemory-reserved=1330
Protocol	RESP2 (pinned through a DefaultOptionsProvider). The same failures occurred on 3.4.0 with the default protocol

Client configuration

Each ConnectionMultiplexer is created with these options (effective values, as logged at runtime):

<cache>.redis.cache.windows.net:6380,keepAlive=45,syncTimeout=2000,connectTimeout=5000,connectRetry=3,ssl=True,abortConnect=False,$SUBSCRIBE=
SyncTimeout=2000; AsyncTimeout=2000; ConnectTimeout=5000; ConnectRetry=3; KeepAlive=45; HeartbeatInterval=00:00:01;
ConfigCheckSeconds=60; AbortOnConnectFail=False; Ssl=True; Protocol=Resp2; HighIntegrity=False;
SocketManager=ThreadPoolSocketManager; DefaultVersion=6.0.0

The application keeps a pool of 30 multiplexers per logical shard and uses them round-robin. Each multiplexer therefore usually goes about 10–20 s between commands, so LastReadSecondsAgo is normally above 4 × SyncTimeout (8 s) when a new command is written.

The workload that fails is a periodic conditional write:

var tran = db.CreateTransaction();
tran.AddCondition(Condition.HashEqual(key, "owner", owner));   // -> WATCH key ; HGET key owner
_ = tran.HashSetAsync(key, "beat", value);
await tran.ExecuteAsync();

Repro (local Redis, no Azure needed)

The failure needs two things: a connection with no reads for more than 4 × SyncTimeout, and a heartbeat that runs while a transaction's reply is still in flight. This repro sets up exactly that, using only latency:

• A small TCP proxy in front of a local Redis delays every reply by a fixed 64 ms, our client↔server RTT. It never stalls.
• Automatic heartbeats are pushed out (HeartbeatInterval = 1h), and one heartbeat is forced right after the transaction is written by calling the internal ConnectionMultiplexer.OnHeartbeat() (ConnectionMultiplexer.cs#L1394), as the test suite does. This controls when the heartbeat lands instead of leaving it to chance.

proxy.py: forwards commands to Redis immediately and delays every reply by a fixed amount (see the docstring):

"""
Latency-injecting TCP proxy for the repro.

  client  --->  127.0.0.1:6400 (this proxy)  --->  Redis (localhost:6379)
          <---  replies held back REPLY_DELAY  <---

What it does:
  * Accepts client connections on LISTEN_PORT and opens one matching connection to Redis per client.
  * Bytes from the client (commands) are forwarded to Redis immediately.
  * Bytes from Redis (replies) are forwarded to the client REPLY_DELAY seconds after they arrived.
    Every chunk is delayed by the same amount, so ordering is preserved and throughput is unaffected:
    the connection behaves like a healthy link with a fixed round-trip time.
  * When either side closes, the other side is closed too.

It does not parse RESP, drop data or pause anything; it only shifts reply bytes later in time.

Usage:  python proxy.py [delay_seconds]      (default 0.064 = 64 ms, our cross-region RTT)
"""
import asyncio
import sys
import time

LISTEN_PORT = 6400
REDIS = ("localhost", 6379)
REPLY_DELAY = float(sys.argv[1]) if len(sys.argv) > 1 else 0.064


async def forward(source: asyncio.StreamReader, dest: asyncio.StreamWriter, delay: float) -> None:
    """Copy bytes from source to dest, releasing each chunk `delay` seconds after it was read."""
    pending: asyncio.Queue = asyncio.Queue()  # (release_time, data) in arrival order; data=None means "source closed"

    async def release_in_order() -> None:
        while True:
            release_time, data = await pending.get()
            if data is None:
                break
            wait = release_time - time.monotonic()
            if wait > 0:
                await asyncio.sleep(wait)  # hold this chunk until its release time
            dest.write(data)
            await dest.drain()
        dest.close()

    releaser = asyncio.create_task(release_in_order())
    try:
        # Read as fast as data arrives and stamp each chunk with when it may be sent on.
        # Reading never waits on the delay, so a burst of replies is shifted as a whole rather than spread out.
        while data := await source.read(65536):
            await pending.put((time.monotonic() + delay, data))
    finally:
        await pending.put((0, None))  # source closed: flush what is queued, then close dest
        await releaser


async def handle_client(client_reader: asyncio.StreamReader, client_writer: asyncio.StreamWriter) -> None:
    redis_reader, redis_writer = await asyncio.open_connection(*REDIS)
    await asyncio.gather(
        forward(client_reader, redis_writer, 0),            # commands: client -> Redis, no delay
        forward(redis_reader, client_writer, REPLY_DELAY),  # replies:  Redis -> client, delayed
        return_exceptions=True,
    )


async def main() -> None:
    server = await asyncio.start_server(handle_client, "127.0.0.1", LISTEN_PORT)
    print(f"proxy 127.0.0.1:{LISTEN_PORT} -> {REDIS[0]}:{REDIS[1]}, reply delay {REPLY_DELAY * 1000:.0f} ms", flush=True)
    async with server:
        await server.serve_forever()


asyncio.run(main())

Client:

using System.Diagnostics;
using System.Reflection;
using Microsoft.Extensions.Logging;
using StackExchange.Redis;

var lf = LoggerFactory.Create(b => b.AddSimpleConsole(o => { o.SingleLine = true; o.TimestampFormat = "HH:mm:ss.fff "; }).SetMinimumLevel(LogLevel.Warning));
var cfg = new ConfigurationOptions
{
    EndPoints = { "127.0.0.1:6400" },              // via the 64 ms proxy
    SyncTimeout = 2000, KeepAlive = 45, AbortOnConnectFail = false, LoggerFactory = lf,
    HeartbeatInterval = TimeSpan.FromHours(1),     // no automatic heartbeats; we force one below
};
var mux = await ConnectionMultiplexer.ConnectAsync(cfg);
var heartbeat = typeof(ConnectionMultiplexer).GetMethod("OnHeartbeat", BindingFlags.Instance | BindingFlags.NonPublic, Type.EmptyTypes)!;
var db = mux.GetDatabase();
await db.HashSetAsync("health", "owner", "me");
heartbeat.Invoke(mux, null);                       // warm-up (JIT) so the forced heartbeat lands promptly

await Task.Delay(10_000);                          // connection idle > 4 x SyncTimeout

var sw = Stopwatch.StartNew();
var tran = db.CreateTransaction();
tran.AddCondition(Condition.HashEqual("health", "owner", "me"));   // also fails without a condition
_ = tran.HashSetAsync("health", "beat", DateTime.UtcNow.Ticks);
var exec = Task.Run(() => tran.ExecuteAsync());
await Task.Delay(10);
heartbeat.Invoke(mux, null);                       // a normal heartbeat, landing while the reply is in flight
try { Console.WriteLine($"committed={await exec} in {sw.ElapsedMilliseconds}ms"); }
catch (Exception ex) { Console.WriteLine($"FAILED in {sw.ElapsedMilliseconds}ms: {ex.GetType().Name}: {ex.Message}"); }

Results against Redis 7.0.15, three runs each:

Client	With condition	Without condition (plain MULTI/EXEC)
3.4.5	3/3 fail: warn: Dead socket detected, no reads in 10 seconds with 2 timeouts, issuing disconnect → RedisConnectionException: SocketClosed on [0]:UNWATCH (TransactionProcessor)	fails: Dead socket … 2 timeouts → TaskCanceledException: A task was canceled. (the #3085 symptom)
2.12.8	3/3 committed=True (~157 ms)	committed=True
3.4.5 + suggested fix (below)	3/3 committed=True (~160 ms)	committed=True

The "2 timeouts" are the WATCH and the condition HGET (or MULTI and the queued HSET when there is no condition). Both were written a few milliseconds before the heartbeat, and neither had timed out. Inside a test-suite test, OnHeartbeat() can be called directly, without reflection; this is the shape we would propose as a regression test.

Natural rate (latency only, real heartbeats)

The same proxy with the default 1 s heartbeat left running, and 30 pooled multiplexers each running a conditional transaction after an idle gap of 10–15 s, for 150 s:

Build	Result
3.4.5	319 committed, 23 failed (6.6%), 23 × Dead socket detected
2.12.8	348 committed, 0 failed, 0 dead sockets
3.4.5 + suggested fix	348 committed, 0 failed, 0 dead sockets

The 6.6% failure rate is close to RTT / HeartbeatInterval (64 ms / 1 s): the share of transactions where the heartbeat runs before the reply arrives. That matches what we see in production, and it is why in-region deployments (≈1 ms RTT) would rarely see this.

Code walkthrough (3.4.5)

1. The transaction's sub-commands bypass the write timestamp. A TransactionMessage is an IMultiMessage. Each sub-command it yields — WATCH and the condition commands (RedisTransaction.cs#L345-L363, Condition.cs#L505) — is written via WriteMessageToServerInsideWriteLock (PhysicalBridge.cs#L844-L850). That method calls EnqueueInsideWriteLock (#L1734) but never calls SetEnqueued/SetWriteTime. The SELECT prefix written just before them (#L847) is not stamped either. Only the outer message is stamped (#L881, #L1380). The sub-commands keep _writeTickCount == 0.

2. Every heartbeat treats them as overdue. HasTimedOut computes now - _writeTickCount (Message.cs#L918-L922). With a write time of 0 that is simply Environment.TickCount — about 181,000,000 ms in our pods, which have been up roughly 2 days.

3. They are counted as sync timeouts. In OnBridgeHeartbeat (PhysicalConnection.cs#L1018-L1048), any overdue message without an async result box goes to the else branch and increments syncTimeoutDetected. WATCH, MULTI and the fire-and-forget SELECT have no result box at all. The condition command (e.g. HGET) has a synchronous box, because the transaction's writer is blocked on it in Monitor.Wait (RedisTransaction.cs#L373-L378), but it was written milliseconds ago, not "before uptime". Before #2965 this branch only checked IsHandshakeCompletion (PhysicalConnection.cs#L780 @ 2.12.8), so the missing timestamp did no harm.

4. The dead-socket check fires. deadConnectionOnSync = syncTimeoutThisHeartbeat > 0 && LastReadSecondsAgo * 1000 > TimeoutMilliseconds * 4 (PhysicalBridge.cs#L709-L718). LastReadSecondsAgo is whole seconds since bytes last arrived (PhysicalConnection.cs#L459, updated at PhysicalConnection.Read.cs#L111 / #L169). With SyncTimeout = 2000 it must reach 9 (9000 > 8000); the shortest value we saw at a production teardown was exactly 9 s. It is so on an idle connection it measures the idle period, not silence while waiting for a reply. The first heartbeat after the WATCH is written therefore disconnects (OnDisconnected(SocketFailure) + Dispose) unless the reply has already arrived. The in-flight transaction then fails on UNWATCH.

In short, the heuristic reads as "we are timing out commands and have heard nothing for 4 timeouts". In practice it becomes "a transaction was written to a connection with no reads for 9 s or more, and its reply took longer than the next heartbeat". With a 64 ms RTT that happens many times an hour across a pool of mostly idle connections.

Code map

In the order things happen when a transaction is executed and a heartbeat then runs:

#	What happens	Where
1	ExecuteAsync hands the outer transaction message to the bridge, which stamps its write time (before any backlog wait)	PhysicalBridge.cs#L1380 (async), #L881 (sync)
2	Inside the write lock, the SELECT prefix is written, then the bridge loops over the transaction's sub-commands	PhysicalBridge.cs#L844-L850 (SELECT at #L847)
3	The transaction yields WATCH and the condition commands	RedisTransaction.cs#L345-L363, Condition.cs#L505
4	Each sub-command is written and added to the awaiting-response queue without a write time	PhysicalBridge.cs#L1734 → PhysicalConnection.cs#L814-L839
5	The transaction flushes and blocks in Monitor.Wait for the condition reply	RedisTransaction.cs#L373-L378
6	Meanwhile the heartbeat timer fires	ConnectionMultiplexer.cs#L1394 → PhysicalBridge.cs#L591
7	Each queued message is checked for being overdue (now - writeTime >= AsyncTimeout); with a write time of 0 it always is	Message.cs#L918-L922
8	Overdue messages without an async box are counted as "sync timeouts"	PhysicalConnection.cs#L1036-L1048
9	The dead-socket rule combines that count with the time since the last read, which is only updated when bytes arrive	PhysicalBridge.cs#L703-L719; last read: PhysicalConnection.cs#L459, updated at PhysicalConnection.Read.cs#L111 / #L169
10	The socket is torn down; the transaction's blocked writer and pending replies fail (UNWATCH)	PhysicalBridge.cs#L716-L718

For comparison:

• The same overdue loop in 2.12.8, where messages without an async box only triggered anything if they were the handshake: PhysicalConnection.cs#L749-L800 @ 2.12.8
• Library changes between the last good and first bad versions: https://github.com/StackExchange/StackExchange.Redis/compare/2.12.8...2.12.14

Production evidence (3.4.5, 5 pods, 52 minutes)

We captured the awaiting-response queue (via reflection, synchronously inside the LogWarningDeadSocketDetected callback, before the queue is drained):

Metric	Value
"Dead socket detected" events	243
Teardowns where the queue held an overdue message	238
… overdue messages = WATCH + HGET	231
… overdue messages = WATCH + HEXISTS	6
… overdue message = INFO (fire-and-forget, real write time, 2001 ms)	1
Overdue messages with a non-zero write time	1 of 238
LastReadSecondsAgo at teardown	min 9 s, median 16 s, max 20 s
Time since last write at teardown	median 40 ms (min 8 ms); shorter than one RTT
Resulting operation failures	236 × RedisConnectionException: SocketClosed on [0]:UNWATCH, 1 × ProtocolFailure on [0]:EXEC

A representative snapshot:

in-flight 10.x.x.x:15001 Interactive trigger="Dead socket detected, no reads in 13 seconds with 2 timeouts, issuing disconnect"
  lastReadAgo=13s lastWriteAgoMs=52 awaiting=2 syncTimeoutMs=2000
WATCH flags=NoRedirect, CommandRetryNever     internal=False asyncResult=False waitedMs=181433821 type=CommandKeyMessage
HGET  flags=NoRedirect, CommandRetryReadOnly  internal=False asyncResult=False waitedMs=181433821 type=ConditionMessage

waitedMs equals Environment.TickCount, i.e. the write time is 0. The connection was torn down 52 ms after the WATCH was written, before a 64 ms round trip could complete.

A client-side RESP capture (LoggingTunnel) of the torn-down connections showed the same pattern: the last commands sent have no reply when the socket closes.

Version bisect (same deployment, same cache, about 1 hour per version)

Version	Dead-socket teardowns
2.10.1	1 in ~112 pod-min
2.12.1	1 in ~100 pod-min
2.12.4	0 in ~100 pod-min
2.12.8	0 in ~75 pod-min
2.12.14	30 in ~36 pod-min
2.13.1 / 2.13.17	28 in ~55 / 18 in ~50
3.1.31	26 in ~92
3.4.5	243 in 52 min (5 pods)

Between 2.12.8 and 2.12.14 (https://github.com/StackExchange/StackExchange.Redis/compare/2.12.8...2.12.14) the only change to library code other than the high-integrity -MOVED fix (#3049) is #2965.

Suggested fix

A fix needs two parts, and neither one is enough on its own. We tested each separately and then both together:

1. Give multi-message sub-commands the parent's enqueue time. Sub-commands never pass through SetEnqueued. Copying the parent's _writeTickCount means they share its timeout budget, including any time spent in the backlog. Timeouts still apply to queued commands; the parent's own timestamp is not changed, and these messages no longer show a write time of 0. This matters because a transaction's condition command (e.g. HGET) does have a synchronous result box: the transaction's writer blocks on it with Monitor.Wait while it waits for the precondition reply (RedisTransaction.cs#L373-L378). With a write time of 0, that real waiter looks overdue the moment it is written.
2. Count only messages a synchronous caller is actually blocked on as "sync timeouts" (a non-async result box that has not completed). Other prefix commands are written directly with EnqueueInsideWriteLock and are never stamped either. SELECT (sent from the static, cross-connection ReusableChangeDatabaseCommands, PhysicalConnection.cs#L35), READONLY and ASKING (PhysicalBridge.cs#L1606, #L1687, #L1696) are fire-and-forget. So are INFO and PING/ECHO. Async messages whose box was cleared by an earlier timeout (Complete() sets resultBox = null, Message.cs#L579) would otherwise be counted again on every heartbeat. This matches the stated intent of #2965 ("restart the pipe thread with only sync commands") and does not change when any command times out.

--- a/src/StackExchange.Redis/Message.cs
+++ b/src/StackExchange.Redis/Message.cs
@@ -589,6 +589,9 @@ public void Complete(PhysicalConnection? connection)
 
         internal bool ResultBoxIsAsync => Volatile.Read(ref resultBox)?.IsAsync == true;
 
+        /// <summary>Whether a synchronous caller is still waiting on this message (a non-async result box that has not completed).</summary>
+        internal bool ResultBoxIsSync => Volatile.Read(ref resultBox) is { IsAsync: false };
+
         internal static Message Create(int db, CommandFlags flags, RedisCommand command, in RedisKey key,
             RedisKey[] keys) => keys.Length switch
         {
@@ -891,6 +894,8 @@ internal void SetWriteTime()
 
         public int GetWriteTime() => Volatile.Read(ref _writeTickCount);
 
+        internal void InheritWriteTime(Message parent) => Volatile.Write(ref _writeTickCount, parent.GetWriteTime());
+
         /// <summary>
         /// Gets if this command should be sent over the subscription bridge.
         /// </summary>
--- a/src/StackExchange.Redis/PhysicalBridge.cs
+++ b/src/StackExchange.Redis/PhysicalBridge.cs
@@ -847,6 +847,9 @@ private WriteResult WriteMessageInsideLock(PhysicalConnection physical, Message
                 SelectDatabaseInsideWriteLock(physical, message); // need to switch database *before* the transaction
                 foreach (var subCommand in multiMessage.GetMessages(physical))
                 {
+                    // sub-commands never pass through SetEnqueued; give them the parent's enqueue time so they
+                    // share its timeout budget (including any backlog wait) instead of a zero write time
+                    if (subCommand != message) subCommand.InheritWriteTime(message);
                     result = WriteMessageToServerInsideWriteLock(physical, subCommand);
                     if (result != WriteResult.Success)
                     {
--- a/src/StackExchange.Redis/PhysicalConnection.cs
+++ b/src/StackExchange.Redis/PhysicalConnection.cs
@@ -1036,8 +1036,11 @@ internal void OnBridgeHeartbeat(out int asyncTimeoutDetected, out int syncTimeou
                             else
                             {
                                 // Only count how many sync timeouts we detect here (do not poke them;
-                                // the actual timeout is handled in ConnectionMultiplexer.ExecuteSyncImpl)
-                                syncTimeoutDetected++;
+                                // the actual timeout is handled in ConnectionMultiplexer.ExecuteSyncImpl).
+                                // Only messages a synchronous caller is blocked on count: fire-and-forget and internal
+                                // prefix commands (SELECT, READONLY, ASKING), box-less sub-commands (WATCH, MULTI, ...) and
+                                // async messages whose box was already completed by a timeout have no waiting caller.
+                                if (msg.ResultBoxIsSync) syncTimeoutDetected++;
 
                                 if (msg.IsHandshakeCompletion)
                                 {

We validated the patch with the two latency-only setups from the repro section (64 ms reply delay, server never stalled):

Build	Forced heartbeat (repro above)	Natural rate (30 pooled connections, 150 s)
3.4.5	fail (3/3)	23 of 347 transactions failed (6.6%)
3.4.5 + part 1 only	commit (3/3)¹	21 of 346 failed (6.1%): teardown counts a SELECT with write time 0
3.4.5 + part 2 only	fail (3/3): 1 timeouts, the condition HGET	17 of 348 failed (4.9%): teardown counts the condition HGET (synchronous waiter, write time 0)
3.4.5 + both	commit (3/3)	348 of 348 committed, 0 dead sockets
2.12.8	commit (3/3)	348 of 348 committed

¹ Part 1 alone passes the single-transaction repro, but in the natural-rate run some transactions were preceded by a SELECT that has no write time either (the queue snapshots at those teardowns show it at the head), and that still caused teardowns. That is why both parts are needed.

The patch keeps what #2965 is for. When a connection really is dead (the server stops replying entirely while a synchronous GET is blocked on it), the patched client still logs Dead socket detected … 1 timeouts and drops the connection, the same as 3.4.5. We have not run the library's own test suite against the patch.

It may also be worth measuring silence from the oldest pending write rather than from LastReadSecondsAgo, so that idle time before a write is not counted as server silence.

Questions for maintainers

1. Is counting messages that have no waiting synchronous caller (fire-and-forget, internal prefix commands, multi-message sub-commands) as "sync timeouts" intended in #2965? Or was the intent only to cover callers blocked in ExecuteSyncImpl?
2. Are sub-commands of an IMultiMessage meant to have no write time? If not, should they share the parent's timeout budget (our patch), or be stamped some other way?
3. Would you accept a PR along the lines of the suggested fix? We can add tests based on the repros above.

Related: #3085, #3100, #2965