Save/Load + Rewind oddity

[Forestidia86]

I'm not sure if that's intended but I encountered something as I retried "Santa's Workshop".

If you do the following:

do some actions,
then use save,
rewind and cancel replay,
get past the point of the actions,
save and load
and (cancel replay,) then rewind again

then the old actions of the old save are done/present in the rewind.

This seems odd since you discarded these old actions by your first rewind and it leads to odd jumps in play.

I know this explanation is convoluted, so I attached a video that tries to demonstrate that.

[Simon]

Excellent catch, and a useful video with a reduced bug showcase. I can reproduce this exactly. Thanks!

Lix caches the gamestate in regular intervals to avoid expensive recalculation from the very beginning. It looks like the cache keeps outdated states after the save-and-load. A year ago, I had already fixed a similar cache invalidation with restart-level instead of load-state.

Github issue #261

-- Simon

[Forestidia86]

What I encountered with "Santa's Workshop" seemed to be even a more significant instance of the issue since rewinding seemed to even get to a "future" state:

Spoiler (click to show/hide)

I loaded a state where there was no basher tunnel at a certain place, I hadn't even assigned the basher in this loaded state yet, but if I pressed rewind just once it got to a state where there was a finished basher tunnel there.

Unfortunately I didn't record it and couldn't reproduce this extreme case but therefore I think my video nevertheless shows an instance of the same issue. I think your remarks explain the case I encountered originally as well.

[Simon]

I have a fix for this on the stove, it will go into the 0.9.3 release next week.

