search

net-lisias-ksp / KSP-Recall

Recall for KSP blunders, screw ups and borks.
GNU General Public License v2.0
25 stars 2 forks source link

REPORT: Diagnosing the GoAHead Issue #52

Closed Lisias closed 2 years ago

Lisias commented 2 years ago

Some users reported problems on updating to Recall 0.2.2.4.

Random exceptions while gaming are killing the current thread, with various and nasty consequences - from buttons that cease to respond, to graphical items not being drawn, vessels that don't respond to commands, and so goes on.

This is the report for my findings on GoAHead, as he reported that reverting back to 0.2.2.3 solved the problem for him.

My goal on this report is to determine if the problem that affected GoAHead is due the race condition that was mitigated on #45 .

The source material for the research was provided on Forum here but will not be fully copied to this Issue as all that data can potentially have sensitive information.

He provided a ModList with 284 Add'Ons : Modpack.ckan.zip .

However 108 were not installable by CKAN under default command line options.

So I split the thing into two ModLists:

Test Script:

Lisias commented 2 years ago

TUFX had to be deleted, as it doesn't works on MacOS.

Lisias commented 2 years ago

Humm… As an initial run, things are already not too promising….

Screen Shot 2022-06-29 at 23 33 23

I will ignore this for the time being.

Lisias commented 2 years ago

"Good" news. I reproduced the problem.

Now trying to "unreproduce" it.

Lisias commented 2 years ago

AW KRAP

Something is screwing me up royally. This is what I'm getting when installing KSP Recall 0.2.2.3 on an already stablished savegame with that buttload of Add'Ons installed.

    MODULE
    {
            name = AttachedOnEditor
            isEnabled = True
            active = True
            originalPos = (0, 0, 0)
            originalRotation = (0, 0, 0, 0)
            correctlyInitialised = False
            moduleVersion = 0
            stagingEnabled = True
            EVENTS
            {
            }
            ACTIONS
            {
            }
            UPGRADESAPPLIED
            {
            }
    }

And this is what I got when I removed everything but Recall and TweakScale, and updated Recall to 0.2.2.4:

      MODULE
      {
              name = AttachedOnEditor
              isEnabled = True
              active = True
              originalPos = (0, 0, 0)
              originalRotation = (0.331147999, -0.626682758, -0.625449777, -0.326224297)
              moduleVersion = 5
              stagingEnabled = True
              originalAttachNodePos = (0.0, -0.4, 0.0)
              originalAttachNodeSize = 1
              originalAttachNodeOrientation = (0.0, -1.0, 0.0)
              originalAttachNodeOffset = (0.0, 0.0, 0.0)
              originalAttachNodePos = (0.0, 0.6, 0.0)
              originalAttachNodeSize = 0
              originalAttachNodeOrientation = (0.0, 1.0, 0.0)
              originalAttachNodeOffset = (0.0, 0.0, 0.0)
              EVENTS
              {
              }
              ACTIONS
              {
              }
              UPGRADESAPPLIED
              {
              }
      }

Somehow , the AttachedOnEditor.OnLoad is not being called when loading the vessel, because the upgrade code didn't ran on the previous example (moduleVersion is 0, but should be 4). But once I updated to 0.2.2.4 on a clean environment, it worked fine (moduleVersion is 5)

Lisias commented 2 years ago

Oukey, now trying again but using a clean test bed since the beginning:

Recall 0.2.2.3

