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 {