Inputs can "jam" on in certain situations

[ProfanedBane]

In laggy situations your inputs can get stuck "on" and constantly move you in a direction until you mash the offending key to reset it.

[Visne]

Any steps to reproduce?

[PJB3005]

I can confirm this as well but god knows for repro steps.

[metalgearsloth]

I can confirm this as well but god knows for repro steps.

I can repro it now.

1. Start moving in a direction
2. Hold left-click on the windows resize (you don't need to actually resize)
3. Let go of the movement input
4. Let go of left-click
5. Input jammed until window loses focus or you press the key again.

It's a different situation so not sure if it resolves the lag one.

[AJCM-git]

That happens in almost every game (hold a key, unfocus window, come back and the key is jammed) is there really a way to fix that?

[metalgearsloth]

My repro for it is probably fine to ignore but people get it stuck during normal gameplay somehow.

[Willhelm53]

4542 may help solve this perhaps? This one happens to me a lot during normal gameplay.

[Aexxie]

Hmmm bumping this. I've noticed this happens when you have a poor connection, but considering this issue was opened 3 years ago it's probably a different issue. I've noticed that when I'm connected through TeamViewer to test something outside of my house, this happens a lot. Strangely enough, it can be resolved by raising the prediction tick bias in networking settings.

[Aexxie]

Actually, looking at the other comments, I think this is the same situation. It happens after the game would stutter.

[koteq]

The issue strikes hard when you're an engineer on an EVA mission, building something outside the station. Then JAM! you're running out of the station's grid into the void. And due to jetpacks being a limited resource, you can only toss all your belongings and scream into the radio asking for a help, trying to think of any reasonable IC explanation why have you attempted to suicide.

---

From what I've noticed so far. The jam seems to happen server-side and isolated to the InputMoverComponent.HeldMoveButtons. Here is a screenshot with the issue reproduction on the 0237d095 build.

Notice that the client's debug overlay doesn't show any directional inputs pressed (the 'Walk' one is a red herring, it's lit because of the screenshot shortcut combination), while the server's HeldMoveButtons is set to Up.

I've got into the issue simply by running around the station using only the WASD keys to move my character. Here are the server's logs at the moment when the issue hit me.

[WARN] net.ent: Got late MsgEntity! Diff: -2, msgT: 58191, cT: 58193, player: localhost@JoeGenero
[WARN] net.ent: Got late MsgEntity! Diff: -2, msgT: 58191, cT: 58193, player: localhost@JoeGenero
[WARN] net.ent: Got late MsgEntity! Diff: -2, msgT: 58206, cT: 58208, player: localhost@JoeGenero
[WARN] eng: MainLoop: Cannot keep up!
[WARN] net.ent: Got late MsgEntity! Diff: -2, msgT: 58314, cT: 58316, player: localhost@JoeGenero
[DEBG] system.n_p_c: Sleeping mouse (39) (37112/n37112, MobMouse1)
[DEBG] admin.logs: Saving 4 admin logs.
[DEBG] system.n_p_c: Sleeping mouse (39) (37112/n37112, MobMouse1)
[DEBG] admin.logs: Saving 2 admin logs.
[WARN] eng: MainLoop: Cannot keep up!
[DEBG] admin.logs: Saving 2 admin logs.
[WARN] eng: MainLoop: Cannot keep up!

[koteq]

The reason why the jamming occurs is that the server can accidentally process input events out of order. If you take a closer look at the logs below, you may notice that the client's tick goes backward at some point. I'm not familiar with the game engine yet, but my best guess is that when the server's main loop can't keep up it may get behind clients, so there should be some cool mechanism to sync the server's current tick back to clients, which is when the bug with input jamming may happen.

I used ef4afc56 for testing and added logging to client-side and server-side input handlers.

Client-side, Robust.Client.GameObjects.InputSystem.HandleInputCommand() calls

_sawmillInputContext.Debug($"[{clientMsg.Tick}/{clientMsg.SubTick}/{ts}] f={clientMsg.InputFunctionId} state={clientMsg.State}");

[DEBG] input.context: [21737/ 4553/699067317883732] f=55 state=Down
[DEBG] input.context: [21768/ 8286/699067955264720] f=55 state=Up
[DEBG] input.context: [21778/31951/699068235025250] f=55 state=Down
[DEBG] input.context: [21793/38582/699068568776119] f=55 state=Up
[DEBG] input.context: [21806/44900/699068820163782] f=55 state=Down
[DEBG] input.context: [21798/ 8890/699068991730276] f=55 state=Up

Server-side, Content.Shared.Movement.Systems.SharedMoverController.SetMoveInput() calls

Logger.Info($"[{_gameTiming.CurTick}/{subTick}/{ts}] {buttonsBefore}->{buttons} ({bit}, {enabled})");

[INFO] root: [21737/ 4553/699067525925274] None->Right (Right, True)
[INFO] root: [21768/ 8286/699068220934251] Right->None (Right, False)
[INFO] root: [21778/31951/699068416214053] None->Right (Right, True)
[INFO] root: [21793/38582/699068727281074] Right->None (Right, False)
[WARN] eng: MainLoop: Cannot keep up!
[WARN] net.ent: Got late MsgEntity! Diff: -7, msgT: 21798, cT: 21805, player: localhost@JoeGenero
[INFO] root: [21805/ 8890/699069207261654] None->None (Right, False)
[INFO] root: [21806/44900/699069228388281] None->Right (Right, True)  <-- it gets jammed here

The large number I obtained via System.Diagnostics.Stopwatch.GetTimestamp(), which counts nanoseconds from some arbitrary starting time.

[koteq]

I noticed that FullInputCmdMessage has a convenient InputSequence field, which, I believe, can be used on the server-side to distinguish those pesky out-of-order key presses. Here is pseudocode-ish example:

HandleCmdMessage(IFullInputCmdMessage message) {
    if (message.State == BoundKeyState.Down && lastObservedInputSequence > message.InputSequence) {
        Logger.Warn("");
        return false;
    }
}

[koteq]

Here is me again with my daily findings. I've added more logging lines to the place where the client sends network messages and the place where the server receives the message. Interestingly, the jam isn't happening due to the network errors. It happens because the priority queue that sorts received messages by their ticks.

Here is the full story of how the bug reproduces:

• Server begins to lag behind Client by a couple of Ticks
• Client runs its internal Ticks ahead of Server due to how prediction works
• Player presses a direction button
• Client sends a message to Server about the key press
• Server receives the message and places it into a priority queue to be handled in the future
• Client receives the full state update and rewinds its Tick counter to align with Server
• Player releases the directional button
• Client sends a message to Server about the key release using a Tick that is behind the key press Tick
• Server receives the message and places it into the priority queue
• Server processes the messages in the wrong order, by their Ticks

---

I hope someone more experienced with the game engine can find the information helpful to create a solution to the issue because I don't believe I'll make on my own.

---

Logs and Diffs

There are some logs from when the issue with the input jam happens: ``` Client: [DEBG] input: [8781/16828/744782124333965] fn=MoveLeft state=Down seq=0 [DEBG] net: [8781/ -/744782124408456] CLI-SEND: sec=747 nid=0 euid=0 smsg=tick=8781, subTick=16828, seq=747 func=53; MsgEntity ReliableOrdered 42 [DEBG] input: [8770/ 8914/744782211346301] fn=MoveLeft state=Up seq=0 [DEBG] net: [8770/ -/744782211442027] CLI-SEND: sec=748 nid=0 euid=0 smsg=tick=8770, subTick=8914, seq=748 func=53; MsgEntity ReliableOrdered 41 Server: [DEBG] net.ent: [8781/-/744782272204886] SRV-HAND: sec=747 nid=0 euid=0 smsg=tick=8781, subTick=16828, seq=747 func=53; MsgEntity [DEBG] net.ent: [8770/-/744782423386501] SRV-HAND: sec=748 nid=0 euid=0 smsg=tick=8770, subTick=8914, seq=748 func=53; MsgEntity [WARN] net.ent: Got late MsgEntity! Diff: -10, msgT: 8770, cT: 8780, player: localhost@JoeGenero [DEBG] root: [8780/ 8914/744782423536067] bit=Left enabled=False inputSequence=748 buttons=(None --> None) [DEBG] root: [8781/16828/744782440666152] bit=Left enabled=True inputSequence=747 buttons=(None --> Left) ``` The logs obtained with the following changes (`git diff --submodule=diff`): ```diff diff --git a/Content.Shared/Movement/Systems/SharedMoverController.Input.cs b/Content.Shared/Movement/Systems/SharedMoverController.Input.cs index 1d323a9187..863354d981 100644 --- a/Content.Shared/Movement/Systems/SharedMoverController.Input.cs +++ b/Content.Shared/Movement/Systems/SharedMoverController.Input.cs @@ -6,6 +6,7 @@ using Content.Shared.Movement.Events; using Robust.Shared.Input; using Robust.Shared.Input.Binding; +using Robust.Shared.Network; using Robust.Shared.Player; using Robust.Shared.Serialization; using Robust.Shared.Timing; @@ -20,6 +21,9 @@ public abstract partial class SharedMoverController { public bool CameraRotationLocked { get; set; } + [Dependency] private readonly IGameTiming _gameTiming = default!; + [Dependency] private readonly INetManager _net = default!; + private void InitializeInput() { var moveUpCmdHandler = new MoverDirInputCmdHandler(this, Direction.North); @@ -238,7 +242,7 @@ private void OnInputParentChange(EntityUid uid, InputMoverComponent component, r Dirty(uid, component); } - private void HandleDirChange(EntityUid entity, Direction dir, ushort subTick, bool state) + private void HandleDirChange(EntityUid entity, Direction dir, ushort subTick, bool state, uint inputSequence = 0) { // Relayed movement just uses the same keybinds given we're moving the relayed entity // the same as us. @@ -276,7 +280,7 @@ private void HandleDirChange(EntityUid entity, Direction dir, ushort subTick, bo RaiseLocalEvent(xform.ParentUid, ref relayMoveEvent); } - SetVelocityDirection(moverComp, dir, subTick, state); + SetVelocityDirection(moverComp, dir, subTick, state, inputSequence); } private void OnInputInit(EntityUid uid, InputMoverComponent component, ComponentInit args) @@ -359,7 +363,7 @@ private void HandleRunChange(EntityUid uid, ushort subTick, bool walking) /// composed into a single direction vector, . Enabling /// opposite directions will cancel each other out, resulting in no direction. /// - public void SetVelocityDirection(InputMoverComponent component, Direction direction, ushort subTick, bool enabled) + public void SetVelocityDirection(InputMoverComponent component, Direction direction, ushort subTick, bool enabled, uint inputSequence = 0) { // Logger.Info($"[{_gameTiming.CurTick}/{subTick}] {direction}: {enabled}"); @@ -372,10 +376,10 @@ public void SetVelocityDirection(InputMoverComponent component, Direction direct _ => throw new ArgumentException(nameof(direction)) }; - SetMoveInput(component, subTick, enabled, bit); + SetMoveInput(component, subTick, enabled, bit, inputSequence); } - private void SetMoveInput(InputMoverComponent component, ushort subTick, bool enabled, MoveButtons bit) + private void SetMoveInput(InputMoverComponent component, ushort subTick, bool enabled, MoveButtons bit, uint inputSequence = 0) { // Modifies held state of a movement button at a certain sub tick and updates current tick movement vectors. ResetSubtick(component); @@ -392,6 +396,7 @@ private void SetMoveInput(InputMoverComponent component, ushort subTick, bool en } var buttons = component.HeldMoveButtons; + var buttonsBefore = buttons; if (enabled) { @@ -402,6 +407,14 @@ private void SetMoveInput(InputMoverComponent component, ushort subTick, bool en buttons &= ~bit; } + // TODO input-jam + if (_net.IsServer) + { + var ts = System.Diagnostics.Stopwatch.GetTimestamp(); + Logger.Debug( + $"[{_gameTiming.CurTick}/{subTick}/{ts}] bit={bit} enabled={enabled} inputSequence={inputSequence} buttons=({buttonsBefore} --> {buttons})"); + } + SetMoveInput(component, buttons); } @@ -518,7 +531,7 @@ public override bool HandleCmdMessage(IEntityManager entManager, ICommonSession? { if (session?.AttachedEntity == null) return false; - _controller.HandleDirChange(session.AttachedEntity.Value, _dir, message.SubTick, message.State == BoundKeyState.Down); + _controller.HandleDirChange(session.AttachedEntity.Value, _dir, message.SubTick, message.State == BoundKeyState.Down, message.InputSequence); return false; } } Submodule RobustToolbox contains modified content diff --git a/RobustToolbox/Robust.Client/GameObjects/EntitySystems/InputSystem.cs b/RobustToolbox/Robust.Client/GameObjects/EntitySystems/InputSystem.cs index 41bd23cee..3a28ccd6a 100644 --- a/RobustToolbox/Robust.Client/GameObjects/EntitySystems/InputSystem.cs +++ b/RobustToolbox/Robust.Client/GameObjects/EntitySystems/InputSystem.cs @@ -95,6 +95,11 @@ namespace Robust.Client.GameObjects Uid = GetNetEntity(clientMsg.Uid) }; + // TODO input-jam + var ts = System.Diagnostics.Stopwatch.GetTimestamp(); + var keyFunc = _inputManager.NetworkBindMap.KeyFunctionName(clientMsg.InputFunctionId); + _sawmillInputContext.Debug($"[{clientMsg.Tick}/{clientMsg.SubTick}/{ts}] fn={keyFunc.FunctionName} state={clientMsg.State} seq={clientMsg.InputSequence}"); + DispatchInputCommand(clientMsg, fullMsg); return false; } diff --git a/RobustToolbox/Robust.Client/Input/InputManager.cs b/RobustToolbox/Robust.Client/Input/InputManager.cs index 62ea0f64f..20fb23f24 100644 --- a/RobustToolbox/Robust.Client/Input/InputManager.cs +++ b/RobustToolbox/Robust.Client/Input/InputManager.cs @@ -205,6 +205,9 @@ namespace Robust.Client.Input return; } + var ts = System.Diagnostics.Stopwatch.GetTimestamp(); + Logger.ErrorS("input", "{0}, {1}, {2}, {3}", ts, args.Key, args.ScanCode, args.IsRepeat); + FirstChanceOnKeyEvent?.Invoke(args, args.IsRepeat ? KeyEventType.Repeat : KeyEventType.Down); if (args.Handled) diff --git a/RobustToolbox/Robust.Server/GameObjects/ServerEntityManager.cs b/RobustToolbox/Robust.Server/GameObjects/ServerEntityManager.cs index 280402a16..735fd15ab 100644 --- a/RobustToolbox/Robust.Server/GameObjects/ServerEntityManager.cs +++ b/RobustToolbox/Robust.Server/GameObjects/ServerEntityManager.cs @@ -19,6 +19,7 @@ using Robust.Shared.Prototypes; using Robust.Shared.Replays; using Robust.Shared.Timing; using Robust.Shared.Utility; +using static System.Diagnostics.Stopwatch; namespace Robust.Server.GameObjects { @@ -194,6 +195,10 @@ namespace Robust.Server.GameObjects private void HandleEntityNetworkMessage(MsgEntity message) { + var ts = GetTimestamp(); + _netEntSawmill.Debug( + $"[{message.SourceTick}/-/{ts}] SRV-HAND: sec={message.Sequence} nid={message.NetId} euid={message.EntityUid} smsg={message.SystemMessage}; {message.GetType().Name}"); + var msgT = message.SourceTick; var cT = _gameTiming.CurTick; diff --git a/RobustToolbox/Robust.Shared/Network/NetManager.cs b/RobustToolbox/Robust.Shared/Network/NetManager.cs index 58c14da53..abf759861 100644 --- a/RobustToolbox/Robust.Shared/Network/NetManager.cs +++ b/RobustToolbox/Robust.Shared/Network/NetManager.cs @@ -10,14 +10,17 @@ using System.Threading.Tasks; using Lidgren.Network; using Prometheus; using Robust.Shared.Configuration; +using Robust.Shared.GameObjects; using Robust.Shared.IoC; using Robust.Shared.Log; +using Robust.Shared.Network.Messages; using Robust.Shared.Profiling; using Robust.Shared.Serialization; using Robust.Shared.Timing; using Robust.Shared.Utility; using Robust.Shared.ViewVariables; using SpaceWizards.Sodium; +using static System.Diagnostics.Stopwatch; namespace Robust.Shared.Network { @@ -1039,6 +1042,8 @@ namespace Robust.Shared.Network var method = message.DeliveryMethod; peer.SendMessage(packet, channel.Connection, method); LogSend(message, method, packet); + // TODO input-jam + // _logger.Debug($"SEND: {message.GetType().Name} {method} {packet.LengthBytes}"); } private static void LogSend(NetMessage message, NetDeliveryMethod method, NetOutgoingMessage packet) @@ -1079,6 +1084,13 @@ namespace Robust.Shared.Network peer.Peer.SendMessage(packet, peer.ConnectionsWithChannels[0], method); LogSend(message, method, packet); + // TODO input-jam + if (message is MsgEntity { Type: EntityMessageType.SystemMessage } msg) + { + var ts = GetTimestamp(); + _logger.Debug( + $"[{msg.SourceTick}/-/{ts}] CLI-SEND: sec={msg.Sequence} nid={msg.NetId} euid={msg.EntityUid} smsg={msg.SystemMessage}; {message.GetType().Name} {method} {packet.LengthBytes}"); + } } #endregion NetMessages ```

[DrMelon]

Nice find! It definitely feels like ticks should be monotonic; when the client rewinds to replay server messages, it should replay back up to the current tick instead of ending with a tick count lower than before. To that end, it may be necessary for the client to catch up over several frames and ensure that input is sent using the "real" current tick and not the replay-in-progress tick count.

[ElectroJr]

Its been a long time since I last looked at input handling, but the client should send the inputs reliably while always incrementing InputSequence, and the server shouldn't process them out of order (not saying that's what it does, but what it should do). It also needs to send input windows to make input more resilient to packet loss (e.g., see space-wizards/RobustToolbox/issues/3031). It shouldn't be hard to do, someone just needs to do it

[jamilnielsen]

would be nice if this got fixed, the 2 second lag anytime the server hits a lag spike is my nr.1 gripe.

[jamilnielsen]

i have found the culprit of my issue specifically. Vsync+linux= obvious extremely bad behavior.