On an absolute clean KSP (only ModuleManager installed), I installed KSP-Recall 0.2.2.3 and TS (any version, it doesn't matter).

Created a Career game, made a simple craft with a Mk1 Capsule and a Flea. Launched it, quit the game.

screenshot68

SaveGame: default.zip

Correctly initialised Module from the Capsule:

MODULE
{
        name = AttachedOnEditor
        isEnabled = True
        active = True
        originalPos = (0, 15, 0)
        originalRotation = (0, 0, 0, 1)
        correctlyInitialised = False
        moduleVersion = 4
        stagingEnabled = True
        originalAttachNodePos = (0.0, -0.4, 0.0)
        originalAttachNodePos = (0.0, 0.6, 0.0)
        EVENTS
        {
        }
        ACTIONS
        {
        }
        UPGRADESAPPLIED
        {
        }
}

Recall 0.2.2.4

Ditto, but using Recall 2.2.4 instead.

MODULE
{
        name = AttachedOnEditor
        isEnabled = True
        active = True
        originalPos = (0, 15, 0)
        originalRotation = (0, 0, 0, 1)
        correctlyInitialised = False
        moduleVersion = 4
        stagingEnabled = True
        originalAttachNodePos = (0.0, -0.4, 0.0)
        originalAttachNodePos = (0.0, 0.6, 0.0)
        EVENTS
        {
        }
        ACTIONS
        {
        }
        UPGRADESAPPLIED
        {
        }
}

Not good, OnLoad didn't was called, moduleVersion is still 4. :(

And we got that ArgumentOutOfRangeException. So the problem was confirmed. However, and this is what is really bugging me out: this is the saveTo code:

        private void SaveTo(ConfigNode node)
        {
            for(int i = 0; i < this.originalAttachNodePos.Count; ++i)
            {
                node.AddValue("originalAttachNodePos", this.originalAttachNodePos[i].ToString());
                node.AddValue("originalAttachNodeSize", this.originalAttachNodeSize[i].ToString());
                node.AddValue("originalAttachNodeOrientation", this.originalAttachNodeOrientation[i].ToString());
                node.AddValue("originalAttachNodeOffset", this.originalAttachNodeOffset[i].ToString());
            }
        }

Hummm… The OnLoad is not being called on loading the vessel… So the upgradeCode didn't ran, so the this.originalAttachNodeOffset is still empty, as it was not populated by the upgrade tool…. (sigh).

I need to compile a Debug version of Recall to further investigate this crap.

Lisias commented 2 years ago

Question… Between 0.2.2.2 and 0.2.2.3 AttachedOnEditor had the moduleVersion bumped… Why this didn't happened before??? o.O

Lisias commented 2 years ago

Humm… I was kinda wrong, the OnLoad is being called:

[LOG 02:12:15.232] [KSP-Recall.AttachedOnEditor] TRACE: OnLoad Untitled Space Craft-mk1pod.v2:FFFA3CA0 True
[LOG 02:12:15.232] [KSP-Recall.AttachedOnEditor] TRACE: PreserveCurrentAttachmentPoints for Untitled Space Craft-mk1pod.v2:FFFA3CA0 hasAttachNodes? True
[LOG 02:12:15.232] [KSP-Recall.AttachedOnEditor] TRACE: PreserveCurrentAttachments Untitled Space Craft-mk1pod.v2:FFFA3CA0 from (0.0, 15.0, 0.0) to (0.0, 0.0, 0
.0)
[LOG 02:12:15.233] [KSP-Recall.Refunding] TRACE: OnDestroy mk1pod.v2(Clone):FFFA3CF8
[LOG 02:12:15.233] [KSP-Recall.AttachedOnEditor] TRACE: OnDestroy Part
[LOG 02:12:15.239] [KSP-Recall.Refunding] TRACE: OnAwake <NO VESSEL>-solidBooster.sm.v2(Clone):FFFA3C6E
[LOG 02:12:15.240] [KSP-Recall.AttachedOnEditor] TRACE: OnAwake <NO VESSEL>-solidBooster.sm.v2(Clone):FFFA3C6E
[LOG 02:12:15.243] [KSP-Recall.Refunding] TRACE: OnLoad Untitled Space Craft-solidBooster.sm.v2:FFFA3C6E True
[LOG 02:12:15.243] [KSP-Recall.Refunding] TRACE: Resetting RefundingForKSP111x on part Untitled Space Craft-solidBooster.sm.v2:FFFA3C6E

But so, why the upgrade code is not kicking in?

            Log.dbg("OnLoad {0} {1}", this.PartInstanceId, null != node);
            base.OnLoad(node);
            if (this.moduleVersion < MODULE_VERSION)
            {   // Salvage any previsouly saved values
                Log.dbg("Older version {0} detected. Migrating to {1}", this.moduleVersion, MODULE_VERSION);

this.moduleVersion is initialised with 0 on class creation, and it's persisted by KSP.

So to that code be fooled into not entering the upgrade code, this.moduleVersion should be at least equal to MODULE_VERSION(currently 5)… But on the persistent.sfs file, the config says moduleVersion = 4. So from what deepness of hell a bigger number is coming from? Prefab?

Need to add a log to that code.

Lisias commented 2 years ago

I do not understand…

I shoved this line on the OnLoad:

            Log.dbg("OnLoad {0} {1} {2}", this.PartInstanceId, null != node, this.moduleVersion);

And got:

[LOG 02:30:36.676] [KSP-Recall.AttachedOnEditor] TRACE: OnLoad Untitled Space Craft-solidBooster.sm.v2:FFFA3C6E True 4

So, the value is correct. But yet… That if is not kicking in… o.O

Lisias commented 2 years ago

AND NOW THIS CRAP WORKS???

I changed that log line to:

Log.dbg("OnLoad {0} {1} {2} {3}", this.PartInstanceId, null != node, this.moduleVersion, MODULE_VERSION);

And it unsurprisingly logged:

[LOG 02:37:59.233] [KSP-Recall.AttachedOnEditor] TRACE: OnLoad Untitled Space Craft-mk1pod.v2:FFFA3CA0 True 4 5
[LOG 02:37:59.233] [KSP-Recall.AttachedOnEditor] TRACE: Older version 4 detected. Migrating to 5```

BUT NOW THE UPGRADE CODE WORKED. DAMNIT!!!!

Lisias commented 2 years ago

Oukey - I found the problem on the mysterious if not kicking in.

I'm on UNIX, so the file system lives by the iNodes stunt. When VisualStudio rebuilds a project, apparently it is deleting the whole directory instead of deleting just the files.

But it happens I'm using Midnight Commander - way more practical to use it to copy a single DLL than deploying the whole shebang. But apparently, MC keeps the directory iNode opened while we are visualising it, and so when VisualStudio recompile the world, the new binaries end up on a new directory on a new iNode, and I wasn't aware.

By doing something (like hitting CTRL-O or switching directories for a second), apparently MC closes the iNode and open the directory again, and this time the correct iNode is served.

I don't really know if this is what happened, but it's the more plausible explanation I have for that misbehaviour right now. :)

Lisias commented 2 years ago

Schrödinger's fault: it's not my fault, but it is my fault - depending if I'm looking on it or not. #DAMNIT :P

Lisias commented 2 years ago

Found the problem, got rid it. But I still not understanding why this happened…

That's the history:

On Recall 0.2.2.1, I realised I needed to preserve more data on the Module. So I coded the upgrade tool to fill the empty spaces without overwriting the current ones - it looked at a good idea at that time. And the damned thing worked - besides looking into it, it should not. In a way or another, I planted a bomb on 0.2.2.1 that kept ticking until nowadays.

On Recall 0.2.2.2, I realised that the part rotation was also missing on OnLoad, and AttachedOnEditor was updated to save this info too.

Now, on Recall 0.2.2.3 , I realised that I had to apply AttachedOnEditor on all parts, and not only on the parts that have TweakScale. It's counterintuitive, but in fact when attaching parts into each other, TweakScale is called to check if the nodes are correct - and on this process, TS needs to find the scaling part counter-part nodes on the attached part and if the attached part doesn't have it initialised as expected, TS borks. (and yeah, this is the KSP 1.9 Editor screwing up with us). But by this time, lots of people has already their surface of exposure expanded by 0.2.2.2, and now a lot of people ended up stepping on the land-mine.

Oh, well.. Problem diagnosed. Now the job is to fix the damned thing - something that I'm struggling by some reason, it should not be that hard…. Anyway, this is a job for another issue, this one is closed now.

Lisias commented 2 years ago

The problem itself will be worked on #49

Lisias commented 2 years ago

Post Mortem.

I audit the git history looking on where I had made such mistake and…

On commit https://github.com/net-lisias-ksp/KSP-Recall/commit/22cb39dc884dfdf12b0ac1d5fcda3ba6a575d04e on April, 19, I added yet more data to be preserved (if the attachment nodes position are missing, so obviously the rotation and offset are too!!). But I forgot to update the MODULE_VERSION to 6!!!! #facePalm .

THIS is the reason things are borking on my rig and I was not finding why. It was not a buggy code, it's MISSING CODE.

Lisias commented 2 years ago

Addendum to https://github.com/net-lisias-ksp/KSP-Recall/issues/52#issuecomment-1171426138 :

So, now, on 0.2.2.4 I had (finally) realised that if the part's attachment node positions are missing, so are the rotation and offset, and included these ones on the solution. But… (and this is here that huge brain fart happened), I forgot to increase the MODULE_VERSION. So the damned upgrade code was not detecting the problem, and so it was not running that specific upgrade - and this is the reason this was working for MODULE_VERSION 3, 4 and 5 (from 0.2.2.2 and previous).