"Clock Blockers" replay problem. UserCMD replay is not synchronous between player and bot.

[video]https://youtu.be/HmLw811XG6M[/video]

This video tells you everything you need to know, but in case you can’t watch it here’s the details:

The gamemode I’m experimenting with is called Clock Blockers which is based on a video of the same name by Corridor Digital. The concept of the video is that it’s a Time-Travel FPS; whatever happened in the last round happens again in the next round, allowing you to change the events of the last round.

I’ve made a functional version of the game in Garry’s Mod but I’ve run into a serious speed-bump in development: I can’t get my bots to do exactly what happened in the previous round. It’s very close but it’s never perfect. Currently I have a module that records UserCMD data. That module will replay recorded UserCMDs onto bots, effectively making them replicate key-presses. Other information is recorded as well but that’s not important…

The problem is what happens when the bots attempt to replicate the recording. I currently have two methods for synchronizing the replay rate, both of which are not perfect:

SOLUTION 1:
Think-Counter

SOLUTION 2:
UserCommand-Counter

Does anyone have any idea how I could fix this? Ignoring stuff like lag compensation and prediction, there should be a way to get this to work… right??

The second method seems the one you’re looking for. Are you sure you are recording the events properly based on absolute time? Could you go into more detail? Provide source pls?

Try recording in

GM/FinishMove and StartCommand to replay.

That’s not a bad idea, I’ll give that a shot.

offtopic but that is a really cool idea for a gamemode, good luck

I’m afraid I cannot provide source. There’s just too much code and it’s god damned messy. This was only meant as a prototype anyways; I’m testing the concept out so that I’ll know it can be done before I try to write up the gamemode in a more professional format.

So, to clarify, each player (including the bots, just incase they become “unlinked”) have their own recording for the round. While their recording is in writemode, it takes snapshots (keyframes) of the UserCMD data every time the GM/StartCommand hook is called. Every once in a while the recording will also record other information in a separate buffer about the player’s position, health, weapon, etc… Regardless of which solution is being used, the snapshots record two instances of time-stamp information:

  1. the number of ticks that have occurred so far during that round (which is tracked using the GM/Think hook)
  2. the current count for the number of times the GM/StartCommand hook has been called for that player.

It’s only during replay (that is, readmode) that I can decide which of those two values is used to keep things synchronized. The bots will have their UserCMD data overwritten with whichever data is currently being read by the “readhead.” It is possible for more than one instance of data to be output at a time, assuming that the readhead was more than one instance of data behind in time. Likewise, it’s also possible for the same data to be output more than once (but not at the same time), given than time hasn’t elapsed enough for the readhead to move to the next bit of data in the recording.

Ok, so this uses CMoveData instead of CUserCmd data, but I think I see how a hybrid of the two systems this could be used.

Though figuring out how to mix these all together is going to be tough. The main issue I see with directly manipulating the CMoveData is that reality might not match up with what is expected. For example, the player may have walked through a doorway during the last round, but the door is closed this round. I’m guessing if I override the CMoveData, the bot will simply pass through the door. Mmm, there’s has to be a better way…

EDIT: Ok, so I think I may have found the cause of the problem. I have confirmed that every time the StartCommand hook is called, it is immediately followed up with SetupMove, then Move, and then FinishMove. They’re all synchronous with each other.

It seems that, for whatever reason, the bots do these hooks at a different rate than the human players do. Occasionally, the bots will do an extra call than a human player would.
For example, when I tell the StartCommand hook to print the name of the player, the console outputs something like this



