REPORT: Diagnosing the GoAHead Issue
Lisias opened this issue · 15 comments
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:
- Installable (with 175 Add'Ons), that CKAN successfully installed on my test bed:
- Not Installable (with 108 Add'Ons) that were not installed by CKAN, and it will be used later as the test progresses.
Test Script:
- I will try first to create a new empty savegame and see if I can reproduce the problem easily with the Installable add'ons.
- If I fail, I will try to load the provided savegame and just let crafts be removed as the needed add'ons (if any) are not present, and then I will try to reproduce the problem.
- If I still fail, I will start to install the Add'Ons from the 'not installable' ModList somehow, and try again.
Addendum to #52 (comment) :
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).
The problem itself will be worked on #49
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.
Post Mortem.
I audit the git history looking on where I had made such mistake and…
On commit 22cb39d 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.
Humm… As an initial run, things are already not too promising….
I will ignore this for the time being.
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)
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.
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.
Question… Between 0.2.2.2 and 0.2.2.3 AttachedOnEditor had the moduleVersion bumped… Why this didn't happened before??? o.O
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.
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
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!!!!
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. :)