07th-mod / higurashi-rei

3 stars 4 forks source link

Stuck Sprite Issue [Fix Applied] #4

Open drojf opened 2 years ago

drojf commented 2 years ago

If you get stuck/overlapped sprite issue, please take a screenshot and send us your player.log and Player-prev.log without restarting the game (Press F10 -> Troubleshooting -> Show output_log.txt / Player.log) . If you already closed the game, navigate to the game folder and run the Open Save Folder.bat to show the Player.log files.

Like the previous chapters 5-8. this chapter also seems to have the 'stuck sprite issue'. This doesn't seem related to lipsync, since it was reported on hiru PC ver. See this issue for more details: https://github.com/07th-mod/higurashi-rei/issues/4


We're still getting the stuck sprite issue on Rei

Very importantly:

DD: Also a noting that it happened twice in hiru pc but never in hiru console :naothink: d: oh, so it was without lipsync then? DD: yes d: were the screenshots taken immediately after the bug happened? DD: pretty much yea

d: Today at 12:24 PM does loading the save make the sprite re-appear on your end? I always thought the stuck sprite would be saved into the save, but that doesn't seem to happen DD: Today at 12:26 PM I actually tried loading an earlier save while it was like that, and the sprite came with it, and was now drawn on a scene before that sprite even appeared d: Today at 12:27 PM right so it's more like the session still has it there rather than the save itself once you restart the game it goes away? DD: Today at 12:27 PM Yep

unknown

I tried it again and it didn't have a sprite issue the second time Guess it's just our weird sprite sticking issue, still around even in Rei

unknown2

Save files

Save009, the bottom right corner

SpriteIssue.zip

drojf commented 2 years ago

I was able to reproduce this on the first try starting from near the start of hirukowashi02_2.txt just playing till the stuck sprite occured

