https://metaplay.io logo
Leader and Follower timelines diverge, leading to ...
# questions-and-feedback
a
Alright, this one’s been bugging me for two straight days and I could use some input. For context: I’m working on a quest system that can progress, remove, and add new quests. At the start of the game, I have Tutorial quests that are delivered one by one. Here’s the issue: * When I complete the first Tutorial quest, the second quest’s ProgressAction gets staged and then re-run on the CheckpointModel. * On client, everything works fine — staging and re-running behave as expected. * On server, the staging still works correctly, but when it re-runs, it somehow operates on an already mutated model. Because of that, the quest fails for obvious reasons, even though no error is thrown (yet). Eventually, on subsequent actions, the system realizes there’s a desync and ends up sending desync with a null action. So basically, the rerun logic is fine on client, but server-side it’s working on a mutated state, which is causing the desync.
j
Could you share more info? E.g. the actions, and how you're enqueuing actions?
a
The Quests are held inside
PlayerModel
as
MetaDictionary<QuestId,QuestModel>
. * When the player session starts, they are calculated on
PlayerActor
and added by a
QuestAddAction : SynchronizedServerAction
* When players progresses through the quest,
QuestProgressAction : PlayerAction
is enqued, incrementing progress inside
QuestModel
and making the quest collectable * After player collects this quest,
QuestCollectAction
is called by Client. This actions removes quest from
MetaDictionary<QuestId, QuestModel>
and calls
ServerListener.QuestCollected()
. * From here on
ServerListener.QuestCollected
calculates new quests to adds them with
QuestAddAction
completing the cycle.
When I finish the first quest and get the second one, the
ProgressAction
enqued on Client (finishes with success both at staging and checkpoint rerun) BUT on the Server completes as expected on
stagedModel
but fails on
checkpointModel
. The reason is inside
ProgressAction
I check an enum field and see if the quest is already completed; if so return error code. And somehow on the checkpointModel the quest is already completed breaking the timeline :/
j
The most common cause would be that the player model is being mutated outside of the action, e.g. the serverlistener gets passed a reference which then gets modified. Another possibility is that if 2 members refer to the same object, when the model is serialized and deserialized, these no longer point to the same object but to 2 separate instances instead. You can also try changing the consistency checks to be more aggressive (in exchange for performance), which might give better error messages. You can add the following to your options file:
Copy code
Player:
  DebugConfig:
    ClientConsistencyChecks: true
    ServerConsistencyChecks: true
    ChecksumGranularity: PerOperation