...
Player [1][raubana]
Player [2][raubana 2]
Player [1][raubana]
Player [2][raubana 2]
Player [1][raubana]
Player [2][raubana 2]
Player [1][raubana]
Player [2][raubana 2]
Player [1][raubana]
Player [2][raubana 2]
Player [1][raubana]
Player [2][raubana 2]
Player [2][raubana 2] // Notice the two consecutive calls here.
Player [1][raubana]
Player [2][raubana 2]
Player [1][raubana]
Player [2][raubana 2]
Player [1][raubana]
Player [2][raubana 2]
Player [1][raubana]
Player [2][raubana 2]
Player [1][raubana]
Player [2][raubana 2]
Player [1][raubana]
Player [2][raubana 2]
Player [1][raubana]
Player [2][raubana 2]
Player [1][raubana]
Player [2][raubana 2]
Player [1][raubana]
...


If I were able to get those to be at the same frequency, the timing should match up right.

EDIT: I do know that a human player who’s both a client and the host would have their StartCommand hooks (and all the one’s that are synchronous) called in time with the GM:Tick hook because of this test below. This time I printed out the number of ticks this round has had (I also moved the counter to GM:Tick just to be on the safe side) as well as which player was calling the StartCommand hook.



...
Player [2][raubana 2]
2120
Player [1][raubana]
Player [2][raubana 2]
2121
Player [2][raubana 2]
Player [1][raubana]
2122
Player [1][raubana]
Player [2][raubana 2]
Player [2][raubana 2] // Extra
2123
Player [1][raubana]
Player [2][raubana 2]
2124
Player [1][raubana]
Player [2][raubana 2]
2125
Player [1][raubana]
Player [2][raubana 2]
2126
Player [1][raubana]
Player [2][raubana 2]
2127
Player [1][raubana]
Player [2][raubana 2]
2128
Player [1][raubana]
Player [2][raubana 2]
2129
Player [1][raubana]
Player [2][raubana 2]
2130
Player [1][raubana]
Player [2][raubana 2]
2131
Player [1][raubana]
Player [2][raubana 2]
2132
Player [1][raubana]
Player [2][raubana 2]
2133
Player [1][raubana]
Player [2][raubana 2]
2134
Player [2][raubana 2]
Player [1][raubana]
2135
Player [1][raubana]
Player [2][raubana 2]
Player [2][raubana 2] // Extra
2136
Player [1][raubana]
Player [2][raubana 2]
2137
Player [1][raubana]
Player [2][raubana 2]
2138
Player [1][raubana]
Player [2][raubana 2]
2139
Player [1][raubana]
Player [2][raubana 2]
2140
Player [1][raubana]
Player [2][raubana 2]
...


It’s hard to say whether or not actual human clients who’ve connected externally would exhibit this same behaviour on the server as a bot would. I’ll need to do more tests to determine that.

try looking at the tick counts

Could you be more specific please.

Well, I remember reading someone preventing usercmds with tickout 0 from being processed,
because garrysmod apperently called CreateMove with invalid usercmds ( maybe for prediction though? ) sometimes.
The same might apply to StartCommand. They should also increase in a normal sequence ( 1-2-3-4-5 … ).
Otherwise, as semi hacky idea, you could try working around with CurTime or something to decide whenever it’s the right time for a new cmd.

I redid the test, this time with an external client. It seems that clients are synchronous with the server’s tickrate, but I assume because of how TCP/IP works that several instances of that hook are processed at a time when the server receives a packet containing several instances of CUserCmd (and CMoveData??).



