diff --git a/SVSim.BattleNode/Protocol/WireConstants.cs b/SVSim.BattleNode/Protocol/WireConstants.cs index 78a0504..47098c3 100644 --- a/SVSim.BattleNode/Protocol/WireConstants.cs +++ b/SVSim.BattleNode/Protocol/WireConstants.cs @@ -16,6 +16,15 @@ internal static class WireConstants /// SIO event name for Gungnir keepalive frames (both directions). public const string AliveEvent = "alive"; + /// + /// SIO event name for client-emitted hand frames (touches + skill/object selection). + /// Stocked variants (SELECT_SKILL_URI, SLIDE_OBJECT_URI) carry an ack-id; + /// fire-and-forget variants (TOUCH_URI, SELECT_OBJECT_URI, + /// TURN_END_READY_URI) do not. The body wire shape differs from msg + /// frames — see HandleHandEventAsync. + /// + public const string HandEvent = "hand"; + /// /// Placeholder UUID we stamp on every server-originated envelope. Prod servers stamp a /// real per-request UUID; the client doesn't validate it. diff --git a/SVSim.BattleNode/Sessions/Participants/RealParticipant.cs b/SVSim.BattleNode/Sessions/Participants/RealParticipant.cs index 3432966..b5d0653 100644 --- a/SVSim.BattleNode/Sessions/Participants/RealParticipant.cs +++ b/SVSim.BattleNode/Sessions/Participants/RealParticipant.cs @@ -101,54 +101,82 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase var buffer = new byte[8192]; var pendingAttachments = new List(); SocketIoFrame? pendingFrame = null; + string exitReason = "loop-condition-false"; - while (_ws.State == WebSocketState.Open && !cancellation.IsCancellationRequested) + try { - var msg = await ReadCompleteMessageAsync(buffer, cancellation); - if (msg is null) break; - - if (msg.Value.IsText) + while (_ws.State == WebSocketState.Open && !cancellation.IsCancellationRequested) { - var text = Encoding.UTF8.GetString(msg.Value.Bytes); - if (text.Length == 0) continue; - var eio = EngineIoFrame.Parse(text); - if (eio.Type == EngineIoPacketType.Ping) - { - await SendTextAsync("3", cancellation); - continue; - } - if (eio.Type != EngineIoPacketType.Message) continue; + var msg = await ReadCompleteMessageAsync(buffer, cancellation); + if (msg is null) { exitReason = "read-returned-null"; break; } - var sio = SocketIoFrame.Parse(eio.Payload); - if (sio.AttachmentCount > 0) + if (msg.Value.IsText) { - pendingFrame = sio; - pendingAttachments.Clear(); - continue; + 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 (eio.Type == EngineIoPacketType.Ping) + { + await SendTextAsync("3", cancellation); + continue; + } + if (eio.Type != EngineIoPacketType.Message) continue; + + var sio = SocketIoFrame.Parse(eio.Payload); + if (sio.AttachmentCount > 0) + { + pendingFrame = sio; + pendingAttachments.Clear(); + continue; + } + await DispatchSocketIo(sio); } - await DispatchSocketIo(sio); - } - else - { - var bin = msg.Value.Bytes; - if (bin.Length > 0 && bin[0] == (byte)EngineIoPacketType.Message) + else { - bin = bin.AsSpan(1).ToArray(); - } - pendingAttachments.Add(bin); - if (pendingFrame is not null && pendingAttachments.Count == pendingFrame.AttachmentCount) - { - var assembled = pendingFrame.WithAttachments(pendingAttachments.ToArray()); - pendingFrame = null; - await DispatchSocketIo(assembled); + var bin = msg.Value.Bytes; + if (bin.Length > 0 && bin[0] == (byte)EngineIoPacketType.Message) + { + 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 (pendingFrame is not null && pendingAttachments.Count == pendingFrame.AttachmentCount) + { + var assembled = pendingFrame.WithAttachments(pendingAttachments.ToArray()); + pendingFrame = null; + await DispatchSocketIo(assembled); + } } } } + catch (Exception ex) + { + exitReason = $"throw:{ex.GetType().Name}:{ex.Message}"; + throw; + } + finally + { + _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); await EncodeAndSendAsync(stamped, WireConstants.SynchronizeEvent, ct); } @@ -180,6 +208,9 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase case WireConstants.AliveEvent when frame.BinaryAttachments.Count == 1: await HandleAliveEventAsync(frame); return; + case WireConstants.HandEvent when frame.BinaryAttachments.Count == 1: + await HandleHandEventAsync(frame); + return; } } _log.LogDebug("RealParticipant viewer={Vid}: dropping SIO event={Event}", ViewerId, frame.EventName); @@ -198,14 +229,34 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase } bool shouldDispatch = true; + bool ackSent = false; + long? ackArg = null; if (env.PubSeq.HasValue) { shouldDispatch = Inbound.Observe(env.PubSeq.Value); if (frame.AckId.HasValue) { await SendSioAckAsync(frame.AckId.Value, env.PubSeq.Value); + ackSent = true; + 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 (!shouldDispatch) return; if (FrameEmitted is not null) @@ -219,6 +270,56 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase } } + /// + /// Ack hand events from the client so the client's stockEmitMessageMgr + /// drains and subsequent emits transmit. Wire shape differs from msg: the body + /// is {"StockHandData":[uri_int, viewerId, udid, ...params, pubSeq], "try":0, "pubSeq":N} + /// (no top-level uri), so we can't reuse — its + /// path requires a top-level uri. + /// + /// In scripted/Bot mode the server has no opponent to forward touches to; ack-only is + /// correct. PvP-side forwarding (so the other player's client can render opponent + /// touch/cursor UI) is unverified — see docs/audits/battle-node-sio-events-2026-06-02.md. + /// + /// + /// Fire-and-forget hand frames (TOUCH_URI / SELECT_OBJECT_URI / TURN_END_READY_URI) arrive + /// with no ack-id; we swallow without decoding. Stocked variants (SELECT_SKILL_URI / + /// SLIDE_OBJECT_URI) arrive with an ack-id and must be acked with the body's pubSeq + /// or the client's emit queue softlocks behind them. + /// + /// + private async Task HandleHandEventAsync(SocketIoFrame frame) + { + if (!frame.AckId.HasValue) + { + // Fire-and-forget; no queue-blocking risk. Swallow without decoding. + return; + } + try + { + var encryptedString = MessagePack.MessagePackSerializer.Deserialize(frame.BinaryAttachments[0]); + var json = NodeCrypto.DecryptForNode(encryptedString); + using var doc = System.Text.Json.JsonDocument.Parse(json); + if (!doc.RootElement.TryGetProperty("pubSeq", out var psEl) + || psEl.ValueKind != System.Text.Json.JsonValueKind.Number) + { + _log.LogWarning( + "RealParticipant viewer={Vid}: 'hand' event ackId={AckId} body missing numeric pubSeq; " + + "acking with 0 as a fallback (client's stockEmitMessageMgr lookup will see null selectData).", + ViewerId, frame.AckId); + await SendSioAckAsync(frame.AckId.Value, 0); + return; + } + await SendSioAckAsync(frame.AckId.Value, psEl.GetInt64()); + } + catch (Exception ex) + { + _log.LogWarning(ex, + "RealParticipant viewer={Vid}: failed to decode 'hand' event body; not acking. ackId={AckId}", + ViewerId, frame.AckId); + } + } + private async Task HandleAliveEventAsync(SocketIoFrame frame) { try @@ -306,9 +407,23 @@ public sealed class RealParticipant : IBattleParticipant, IHasHandshakePhase do { try { result = await _ws.ReceiveAsync(buffer, ct); } - catch (OperationCanceledException) { return null; } - catch (WebSocketException) { return null; } - if (result.MessageType == WebSocketMessageType.Close) return null; + catch (OperationCanceledException) + { + _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); + 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); + return null; + } ms.Write(buffer, 0, result.Count); } while (!result.EndOfMessage); return (ms.ToArray(), result.MessageType == WebSocketMessageType.Text); diff --git a/SVSim.UnitTests/BattleNode/Sessions/Participants/RealParticipantHandEventTests.cs b/SVSim.UnitTests/BattleNode/Sessions/Participants/RealParticipantHandEventTests.cs new file mode 100644 index 0000000..706c37d --- /dev/null +++ b/SVSim.UnitTests/BattleNode/Sessions/Participants/RealParticipantHandEventTests.cs @@ -0,0 +1,146 @@ +using System.Net.WebSockets; +using System.Text; +using System.Text.Json; +using MessagePack; +using Microsoft.Extensions.Logging.Abstractions; +using NUnit.Framework; +using SVSim.BattleNode.Bridge; +using SVSim.BattleNode.Protocol; +using SVSim.BattleNode.Sessions; +using SVSim.BattleNode.Sessions.Participants; +using SVSim.BattleNode.Wire; +using SVSim.UnitTests.BattleNode.Infrastructure; + +namespace SVSim.UnitTests.BattleNode.Sessions.Participants; + +/// +/// Regression tests for the "hand" SIO event handler. The active bug at +/// docs/audits/battle-node-sio-events-2026-06-02.md §"Active bug" was: +/// client-stocked SELECT_SKILL_URI / SLIDE_OBJECT_URI hand emits arrive +/// with an ack-id; without a server ack, the client's stockEmitMessageMgr deadlocks +/// behind them and every subsequent emit (PlayActions, TurnEndActions, TurnEnd) is queued +/// but never transmitted. These tests drive a hand frame through the WS read loop and +/// inspect the outbound text-frame queue for the SIO ack. +/// +[TestFixture] +public class RealParticipantHandEventTests +{ + // Any 32-char ASCII string is a valid AES key for NodeCrypto — DecryptForNode reads the + // key from the first 32 chars of the encrypted blob. + private const string TestKey = "abcdefghijklmnopqrstuvwxyz012345"; + + [Test] + public async Task Stocked_hand_event_acks_with_body_pubSeq() + { + var ws = new TestWebSocket(); + var p = new RealParticipant(ws, viewerId: 906_243_102L, FixtureCtx(), + NullLogger.Instance); + + // Client-shape hand body for a SELECT_SKILL emit: StockHandData[0] = uri_int + // (HAND_URI_TYPE.SELECT_SKILL_URI = 2), top-level "try" + "pubSeq" added by + // EmitMsgUriPack. The handler reads top-level "pubSeq" — body contents otherwise + // don't matter for ack semantics. + const long expectedPubSeq = 42L; + var body = $"{{\"StockHandData\":[2,906243102,\"u\",1,0,{expectedPubSeq}],\"try\":0,\"pubSeq\":{expectedPubSeq}}}"; + EnqueueHandFrame(ws, ackId: 26, body: body); + ws.CompleteIncoming(); + + await p.RunAsync(CancellationToken.None); + + var ackFrame = FindAckFrame(ws, ackId: 26); + Assert.That(ackFrame, Is.Not.Null, + $"Expected an SIO Ack frame for ackId=26 in outbound sends; got: [{string.Join(", ", AllTextSends(ws))}]"); + Assert.That(ackFrame, Does.Contain($"[{expectedPubSeq}]"), + "Ack arg must echo the body's pubSeq so the client's stockEmitMessageMgr.GetSelectData lookup succeeds."); + } + + [Test] + public async Task Hand_event_without_ackId_is_swallowed_silently_no_ack_sent() + { + // Fire-and-forget hand emits (TOUCH_URI, SELECT_OBJECT_URI, TURN_END_READY_URI) arrive + // without an ack-id and don't block the client's emit queue. We should swallow them + // without trying to decode or ack. + var ws = new TestWebSocket(); + var p = new RealParticipant(ws, viewerId: 1, FixtureCtx(), + NullLogger.Instance); + + var body = "{\"StockHandData\":[1,1,\"u\",0],\"try\":0}"; + EnqueueHandFrame(ws, ackId: null, body: body); + ws.CompleteIncoming(); + + await p.RunAsync(CancellationToken.None); + + // Only the EIO Open handshake should be in Sends; no Ack frame. + var ackFrames = AllTextSends(ws).Where(s => s.StartsWith("43")).ToList(); + Assert.That(ackFrames, Is.Empty, + $"No-ack-id hand frame must not produce an Ack; got: [{string.Join(", ", ackFrames)}]"); + } + + [Test] + public async Task Hand_event_with_missing_pubSeq_falls_back_to_ack_arg_0() + { + // If a stocked hand frame ever arrives without a pubSeq, we still ack so the + // client doesn't softlock — but with arg=0 (the client's GetSelectData lookup + // will miss and OnAck fires with null selectData, which is the same path as a + // normal cache-miss; not great, but not a deadlock). + var ws = new TestWebSocket(); + var p = new RealParticipant(ws, viewerId: 1, FixtureCtx(), + NullLogger.Instance); + + var body = "{\"StockHandData\":[2,1,\"u\"],\"try\":0}"; // no pubSeq + EnqueueHandFrame(ws, ackId: 99, body: body); + ws.CompleteIncoming(); + + await p.RunAsync(CancellationToken.None); + + var ackFrame = FindAckFrame(ws, ackId: 99); + Assert.That(ackFrame, Is.Not.Null, + "Missing-pubSeq fallback should still ack (arg=0), not silently swallow."); + Assert.That(ackFrame, Does.Contain("[0]"), + "Fallback ack arg should be 0."); + } + + // ----------------------------------------------------------------------- + // Helpers + // ----------------------------------------------------------------------- + + /// + /// Enqueue an SIO BinaryEvent("hand", {placeholder}) text frame followed by its single + /// binary attachment (NodeCrypto-encrypted msgpack-string of ). + /// Wire format mirrors what EmitFrontStockData:717-720 emits. + /// + private static void EnqueueHandFrame(TestWebSocket ws, int? ackId, string body) + { + // Text frame: 4 (EIO Message) + 5 (SIO BinaryEvent) + 1- (1 attachment) + ackId + json + var ackPart = ackId.HasValue ? ackId.Value.ToString() : ""; + var text = $"451-{ackPart}[\"hand\",{{\"_placeholder\":true,\"num\":0}}]"; + ws.EnqueueIncoming(Encoding.UTF8.GetBytes(text), WebSocketMessageType.Text); + + // Binary attachment: EIO Message prefix (0x04) + msgpack-string(NodeCrypto.Encrypt(json)). + var encrypted = NodeCrypto.EncryptForNode(body, TestKey); + var msgpackBytes = MessagePackSerializer.Serialize(encrypted); + var prefixed = new byte[msgpackBytes.Length + 1]; + prefixed[0] = (byte)EngineIoPacketType.Message; + Buffer.BlockCopy(msgpackBytes, 0, prefixed, 1, msgpackBytes.Length); + ws.EnqueueIncoming(prefixed, WebSocketMessageType.Binary); + } + + private static IEnumerable AllTextSends(TestWebSocket ws) => + ws.Sends + .Where(f => f.Type == WebSocketMessageType.Text) + .Select(f => Encoding.UTF8.GetString(f.Payload)); + + /// + /// SIO Ack wire form: EIO Message (4) + SIO Ack (3) + ackId + [arg]. Filter the text + /// sends for that shape. + /// + private static string? FindAckFrame(TestWebSocket ws, int ackId) => + AllTextSends(ws).FirstOrDefault(s => s.StartsWith($"43{ackId}[")); + + private static MatchContext FixtureCtx() => new( + SelfDeckCardIds: Enumerable.Range(1, 30).Select(_ => 100_011_010L).ToList(), + ClassId: "1", CharaId: "1", CardMasterName: "card_master_node_10015", + CountryCode: "KOR", UserName: "Player", SleeveId: "3000011", + EmblemId: "701441011", DegreeId: "300003", FieldId: 43, IsOfficial: 0, + BattleType: 11); +}