It'd be helpful if you could post the error message that you're getting as well to further narrow down, similarly the code snippets for the actions and server listener would be appreciated.
a
If you have time I can show it you, I guess it would be quicker 😌
but thanks I'll check with the config you've given and provide you the console logs.
j
Unfortunately, we're not able to offer support calls without a support contract. We're happy to continue to help here though!
a
That is totally fine 😌
Btw everyhing inside
SharedCode
is set internally so I assume mutating the model outside actions is not the case. I'll explore the second option and try to find a solution. Btw this may sound lame but i am going add this option to
Options.base.yaml
right? wanted to be sure
j
Yep,
Options.base.yaml
or
Options.local.yaml
both work, the latter is likely better if you're going to keep the setting around, but if you're going to remove it, then either works
a
Alright here is there deal, once I add the config you've provided, the error does not happen.
j
It does indeed seem like there is a some modification of the player model outside of an PlayerAction executed in the PlayerContext or some similar case where it is unintuitively causing an illegal modification of the player model. This is difficult to debug without an isolated repro case, if you'd be able to create and share one that would be appreciated, or if you want further hands-on debugging help, we can provide that under a paid support plan.
a
What happens is, since the action cannot run on the checkpoint model, it cannot make the proper changes inside the checkpoint model hence the server checkpoint diverges while the stagedModel is fine. I will try to isolate it once I catch up with work and keep you posted once it is done.
a
Hi, while waiting for a repro case we've been trying to reason about what you might be seeing here and we've had some difficulty in interpreting your discoveries on the actual mechanism of the bug. Let me try to elaborate on the shared model timeline design a bit in the hopes that it helps narrowing down the issue faster. As this is happening with the player model, the timeline is "owned" by the client. In the terms we use in the SDK source code, the client is the "leader" and the server is a "follower". On both ends the most up-to-date version of the model is indeed called "staged model". On the leader (client) side only we additionally keep an older version of the model that is called the "checkpoint model". The checkpoint model is essentially a historical snapshot of the model, and it is updated to match the latest time that the server has acknowledged to be in sync. The checkpoint model is kept only for desync debugging purposes, and no actual game code should ever interface with it. When a desync (checksum mismatch) is detected things have already gone wrong, the current ("staged") models on client and server do no match based on their checksums. It's only after the server reports the mismatch that we consult the checkpoint model by bringing it up-to-date to the time of the checksum mismatch (by rerunning actions on the checkpoint model between when the snapshot was taken and the time of the desync) and dump the diff to console. The config option that @Jurjen proposed changes the frequency that we calculate checksums at. A checksum is taken after every Action in both the default and the modified settings, the difference is with how often checksums are taken between actions. It is very unexpected that changing the setting would change the occurrence of a desync issue.
a
Hey @Antti // Metaplay! Thanks a lot for your response and your thorough explanation about the internals of Metaplay, I will look into the issue with the insight you've provided. I find it quite interesting that the 'checkpoint model' is only on the client. It feels contradictory to me catching this error on the server side. I've actually used
DebugLog
to see if the action is being executed on a correct model or not and while the client side prints 2 successes (guessing one for stage and one for check point), the server side runs the same action twice as well but with 1 success and 1 fail (first one being stage and second one on checkpoint). Additionally, when I drop a breakpoint to this 'fault state check' inside the action, I can catch it on server and the stack points to the checkpoint rerun (
ModelJournal.Follower.CommitOperationRange
). From what I understand from your explanation the
_timeline.IsCheckpointingEnabled
should be false or not have to checkpoint logic to begin with, alas, neither is the case 😄 Meanwhile I've made a simple flow of Actions being taken from both the server side and the client side which you can find here: https://drive.google.com/file/d/1r2PidDms2wuY_0Zb0ky_aygauuB4PXRT/view?usp=sharing
a
Turns out my grasp of the internals is rusty 😊 . You are right, the server also maintains a checkpoint model (with default configuration) for the same purpose of being able to pinpoint the location of a desync when one happens. And indeed as you have observed, when a batch of actions has been successfully executed on the server staged model they are then run on the checkpoint model to bring it up to date (faster than taking a copy of the model via serialization roundtrip).
In the same fashion as on the client, the checkpoint model shouldn't be used for anything else than desync debugging. The fact that the action you were debugging is observing a different state between the staged and checkpoint model is a clear indication of something being off, but the diverged checkpoint model shouldn't be causing an error by itself. It just means that when a server/client desync is detected we're probably not getting reliable info on the location of the mismatch.
Just making sure: after enabling the more extensive debug checks have you checked if the server logs contain any potentially useful information? The "ServerConsistencyChecks" report any issues found by error-level logging rather than informing the client.
a
That is the curveball on this matter I guess, 'ServerConsistencyChecks' actually solve the issue rather than giving more information on it. I have looked through the logs multiple times to see and inconsistency that might give more information about the bug to no avail 😔
a
The consistency checks, among other things, end up re-running those same actions on yet different models. If there's any leaking of state happening from an action run then maybe further re-runs end up masking the error situation. But the consistency checks definitely aren't intentionally fixing anything.
We've identified the issue that causes
ServerConsistencyChecks
to accidentally alter the behavior of the checkpoint model re-run and this will be fixed in the next SDK update. This explains why enabling the checks hides the issue, but the original issue turned out to be sneaky sharing of state between the actual and the checkpoint model.