From 9441877db340e1e48a4f9601648c6d69f08ce8f2 Mon Sep 17 00:00:00 2001 From: AdaInTheLab Date: Thu, 28 May 2026 22:31:54 -0400 Subject: [PATCH] fix(websocket): stop LogCallbackEvent broadcast recursion in shutdown EventBroadcaster.Initialize subscribed to LogCallbackEvent with `e => Broadcast("LogCallback", e)`. Broadcast's catch block called Log.Warning(...) on failure. On 7DTD, Log.Warning fires another LogCallbackEvent through the same bus -> re-enters this subscriber -> Broadcast throws again -> Log.Warning again -> infinite recursion -> stack overflow -> KC crashes. The throw is reliably reproducible during shutdown: once the WebSocketServer manager has stopped, _server.WebSocketServices... .Broadcast(json) raises "The current state of the manager is not Start." Observed live on a Windows prod box -- 65+ minutes after a botched auto-start, KC's GracefulRestart wedge cascade ended in "Error in event handler for LogCallbackEvent: The requested operation caused a stack overflow." repeated dozens of times in the log, crashing KC and forcing a service auto-restart. Fix, scoped narrowly to the LogCallbackEvent path: 1. [ThreadStatic] _inLogBroadcast re-entrancy guard. Only on the LogCallback path -- other event types don't loop back into the logger from their failure handler, so they keep the existing Log.Warning-on-failure to surface real broadcast bugs. 2. Pulled the LogCallbackEvent subscriber out into a named BroadcastLogCallback method so the guard logic stays readable instead of being inlined in a lambda. Sets the flag, calls Broadcast, clears the flag in finally. 3. Broadcast gains a suppressFailureLogging parameter. When true (LogCallbackEvent path), the catch falls back to Console.Error.WriteLine instead of Log.Warning so the failure notification itself cannot fire a fresh LogCallbackEvent and restart the recursion. Wrapped in its own try/catch in case stderr is also unhappy during shutdown. The dropped log-broadcast on re-entry is the right tradeoff: we'd only be re-entering because Broadcast just failed, which means the ws clients aren't going to see this log line anyway. Better one lost diagnostic line than a crashed service. No unit test included. EventBroadcaster is a static class tightly coupled to WebSocketSharp.Server and the 7DTD Log type (already called out as game-runtime-only in ModEventBusTests.cs:97). The actual recursion only happens when _server is non-null AND Broadcast throws, neither of which is reachable from the existing test harness without restructuring the class. The fix is small and the failure mode is reproducible in vivo -- verifying the absence of recursion in prod logs after deploy is the better signal. Co-Authored-By: Claude Opus 4.7 (1M context) --- CHANGELOG.md | 20 +++++ .../WebSocket/EventBroadcaster.cs | 73 ++++++++++++++++++- 2 files changed, 90 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index dbbeb3d..b321a8a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,26 @@ pulls notes from — it's the minimum, the GitHub release page is the maximum. ## [Unreleased] +### Fixed + +- **No more stack overflow from `LogCallbackEvent` re-entrancy during + shutdown.** `EventBroadcaster` subscribed to `LogCallbackEvent` and + broadcast each fired log message over the WebSocket. When KC was + mid-shutdown and the WebSocket manager had already stopped, the + inner `Broadcast` threw ("The current state of the manager is not + Start.") and the catch block called `Log.Warning(...)` — which fired + another `LogCallbackEvent`, re-entered the same subscriber, threw + again, logged again, and recursed until the stack overflowed and KC + crashed. Observed live on a Windows prod box: a botched + `GracefulRestart` left the WS manager stopped while the event bus + was still alive, and KC logged "Error in event handler for + LogCallbackEvent: The requested operation caused a stack overflow." + dozens of times before the service died. Fix: a `[ThreadStatic]` + re-entrancy guard scoped to the `LogCallbackEvent` path only (other + events don't loop back into the logger), and the failure path on + that path writes to `Console.Error` instead of `Log.Warning` so the + recursion can't restart. + ## [2.8.1] - 2026-05-29 > [Full notes](https://github.com/Kitsune-Den/KitsuneCommand/releases/tag/v2.8.1) diff --git a/src/KitsuneCommand/WebSocket/EventBroadcaster.cs b/src/KitsuneCommand/WebSocket/EventBroadcaster.cs index f6411b8..2ac1e63 100644 --- a/src/KitsuneCommand/WebSocket/EventBroadcaster.cs +++ b/src/KitsuneCommand/WebSocket/EventBroadcaster.cs @@ -15,6 +15,29 @@ public static class EventBroadcaster ContractResolver = new Newtonsoft.Json.Serialization.CamelCasePropertyNamesContractResolver() }; + /// + /// Thread-local re-entrancy guard for only. + /// + /// 7DTD routes its Log.* writes through the same logging chain that fires + /// LogCallbackEvent. If Broadcast() throws while handling a LogCallbackEvent + /// (typical during shutdown once the WebSocketServer manager has stopped: + /// "The current state of the manager is not Start.") and we then call + /// Log.Warning(...) to report it, that Log.Warning fires another + /// LogCallbackEvent, re-enters this subscriber, throws again, logs again, + /// and recurses until the stack overflows and KC crashes. + /// + /// Observed live on a Windows prod box: a botched GracefulRestart left the + /// WS manager stopped while the event bus was still alive, and KC logged + /// "Error in event handler for LogCallbackEvent: The requested operation + /// caused a stack overflow." dozens of times before the service died. + /// + /// Scope is intentionally narrow: other event types don't loop back into + /// the logger from their failure path, so they keep the normal + /// Log.Warning-on-failure behavior to surface real broadcast bugs. + /// + [ThreadStatic] + private static bool _inLogBroadcast; + public static void Initialize(WebSocketServer server, ModEventBus eventBus) { _server = server; @@ -32,7 +55,7 @@ public static void Initialize(WebSocketServer server, ModEventBus eventBus) eventBus.Subscribe(e => Broadcast("EntityKilled", e)); eventBus.Subscribe(e => Broadcast("ChatMessage", e)); eventBus.Subscribe(e => Broadcast("SkyChanged", e)); - eventBus.Subscribe(e => Broadcast("LogCallback", e)); + eventBus.Subscribe(BroadcastLogCallback); eventBus.Subscribe(e => Broadcast("PlayersPositionUpdate", e)); eventBus.Subscribe(e => Broadcast("PointsUpdate", e)); eventBus.Subscribe(e => Broadcast("BloodMoonVoteUpdate", e)); @@ -40,7 +63,33 @@ public static void Initialize(WebSocketServer server, ModEventBus eventBus) eventBus.Subscribe(e => Broadcast("TicketUpdated", e)); } - private static void Broadcast(string eventType, T data) + /// + /// Re-entrancy-safe LogCallbackEvent broadcaster. + /// + /// If we're already inside a LogCallbackEvent broadcast on this thread, + /// drop the event silently — anything we'd log here would just fire + /// another LogCallbackEvent and we'd be back to the recursion bug this + /// guard exists to prevent. Likewise, if the inner broadcast throws, + /// we deliberately do NOT route the failure through Log.Warning. + /// Console.Error.WriteLine is the closest we'll get to surfacing it, + /// and even that is wasted noise during shutdown — but it's bounded. + /// + internal static void BroadcastLogCallback(LogCallbackEvent e) + { + if (_inLogBroadcast) return; + + _inLogBroadcast = true; + try + { + Broadcast("LogCallback", e, suppressFailureLogging: true); + } + finally + { + _inLogBroadcast = false; + } + } + + private static void Broadcast(string eventType, T data, bool suppressFailureLogging = false) { if (_server == null) return; @@ -58,7 +107,25 @@ private static void Broadcast(string eventType, T data) catch (Exception ex) { // Don't let broadcast failures crash the game - Log.Warning($"[KitsuneCommand] Broadcast error for {eventType}: {ex.Message}"); + if (suppressFailureLogging) + { + // LogCallbackEvent path: Log.* feeds back into the broadcaster, + // so any logger call here is a recursion hazard. Use the bare + // Console.Error channel instead — bounded and won't re-enter. + try + { + Console.Error.WriteLine( + $"[KitsuneCommand] Broadcast error for {eventType}: {ex.Message}"); + } + catch + { + // Last-resort: stderr itself failed. Nothing safe left to do. + } + } + else + { + Log.Warning($"[KitsuneCommand] Broadcast error for {eventType}: {ex.Message}"); + } } } }