...
16770
Player [1][raubana] // 1
16771
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
16772
Player [1][raubana] // 1
16773
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
16774
Player [1][raubana] // 1
16775
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
Player [2][NAME_REMOVED] // -1
16776
Player [1][raubana] // 0
16777
Player [1][raubana] // 1
16778
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
16779
Player [1][raubana] // 1
16780
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
16781
Player [1][raubana] // 1
16782
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
16783
Player [1][raubana] // 1
16784
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
Player [2][NAME_REMOVED] // -1
16785
Player [1][raubana] // 0
16786
Player [1][raubana] // 1
Player [2][NAME_REMOVED] // 0
Player [2][NAME_REMOVED] // -1
16787
Player [1][raubana] // 0
16788
Player [1][raubana] // 1
16789
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
16790
Player [1][raubana] // 1
16791
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
16792
Player [1][raubana] // 1
16793
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
16794
Player [1][raubana] // 1
16795
Player [1][raubana] // 2
16796
Player [1][raubana] // 3
Player [2][NAME_REMOVED] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
16797
Player [1][raubana] // 1
checked game state
16798
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
16799
Player [1][raubana] // 1
16800
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
16801
Player [1][raubana] // 1
16802
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
16803
Player [1][raubana] // 1
16804
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
Player [2][NAME_REMOVED] // -1
16805
Player [1][raubana] // 0
16806
Player [1][raubana] // 1
16807
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
16808
Player [1][raubana] // 1
Player [2][NAME_REMOVED] // 0
Player [2][NAME_REMOVED] // -1
16809
Player [1][raubana] // 0
16810
Player [1][raubana] // 1
Player [2][NAME_REMOVED] // 0
Player [2][NAME_REMOVED] // -1
16811
Player [1][raubana] // 0
16812
Player [1][raubana] // 1
16813
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
16814
Player [1][raubana] // 1
16815
Player [1][raubana] // 2
Player [2][NAME_REMOVED] // 1
Player [2][NAME_REMOVED] // 0
Player [2][NAME_REMOVED] // -1
16816
Player [1][raubana] // 0
16817
Player [1][raubana] // 1
...


In theory, this should NOT cause a problem with replays (unless there’s packet loss, I believe).
At this point I believe it’s fair to say that the bots are the cause of this problem. For whatever reason, the game engine gives them an extra tick than players get (this would explain why they can run slightly faster than me). Wouldn’t this count as a bug? Perhaps I should report it.

[editline]18th February 2016[/editline]

Ah, I see. Well unfortunately calling CUserCmd/TickCount will only output 0 for bots, which seems to hamper my ability to come up with a hacky solution to the problem. Solution 1 that I listed above (which keeps track of the number of times GM:Tick is called) is essentially the same idea as using CurTime as a timestamp. It seems that the bot still has its movement simulated for those keyframes that are repeated when the bot calls the GM:StartCommand hook more than once per tick, which I believe is why its position becomes offset - the engine is having to run movement simulations more than once for the same keyframe during a single tick.

EDIT: Oh! I see what you mean now. Assuming that the readhead hasn’t moved between calls, then the bot should not process any CUserCmd data and/or CMoveData. I don’t know if there’s a way to suppress CUserCmd data, but I’ll look into it though. Thanks!

Source engine uses UDP and lua isn’t multithreaded :v
You could try reporting it or compensating it and no problem,
if you have any questions, feel free to add me on steam.
I don’t really do anything with gmod though,
but I wouldn’t mind helping

Based on the suggestion from Leystryku, I’ve managed to come up with a very hacky solution that kind of works.

I’ve changed the recording system to only output keyframes that have timestamp data in the past. That means that a keyframe will be output once and only once. In the event that no keyframes are output (like when a bot calls GM/StartCommand more than once per tick), then the bot will have a temporary variable “temp_frozen” set to true. This variable is referenced in GM/FinishMove, which will return “true” if that variable is also true for that player. This effectively suppresses their simulation without killing their momentum. Although it’s not perfect, it’s pretty damn close.

EDIT: Ok, as it turns out, this only kind of works when the player keeps their feet on the ground. It’s totally broken whenever they jump a lot.

A report was made on the bug I mentioned before. Hopefully it’ll be fixed, because it’s the main cause of my agony right now.

eww udp

I believe a quick solution to my problem might be to use actual bots instead of player NextBots.

Personally I would wait for an official patch, nextbot players is the best thing to do right now imo

As of the update released today this problem has been resolved!

I’ve recorded and uploaded me testing out this update. Here are the results:
[video]https://youtu.be/Ru8rcGLDPrM[/video]

This was fixed really quickly. Thank you, Facepunch Team :smiley: