Understand why `BetterEditorUndoRedo` ended up screwing `AttachedOnEditor` indirectly

[Lisias]

Long history made short:

• Install TweakScale/L 2.4.7.4 and KSPCF 1.34.0.0 with BetterEditorUndoRedo enabled
• In the editor, place a central fuel tank
• place another fuel tank attached in 4x symmetry to the side
• pick up the part placed in symmetry
• reattach it in a different location

See https://github.com/KSPModdingLibs/KSPCommunityFixes/issues/191 and KSPCF Forum for the gory details.

This absolutely weird unfortunate interaction is already mitigated, but I'm very uncomfortable it had happened at all. due:

• To the best of my knowledge, the KSPCF patch should not had caused something like that.
• It mades clear that AttachedOnEditor is brittle.

The purpose of this issue is:

• [x] to try to figure out exactly WHY this is happening, i.e., why BetterEditorUndoRedo changed the runtime environment in a way that induced this misbehaviour
• [x] figure out why AttachedOnEditor had failed
  • Apparently already figured out by KSPCF guys.
    • [x] Confirm the diagnosis.
• [x] propose a measure to make AttachedOnEditor more resilient with the least collateral damage (ideally none) possible.

[Lisias]

First things first.

I need to understand exactly what changes by having BetterEditorUndoRedo activated. So, yeah, MOAR TESTS.

The test session is:

1. Firing KSP (with, and later, without KSPFC 1.34.0.0), and using a heavily instrumented debug compile for TweakScale 2.4.7.4
2. Opening to a preexistent empty SandBox savegame
3. Going to editor
4. Taking a Kerbodyne S4-512 Fuel Tank as root part.
5. Taking a Mk1 Liquid Fuel Fuselage and attaching it on the S4-512 with radial symmetry (I use 2 to keep the logging simpler)
6. Detaching the Mk1 LF Fuselage and reataching it again in another place
7. Noticing the misbehaviour (or its absence)
8. Exiting Editor
9. Quitting KSP.

This is the respective KSP logs from two Test Sessions (with and without KSPCF). Further analysis will follow.

• KSP-with-KSPCF.log
• KSP-stock.log

[Lisias]

This is the logs from the previous comment with only the "interesting bits" related to the problem at hands.

These excerpts start when you instantiate the S4-512 tank, and finishes when you exit Editor. So it logs the TweakScale (and AttachedOnEditor) points of view for the whole process.

• KSP-with-KSPCF.interesting-bits.log
• KSP-Stock.interesting-bits.log

Analysis of these logs reveals what I had already inferred: somehow, BetterEditorUndoRedo changed something on the expected Life Cycle of something inside Editor:

A DIFF between these two logs revealed (left is with BetterEditorUndoRedo enabled):

So, indeed, things are getting "out of order" on the process.

This doesn't necessarily means any wrongdoing by BetterEditorUndoRedo. It only means what should be obvious for some time: that mangling inside KSP's guts will change expected behaviour.

Such changing behaviours can lead to bugs due the change itself, or can reveal weakness on the affected code that could be had written in a more robust way. My current working theory is that AttachedOnEditor is on the later, because… well… KSPEvents should be handled as asynchronous message passing, not as synchronous procedure calls and apparently this is what I ended up doing.

I will cross check these findings with the ones on https://github.com/KSPModdingLibs/KSPCommunityFixes/issues/191 just to satisfy my inherent stubbornness on identifying exactly where and how the problem is, but GotMachine's diagnosis appears to be right.

[Lisias]

I choose to go grunt on the problem. I will send all the needed data on a BaseEventDetails data structure - this is going to run on Editor, not Flight. Performance is not an issue here.

[Lisias]

Frak. It's not for any other reason than KSP is a pile of dog shit. Exceptions when fetching BaseEventDetails data are logged, but not raised to the caller.

My code just don't know when a Invalid Key exception happened.

Shit.

The following code

            Log.dbg("OnPartAttachmentNodesChanged for InstanceId {0:X}", instanceId);
            try
            {
                this.PreserveThisAttachmentNodes(data);
            }
            catch (Exception e)
            {
                Log.error(this, e);
                this.PreserveCurrentAttachmentNodes();
            }

Should be issuing a log like this:

[LOG 00:00:00.001] [KSP-Recall.AttachedOnEditor] TRACE: PreserveThisAttachmentNodes(BaseEventDetails) for <NO VESSEL>-miniFuselag
[ERR 00:00:00.002] [KSP-Recall.AttachedOnEditor] ERROR: Exception <yada yada yada>
[LOG 00:00:00.003] [KSP-Recall.AttachedOnEditor] TRACE: PreserveCurrentAttachmentNodes() for <NO VESSEL>-miniFuselag
[LOG 00:00:00.004] [KSP-Recall.Refunding.EditorHelper] TRACE: OnEditorShipModified Untitled Space Craft

But instead this is what I'm getting instead.

[LOG 21:38:10.475] [KSP-Recall.AttachedOnEditor] TRACE: PreserveThisAttachmentNodes(BaseEventDetails) for <NO VESSEL>-miniFuselag
[ERR 21:38:10.475] Invalid key: attachNodesCount

[LOG 21:38:10.477] [KSP-Recall.Refunding.EditorHelper] TRACE: OnEditorShipModified Untitled Space Craft

This is just maddening. You just can't trust anything on this code.

[Lisias]

At least, UnityEngine.Vector3 is serializable to BaseEventDetails. Things would be pretty inconvenient if not.

[Lisias]

Implemented on commit: https://github.com/TweakScale/TweakScale/commit/768fad9c946f6d7ae70b06227ce2f15fac392d00

=== == = EDIT

I mean... Commit https://github.com/net-lisias-ksp/KSP-Recall/commit/8fac9f1f02100b235ce008f522e4fe28c8c8b248