EDIT: Easiest way to reproduce is by starting from near the start of `hirukowashi02_2.txt', then continously clicking (using an auto clicker?)

I haven't analsyed yet but here is scrshots etc.

stuck-sprite-drojf

I resized the save screenshots, hopefully the game can still load them

(logs were taken after first image) drojf-saves-and-log-resized.zip

stuck-sprite-drojf-2

stuck-sprite-drojf-3

drojf commented 2 years ago

I noticed during development and also just now while testing that if you right click at a certain time, the cursor (little arrow) will jump to the center of the screen. However DrDiablo has hardly been using it and still gets the issue, has said they were using the quicksave button. Not sure if these issue are related or not.

drojf commented 2 years ago

May be inconsequential/red herring, but I noticed that fading will flicker once the stuck sprite has happened (or before it's about to happen?)

drojf commented 2 years ago

DD: The script for that part had this

    FadeBustshotWithFiltering( 3, "effect/left", 1, FALSE, 0, 0, 300, TRUE );
    ModDrawCharacterWithFiltering(3, 1, "sprite/kei1_ikari1_", "0", "effect/right", 1, 160, 0, FALSE, 0, 0, 0, 0, 0, 20, 300, TRUE );

Where previously Satoko was drawn on layer 3 and it was trying to delete her then draw keiichi d: Today at 3:04 PM I was wondering about that too, but I thought it's fairly common in all the scripts? to fade then draw on the same layer? ACTUALLY oh waitt no console arcs use ch4 so they wouldn't have the issue anyway I was going to ask on console if you do things differently like if you always try to fade on one layer, then draw on another ...actually we can reproduce this so easily that it's worht a shot just never do the fade and draw on same layer? DD: Today at 3:07 PM I'm wondering if it's a difference between FadeBustshot and FadeBustshotWithFiltering d: Today at 3:07 PM ah ok I can also reproduce it on my end very quickly, so I can try that DD: Today at 3:07 PM cool d: Today at 3:07 PM I should setup an auto-clicker (or just edit the dll to auto click) DD: and actually, I think the console arcs never use FadeBustshotWithFiltering, because my code had no idea how to determine what filter to use :shiteatinggrin:

drojf commented 2 years ago

OK, here are detailed reproduction instructions which seem to always work on my computer:

  1. Optional: Install Autohotkey and run this script, which activates an auto-clicker while you hold ALT-B:
    
    #MaxThreadsPerHotkey 3

!b:: While GetKeyState("ALT", "B") Click Sleep 51 ; Make this number higher for slower clicks, lower for faster Return


2. Replace your save data with the one in this archive (**not sure if global.dat is necessary to be replaced**)
[repro-stuck-sprite.zip](https://github.com/07th-mod/higurashi-rei/files/9276016/repro-stuck-sprite.zip)
3. Boot the game
4. Load the save (there is only one save in the first save slot)
5. Click continously or activate the auto clicker
6. When you reach the below scene, there is a very high chance keichi's sprite will overlay mion's sprite:

![image](https://user-images.githubusercontent.com/1249449/183234191-ea2cad50-8bf8-41f3-a421-a4bbafdab2e9.JPG)

Note that the bug state may persist even through loading/saving etc, so if you want to be 100% sure of reproducibility, you should restart the game each time.
drojf commented 2 years ago

I've looked into the issue some more. I'm pretty sure the problem has to do with when you call OperationFadeBustshot()/OperationFadeBustshotWithFiltering() with "isblocking" (the last argument) set to FALSE. I guess this could affect any function with "isblocking" set to FALSE which eventually calls FadeOutLayer.

When this happens, and you click through the fade (I think?), it causes the innermost if statement (if (isBlocking) { ... to NOT execute:

https://github.com/07th-mod/higurashi-assembly/blob/5796215489199032ce5e292f90f78d7ddf7ca2e5/Assets.Scripts.Core.Scene/Layer.cs#L316-L342

This causes the layer to fade out visually, but not become deleted/reclaimed by the layer system (HideLayer() is never called).

I tried just adding an else to the if statement with HideLayer(), which does fix the problem, however I think it may cause some other issues. I'll do some more investigation later.

I also tried changing the isblocking fadebustshot calls to TRUE instead of FALSE and that also fixes the problem.

I also wonder if I'm missing something here, because this is the same as the base game code, and the base game doesn't have this issue (unless the base game just never uses isblocking=FALSE)


edit: I forgot to add a step-by-step of the problem:

  1. While playing, OperationFadeBustshot() (or something similar) is called with FALSE as last argument (isBlocking=FALSE)
  2. You click through this line? causing the bad code path to be executed (HideLayer() never called, layer never reclaimed)
  3. Later on in the script, the layer can be used to draw on just fine
  4. However, when you go to fade that layer again, (with isBlocking=TRUE?) (and it is also clicked through?), it won't fade properly, because the game thinks the layer is not in use and just does nothing

I'm not sure if you need to click through the first time, second time, or both, but clicking through both times seems to cause the issue. Also writing this up, some things don't quite make sense, but I'm pretty sure I'm on the right track.

I also recorded logs with/without the bug happening + debug logging I added, and you can see a difference in the calls to FadeSprite() . Noticeably, I added a log for when the if statement isn't executed (search for "Do nothing???"), and this "Do nothing???" only occurs when the bug occurs. log-for-comparison.zip


edit2: I also forgot to mention that in the FadeSprite function, there is a check to see if the layer is in use via the GetIfInUse() function before performing a fade.

When the bug occurs (on the second call to FadeSprite, when the sprite fails to fade out), the FadeSprite function thinks the layer is "not in use".

I added some debug statements to see exactly why it thinks the layer is not in use, and it is specifically due to the !LayerPool.IsInPool(layers[id].gameObject) part of the conditional: https://github.com/07th-mod/higurashi-assembly/blob/5796215489199032ce5e292f90f78d7ddf7ca2e5/Assets.Scripts.Core.Scene/SceneController.cs#L91-L98

See the below log - check for strings

On the hidelayer-fix.log: FadeOutLayer - WARNING: Attemping hidelayer() FIX On the hidelayer-nofix.log: FadeSprite: 1 inuse: wait: 0.3 isblocking: True - [ERROR: Can't fade sprite as layer is already in pool] hidelayer-check.zip

drojf commented 2 years ago

EDIT: not sure the below is 100% true. Probably need to insert a dummy fn to check whether it is actually called.


Not sure how I missed this earlier, but I know why clicking through the non-blocking fade causes HideLayer() not to be called.

Here is the FadeOutLayer Code


public void FadeOutLayer(float time, bool isBlocking)
{
    if (!(primary == null))
    {
        float current = targetRange;
        targetRange = 0f;
        targetAlpha = 0f;
        GameSystem.Instance.RegisterAction(delegate
        {
            if (Mathf.Approximately(time, 0f))
            {
                HideLayer();
            }
            else
            {
                material.shader = shaderDefault;
                current = 1f;
                FadingOut = true;
                iTween.ValueTo(base.gameObject, iTween.Hash("from", current, "to", targetRange, "time", time, "onupdate", "SetRange", "oncomplete", "HideLayer"));
                if (isBlocking)
                {
                    GameSystem.Instance.AddWait(new Wait(time, WaitTypes.WaitForMove, HideLayer));
                }
            }
        });
    }
}

The iTween.ValueTo(...) function has "HideLayer" as its last argument. When the tween finishes, it will eventually call "HideLayer". However, tweens can be cancelled by clicking, which means "HideLayer" won't be called if you click through the fade AND isBlocking = FALSE.

I had a look through and this "HideLayer" in a tween is called from (proabbly):

  1. FadeOutLayer
  2. FadeLayerWithMask
  3. FadeOut (which is only called from MoveLayer if alpha is set to 0 for a fadeout, not sure if we ever use it in that way)
drojf commented 2 years ago

This comment has been removed because it had inaccurate information, Ill post another comnment later

drojf commented 2 years ago

I've done some more analysis just now.

The main issue looks to be a "double free".

The game internally has a pool of 17? internal layers (this is slightly different from how you draw something on 'layer 1'). When you draw a 'thing', it grabs one of those layers for use. When you fade out the 'thing' or hide it, it puts the layer back.

When you click through the nonblocking fade, it seems to free the layer twice (HideLayer() is called twice). Because there is no protection, it inserts the same layer twice into the layer pool. This causes really strange problems, because then two things might be using a layer at the same time.

I haven't actually traced 100% that the double free/ double HideLayer() is coming from the nonblocking fade, but that is fairly easy to do.

Adding a fix for a double free is pretty easy, and seems to work from my limited testing:

Just call this at the start of LayerPool's void ReturnLayer(Layer layer) function, or at the start of the HideLayer() function (or maybe both)

GameObject gameObject = layer.gameObject;
// Prevent 'double free' where layer returned to the layer pool twice
if (IsInPool(gameObject))
{
    Debug.Log($"WARNING: attempted to return layer [{layer.GetUniqueID()}] more than once!");
    return;
}

Here are two logs, one where the bug happens, and one where it does not. I've allocated each internal layer with a unique ID (Z0, Z1, Z2, Z3 ...).

Comparing the two logs, you can see that the layer Z5 is hidden twice on the buggy version, and appears twice in the layerList.

layer-capture.zip

drojf commented 2 years ago

Just now I was trying to reproduce the bug on Matsuribayashi.

So far, I don't think I've reproduced it "normally", however by making a small change to the timing of FadeOutLayer (making one of the "time" arguments different to the other), I could reproduce the problem exactly the same as we've had in the reported screenshots, I'm actually not sure if that change actually caused it, becauseI could only get it to happen once only happened once. I also had one other time it had basically the same bug, but it didn't quite match the screenshots exactly).

Checking the logs, the code path I mentioned in the last comment was definitely executed (I removed the actual "fix" (the return statement) so I could see the bug), Wherelse it's never executed if the bug does not happen.

I think I may just apply the above fix to all answer arcs chapters and Rei, seeing as it shouldn't do anything bad normally (the path is hardly every triggered anyway). If people still get the bug, we can also ask them to send their logs and check if the code path was hit.

Note that I initially had LipSync ON, but in chapters earlier than Rei, clicking through with LipSync is slow, so I turned LipSync OFF. After turning lipsync off, I got the above two bugs, so this implies (as per reports) that the bug can happen with/without lipsync.


Here is the log from first time I reproduced a similar bug (search "WARNING" in the text file): matsu-simulated-bug-1-not-matching.txt

Here is the log from the second time I reproduce the bug which was exactly the same as other people have sent in (search "WARNING" in the text file): matsu-simulated-bug-2.txt

Here are my save files - the save from when the bug happened is in Folder 5, slots 1 (and 2? not sure). When loaded, mion will appear in a scene she's not meant to be in.

save-with-bug-folder-5-2022-08-13.zip

Here are some images. Please note:

matsu-simulated-bug-2 1

matsu-simulated-bug-2 2

matsu-simulated-bug-2 3

drojf commented 2 years ago

Oh, there is some stuff I've forgot to mention.


Firstly, I don't think this issue requires a non-blocking FadeBustShot anymore - although that may make the issue easier to trigger for unknownreasons. This is because on Rei I could cause the bug even if the the FadeBustShot commented out.


Secondly, my most recent up until just now was that there was a race condition in FadeOutLayer/FadeLayerWithMask if the iTween ended before the Wait. This would cause HideLayer() to be called once by the iTween, then again by the Wait. However in the reverse order, the wait will (presumably) cancel the tween operation, so HideLayer only gets called once.

However, I tried forcing this to happen on matsuribayashi and it doesn't always happen?? so perhaps that's not the actual cause. But on rei, forcing the 'bad' order seemed to always cause the stuck sprite/double HideLayer() to happen.

If the fix mentioned here: https://github.com/07th-mod/higurashi-rei/issues/4#issuecomment-1209277871 does not fix the issue, I guess I'll try to investigate exactly what's causing the issue, but for now I'm not sure it's worth it to get to the absolute root cause.

See comments in below code:


public void FadeOutLayer(float time, bool isBlocking)
{
    if (!(primary == null))
    {
        float current = targetRange;
        targetRange = 0f;
        targetAlpha = 0f;
        GameSystem.Instance.RegisterAction(delegate
        {
            if (Mathf.Approximately(time, 0f))
            {
                HideLayer();
            }
            else
            {
                material.shader = shaderDefault;
                current = 1f;
                FadingOut = true;
                //HideLayer called here once tween ends
                iTween.ValueTo(base.gameObject, iTween.Hash("from", current, "to", targetRange, "time", time, "onupdate", "SetRange", "oncomplete", "HideLayer"));
                if (isBlocking)
                {
                    //On a blocking call, HideLayer called here once Wait ends
                    GameSystem.Instance.AddWait(new Wait(time, WaitTypes.WaitForMove, HideLayer));
                }
            }
        });
    }
}
drojf commented 2 years ago

The fix for the stuck sprite issue should be live now.

Do not close this issue yet - only close it once some time has passed (a month or two?) with no reports of stuck sprites on Rei