Skip to content

Commit 2ffb18f

Browse files
HandyS11claude
andauthored
fix(connections): survive transient map-endpoint timeouts (no more permanent connection death) (#63)
* fix(connections): stop a transient request timeout from killing the connection loop A per-request timeout during a connected window surfaces as an OperationCanceledException even when the connection token is NOT cancelled. GetRigPositionsAsync rethrew it unconditionally and RunAsync treats any OCE as a shutdown signal, so a transient slow map endpoint permanently terminated the per-server connection loop with no reconnect (bot connected, dropped ~20s later, then went silent). Confirmed via a live repro trace. Guard the timeout catches with `when (ct.IsCancellationRequested)` in GetRigPositionsAsync, PollMarkersAsync and PollReachabilityAsync so a request timeout degrades that one window instead of tearing down the connection, and add the missing `.WaitAsync` timeout guard to GetClanInfoAsync (the one connect-time probe that could block indefinitely on a dead socket). Regression test: Connect_MonumentsTimeout_DoesNotKillLoop_AndStillReconnects. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * feat(connections): detect server-initiated socket drops with a liveness watchdog The Rust+ library raises no event when the server closes the socket, so a silent drop previously went unnoticed until the next heartbeat (up to HeartbeatInterval, default 60s) — a long window of a dead-but-"connected" socket. Add IsConnected to IRustServerConnection (backed by RustPlusSocket.IsConnected) and a WatchLivenessAsync watchdog that races the heartbeat loop and returns Unreachable as soon as the socket is no longer open, bounded by the new ConnectionOptions.LivenessPollInterval (default 5s). Test: ServerClosesSocket_LivenessWatchdog_DrivesReconnect (heartbeat keeps answering Ok, so only the watchdog can detect the drop). Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * perf(connections): move the heavy map fetch off the critical connect path GetMapDimensions and GetRigPositions (the two full-map downloads) ran on the connect path before the heartbeat/marker loops started, so a slow or degraded map endpoint delayed the whole connection going live — and its stalls were the trigger for the drop that used to kill the loop. Fetch dims + rig positions at the start of PollMarkersAsync instead. The connection now goes live immediately (heartbeat + chat relay), and marker/rig detection activates once the map resolves; a map timeout just disables rig detection for that window (dims -> null, rigs -> empty) without blocking anything. Verified live against a degraded map endpoint: clan probe now lands ~1s after connect (was blocked ~15s behind the map fetch), and the monuments/marker timeouts degrade in the background with the connection staying fully alive. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * style(connections): satisfy member ordering for IsConnected The pre-push formatter relocates the IsConnected member added with the liveness watchdog (property after the constructor / in declared order). No behavior change. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * refactor(connections): apply PR review feedback - WatchLivenessAsync now catches the cancellation OperationCanceledException and returns ReconnectReason.Stopped, so on shutdown the WhenAny winner is a clean reason instead of a faulted task (its doc already advertised Stopped). - Reword the fake's monuments-timeout helpers/test: the rig/monuments fetch runs in the background marker poll now, not on the connect path. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> --------- Co-authored-by: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
1 parent c6ad400 commit 2ffb18f

6 files changed

Lines changed: 186 additions & 17 deletions

File tree

src/RustPlusBot.Features.Connections/ConnectionOptions.cs

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -44,4 +44,11 @@ public sealed class ConnectionOptions
4444

4545
/// <summary>How often to poll managed devices for reachability changes while connected. Default 5m.</summary>
4646
public TimeSpan ReachabilityPollInterval { get; set; } = TimeSpan.FromMinutes(5);
47+
48+
/// <summary>
49+
/// How often the liveness watchdog checks whether the socket is still open while connected. The Rust+
50+
/// library raises no event when the server closes the socket, so this bounds how long a silent drop goes
51+
/// unnoticed (independently of <see cref="HeartbeatInterval"/>). Default 5s.
52+
/// </summary>
53+
public TimeSpan LivenessPollInterval { get; set; } = TimeSpan.FromSeconds(5);
4754
}

