From 8f270a87f0b9b969fe0d1560a0b8e1b574d9e1b9 Mon Sep 17 00:00:00 2001 From: gamer147 Date: Tue, 2 Jun 2026 16:49:17 -0400 Subject: [PATCH] refactor(battle-node): gate WS diagnostic logging behind config flag MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The temporary [sio-in] / [sio-out] / [ws-rx-text] / [ws-rx-bin] / [ws-recv-exit] / [ws-loop-exit] logs added during the hand-ack investigation are useful enough to keep around (PvP testing, future WS debugging) but too chatty to leave on by default. Promote them from "strip before merge" to a permanent opt-in. New BattleNodeOptions.DiagnosticLogging (bool, default false). Wired through BattleNodeWebSocketHandler to RealParticipant via a new optional ctor parameter (default false — existing test sites pick up the silent default with no changes). Every Information/Warning log added during the investigation is now if-gated; non-diagnostic logs (the decode-failure warnings, the dispatch-drop debug) stay as-is. Toggle via appsettings*.json: "BattleNode": { "DiagnosticLogging": true } Or live via the singleton: factory.Services.GetRequiredService().DiagnosticLogging = true 175 battle-node tests still passing — existing tests use the constructor default and emit nothing, so no test changes were required. Co-Authored-By: Claude Opus 4.7 --- SVSim.BattleNode/Bridge/BattleNodeOptions.cs | 14 ++++ .../Hosting/BattleNodeWebSocketHandler.cs | 6 +- .../Sessions/Participants/RealParticipant.cs | 79 ++++++++++--------- 3 files changed, 59 insertions(+), 40 deletions(-) diff --git a/SVSim.BattleNode/Bridge/BattleNodeOptions.cs b/SVSim.BattleNode/Bridge/BattleNodeOptions.cs index 40306ca..dab4901 100644 --- a/SVSim.BattleNode/Bridge/BattleNodeOptions.cs +++ b/SVSim.BattleNode/Bridge/BattleNodeOptions.cs @@ -26,4 +26,18 @@ public sealed class BattleNodeOptions /// is the only way to get PvP behavior. /// public bool SoloDefaultsToScripted { get; set; } = false; + + /// + /// When true, emits per-frame + /// diagnostic logs at Information level: [sio-in] on every inbound msg/alive/hand + /// envelope (URI, pubSeq, ackId, dispatch decision, ack-sent flag, ack arg, inbound + /// watermark); [sio-out] on every outbound push (URI, pubSeq, playSeq, noStock); + /// [ws-rx-text] / [ws-rx-bin] on every WS frame received at the transport + /// layer; [ws-recv-exit] / [ws-loop-exit] on read-loop termination + /// (with WebSocket state + exception type when applicable). Default false — keeps + /// production logs clean. Flip on per session for live WS debugging, PvP investigation, + /// or to reproduce the kind of softlock chased in + /// docs/audits/battle-node-sio-events-2026-06-02.md. + /// + public bool DiagnosticLogging { get; set; } = false; } diff --git a/SVSim.BattleNode/Hosting/BattleNodeWebSocketHandler.cs b/SVSim.BattleNode/Hosting/BattleNodeWebSocketHandler.cs index 8c5a2a0..944a7a6 100644 --- a/SVSim.BattleNode/Hosting/BattleNodeWebSocketHandler.cs +++ b/SVSim.BattleNode/Hosting/BattleNodeWebSocketHandler.cs @@ -124,7 +124,7 @@ public sealed class BattleNodeWebSocketHandler { _store.RemovePending(battleId); var realParticipant = new RealParticipant(ws, viewerId, pending.P1.Context, - _loggerFactory.CreateLogger()); + _loggerFactory.CreateLogger(), _options.DiagnosticLogging); var scriptedBot = new ScriptedBotParticipant(); var session = new BattleSession(battleId, pending.Type, realParticipant, scriptedBot, _loggerFactory.CreateLogger()); @@ -137,7 +137,7 @@ public sealed class BattleNodeWebSocketHandler // Pick this connection's MatchContext (P1's if isP1, P2's if isP2). var selfCtx = isP1 ? pending.P1.Context : pending.P2!.Context; var self = new RealParticipant(ws, viewerId, selfCtx, - _loggerFactory.CreateLogger()); + _loggerFactory.CreateLogger(), _options.DiagnosticLogging); var firstArriver = _waitingRoom.Pair(battleId, self); @@ -202,7 +202,7 @@ public sealed class BattleNodeWebSocketHandler // earlier isP1/isP2 check has already rejected viewer mismatches. _store.RemovePending(battleId); var botReal = new RealParticipant(ws, viewerId, pending.P1.Context, - _loggerFactory.CreateLogger()); + _loggerFactory.CreateLogger(), _options.DiagnosticLogging); var noopBot = new NoOpBotParticipant(); var botSession = new BattleSession(battleId, BattleType.Bot, botReal, noopBot, _loggerFactory.CreateLogger()); diff --git a/SVSim.BattleNode/Sessions/Participants/RealParticipant.cs b/SVSim.BattleNode/Sessions/Participants/RealParticipant.cs index b5d0653..a1ff664 100644 --- a/SVSim.BattleNode/Sessions/Participants/RealParticipant.cs +++ b/SVSim.BattleNode/Sessions/Participants/RealParticipant.cs @@ -33,6 +33,7 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase { private readonly WebSocket _ws; private readonly ILogger _log; + private readonly bool _diagnosticLogging; private CancellationToken _sessionCt; public long ViewerId { get; } @@ -85,10 +86,11 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase } public RealParticipant(WebSocket ws, long viewerId, MatchContext context, - ILogger log) + ILogger log, bool diagnosticLogging = false) { _ws = ws; _log = log; + _diagnosticLogging = diagnosticLogging; ViewerId = viewerId; Context = context; } @@ -115,11 +117,13 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase var text = Encoding.UTF8.GetString(msg.Value.Bytes); if (text.Length == 0) continue; var eio = EngineIoFrame.Parse(text); - // Diagnostic: log every EIO frame type so we can see Ping/Close packets too. - _log.LogInformation( - "[ws-rx-text] viewer={Vid} eioType={Eio} len={Len} preview={Preview}", - ViewerId, eio.Type, text.Length, - text.Length > 60 ? text.Substring(0, 60) + "..." : text); + if (_diagnosticLogging) + { + _log.LogInformation( + "[ws-rx-text] viewer={Vid} eioType={Eio} len={Len} preview={Preview}", + ViewerId, eio.Type, text.Length, + text.Length > 60 ? text.Substring(0, 60) + "..." : text); + } if (eio.Type == EngineIoPacketType.Ping) { await SendTextAsync("3", cancellation); @@ -144,9 +148,12 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase bin = bin.AsSpan(1).ToArray(); } pendingAttachments.Add(bin); - _log.LogInformation( - "[ws-rx-bin] viewer={Vid} binLen={Len} pendingFrame={Pending} attachCount={AttachCount}", - ViewerId, bin.Length, pendingFrame?.EventName ?? "(null)", pendingAttachments.Count); + if (_diagnosticLogging) + { + _log.LogInformation( + "[ws-rx-bin] viewer={Vid} binLen={Len} pendingFrame={Pending} attachCount={AttachCount}", + ViewerId, bin.Length, pendingFrame?.EventName ?? "(null)", pendingAttachments.Count); + } if (pendingFrame is not null && pendingAttachments.Count == pendingFrame.AttachmentCount) { var assembled = pendingFrame.WithAttachments(pendingAttachments.ToArray()); @@ -163,20 +170,24 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase } finally { - _log.LogWarning( - "[ws-loop-exit] viewer={Vid} reason={Reason} wsState={State} cancelled={Cancelled}", - ViewerId, exitReason, _ws.State, cancellation.IsCancellationRequested); + if (_diagnosticLogging) + { + _log.LogWarning( + "[ws-loop-exit] viewer={Vid} reason={Reason} wsState={State} cancelled={Cancelled}", + ViewerId, exitReason, _ws.State, cancellation.IsCancellationRequested); + } } } public async Task PushAsync(MsgEnvelope envelope, bool noStock, CancellationToken ct) { var stamped = noStock ? Outbound.WrapNoStock(envelope) : Outbound.AssignAndArchive(envelope); - // Temporary diagnostic log to pair with the [sio-in] log — gives full inbound/outbound - // sequence numbering for the scripted-attack TurnEnd-never-fires investigation. - _log.LogInformation( - "[sio-out] viewer={Vid} uri={Uri} pubSeq={Pseq} playSeq={Plseq} noStock={NoStock}", - ViewerId, stamped.Uri, stamped.PubSeq, stamped.PlaySeq, noStock); + if (_diagnosticLogging) + { + _log.LogInformation( + "[sio-out] viewer={Vid} uri={Uri} pubSeq={Pseq} playSeq={Plseq} noStock={NoStock}", + ViewerId, stamped.Uri, stamped.PubSeq, stamped.PlaySeq, noStock); + } await EncodeAndSendAsync(stamped, WireConstants.SynchronizeEvent, ct); } @@ -241,21 +252,12 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase ackArg = env.PubSeq.Value; } } - // Temporary diagnostic log to chase a scripted-bot bug where the client - // sends TurnEndActions after a PlayActions(type=10) attack but never sends the - // follow-up TurnEnd. We need to confirm whether the server actually sent the - // SIO ack for the offending TurnEndActions (and what arg). Log shape: - // uri / pubSeq / ackId / dispatch / ackSent / ackArg / watermark - _log.LogInformation( - "[sio-in] viewer={Vid} uri={Uri} pubSeq={Pseq} ackId={AckId} dispatch={Dispatch} ackSent={AckSent} ackArg={AckArg} highWaterMark={Hwm}", - ViewerId, - env.Uri, - env.PubSeq, - frame.AckId, - shouldDispatch, - ackSent, - ackArg, - Inbound.HighWaterMark); + if (_diagnosticLogging) + { + _log.LogInformation( + "[sio-in] viewer={Vid} uri={Uri} pubSeq={Pseq} ackId={AckId} dispatch={Dispatch} ackSent={AckSent} ackArg={AckArg} highWaterMark={Hwm}", + ViewerId, env.Uri, env.PubSeq, frame.AckId, shouldDispatch, ackSent, ackArg, Inbound.HighWaterMark); + } if (!shouldDispatch) return; @@ -409,19 +411,22 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase try { result = await _ws.ReceiveAsync(buffer, ct); } catch (OperationCanceledException) { - _log.LogWarning("[ws-recv-exit] viewer={Vid} reason=OperationCanceled wsState={State}", ViewerId, _ws.State); + if (_diagnosticLogging) + _log.LogWarning("[ws-recv-exit] viewer={Vid} reason=OperationCanceled wsState={State}", ViewerId, _ws.State); return null; } catch (WebSocketException wsex) { - _log.LogWarning(wsex, "[ws-recv-exit] viewer={Vid} reason=WebSocketException wsState={State} errCode={ErrCode}", - ViewerId, _ws.State, wsex.WebSocketErrorCode); + if (_diagnosticLogging) + _log.LogWarning(wsex, "[ws-recv-exit] viewer={Vid} reason=WebSocketException wsState={State} errCode={ErrCode}", + ViewerId, _ws.State, wsex.WebSocketErrorCode); return null; } if (result.MessageType == WebSocketMessageType.Close) { - _log.LogWarning("[ws-recv-exit] viewer={Vid} reason=ClientCloseFrame wsState={State} closeStatus={Status} desc={Desc}", - ViewerId, _ws.State, result.CloseStatus, result.CloseStatusDescription); + if (_diagnosticLogging) + _log.LogWarning("[ws-recv-exit] viewer={Vid} reason=ClientCloseFrame wsState={State} closeStatus={Status} desc={Desc}", + ViewerId, _ws.State, result.CloseStatus, result.CloseStatusDescription); return null; } ms.Write(buffer, 0, result.Count);