From 01a868eada55d421f2ea039ad8043066e4ff7228 Mon Sep 17 00:00:00 2001 From: Resurrected Trader Date: Sun, 23 Aug 2026 21:51:26 +0100 Subject: [PATCH] fix: Scope crash-retry budget to launch failures Heartbeat timeouts, hung windows, unexpected exits and any exception escaping RunProfileAsync all fed one lifetime CrashCount, capped at 5 and reset only by a manual start. Time-to-give-up was therefore a function of uptime alone: at a couple of transient faults a day a profile was absorbed after roughly two days and had its schedule disabled, whether or not anything was actually wrong with it. D2Bot# kept these concerns separate. Its budget (Crashed, cap 6) was incremented only from the two LoadRemoteLibrary catch blocks and cleared on every successful load, while the heartbeat and Responding watchdogs restarted unconditionally and forever, and no failure path ever touched ScheduleEnable. - Split CrashCount into LaunchFailureCount (the budget, cleared by any successful launch) and RuntimeRestartCount (drives backoff, never fatal). - Back runtime restarts off from 5s to a 5min ceiling instead of a flat 5s delay and a hard cap. Reset only after a run stays up 60s and reports in, so a crash-looping bot cannot zero its own backoff. - Stop writing ScheduleEnabled = false on exhaustion; leave schedule recovery to ScheduleEngine, and the stopSchedule message as the way a script opts out. - Record heartbeat liveness on the message pump rather than at dispatch, so a backed-up queue no longer reads as a dead bot. kolbot's heartbeat thread sends mode 0xBBBB at 1Hz, so heartbeats no longer enter the shared queue at all. - Store the registered game window handle on the instance. Removals keyed on a live Process.GameWindow re-read no-opped once the process had exited, leaking a routing entry per launch and letting the handoff snapshot hand a successor a dead handle. Warn on unrouted messages instead of dropping them into Debug. - Run restart/stop off the message loop, and drop the hung-window probe from 1Hz to 5s using the cached handle instead of an EnumWindows sweep per second. Co-Authored-By: Claude Opus 5 (1M context) --- src/D2BotNG/Engine/Handoff/HandoffManifest.cs | 5 +- src/D2BotNG/Engine/ProfileEngine.cs | 339 +++++++++++++----- src/D2BotNG/Engine/ProfileInstance.cs | 49 ++- src/D2BotNG/Services/D2BSMessageHandler.cs | 55 ++- src/D2BotNG/Windows/MessageWindow.cs | 46 ++- 5 files changed, 390 insertions(+), 104 deletions(-) diff --git a/src/D2BotNG/Engine/Handoff/HandoffManifest.cs b/src/D2BotNG/Engine/Handoff/HandoffManifest.cs index 5bc74db..1448369 100644 --- a/src/D2BotNG/Engine/Handoff/HandoffManifest.cs +++ b/src/D2BotNG/Engine/Handoff/HandoffManifest.cs @@ -43,7 +43,10 @@ public class HandoffProfile [JsonPropertyName("proxyName")] public string? ProxyName { get; set; } - [JsonPropertyName("crashCount")] public int CrashCount { get; set; } + // Renamed from "crashCount" when the retry budget was scoped to launch failures. A manifest + // written by an older predecessor simply won't bind this, leaving 0 — a fresh budget, which + // is the permissive direction. + [JsonPropertyName("launchFailureCount")] public int LaunchFailureCount { get; set; } [JsonPropertyName("startedAt")] public DateTime? StartedAt { get; set; } diff --git a/src/D2BotNG/Engine/ProfileEngine.cs b/src/D2BotNG/Engine/ProfileEngine.cs index 6522fe3..651be40 100644 --- a/src/D2BotNG/Engine/ProfileEngine.cs +++ b/src/D2BotNG/Engine/ProfileEngine.cs @@ -111,6 +111,53 @@ public async Task InitializeAsync() return null; } + /// + /// Registers the game window a profile's D2BS will send WM_COPYDATA from, and remembers it + /// on the instance so every later removal keys off the value we actually registered. + /// + private void RegisterHandle(ProfileInstance instance, nint handle) + { + if (handle == 0) return; + + if (_handleToProfile.TryGetValue(handle, out var existing) && existing != instance.ProfileName) + { + // USER handle values are recycled. If this ever fires, messages for one of the two + // profiles were about to be routed to the other — which presents as a perfectly + // healthy bot that never heartbeats. + _logger.LogError( + "Window handle {Handle} was still mapped to profile {Existing} while registering {New} — " + + "stale routing entry; messages for one of them may have been misrouted", + handle, existing, instance.ProfileName); + } + + instance.GameWindowHandle = handle; + _handleToProfile[handle] = instance.ProfileName; + } + + /// + /// Removes every routing entry for a profile. Uses the stored handle rather than re-reading + /// Process.GameWindow: that enumerates windows owned by the pid, so once the process + /// has exited it returns 0 and the removal silently no-ops, leaking the entry for the life + /// of the manager. The sweep by name is belt-and-braces for an entry registered under a + /// different handle (e.g. restored from a handoff manifest recording a drifted top-level). + /// + private void UnregisterHandles(ProfileInstance instance) + { + if (instance.GameWindowHandle != 0) + { + _handleToProfile.TryRemove(instance.GameWindowHandle, out _); + _messageWindow.ForgetHandle(instance.GameWindowHandle); + instance.GameWindowHandle = 0; + } + + foreach (var kvp in _handleToProfile) + { + if (kvp.Value != instance.ProfileName) continue; + _handleToProfile.TryRemove(kvp.Key, out _); + _messageWindow.ForgetHandle(kvp.Key); + } + } + public void BroadcastToAll(MessageType messageType, string message) { foreach (var instance in _instances.Values) @@ -159,7 +206,8 @@ public async Task StartProfileAsync(string profileName, [System.Runtime.Co _logger.LogDebug("Starting profile {Name} (caller: {Caller})", profileName, caller); - instance.CrashCount = 0; + instance.LaunchFailureCount = 0; + instance.RuntimeRestartCount = 0; await NotifyProfileStateChangedAsync(profileName); _ = RunProfileBackgroundAsync(instance); @@ -190,7 +238,7 @@ public async Task StopProfileAsync(string profileName, bool force = false, instance.CancelRun(); // Unregister handle before terminating - _handleToProfile.TryRemove(instance.Process?.GameWindow ?? 0, out _); + UnregisterHandles(instance); if (instance.Process != null) { @@ -584,6 +632,10 @@ private async Task RunProfileAsync(ProfileInstance instance) instance.MissedHeartbeats = 0; await NotifyProfileStateChangedAsync(profileName); + // Set by the launch step below so the catch-all can tell a game that never started from + // one that started and later failed. Only the former consumes the retry budget. + var launchFailed = false; + try { var profile = await _profileRepository.GetByKeyAsync(profileName); @@ -705,15 +757,34 @@ await instance.SetErrorAsync(string.IsNullOrEmpty(profile.Framework) Environment = environment }; - // Launch game - var gameProcess = await _gameLauncher.LaunchAsync(config, cancellationToken); + // Launch game. Only a failure to get the game up consumes the retry budget — see + // HandleCrashAsync. Anything that goes wrong after this point is a runtime fault and + // is retried indefinitely with backoff instead. + Process gameProcess; + try + { + gameProcess = await _gameLauncher.LaunchAsync(config, cancellationToken); + } + catch (OperationCanceledException) + { + throw; + } + catch + { + launchFailed = true; + throw; + } + instance.SetGameProcess(gameProcess); // Register handle for message routing - if (gameProcess.GameWindow != 0) - { - _handleToProfile[gameProcess.GameWindow] = profileName; - } + RegisterHandle(instance, gameProcess.GameWindow); + + // The game is up, so the budget is spent on nothing: clear it. This is what makes + // the counter mean "consecutive failures to start" rather than "things that have + // ever gone wrong", and it is why a long-running fleet can no longer ratchet itself + // into a permanent stop one incident at a time. + instance.LaunchFailureCount = 0; if (!await instance.TransitionToAsync(RunState.Running)) { @@ -734,14 +805,13 @@ await instance.SetErrorAsync(string.IsNullOrEmpty(profile.Framework) _logger.LogError(ex, "Error running profile {Name}", profileName); // Clean up handle mapping - if (instance.Process?.GameWindow is > 0 and var handle) - _handleToProfile.TryRemove(handle, out _); + UnregisterHandles(instance); await instance.SetErrorAsync(ex.Message); await NotifyProfileStateChangedAsync(profileName); // Handle crash recovery - await HandleCrashAsync(instance, cancellationToken); + await HandleCrashAsync(instance, cancellationToken, launchFailed); } } @@ -810,6 +880,11 @@ private async Task MonitorProcessAsync(ProfileInstance instance, CancellationTok process.SendMessage((MessageType)_messageWindow.Handle, "Handle"); var lastHeartbeatCheck = DateTime.UtcNow; + var lastHungCheck = DateTime.UtcNow; + // The hung-window probe blocks for up to a second on a wedged window, on a thread-pool + // thread. It feeds a timeout measured in tens of seconds, so 1Hz precision buys nothing + // and costs a pinned thread per unhealthy profile. + const int hungCheckIntervalSeconds = 5; // Retry handle delivery for ~10s (loop cadence is 1s) even when heartbeats are // disabled, then stop so a no-heartbeat framework doesn't ping forever. const int maxHandleResends = 10; @@ -822,7 +897,7 @@ private async Task MonitorProcessAsync(ProfileInstance instance, CancellationTok _logger.LogDebug("Profile {Name} process exited with code {Code}", instance.ProfileName, process.ExitCode); - _handleToProfile.TryRemove(process.GameWindow, out _); + UnregisterHandles(instance); if (instance.State == RunState.Running) { @@ -846,8 +921,30 @@ private async Task MonitorProcessAsync(ProfileInstance instance, CancellationTok handleResends++; } - // Check heartbeat every ~10 seconds var now = DateTime.UtcNow; + + // Pull liveness from the message pump rather than waiting for the dispatch queue to + // deliver it. The timestamp is when the heartbeat was *received*; stamping it at + // dispatch made a backed-up queue indistinguishable from a dead bot, and under the + // old shared counter that mistake was then recorded as a crash. + if (instance.GameWindowHandle != 0 + && _messageWindow.TryGetLastHeartbeat(instance.GameWindowHandle, out var seenAt) + && seenAt > (instance.LastHeartbeat ?? DateTime.MinValue)) + { + instance.UpdateHeartbeat(seenAt); + + // A run that has been up a while and is reporting in has earned a clean slate. + // Gated on uptime so a bot that crash-loops while emitting the odd heartbeat + // can't keep resetting its own backoff. + if (instance.RuntimeRestartCount > 0 + && instance.StartedAt.HasValue + && (now - instance.StartedAt.Value).TotalSeconds >= 60) + { + instance.RuntimeRestartCount = 0; + } + } + + // Check heartbeat every ~10 seconds if ((now - lastHeartbeatCheck).TotalSeconds >= 10) { lastHeartbeatCheck = now; @@ -895,20 +992,28 @@ await KillUnresponsiveAndRecoverAsync( // (OS-level "not responding") continuously past the timeout, the bot is hung // even though kolbot's background heartbeat thread may still be ticking. // Mirrors the reference manager's Process.Responding watchdog. - var hwnd = process.GameWindow; - if (unresponsiveTimeout > 0 && hwnd != 0 && IsGameWindowHung(hwnd)) + // Use the handle captured at launch rather than re-deriving it: Process.GameWindow + // is an EnumWindows sweep of every top-level window in the session, and it cannot + // change for a running game. + var hwnd = instance.GameWindowHandle; + if (unresponsiveTimeout > 0 && hwnd != 0 + && (now - lastHungCheck).TotalSeconds >= hungCheckIntervalSeconds) { - instance.UnresponsiveSince ??= now; - if ((now - instance.UnresponsiveSince.Value).TotalSeconds >= unresponsiveTimeout) + lastHungCheck = now; + if (IsGameWindowHung(hwnd)) { - await KillUnresponsiveAndRecoverAsync( - instance, process, "Game window not responding", cancellationToken); - return; + instance.UnresponsiveSince ??= now; + if ((now - instance.UnresponsiveSince.Value).TotalSeconds >= unresponsiveTimeout) + { + await KillUnresponsiveAndRecoverAsync( + instance, process, "Game window not responding", cancellationToken); + return; + } + } + else + { + instance.UnresponsiveSince = null; } - } - else - { - instance.UnresponsiveSince = null; } await Task.Delay(1000, cancellationToken); @@ -938,7 +1043,7 @@ private async Task KillUnresponsiveAndRecoverAsync( ProfileInstance instance, Process process, string reason, CancellationToken cancellationToken) { _logger.LogWarning("Profile {Name} {Reason}, treating as crash", instance.ProfileName, reason); - _handleToProfile.TryRemove(process.GameWindow, out _); + UnregisterHandles(instance); // Kill the unresponsive process. Pass the cancellation token so that if the user // clicks Stop while we're waiting out the WM_CLOSE grace period, the wait aborts @@ -953,10 +1058,28 @@ private async Task KillUnresponsiveAndRecoverAsync( await HandleCrashAsync(instance, cancellationToken); } - private async Task HandleCrashAsync(ProfileInstance instance, CancellationToken cancellationToken) + /// + /// Restarts a profile after a failure. + /// + /// The failed profile's runtime state. + /// Cancelled when the user stops the profile mid-backoff. + /// + /// True when the game never came up (launch or DLL injection threw). Only these consume the + /// retry budget, and only consecutively — a successful launch clears the count. A runtime + /// fault (heartbeat timeout, hung window, unexpected exit) is always retried, with backoff. + /// + /// This mirrors D2Bot#, where the budget (Crashed, cap 6) was incremented only from + /// the two LoadRemoteLibrary catch blocks and cleared on every successful load, while the + /// heartbeat and Responding watchdogs restarted unconditionally and forever. D2BotNG had + /// collapsed both into one lifetime counter, which made time-to-give-up a function of + /// uptime alone: at a couple of transient faults a day, a profile was absorbed in ~2 days + /// regardless of whether anything was actually wrong with it. + /// + /// + private async Task HandleCrashAsync( + ProfileInstance instance, CancellationToken cancellationToken, bool launchFailure = false) { var profileName = instance.ProfileName; - instance.CrashCount++; var profile = await _profileRepository.GetByKeyAsync(profileName); if (profile != null) @@ -970,60 +1093,107 @@ private async Task HandleCrashAsync(ProfileInstance instance, CancellationToken ? (await ResolveFrameworkAsync(profile))?.MaxCrashRetriesOrDefault() ?? 5 : 5; - if (instance.CrashCount < maxCrashRetries) + TimeSpan delay; + if (launchFailure) { - _logger.LogWarning("Profile {Name} crashed, restarting ({Count}/{Max})", - profileName, instance.CrashCount, maxCrashRetries); - - try - { - await Task.Delay(TimeSpan.FromSeconds(5), cancellationToken); - } - catch (OperationCanceledException) - { - _logger.LogDebug("Profile {Name} crash delay interrupted by stop request", profileName); - return; - } - - // If state changed during delay (e.g. user stopped), don't restart - if (instance.State != RunState.Error) + instance.LaunchFailureCount++; + if (instance.LaunchFailureCount >= maxCrashRetries) { - _logger.LogDebug("Profile {Name} state changed to {State} during crash delay, not restarting", - profileName, instance.State); + await GiveUpAfterLaunchFailuresAsync(instance, maxCrashRetries); return; } - if (await instance.TransitionToAsync(RunState.Starting)) - { - await NotifyProfileStateChangedAsync(profileName); - _ = RunProfileBackgroundAsync(instance); - } + _logger.LogWarning("Profile {Name} failed to launch, retrying ({Count}/{Max})", + profileName, instance.LaunchFailureCount, maxCrashRetries); + delay = TimeSpan.FromSeconds(5); } else { - _logger.LogError("Profile {Name} exceeded max crash retries", profileName); + // Runtime faults are never fatal. Back off instead so a profile that comes up but + // can never report in (bad DLL, broken entry script, wrong game version) stops + // burning keys and shared message-loop time, without ever becoming permanently dead + // the way a hard cap made it. + instance.RuntimeRestartCount++; + delay = RuntimeRestartDelay(instance.RuntimeRestartCount); + _logger.LogWarning("Profile {Name} crashed, restarting in {Delay} (attempt {Count})", + profileName, delay, instance.RuntimeRestartCount); + instance.Status = delay > TimeSpan.FromSeconds(15) + ? $"Restarting in {FormatDelay(delay)}..." + : "Restarting..."; + await NotifyProfileStateChangedAsync(profileName); + } - // Disable schedule to prevent ScheduleEngine from restarting - if (profile is { ScheduleEnabled: true }) - { - profile.ScheduleEnabled = false; - await _profileRepository.UpdateAsync(profile); - _logger.LogWarning("Disabled schedule for profile {Name} due to repeated crashes", profileName); - } + try + { + await Task.Delay(delay, cancellationToken); + } + catch (OperationCanceledException) + { + _logger.LogDebug("Profile {Name} crash delay interrupted by stop request", profileName); + return; + } - // Set error status before transitioning to Stopped so the message is preserved. - // Do NOT use SetErrorAsync here — it would set state to Error, allowing restarts. - instance.Status = $"Exceeded max crash retries ({maxCrashRetries})"; - instance.KeyName = null; - instance.ProxyName = null; - await instance.TransitionToAsync(RunState.Stopped); - await NotifyProfileStateChangedAsync(profileName, includeProfile: true); - await BroadcastKeyListsSnapshotAsync(); - await BroadcastProxiesSnapshotAsync(); - await BroadcastFrameworksSnapshotAsync(); + // If state changed during delay (e.g. user stopped), don't restart + if (instance.State != RunState.Error) + { + _logger.LogDebug("Profile {Name} state changed to {State} during crash delay, not restarting", + profileName, instance.State); + return; + } + + if (await instance.TransitionToAsync(RunState.Starting)) + { + await NotifyProfileStateChangedAsync(profileName); + _ = RunProfileBackgroundAsync(instance); } } + /// + /// Stops a profile that has failed to launch maxCrashRetries times in a row. + /// + /// + /// Deliberately does NOT touch ScheduleEnabled. That wrote persisted user + /// configuration as a side effect of a fault the manager cannot diagnose — it sees "N things + /// went wrong" without knowing whether that is a dead DLL, a realm-down, or its own message + /// loop running behind — and it turned a transient failure into one that survived restart + /// and needed per-profile manual repair. D2Bot# set ScheduleEnable = false from + /// exactly four places, all deliberate (the script's stopSchedule message, the context menu, + /// the IRC command, the profile editor), and left an exhausted profile for the scheduler to + /// recover on its next tick. The stopSchedule handler remains the supported way for a + /// script — which does know why it is failing — to opt out. + /// + private async Task GiveUpAfterLaunchFailuresAsync(ProfileInstance instance, int maxCrashRetries) + { + _logger.LogError("Profile {Name} failed to launch {Count} times in a row, giving up until restarted", + instance.ProfileName, maxCrashRetries); + + // Set error status before transitioning to Stopped so the message is preserved. + // Do NOT use SetErrorAsync here — it would set state to Error, allowing restarts. + instance.Status = $"Failed to launch {maxCrashRetries} times in a row"; + instance.KeyName = null; + instance.ProxyName = null; + await instance.TransitionToAsync(RunState.Stopped); + await NotifyProfileStateChangedAsync(instance.ProfileName, includeProfile: true); + await BroadcastKeyListsSnapshotAsync(); + await BroadcastProxiesSnapshotAsync(); + await BroadcastFrameworksSnapshotAsync(); + } + + /// + /// Backoff for repeated runtime failures: 5s doubling to a 5 minute ceiling. + /// + private static TimeSpan RuntimeRestartDelay(int consecutiveRestarts) + { + const int baseSeconds = 5; + const int capSeconds = 300; + // Shift is clamped before it can overflow the exponent. + var exponent = Math.Min(Math.Max(consecutiveRestarts - 1, 0), 8); + return TimeSpan.FromSeconds(Math.Min(baseSeconds << exponent, capSeconds)); + } + + private static string FormatDelay(TimeSpan delay) => + delay.TotalMinutes >= 1 ? $"{(int)delay.TotalMinutes}m" : $"{(int)delay.TotalSeconds}s"; + public void AddProfile(string profileName) { _instances.TryAdd(profileName, new ProfileInstance(profileName)); @@ -1080,12 +1250,13 @@ public List SnapshotInstances() continue; } - // Reverse-lookup the routing-map entry for this profile so the successor can - // restore it verbatim (Process.MainWindowHandle can drift to a different - // top-level window than the one D2BS sends from). - var registeredHandle = _handleToProfile - .FirstOrDefault(kvp => kvp.Value == instance.ProfileName) - .Key.ToInt64(); + // The handle registered at launch, so the successor can restore it verbatim + // (Process.MainWindowHandle can drift to a different top-level window than the one + // D2BS sends from). Read from the instance rather than reverse-looked-up out of the + // routing map: with more than one row per profile that lookup returned an arbitrary + // one, so a stale entry could hand the successor a dead handle and silently drop + // every message from that profile after an update. + var registeredHandle = instance.GameWindowHandle.ToInt64(); result.Add(new HandoffProfile { @@ -1095,7 +1266,7 @@ public List SnapshotInstances() Status = instance.Status, KeyName = instance.KeyName, ProxyName = instance.ProxyName, - CrashCount = instance.CrashCount, + LaunchFailureCount = instance.LaunchFailureCount, StartedAt = instance.StartedAt, Handle = registeredHandle // MissedHeartbeats and LastHeartbeat intentionally not carried over — @@ -1167,10 +1338,11 @@ public async Task RehydrateAsync(IEnumerable profiles) snapshot.Status, snapshot.KeyName, snapshot.ProxyName, - snapshot.CrashCount, + snapshot.LaunchFailureCount, missedHeartbeats: 0, snapshot.StartedAt, - lastHeartbeat: DateTime.UtcNow); + lastHeartbeat: DateTime.UtcNow, + gameWindowHandle: snapshot.Handle != 0 ? (nint)snapshot.Handle : process.GameWindow); _logger.LogInformation("Adopted profile {Name} (PID {Pid}, state {State})", snapshot.ProfileName, snapshot.Pid, snapshot.State); @@ -1178,16 +1350,9 @@ public async Task RehydrateAsync(IEnumerable profiles) // Restore the predecessor's routing entry verbatim. The HWND D2BS sends // from is whatever was registered before — may differ from what we'd read // now if Process.MainWindowHandle has drifted to a different top-level. - if (snapshot.Handle != 0) - { - _handleToProfile[(nint)snapshot.Handle] = snapshot.ProfileName; - } - else if (process.GameWindow != 0) - { - // Predecessor had no entry for this profile (e.g. registration raced with - // launch); fall back to the game window we can see now. - _handleToProfile[process.GameWindow] = snapshot.ProfileName; - } + // RestoreFromHandoff already resolved this (manifest handle, else the window we can + // see now for a predecessor whose registration raced with launch). + RegisterHandle(instance, instance.GameWindowHandle); // Proactively push the new manager HWND to the running D2BS script so it // redirects future WM_COPYDATA messages to this process's MessageWindow. diff --git a/src/D2BotNG/Engine/ProfileInstance.cs b/src/D2BotNG/Engine/ProfileInstance.cs index 1a3b93b..6a460b2 100644 --- a/src/D2BotNG/Engine/ProfileInstance.cs +++ b/src/D2BotNG/Engine/ProfileInstance.cs @@ -17,9 +17,32 @@ public class ProfileInstance : IDisposable public string Status { get; set; } = ""; public DateTime? StartedAt { get; private set; } public DateTime? LastHeartbeat { get; private set; } - public int CrashCount { get; set; } + + /// + /// Consecutive failures to get the game up (launch or DLL injection). This is the only + /// counter that feeds the retry budget, and any successful launch zeroes it — a runtime + /// fault never consumes it. Mirrors D2Bot#'s Crashed, which was incremented only + /// from the two LoadRemoteLibrary catch blocks and cleared on every successful load. + /// + public int LaunchFailureCount { get; set; } + + /// + /// Consecutive restarts caused by a runtime fault (heartbeat timeout, hung window, + /// unexpected exit). Drives restart backoff only — never a budget, so a failing bot keeps + /// being retried, just progressively more slowly. + /// + public int RuntimeRestartCount { get; set; } + public int MissedHeartbeats { get; set; } + /// + /// The game window handle registered for WM_COPYDATA routing, captured once at launch. + /// Deliberately stored rather than re-derived: Extensions.GameWindow enumerates the + /// windows owned by the pid, so a process that has already exited yields 0 — and every + /// removal keyed on a live re-read silently leaks its routing entry instead. + /// + public nint GameWindowHandle { get; set; } + /// When the game window first became continuously unresponsive; null while responsive. public DateTime? UnresponsiveSince { get; set; } @@ -63,13 +86,19 @@ public void SetGameProcess(Process process) UnresponsiveSince = null; } - public void UpdateHeartbeat() + /// + /// Records a heartbeat. is when the message was *received* on the + /// message pump, not when it was dispatched — see . Passing the + /// receive time is what keeps a backed-up dispatch queue from looking like a dead bot. + /// + public void UpdateHeartbeat(DateTime? at = null) { - LastHeartbeat = DateTime.UtcNow; + LastHeartbeat = at ?? DateTime.UtcNow; MissedHeartbeats = 0; - // CrashCount is deliberately NOT reset here: a crash-looping bot that emits even one - // heartbeat between failures would otherwise zero its budget and never reach - // MaxCrashRetries. It is reset only on a manual start (ProfileEngine.StartProfileAsync). + // Neither retry counter is reset here. LaunchFailureCount is cleared by a successful + // launch; RuntimeRestartCount only by a run that stays up long enough to count as + // healthy (see ProfileEngine.MonitorProcessAsync) — a bot that emits a single heartbeat + // between failures must not be able to zero its own backoff. } /// @@ -82,10 +111,11 @@ public void RestoreFromHandoff( string status, string? keyName, string? proxyName, - int crashCount, + int launchFailureCount, int missedHeartbeats, DateTime? startedAt, - DateTime? lastHeartbeat) + DateTime? lastHeartbeat, + nint gameWindowHandle) { Process?.Dispose(); Process = process; @@ -93,7 +123,8 @@ public void RestoreFromHandoff( Status = status; KeyName = keyName; ProxyName = proxyName; - CrashCount = crashCount; + LaunchFailureCount = launchFailureCount; + GameWindowHandle = gameWindowHandle; MissedHeartbeats = missedHeartbeats; StartedAt = startedAt; LastHeartbeat = lastHeartbeat; diff --git a/src/D2BotNG/Services/D2BSMessageHandler.cs b/src/D2BotNG/Services/D2BSMessageHandler.cs index 00c7ec6..9b42d49 100644 --- a/src/D2BotNG/Services/D2BSMessageHandler.cs +++ b/src/D2BotNG/Services/D2BSMessageHandler.cs @@ -1,3 +1,4 @@ +using System.Collections.Concurrent; using System.Text.Json; using System.Text.Json.Nodes; using D2BotNG.Core.Protos; @@ -31,6 +32,11 @@ public class D2BSMessageHandler : BackgroundService private readonly SettingsRepository _settingsRepository; private readonly CharacterStateService _characterStateService; + /// + /// Handles we've already warned about, so a 1Hz sender doesn't flood the log. + /// + private readonly ConcurrentDictionary _unroutedHandles = new(); + public D2BSMessageHandler( ILogger logger, MessageWindow messageWindow, @@ -89,7 +95,22 @@ private async Task HandleMessageAsync(D2BSMessage msg) _logger.LogDebug("D2BS command: {Command} from {Profile}", msg.Message, profile?.Name ?? "unknown"); if (profile == null) + { + // A message we cannot attribute is a message we throw away — including a heartbeat, + // which then reads as a dead bot. This used to vanish into the Debug log above with + // no counter, so a leaked or misrouted entry in the engine's handle map was + // invisible. Warn once per handle rather than per message: a bot sends ~1Hz. + if (_unroutedHandles.TryAdd(msg.SenderHandle, 0)) + { + _logger.LogWarning( + "Discarding D2BS message from unknown window handle {Handle} ({Function}) — " + + "no running profile is registered for it", + msg.SenderHandle, msg.Message.Function ?? "?"); + } return; + } + + _unroutedHandles.TryRemove(msg.SenderHandle, out _); var args = msg.Message.Arguments; @@ -154,11 +175,11 @@ private async Task HandleMessageAsync(D2BSMessage msg) break; case "restartProfile": - await HandleRestartProfileAsync(profile.Name, args.Length > 1 && args[1].Equals("true", StringComparison.OrdinalIgnoreCase)); + HandleRestartProfile(profile.Name, args.Length > 1 && args[1].Equals("true", StringComparison.OrdinalIgnoreCase)); break; case "stop": - await _profileEngine.StopProfileAsync(profile.Name); + RunDetached("Stop", profile.Name, () => _profileEngine.StopProfileAsync(profile.Name)); break; case "start": @@ -304,7 +325,7 @@ private async Task HandleUpdateRunsAsync(Profile profile) await _profileEngine.UpdateProfileAndNotifyAsync(profile); if (rollover) - await _profileEngine.RestartProfileAsync(profile.Name, rotateKey: profile.SwitchKeysOnRestart); + HandleRestartProfile(profile.Name, rotateKey: profile.SwitchKeysOnRestart); } private async Task HandleUpdateChickensAsync(Profile profile) @@ -442,9 +463,33 @@ private async Task HandleSetProfileAsync(Profile profile, string[] args) await _profileEngine.UpdateProfileAndNotifyAsync(profile); } - private async Task HandleRestartProfileAsync(string profileName, bool rotateKey) + /// + /// Runs profile lifecycle work off the dispatch loop. + /// + /// + /// This loop processes one message at a time for the entire fleet, so anything awaited here + /// is time during which no other profile's messages — including its heartbeats — are read. + /// A restart is StopProfileAsync (up to a 5s terminate grace) + a 1s settle + start, + /// so awaiting it inline stalls the whole pipeline for six seconds or more; a handful of + /// profiles rotating keys together was enough to push uninvolved bots past the missed- + /// heartbeat threshold and recruit them into the same restart storm. + /// + /// D2Bot# never did this inline either — D2Profile.Stop() queued a Worker onto one of + /// ten shards keyed by profile name hash. The engine's own state machine already rejects + /// invalid transitions, so concurrent lifecycle requests for one profile are safe. + /// + /// + private void RunDetached(string description, string profileName, Func work) + { + _ = Task.Run(work).ContinueWith( + t => _logger.LogError(t.Exception, "{Description} failed for profile {Profile}", description, profileName), + TaskContinuationOptions.OnlyOnFaulted); + } + + private void HandleRestartProfile(string profileName, bool rotateKey) { - await _profileEngine.RestartProfileAsync(profileName, rotateKey: rotateKey); + RunDetached("Restart", profileName, + () => _profileEngine.RestartProfileAsync(profileName, rotateKey: rotateKey)); } private async Task HandleCDKeyDisabledAsync(Profile profile, string keyName) diff --git a/src/D2BotNG/Windows/MessageWindow.cs b/src/D2BotNG/Windows/MessageWindow.cs index 8789dac..2e7a487 100644 --- a/src/D2BotNG/Windows/MessageWindow.cs +++ b/src/D2BotNG/Windows/MessageWindow.cs @@ -1,3 +1,4 @@ +using System.Collections.Concurrent; using System.Runtime.InteropServices; using System.Text; using System.Text.Json; @@ -35,6 +36,15 @@ public class MessageWindow : IDisposable { private readonly ILogger _logger; private readonly Channel _messageChannel; + + /// + /// When each sender last reported in, stamped on the message pump. Liveness must not be a + /// function of dispatch latency: the dispatch queue is shared by the whole fleet and does + /// slow work (renders, file writes, profile restarts), so a heartbeat stamped when it + /// reaches the front of that queue says as much about the manager as about the bot. + /// + private readonly ConcurrentDictionary _lastHeartbeatAt = new(); + private nint _wndProcPtr; private WndProcDelegate? _wndProcDelegate; private bool _disposed; @@ -59,6 +69,18 @@ public MessageWindow(ILogger logger) /// public ChannelReader Messages => _messageChannel.Reader; + /// + /// When the given sender last sent a heartbeat, as observed on the message pump. + /// + public bool TryGetLastHeartbeat(nint senderHandle, out DateTime at) => + _lastHeartbeatAt.TryGetValue(senderHandle, out at); + + /// + /// Drops a sender's recorded liveness. Called when a profile's routing entry is removed so + /// the map tracks running profiles instead of accreting a row per game ever launched. + /// + public void ForgetHandle(nint senderHandle) => _lastHeartbeatAt.TryRemove(senderHandle, out _); + /// /// Creates the message-only window. Call once from Program.Main before any hosted /// service runs — handoff rehydration reads Handle. @@ -123,13 +145,33 @@ public void HandleCopyData(nint wParam, nint lParam) while (length > 0 && bytes[length - 1] == 0) length--; var messageType = (MessageType)copyData.dwData.ToInt64(); + + // Heartbeats are recorded here and never enqueued. kolbot's dedicated heartbeat + // thread sends mode 0xBBBB once a second (threads/HeartBeat.js), so this is an O(1) + // check that also keeps the highest-frequency message in the system off the shared + // dispatch queue entirely. A framework that signals liveness some other way still + // works: its message falls through, is parsed properly by the consumer, and the + // "heartBeat" case there records it — late, but correctly. + // + // This deliberately does NOT treat any other message as proof of life. kolbot sends + // console output, characterState and status updates from threads that outlive a + // wedged main script, so counting them would mask the failure the watchdog exists + // to catch. + if (messageType == MessageType.Heartbeat) + { + _lastHeartbeatAt[wParam] = DateTime.UtcNow; + return; + } + var data = Encoding.UTF8.GetString(bytes, 0, length); _logger.LogDebug("WM_COPYDATA received: sender={Sender}, type={Type}, len={Len}, data={Data}", wParam, messageType, copyData.cbData, data); - // Normalize heartbeat event. - if (messageType == MessageType.Heartbeat || data.Contains("heartBeat")) + // Normalize heartbeat event. Only reachable for a sender that doesn't set the + // 0xBBBB mode (handled by the fast path above) — it goes down the queue and the + // consumer's "heartBeat" case records it, later but correctly. + if (data.Contains("heartBeat")) { data = JsonSerializer.Serialize(new ProfileMessage {