This was not cache invalidation, but rather I had flawed logic on the savestate command: (Don't replace the old savestate's replay with the current replay if the current replay is an initial part of the old savestate's replay.) In the original post's example, during the line (save and load), the current replay is empty, therefore the condition is true and we don't replace the old savestate's replay.

The fix is to always save current replay even if it cuts short the already-saved replay. That's not only expected, but makes the code simpler, too.

-- Simon

[Forestidia86]

There still seems to be a problem with saving, loading and rewinding (v. 0.9.8).

I have encountered something really weird in the Daunting level "Hellfire". I couldn't reproduce what exactly happened there to me but maybe something related.
I used save and load at some point in this level because I discarded one idea. Then I made progress in the level but misassigned in a way that I used fast frameskipping back a couple of times.

- One thing that happened was a sudden huge warp back or a warp to a completely other place/situation, which was interestingly close to the save point.
- But unfortuately that was not the only thing: It brought me to a point where later actions were already performed at this much earlier place and almost all my lix were dead due to that. I couldn't fast frameskip back as well anymore so I reloaded.
- I solved the level then and it was automatically saved under solved but as I looked at it, it didn't solve but had seemingly senseless actions in it.

Concerning the last point: I looked in the file and it has this line:
! 778 0 ASSIGN=BLOCKER 1
If you take that out the replay solves. I've attached the replay as well as a replay without that line.
This line somehow makes sense in connection with what I could reproduce. (Although it doesn't have to be since I actualy tried using that blocker placement but discarded it. Hm, I don't know.) Note that the level has only two blockers but the original replay has saved three assignments.

As I indicated I couldn't repoduce any of the situations but I could reprouce an irregularity nevertheless:

- Make some actions.
- Save.
- Fast frameskip back before the last action.
- Load.
- Wait a bit (just turbo fast forward a bit).
- Fast frameskip back.

=> The last action before the save is done (in some sense repeated) at some point, which is actually after it was done originally. (The outcome of the original action is kept as well and it doesn't use up a skill although it is in some sense an extra action in this situation. Hm, it seems to happen at the same place, though, and generally doesn't get into the replay file.)

I have attached a video to demonstrate.

Edit: I tried what I did in the video with exploders and although you can see the explosion and hear the sound of it you get no flinging. So the repeated action has no effect on the surrondings. So maybe another oddity than I have encountered in "Hellfire".

[Simon]

Thanks for the detailed report!

Cache invalidation is hard to track down, I'll keep it in mind. I should stare at the source these days and maybe I'll see something. This bug may be rare, but its impact is severe -- it breaks equality of displayed physics and saved replay.

I've watched the video,  and I believe it's not the physics cache invalidation; rather it seems to be #23: Load user state, framestep back -> unnecessary replay arrows. This is a leftover bug from how I decide which effects to render. Most likely, manaul savestating should preserve the cache of rendered effcets. Effects are arrows, sound effects, explosion animations, flying pickaxes.

-- Simon

[Forestidia86]

I have made a video where I think something odd happens concerning replay storage with saves. Unfortunately I still don't have the exact steps to it.
What happens:

I load the save and do an action.
I load again and let the replay play through. -> It does another action from an earlier attempt.

I used "Goblin City" as test ground.

[Simon]

Wow, you caught it on video, and it matches very much the original description in reply #4. Nice! Still, I see a theory without bug for this video:

When you made the savestate, was the jumper already in the replay? The game prints the R in the corner throughout all of the early part of the video. When you savestate with an undone jumper in the replay, this jumper assignment will be preserved. When you stateload, such an assignment will be written back into the replay.

Speculation from reply #4: Bug might hit more often on huge maps. On larger maps, the game will run out of VRAM sooner, it will then throw away early auto-savestates. It will preserve the manual savestate.

For debugging, maybe I should print the entire replay (one line per assignment in the replay) to the screen at all times.

-- Simon

[Forestidia86]

When you made the savestate, was the jumper already in the replay?

I actually can't answer this question since I did so many things to force it.
But I maybe should say that I've unticked the option to keep the replay when rewinding. So rewinding cancels for me. Nevertheless the jumper could be in the replay by just loading after having done the jumper assignment. Apart from that even with rewind cancelling all the replay up to that is stored in the save.

[Simon]

Rewinding cancels for you, yet you have the floating R in the top-left corner. Hm, yeah, maybe you have stateloaded before you began the video. In this case, the entire session, starting with loading the map, would have been helpful.

No idea what'se easiest for you to transmit fat video file -- forum is bad for longer video, forum still eats large attachments and your typed post without error message.

But even better: I've pushed branch debug-replay to unstable repository. This prints the entire replay during play at all times. I hope this shows how manual savestaes interacts with replay. And it will be very helpful on future video capture.

You shouldn't be able to produce 3 blocker entries in the replay when there are only 2 blockers in the skillset. The original bug report from #4 had 3 blocker entries for 2 blocker skills. I cannot explain that, and will be on the lookout in the code for anything that causes that.

-- Simon

[Forestidia86]

I've tried around and made some videos but unfortunately couldn't reproduce it until now.
To a certain extent the actions within a savestate are stored outside of the running replay. For example if you cancel an actions before the savestate point it doesn't show them anymore on the list but if you load the save it brings them back on the list.

[Simon]

Yeah, the manual savestate involves copying the replay, then restoring this copied replay on stateload. It's designed like this:

• On statesave, the active replay replaces the savestate's replay.
  
• On stateload, the savestate's replay usually replaces the active replay -- unless the savestate replay is already a part of the active replay, in which case we keep the active replay.
  

It makes sense to have it like this, but the replay/savestate copying/caching is complicated in total. It's likely that there is still a bug here.

-- Simon

[Forestidia86]

But can you show what is stored in the savestate in an extra list?

What I noticed from my save+load3 video is that it makes the cancel sound when I load after imploder. I think it usually only does it if one has canceled actions of the savestate and then done other actions?

[Simon]

I pushed again to debug-replay. Now, if savestate's replay exists, I print savestate's replay to the right of active replay.

Whenever you stateload: The snipping sound plays because stuff in the active replay is discarded -- unless the stateloaded replay is an initial segment of the active replay, then we keep the active replay and no snipping sound plays.

-- Simon

[Forestidia86]

Thanks.

Whenever you stateload: The snipping sound plays because stuff in the active replay is discarded -- unless the stateloaded replay is an initial segment of the active replay, then we keep the active replay and no snipping sound plays.

But isn't that the problem that it shouldn't make that snipping sound since the jumper is after the savestate and shouldn't therefore be in there?
I've attached a video what normally happens if you do that what I did in save+load3.

[Simon]

Let's first go over save+load4, because we agree that there is no bug here:

* Dig in frame 80
* Savestate in frame 400
  - Savestate's replay has (80 digger)
* Jump in frame 1006
* Load the savestate.
  - Active replay stays active (Reason: State's replay is initial segment of active)
  - No snipping sound (Reason: We didn't cut anything from active replay)
  - We return to frame 400
* Implode at frame 441
  - Snipping sound plays (Reason: We cut the jumper assignment from frame 1006)
* Load the savestate again.
  - Active replay stays active (Reason: (80 digger) is initial segment of (80 digger, 441 imploder))
  - No snipping sound (Reason: We didn't cut anything from active replay)
  - We return to frame 400
  - If we wait until frame 441, we'll see the imploder play back.

Here's a scenario in which save+load3 is bug-free in 0.9.9 design:

* Dig in frame 100
* Jump in frame 1300
* Framestep back to frame 500
* Savestate in frame 500
  - Savestate's replay has (100 digger, 1300 jumper)
  - R in corner is visible (Reason: future assignment of 1300 jumper)
* Begin video capture
* In frame 550, load state.
  - Active replay stays active (Reason: state's replay is identical to active)
  - No snipping sound (Reason: Active remains as-is)
  - We return to frame 500
  - Active replay is still (100 digger, 1300 jumper)
  - State's replay is still (100 digger, 1300 jumper), same as active
* Implode at frame 700
  - This cuts (1300 jumper) from active replay (Reason: 1300 is in the future)
  - Snipping sound plays (Reason: We cut something from active replay)
  - Active replay is now (100 digger, 700 imploder)
* Load the savestate.
  - State's replay is still (100 digger, 2000 runner)
  - State's replay overwrites active (Reason: State's replay isn't initial segment)
  - Snipping sound plays (Reason: We cut (700 imploder) from active replay)
  - Active replay is now (100 digger, 1300 jumper)
  - If we wait until frame 1300, we'll see the jumper play back
 
-- Simon

[Forestidia86]

Here's a scenario in which save+load3 is bug-free in 0.9.9 design:

* Dig in frame 100
* Jump in frame 1300
* Framestep back to frame 500
* Savestate in frame 500
  - Savestate's replay has (100 digger, 1300 jumper)
  - R in corner is visible (Reason: future assignment of 1300 jumper)
* Begin video capture
* In frame 550, load state.
  - Active replay stays active (Reason: state's replay is identical to active)
  - No snipping sound (Reason: Active remains as-is)
  - We return to frame 500
  - Active replay is still (100 digger, 1300 jumper)
  - State's replay is still (100 digger, 1300 jumper), same as active
* Implode at frame 700
  - This cuts (1300 jumper) from active replay (Reason: 1300 is in the future)
  - Snipping sound plays (Reason: We cut something from active replay)
  - Active replay is now (100 digger, 700 imploder)
* Load the savestate.
  - State's replay is still (100 digger, 2000 runner)
  - State's replay overwrites active (Reason: State's replay isn't initial segment)
  - Snipping sound plays (Reason: We cut (700 imploder) from active replay)
  - Active replay is now (100 digger, 1300 jumper)
  - If we wait until frame 1300, we'll see the jumper play back
 

Simon that's just not what usually happens. Rewinding cuts the jumper out of the replay. I have attached a video.

[Forestidia86]

If you have ticked that the replay is kept upon rewinding then it behaves as you describe.
But I'm not sure if that is good since with loading you usually want to discard some of the later actions?

[Simon]

Ah, yeah, I forgot that, during save+load3, you would have discarded replay actions on framestep-back.

Here's the scenario where save+load3 is still bug-free even when you discard replay actions on framestep-back. Changes to reply #15 are in bold.

* Dig in frame 100
* Savestate in frame 500
* Jump in frame 1300
* Load state
  - State's replay was (100 dig)
  - Active replay was (100 dig, 1300 jump)
  - Therefore, keep active replay because state's replay is initial segment.
  - We're back in frame 500
* Savestate again in frame 500
  - State's replay was (100 digger)
  - State's replay is now (100 digger, 1300 jumper)
  - R in corner is visible (Reason: future assignment of 1300 jumper)
* Begin video capture
* In frame 550, load state.
  - Active replay stays active (Reason: state's replay is identical to active)
  - No snipping sound (Reason: Active remains as-is)
  - We return to frame 500
  - Active replay is still (100 digger, 1300 jumper)
  - State's replay is still (100 digger, 1300 jumper), same as active
* Implode at frame 700
  - This cuts (1300 jumper) from active replay (Reason: 1300 is in the future)
  - Snipping sound plays (Reason: We cut something from active replay)
  - Active replay is now (100 digger, 700 imploder)
* Load the savestate.
  - State's replay is still (100 digger, 2000 runner)
  - State's replay overwrites active (Reason: State's replay isn't initial segment)
  - Snipping sound plays (Reason: We cut (700 imploder) from active replay)
  - Active replay is now (100 digger, 1300 jumper)
  - If we wait until frame 1300, we'll see the jumper play back

It's a very concocted sequence, and I've filed #295: Savestate shouldn't preserve future when !(keep replay after ◀▮) because I don't like this behavior in 0.9.9. Still, it's possible in 0.9.9 and doesn't exhibit the reply-#4 bug.

-- Simon

[Forestidia86]

Yeah, that's what probably happened in my tests.

I'm actually out of ideas how to reproduce the bug especially since savestate/stateload behaves intendedly so peculiar.

[Simon]

Thanks for the efforts still, and this debugging code is good to have around.

If you feel that fixing #295 Savestate shouldn't preserve future when !(keep replay after ◀▮) still won't be a good design, feel free to suggest improvements to the savestate-replay-handling. As it stands, it's confusing, even though it often does what you want. Sometimes it does more than what you want, but then you can cancel.

-- Simon

[Forestidia86]

The only thing which could be counted in is that I have slow machine with low FPS. So especially fast frameskipping back behaves shaky/produces bigger steps back by design. Maybe these kinds of recalculations play a role?

[Simon]

I can't be sure since I don't understand the bug, but I doubt the slow machine affects the correctness of the algorithm.

After reading your reply #4 several times, the biggest oddity remains the extra blocker assignment in the replay. Crazily, after you got stuck and restarted from scratch (which should clear the replay considering your option preserves the replay but you'd still erase it on your first assignment before frame 800), this blocker assignment remained in the replay.

-- Simon

[Forestidia86]

I can't be sure since I don't understand the bug, but I doubt the slow machine affects the correctness of the algorithm.

I meant less the slowness of the machine itself but rather how your code handles it. It tends to do at times huge warps backwards when using fast frameskipping back and it really looks shaky then.
Would it be possible that the recalculations access the savestate rather than the active replay?

[Forestidia86]

Simon, I have it recorded. I used the level "Any Way You Want": It shows a basher asssignment as past actions in the list but none of the bashers is used up.
In this case it doesn't seem to erase the action from the active replay when loading a later point phyu-wise and the save is still part of the replay actionwise.

So basically:

Save.
Rewind a bit (don't cancel anything which would belong to the save).
Do an action (before the phyu-point of saving).
Load.
=> Action still in active replay as past action (although not part of the loaded state).

Edit: Exchanged "Hellfire"-video with a much more to the point video.

[Simon]

Amazing reduction! What a glaring and simple way to have unprocessed assignments in the replay.

It certainly looks like a logical error in the code, should be unrelated to increasing the framestep length on slower machines.

-- Simon

[Forestidia86]

I think it belongs more to this thread:

It doesn't seem to desync anymore with the method I found.
To preserving future: The case mentioned in the issue shouldn't work this way anyways since rewinding before an action cancels if you don't keep replay (, unless you've meant A,C instead of A,B in the end?). But you've mentioned another case in the thread, where you load instead of framestep back. Well loading cuts now all out what doesn't belong to the savestate (even if you have keep replay on and it's after the savestate), so with that the future replay is discarded as well.

Just to clarify if you have keep replay when rewinding on there is still a possibility to have future in the savestate: By framestepping back before an action and then saving.

----
Well and one new desync problem: If you go to a phyu before the save now and cancel an action of the save you have to press load twice to get the actions of the savestate in the replay. If you only press once you get the savestate but the action isn't in the active replay.
Video attached.

Edit: Just for clarification: The new desync is a matter of the unstable build.

[Simon]

if you have (option: keep replay when rewinding) on there is still a possibility to have future in the savestate: By framestepping back before an action and then saving.

Yes, this is desired.

Under that option (keep replay after ◀▮), framestepping backwards shall never erase from the replay. And the savestate is designed to preserve as much as possible from the session.

Well and one new desync problem: If you go to a phyu before the save now and cancel an action of the save you have to press load twice to get the actions of the savestate in the replay. If you only press once you get the savestate but the action isn't in the active replay.
Video attached.
Edit: Just for clarification: The new desync is a matter of the unstable build.

Good catch again!

I should really unittest these behaviors and cover our fixes with regression tests, but I'm scared of testing such high-level UI... I guess I have to look into it.

Clicking twice on load-state should have the same effect as clicking once.

-- Simon

[Simon]

Fix for (2 posts above) pushed to unstable master, and I've rebased debug-replay on top of that. If you'd like, you can test debug-replay (ba6e3794), although I'm reasonably confident this time.

Unless we find egregious new problems, I'd like to release these days. I'll include the more frequent garbage collection, even though it didn't fix the ballooning RAM.

-- Simon

[Simon]

I still have bugs. Every time I fix a bug, another of these savestating bugs come back.

But I have now written automatic tests for these savestating bugs. I already test for 3 scenarios, including the 2 from this thread, under both options (keep replay after ◀▮ or discard), which makes 6 automated tests for the state loading. I haven't gotten them to all pass at the same time, but I'm too tired today to investigate further. Will see what I get these days!

Forestidia: You don't have to test anything. Take a couple days off, you earned it.

-- Simon