refactor(battle-node): gate WS diagnostic logging behind config flag
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<BattleNodeOptions>().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 <noreply@anthropic.com>
This commit is contained in:
@@ -26,4 +26,18 @@ public sealed class BattleNodeOptions
|
|||||||
/// is the only way to get PvP behavior.</para>
|
/// is the only way to get PvP behavior.</para>
|
||||||
/// </summary>
|
/// </summary>
|
||||||
public bool SoloDefaultsToScripted { get; set; } = false;
|
public bool SoloDefaultsToScripted { get; set; } = false;
|
||||||
|
|
||||||
|
/// <summary>
|
||||||
|
/// When true, <see cref="Sessions.Participants.RealParticipant"/> emits per-frame
|
||||||
|
/// diagnostic logs at Information level: <c>[sio-in]</c> on every inbound msg/alive/hand
|
||||||
|
/// envelope (URI, pubSeq, ackId, dispatch decision, ack-sent flag, ack arg, inbound
|
||||||
|
/// watermark); <c>[sio-out]</c> on every outbound push (URI, pubSeq, playSeq, noStock);
|
||||||
|
/// <c>[ws-rx-text]</c> / <c>[ws-rx-bin]</c> on every WS frame received at the transport
|
||||||
|
/// layer; <c>[ws-recv-exit]</c> / <c>[ws-loop-exit]</c> 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
|
||||||
|
/// <c>docs/audits/battle-node-sio-events-2026-06-02.md</c>.
|
||||||
|
/// </summary>
|
||||||
|
public bool DiagnosticLogging { get; set; } = false;
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -124,7 +124,7 @@ public sealed class BattleNodeWebSocketHandler
|
|||||||
{
|
{
|
||||||
_store.RemovePending(battleId);
|
_store.RemovePending(battleId);
|
||||||
var realParticipant = new RealParticipant(ws, viewerId, pending.P1.Context,
|
var realParticipant = new RealParticipant(ws, viewerId, pending.P1.Context,
|
||||||
_loggerFactory.CreateLogger<RealParticipant>());
|
_loggerFactory.CreateLogger<RealParticipant>(), _options.DiagnosticLogging);
|
||||||
var scriptedBot = new ScriptedBotParticipant();
|
var scriptedBot = new ScriptedBotParticipant();
|
||||||
var session = new BattleSession(battleId, pending.Type, realParticipant, scriptedBot,
|
var session = new BattleSession(battleId, pending.Type, realParticipant, scriptedBot,
|
||||||
_loggerFactory.CreateLogger<BattleSession>());
|
_loggerFactory.CreateLogger<BattleSession>());
|
||||||
@@ -137,7 +137,7 @@ public sealed class BattleNodeWebSocketHandler
|
|||||||
// Pick this connection's MatchContext (P1's if isP1, P2's if isP2).
|
// Pick this connection's MatchContext (P1's if isP1, P2's if isP2).
|
||||||
var selfCtx = isP1 ? pending.P1.Context : pending.P2!.Context;
|
var selfCtx = isP1 ? pending.P1.Context : pending.P2!.Context;
|
||||||
var self = new RealParticipant(ws, viewerId, selfCtx,
|
var self = new RealParticipant(ws, viewerId, selfCtx,
|
||||||
_loggerFactory.CreateLogger<RealParticipant>());
|
_loggerFactory.CreateLogger<RealParticipant>(), _options.DiagnosticLogging);
|
||||||
|
|
||||||
var firstArriver = _waitingRoom.Pair(battleId, self);
|
var firstArriver = _waitingRoom.Pair(battleId, self);
|
||||||
|
|
||||||
@@ -202,7 +202,7 @@ public sealed class BattleNodeWebSocketHandler
|
|||||||
// earlier isP1/isP2 check has already rejected viewer mismatches.
|
// earlier isP1/isP2 check has already rejected viewer mismatches.
|
||||||
_store.RemovePending(battleId);
|
_store.RemovePending(battleId);
|
||||||
var botReal = new RealParticipant(ws, viewerId, pending.P1.Context,
|
var botReal = new RealParticipant(ws, viewerId, pending.P1.Context,
|
||||||
_loggerFactory.CreateLogger<RealParticipant>());
|
_loggerFactory.CreateLogger<RealParticipant>(), _options.DiagnosticLogging);
|
||||||
var noopBot = new NoOpBotParticipant();
|
var noopBot = new NoOpBotParticipant();
|
||||||
var botSession = new BattleSession(battleId, BattleType.Bot, botReal, noopBot,
|
var botSession = new BattleSession(battleId, BattleType.Bot, botReal, noopBot,
|
||||||
_loggerFactory.CreateLogger<BattleSession>());
|
_loggerFactory.CreateLogger<BattleSession>());
|
||||||
|
|||||||
@@ -33,6 +33,7 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase
|
|||||||
{
|
{
|
||||||
private readonly WebSocket _ws;
|
private readonly WebSocket _ws;
|
||||||
private readonly ILogger<RealParticipant> _log;
|
private readonly ILogger<RealParticipant> _log;
|
||||||
|
private readonly bool _diagnosticLogging;
|
||||||
private CancellationToken _sessionCt;
|
private CancellationToken _sessionCt;
|
||||||
|
|
||||||
public long ViewerId { get; }
|
public long ViewerId { get; }
|
||||||
@@ -85,10 +86,11 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase
|
|||||||
}
|
}
|
||||||
|
|
||||||
public RealParticipant(WebSocket ws, long viewerId, MatchContext context,
|
public RealParticipant(WebSocket ws, long viewerId, MatchContext context,
|
||||||
ILogger<RealParticipant> log)
|
ILogger<RealParticipant> log, bool diagnosticLogging = false)
|
||||||
{
|
{
|
||||||
_ws = ws;
|
_ws = ws;
|
||||||
_log = log;
|
_log = log;
|
||||||
|
_diagnosticLogging = diagnosticLogging;
|
||||||
ViewerId = viewerId;
|
ViewerId = viewerId;
|
||||||
Context = context;
|
Context = context;
|
||||||
}
|
}
|
||||||
@@ -115,11 +117,13 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase
|
|||||||
var text = Encoding.UTF8.GetString(msg.Value.Bytes);
|
var text = Encoding.UTF8.GetString(msg.Value.Bytes);
|
||||||
if (text.Length == 0) continue;
|
if (text.Length == 0) continue;
|
||||||
var eio = EngineIoFrame.Parse(text);
|
var eio = EngineIoFrame.Parse(text);
|
||||||
// Diagnostic: log every EIO frame type so we can see Ping/Close packets too.
|
if (_diagnosticLogging)
|
||||||
_log.LogInformation(
|
{
|
||||||
"[ws-rx-text] viewer={Vid} eioType={Eio} len={Len} preview={Preview}",
|
_log.LogInformation(
|
||||||
ViewerId, eio.Type, text.Length,
|
"[ws-rx-text] viewer={Vid} eioType={Eio} len={Len} preview={Preview}",
|
||||||
text.Length > 60 ? text.Substring(0, 60) + "..." : text);
|
ViewerId, eio.Type, text.Length,
|
||||||
|
text.Length > 60 ? text.Substring(0, 60) + "..." : text);
|
||||||
|
}
|
||||||
if (eio.Type == EngineIoPacketType.Ping)
|
if (eio.Type == EngineIoPacketType.Ping)
|
||||||
{
|
{
|
||||||
await SendTextAsync("3", cancellation);
|
await SendTextAsync("3", cancellation);
|
||||||
@@ -144,9 +148,12 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase
|
|||||||
bin = bin.AsSpan(1).ToArray();
|
bin = bin.AsSpan(1).ToArray();
|
||||||
}
|
}
|
||||||
pendingAttachments.Add(bin);
|
pendingAttachments.Add(bin);
|
||||||
_log.LogInformation(
|
if (_diagnosticLogging)
|
||||||
"[ws-rx-bin] viewer={Vid} binLen={Len} pendingFrame={Pending} attachCount={AttachCount}",
|
{
|
||||||
ViewerId, bin.Length, pendingFrame?.EventName ?? "(null)", pendingAttachments.Count);
|
_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)
|
if (pendingFrame is not null && pendingAttachments.Count == pendingFrame.AttachmentCount)
|
||||||
{
|
{
|
||||||
var assembled = pendingFrame.WithAttachments(pendingAttachments.ToArray());
|
var assembled = pendingFrame.WithAttachments(pendingAttachments.ToArray());
|
||||||
@@ -163,20 +170,24 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase
|
|||||||
}
|
}
|
||||||
finally
|
finally
|
||||||
{
|
{
|
||||||
_log.LogWarning(
|
if (_diagnosticLogging)
|
||||||
"[ws-loop-exit] viewer={Vid} reason={Reason} wsState={State} cancelled={Cancelled}",
|
{
|
||||||
ViewerId, exitReason, _ws.State, cancellation.IsCancellationRequested);
|
_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)
|
public async Task PushAsync(MsgEnvelope envelope, bool noStock, CancellationToken ct)
|
||||||
{
|
{
|
||||||
var stamped = noStock ? Outbound.WrapNoStock(envelope) : Outbound.AssignAndArchive(envelope);
|
var stamped = noStock ? Outbound.WrapNoStock(envelope) : Outbound.AssignAndArchive(envelope);
|
||||||
// Temporary diagnostic log to pair with the [sio-in] log — gives full inbound/outbound
|
if (_diagnosticLogging)
|
||||||
// sequence numbering for the scripted-attack TurnEnd-never-fires investigation.
|
{
|
||||||
_log.LogInformation(
|
_log.LogInformation(
|
||||||
"[sio-out] viewer={Vid} uri={Uri} pubSeq={Pseq} playSeq={Plseq} noStock={NoStock}",
|
"[sio-out] viewer={Vid} uri={Uri} pubSeq={Pseq} playSeq={Plseq} noStock={NoStock}",
|
||||||
ViewerId, stamped.Uri, stamped.PubSeq, stamped.PlaySeq, noStock);
|
ViewerId, stamped.Uri, stamped.PubSeq, stamped.PlaySeq, noStock);
|
||||||
|
}
|
||||||
await EncodeAndSendAsync(stamped, WireConstants.SynchronizeEvent, ct);
|
await EncodeAndSendAsync(stamped, WireConstants.SynchronizeEvent, ct);
|
||||||
}
|
}
|
||||||
|
|
||||||
@@ -241,21 +252,12 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase
|
|||||||
ackArg = env.PubSeq.Value;
|
ackArg = env.PubSeq.Value;
|
||||||
}
|
}
|
||||||
}
|
}
|
||||||
// Temporary diagnostic log to chase a scripted-bot bug where the client
|
if (_diagnosticLogging)
|
||||||
// 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
|
_log.LogInformation(
|
||||||
// SIO ack for the offending TurnEndActions (and what arg). Log shape:
|
"[sio-in] viewer={Vid} uri={Uri} pubSeq={Pseq} ackId={AckId} dispatch={Dispatch} ackSent={AckSent} ackArg={AckArg} highWaterMark={Hwm}",
|
||||||
// uri / pubSeq / ackId / dispatch / ackSent / ackArg / watermark
|
ViewerId, env.Uri, env.PubSeq, frame.AckId, shouldDispatch, ackSent, ackArg, Inbound.HighWaterMark);
|
||||||
_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;
|
if (!shouldDispatch) return;
|
||||||
|
|
||||||
@@ -409,19 +411,22 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase
|
|||||||
try { result = await _ws.ReceiveAsync(buffer, ct); }
|
try { result = await _ws.ReceiveAsync(buffer, ct); }
|
||||||
catch (OperationCanceledException)
|
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;
|
return null;
|
||||||
}
|
}
|
||||||
catch (WebSocketException wsex)
|
catch (WebSocketException wsex)
|
||||||
{
|
{
|
||||||
_log.LogWarning(wsex, "[ws-recv-exit] viewer={Vid} reason=WebSocketException wsState={State} errCode={ErrCode}",
|
if (_diagnosticLogging)
|
||||||
ViewerId, _ws.State, wsex.WebSocketErrorCode);
|
_log.LogWarning(wsex, "[ws-recv-exit] viewer={Vid} reason=WebSocketException wsState={State} errCode={ErrCode}",
|
||||||
|
ViewerId, _ws.State, wsex.WebSocketErrorCode);
|
||||||
return null;
|
return null;
|
||||||
}
|
}
|
||||||
if (result.MessageType == WebSocketMessageType.Close)
|
if (result.MessageType == WebSocketMessageType.Close)
|
||||||
{
|
{
|
||||||
_log.LogWarning("[ws-recv-exit] viewer={Vid} reason=ClientCloseFrame wsState={State} closeStatus={Status} desc={Desc}",
|
if (_diagnosticLogging)
|
||||||
ViewerId, _ws.State, result.CloseStatus, result.CloseStatusDescription);
|
_log.LogWarning("[ws-recv-exit] viewer={Vid} reason=ClientCloseFrame wsState={State} closeStatus={Status} desc={Desc}",
|
||||||
|
ViewerId, _ws.State, result.CloseStatus, result.CloseStatusDescription);
|
||||||
return null;
|
return null;
|
||||||
}
|
}
|
||||||
ms.Write(buffer, 0, result.Count);
|
ms.Write(buffer, 0, result.Count);
|
||||||
|
|||||||
Reference in New Issue
Block a user