src/RustPlusBot.Features.Connections/Listening/IRustServerConnection.cs

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,13 @@ namespace RustPlusBot.Features.Connections.Listening;
55
/// <summary>One live Rust+ socket to a single server, driven by one player credential.</summary>
66
internal interface IRustServerConnection : IAsyncDisposable
77
{
8+
/// <summary>
9+
/// Whether the underlying socket is currently open. Cheap and synchronous: the Rust+ library raises no
10+
/// event when the <em>server</em> closes the socket, so a liveness watchdog polls this to detect a drop
11+
/// promptly instead of waiting for the next (up to a minute apart) heartbeat.
12+
/// </summary>
13+
bool IsConnected { get; }
14+
815
/// <summary>Connects within <paramref name="timeout"/>.</summary>
916
/// <param name="timeout">How long to wait for the connection.</param>
1017
/// <param name="cancellationToken">A cancellation token.</param>

src/RustPlusBot.Features.Connections/Listening/RustPlusSocketSource.cs

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -34,6 +34,8 @@ public IRustServerConnection Create(string ip, int port, ulong steamId, string p
3434
/// <summary>Returned when the player token is unusable; reports the credential as rejected and does nothing else.</summary>
3535
private sealed class RejectedConnection : IRustServerConnection
3636
{
37+
public bool IsConnected => false;
38+
3739
public Task<SocketConnectOutcome> ConnectAsync(TimeSpan timeout, CancellationToken cancellationToken) =>
3840
Task.FromResult(SocketConnectOutcome.AuthRejected);
3941

@@ -170,6 +172,11 @@ public RustPlusServerConnection(string ip,
170172
_rustPlus.OnClanChanged += OnClanChanged;
171173
}
172174

175+
/// <inheritdoc />
176+
// CONFIRMED (2.0.0-beta.5): RustPlusSocket.IsConnected == (_webSocket?.State == WebSocketState.Open),
177+
// so it flips to false as soon as the server closes the socket (the library raises no event for that).
178+
public bool IsConnected => _rustPlus.IsConnected;
179+
173180
public async Task<SocketConnectOutcome> ConnectAsync(TimeSpan timeout, CancellationToken cancellationToken)
174181
{
175182
using var timeoutCts = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken);
@@ -380,7 +387,10 @@ public async Task<ClanProbeResult> GetClanInfoAsync(TimeSpan timeout, Cancellati
380387
{
381388
// CONFIRMED (2.0.0-beta.4): GetClanInfoAsync returns Task<Response<ClanInfo>>, exposing
382389
// IsSuccess, Data, and Error?.Code as the response accessors.
383-
var response = await _rustPlus.GetClanInfoAsync(timeoutCts.Token).ConfigureAwait(false);
390+
// .WaitAsync guards the timeout even if the beta call doesn't internally honor the token
391+
// (matching the other probes): on a dead socket this must never block the connect path.
392+
var response = await _rustPlus.GetClanInfoAsync(timeoutCts.Token)
393+
.WaitAsync(timeoutCts.Token).ConfigureAwait(false);
384394
return ClanMapping.FromResponse(response.IsSuccess, response.Error?.Code, response.Data);
385395
}
386396
catch (OperationCanceledException) when (!cancellationToken.IsCancellationRequested)

src/RustPlusBot.Features.Connections/Supervisor/ConnectionSupervisor.cs

Lines changed: 73 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -558,9 +558,6 @@ void OnTeamMessage(object? sender, TeamChatLine line)
558558
}
559559
#pragma warning restore RCS1163
560560

561-
var dims = await connection.GetMapDimensionsAsync(_options.HeartbeatTimeout, ct).ConfigureAwait(false);
562-
var rigs = await GetRigPositionsAsync(key.Server, connection, ct).ConfigureAwait(false);
563-
564561
#pragma warning disable RCS1163 // Unused 'sender': required by the EventHandler<SmartDeviceTrigger> delegate shape.
565562
void OnSmartDevice(object? sender, SmartDeviceTrigger trigger)
566563
{
@@ -607,21 +604,29 @@ void OnClanChanged(object? sender, ClanProbeResult probe)
607604
await PublishClanStateAsync(key, clanProbe).ConfigureAwait(false);
608605

609606
using var pollCts = CancellationTokenSource.CreateLinkedTokenSource(ct);
610-
var markerPoll = Task.Run(() => PollMarkersAsync(key, connection, dims, rigs, tracker, pollCts.Token),
607+
var markerPoll = Task.Run(() => PollMarkersAsync(key, connection, tracker, pollCts.Token),
611608
CancellationToken.None);
612609
var reachabilityPoll = Task.Run(() => PollReachabilityAsync(key, connection, pollCts.Token),
613610
CancellationToken.None);
611+
// Race the heartbeat against a liveness watchdog: the Rust+ library raises no event when the SERVER
612+
// closes the socket, so without the watchdog a silent drop goes unnoticed until the next heartbeat
613+
// (up to a minute). Whichever signals a reason first wins; the finally cancels and joins the rest.
614+
var heartbeat = RunHeartbeatLoopAsync(key, connection, credentialId, pollCts.Token);
615+
var liveness = WatchLivenessAsync(key, connection, pollCts.Token);
614616
try
615617
{
616-
return await RunHeartbeatLoopAsync(key, connection, credentialId, ct).ConfigureAwait(false);
618+
#pragma warning disable VSTHRD003 // Suppress: heartbeat and liveness are owned by this connected window and joined below.
619+
var winner = await Task.WhenAny(heartbeat, liveness).ConfigureAwait(false);
620+
return await winner.ConfigureAwait(false);
621+
#pragma warning restore VSTHRD003
617622
}
618623
finally
619624
{
620625
await pollCts.CancelAsync().ConfigureAwait(false);
621626
try
622627
{
623-
#pragma warning disable VSTHRD003 // Suppress: markerPoll and reachabilityPoll are owned by this connected window and explicitly joined on exit.
624-
await Task.WhenAll(markerPoll, reachabilityPoll).ConfigureAwait(false);
628+
#pragma warning disable VSTHRD003 // Suppress: all four tasks are owned by this connected window and explicitly joined on exit.
629+
await Task.WhenAll(markerPoll, reachabilityPoll, heartbeat, liveness).ConfigureAwait(false);
625630
#pragma warning restore VSTHRD003
626631
}
627632
catch (OperationCanceledException)
@@ -638,6 +643,42 @@ void OnClanChanged(object? sender, ClanProbeResult probe)
638643
}
639644
}
640645

646+
/// <summary>
647+
/// Polls <see cref="IRustServerConnection.IsConnected"/> while connected and returns
648+
/// <see cref="ReconnectReason.Unreachable"/> as soon as the socket is no longer open. This is the only
649+
/// prompt signal for a server-initiated close, which the Rust+ library does not surface as an event.
650+
/// </summary>
651+
/// <param name="key">The (guild, server) routing key.</param>
652+
/// <param name="connection">The live connection whose liveness is watched.</param>
653+
/// <param name="ct">Cancels when the connected window ends.</param>
654+
/// <returns><see cref="ReconnectReason.Unreachable"/> on a detected drop, else
655+
/// <see cref="ReconnectReason.Stopped"/> when cancelled.</returns>
656+
private async Task<ReconnectReason> WatchLivenessAsync(
657+
(ulong Guild, Guid Server) key,
658+
IRustServerConnection connection,
659+
CancellationToken ct)
660+
{
661+
try
662+
{
663+
while (!ct.IsCancellationRequested)
664+
{
665+
await Task.Delay(_options.LivenessPollInterval, ct).ConfigureAwait(false);
666+
if (!connection.IsConnected)
667+
{
668+
LogSocketDropped(logger, key.Server);
669+
return ReconnectReason.Unreachable;
670+
}
671+
}
672+
}
673+
catch (OperationCanceledException)
674+
{
675+
// The connected window is ending (stop/reconnect): Task.Delay throws on cancellation.
676+
// Return Stopped so the WhenAny winner is a clean reason rather than a faulted task.
677+
}
678+
679+
return ReconnectReason.Stopped;
680+
}
681+
641682
private async Task<ReconnectReason> RunHeartbeatLoopAsync(
642683
(ulong Guild, Guid Server) key,
643684
IRustServerConnection connection,
@@ -667,11 +708,17 @@ await PublishStatusAsync(key, ConnectionStatus.Connected, beat.PlayerCount, cred
667708
private async Task PollMarkersAsync(
668709
(ulong Guild, Guid Server) key,
669710
IRustServerConnection connection,
670-
MapDimensions? dims,
671-
IReadOnlyList<RigPosition> rigs,
672711
TeamStateTracker tracker,
673712
CancellationToken ct)
674713
{
714+
// Fetch map dimensions and oil-rig positions here, off the critical connect path: these are the two
715+
// heavy full-map downloads, and on a degraded map endpoint they can stall for seconds. Doing them in
716+
// this background poll means a slow map no longer delays the connection going live (heartbeat + chat
717+
// relay start immediately); marker/rig detection simply activates once these resolve. Both degrade
718+
// safely on timeout (dims -> null, rigs -> empty) without ending the poll.
719+
var dims = await connection.GetMapDimensionsAsync(_options.HeartbeatTimeout, ct).ConfigureAwait(false);
720+
var rigs = await GetRigPositionsAsync(key.Server, connection, ct).ConfigureAwait(false);
721+
675722
IReadOnlyList<MapMarkerSnapshot>? previous = null;
676723
var rigsInRadius = new HashSet<RigKind>();
677724
while (!ct.IsCancellationRequested)
@@ -703,14 +750,16 @@ await eventBus.PublishAsync(
703750
.ConfigureAwait(false);
704751
}
705752
}
706-
catch (OperationCanceledException)
753+
catch (OperationCanceledException) when (ct.IsCancellationRequested)
707754
{
708755
return; // stopping
709756
}
710-
#pragma warning disable CA1031 // Broad catch: a failed poll is logged and skipped; the previous snapshot is retained.
757+
#pragma warning disable CA1031 // Broad catch: a failed poll (incl. a per-request timeout) is logged and skipped; the previous snapshot is retained.
711758
catch (Exception ex)
712759
#pragma warning restore CA1031
713760
{
761+
// A per-request timeout (OperationCanceledException with ct NOT cancelled) must NOT end the
762+
// poll loop — that would silently stop marker/rig/AFK detection for the rest of the connection.
714763
LogMarkerPollFailed(logger, ex, key.Server);
715764
}
716765

@@ -767,14 +816,16 @@ private async Task PollReachabilityAsync(
767816
{
768817
current = await ReadAllReachabilityAsync(key, connection, ct).ConfigureAwait(false);
769818
}
770-
catch (OperationCanceledException)
819+
catch (OperationCanceledException) when (ct.IsCancellationRequested)
771820
{
772821
throw;
773822
}
774-
#pragma warning disable CA1031 // Broad catch: a failed reachability sweep is logged and retried next cycle.
823+
#pragma warning disable CA1031 // Broad catch: a failed reachability sweep (incl. a per-request timeout) is logged and retried next cycle.
775824
catch (Exception ex)
776825
#pragma warning restore CA1031
777826
{
827+
// A per-request timeout (OperationCanceledException with ct NOT cancelled) must be retried next
828+
// cycle, not rethrown — rethrowing would tear the sweep down for the rest of the connection.
778829
LogReachabilityPollFailed(logger, ex, key.Server);
779830
continue;
780831
}
@@ -942,14 +993,17 @@ private async Task<IReadOnlyList<RigPosition>> GetRigPositionsAsync(
942993

943994
return rigs;
944995
}
945-
catch (OperationCanceledException)
996+
catch (OperationCanceledException) when (ct.IsCancellationRequested)
946997
{
998+
// Real shutdown/reconnect of THIS connection: propagate so the loop tears down.
947999
throw;
9481000
}
949-
#pragma warning disable CA1031 // Broad catch: a monuments-fetch failure just disables rig detection this window.
1001+
#pragma warning disable CA1031 // Broad catch: a monuments-fetch failure (incl. a per-request timeout) just disables rig detection this window.
9501002
catch (Exception ex)
9511003
#pragma warning restore CA1031
9521004
{
1005+
// A per-request timeout surfaces as OperationCanceledException with ct NOT cancelled; it must
1006+
// degrade rig detection for this window, never terminate the connection loop.
9531007
LogMonumentsFetchFailed(logger, ex, serverId); // rig detection degrades gracefully for this window
9541008
return [];
9551009
}
@@ -1435,6 +1489,10 @@ await eventBus.PublishAsync(
14351489
[LoggerMessage(Level = LogLevel.Warning, Message = "Reachability poll for server {ServerId} failed.")]
14361490
private static partial void LogReachabilityPollFailed(ILogger logger, Exception exception, Guid serverId);
14371491

1492+
[LoggerMessage(Level = LogLevel.Information,
1493+
Message = "Socket for server {ServerId} closed by the server; reconnecting.")]
1494+
private static partial void LogSocketDropped(ILogger logger, Guid serverId);
1495+
14381496
[LoggerMessage(Level = LogLevel.Warning,
14391497
Message =
14401498
"Fetching monuments for oil-rig detection on server {ServerId} failed; rig detection disabled for this connection.")]

tests/RustPlusBot.Features.Connections.Tests/ConnectionSupervisorTests.cs

Lines changed: 63 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -67,6 +67,7 @@ private static Harness CreateHarness(FakeRustSocketSource source)
6767
HeartbeatTimeout = TimeSpan.FromMilliseconds(200),
6868
MarkerPollInterval = TimeSpan.FromMilliseconds(20),
6969
MarkerPollFastInterval = TimeSpan.FromMilliseconds(20),
70+
LivenessPollInterval = TimeSpan.FromMilliseconds(20),
7071
}));
7172
services.AddSingleton<ConnectionSecurity>();
7273
services.AddSingleton<ConnectionSupervisor>();
@@ -231,6 +232,68 @@ public async Task Heartbeat_Unreachable_ReconnectsAndRecovers()
231232
Assert.True(source.CreateCount >= 2);
232233
}
233234

235+
/// <summary>
236+
/// A per-request timeout in a connected window (here the marker poll's oil-rig monuments fetch) surfaces
237+
/// as an <see cref="OperationCanceledException"/> even though the connection token is not cancelled. It
238+
/// must degrade rig detection for this window, NOT terminate the whole connection loop — otherwise a
239+
/// transient slow map endpoint permanently kills the connection with no reconnect (the real-world bug).
240+
/// </summary>
241+
[Fact]
242+
public async Task Connect_MonumentsTimeout_DoesNotKillLoop_AndStillReconnects()
243+
{
244+
var source = new FakeRustSocketSource();
245+
source.EnqueueConnect(SocketConnectOutcome.Connected);
246+
source.TimeoutOnMonumentsOnce(); // the marker poll's rig fetch times out on the FIRST connection only
247+
source.EnqueueHeartbeat(HeartbeatResult.Ok(2)); // first heartbeat -> Connected
248+
source.EnqueueHeartbeat(HeartbeatResult.Unreachable); // next heartbeat -> drop
249+
source.EnqueueConnect(SocketConnectOutcome.Connected); // reconnect
250+
source.EnqueueHeartbeat(HeartbeatResult.Ok(4));
251+
await using var h = CreateHarness(source);
252+
var (serverId, _, _) = await SeedAsync(h.Provider);
253+
254+
await h.Supervisor.EnsureConnectionAsync(10UL, serverId);
255+
256+
var recovered = await WaitForStateAsync(
257+
h.Provider, serverId, s => s.Status == ConnectionStatus.Connected && s.PlayerCount == 4);
258+
Assert.NotNull(recovered);
259+
Assert.True(source.CreateCount >= 2);
260+
}
261+
262+
/// <summary>
263+
/// The Rust+ library raises no event when the SERVER closes the socket; only
264+
/// <see cref="IRustServerConnection.IsConnected"/> flips. The liveness watchdog must notice that and
265+
/// drive a reconnect promptly, without waiting for the (up to a minute apart) heartbeat — here the fake's
266+
/// heartbeat keeps reporting Ok, so only the watchdog can detect the drop.
267+
/// </summary>
268+
[Fact]
269+
public async Task ServerClosesSocket_LivenessWatchdog_DrivesReconnect()
270+
{
271+
var source = new FakeRustSocketSource();
272+
source.EnqueueConnect(SocketConnectOutcome.Connected);
273+
source.EnqueueHeartbeat(HeartbeatResult.Ok(2)); // first heartbeat -> Connected; held thereafter
274+
source.EnqueueConnect(SocketConnectOutcome.Connected); // reconnect after the watchdog fires
275+
await using var h = CreateHarness(source);
276+
var (serverId, _, _) = await SeedAsync(h.Provider);
277+
278+
await h.Supervisor.EnsureConnectionAsync(10UL, serverId);
279+
var connected = await WaitForStateAsync(
280+
h.Provider, serverId, s => s.Status == ConnectionStatus.Connected && s.PlayerCount == 2);
281+
Assert.NotNull(connected);
282+
var live = source.LastConnection;
283+
Assert.NotNull(live);
284+
285+
// Simulate a server-initiated close: the socket is no longer open, but the heartbeat still answers Ok.
286+
live.IsConnected = false;
287+
288+
var deadline = DateTimeOffset.UtcNow.AddSeconds(30);
289+
while (source.CreateCount < 2 && DateTimeOffset.UtcNow < deadline)
290+
{
291+
await Task.Delay(15);
292+
}
293+
294+
Assert.True(source.CreateCount >= 2, "the liveness watchdog should have driven a reconnect");
295+
}
296+
234297
/// <summary>
235298
/// WasConnected must be computed from in-process state (the DB status survives restarts and
236299
/// would claim Connected at boot): statuses before the first Connected carry false; the drop

0 commit comments

Comments
 (0)