Merge Craft is getting its surface attachments screwed on 1.9.x and newer

[Lisias]

Unsurprisingly, to tell you the true.

Clone and Merging are different use cases.

[Lisias]

Holy crap!!! The problem is on AttachedOnEditor on KSP-Recal!!!

[EXC 22:49:52.137] ArgumentOutOfRangeException: Index was out of range. Must be non-negative and less than the size of the collection.
Parameter name: index
    System.ThrowHelper.ThrowArgumentOutOfRangeException (System.ExceptionArgument argument, System.ExceptionResource resource) (at <ad04dee02e7e4a85a1299c7ee81c79f6>:0)
    System.ThrowHelper.ThrowArgumentOutOfRangeException () (at <ad04dee02e7e4a85a1299c7ee81c79f6>:0)
    KSP_Recall.AttachedOnEditor.AttachedOnEditor.RestoreCurrentAttachmentNodes () (at <4ccc0cc319b045eda7e028e96d891602>:0)
    KSP_Recall.AttachedOnEditor.AttachedOnEditor.RestoreAttachments () (at <4ccc0cc319b045eda7e028e96d891602>:0)
    KSP_Recall.AttachedOnEditor.AttachedOnEditor.Update () (at <4ccc0cc319b045eda7e028e96d891602>:0)
    UnityEngine.DebugLogHandler:LogException(Exception, Object)
    KSPe.Util.Log.UnityLogDecorator:UnityEngine.ILogHandler.LogException(Exception, Object)
    ModuleManager.UnityLogHandle.InterceptLogHandler:LogException(Exception, Object)
    UnityEngine.Debug:CallOverridenDebugHandler(Exception, Object)

[Lisias]

Using the exact configuration:

• KSPe 2.5.4.2
• KSP-Recall 0.5.0.0
• Module Manager /L 4.2.3.4
• Module Manager Watch Dog 1.1.1.2
• TweakScale Futurely 2.4.8.0 (at commit TweakScale/TweakScale@47fa35c )

KSP 1.8.1 does not borks up!

Oukey, this is bad. Moving this to KSP-Recall

[Lisias]

Crap. The OnStart is being called without OnLoad first. :(

This is the Log from loading the "Untitled Space Craft" and then merging it with itself (look for the two "Untitled Space Craft loaded!" message in sequence.

There should be a OnLoad before the OnStart. The PartModule lifecycle says that, at least.

[LOG 01:16:07.352] Untitled Space Craft loaded!
[LOG 01:16:07.394] Autogen thumbnail for /Users/lisias/Workspaces/KSP/runtime/1.9.1/KSP.app/Contents/../../thumbs/test-ts_VAB_Untitled Space Craft.png from /Users/lisias/Workspaces/KSP/runtime/1.9.1/saves/test-ts/Ships/VAB/Untitled Space Craft.craft
[LOG 01:16:13.361] [KSPUpgradePipeline]: Untitled Space Craft (1.9.1) is up to date.
[LOG 01:16:13.405] [TweakScale] DETAIL: modExP: TweakScale TweakScale.TweakScale
[LOG 01:16:13.421] [TweakScale] DETAIL: modExP: TweakScale TweakScale.TweakScale
[LOG 01:16:13.437] [TweakScale] DETAIL: modExP: TweakScale TweakScale.TweakScale
[LOG 01:16:13.453] [TweakScale] DETAIL: modExP: TweakScale TweakScale.TweakScale
[LOG 01:16:13.469] [TweakScale] DETAIL: modExP: TweakScale TweakScale.TweakScale
[LOG 01:16:13.471] Untitled Space Craft loaded!
[WRN 01:16:13.485] Part Rockomax64.BW(p1) craft ID reset as it matched that of Rockomax64.BW(p2) [4294517472]. New id: 4294499396.
[WRN 01:16:13.485] Part Rockomax64.BW(p1) craft ID reset as it matched that of Rockomax64.BW(p2) [4294517550]. New id: 4294499456.
[WRN 01:16:13.485] Part Rockomax64.BW(p1) craft ID reset as it matched that of Rockomax64.BW(p2) [4294517628]. New id: 4294499516.
[WRN 01:16:13.485] Part Rockomax64.BW(p1) craft ID reset as it matched that of Rockomax64.BW(p2) [4294518020]. New id: 4294499576.
[WRN 01:16:13.485] Part Rockomax64.BW(p1) craft ID reset as it matched that of Rockomax64.BW(p2) [4294522716]. New id: 4294499636.
[WRN 01:16:13.485] Part mk1pod.v2(p1) craft ID reset as it matched that of mk1pod.v2(p2) [4294537402]. New id: 4294499730.
[ERR 01:16:13.489] Module AttachedOnEditor threw during OnStart: System.ArgumentOutOfRangeException: Index was out of range. Must be non-negative and less than the size of the collection.
Parameter name: index
  at System.ThrowHelper.ThrowArgumentOutOfRangeException (System.ExceptionArgument argument, System.ExceptionResource resource) [0x00029] in <ad04dee02e7e4a85a1299c7ee81c7
9f6>:0
  at System.ThrowHelper.ThrowArgumentOutOfRangeException () [0x00000] in <ad04dee02e7e4a85a1299c7ee81c79f6>:0
  at KSP_Recall.AttachedOnEditor.AttachedOnEditor.RestoreCurrentAttachmentNodes () [0x0019e] in <76b099de052b4459a15aadc143a40dcf>:0
  at KSP_Recall.AttachedOnEditor.AttachedOnEditor.RestoreAttachments () [0x00010] in <76b099de052b4459a15aadc143a40dcf>:0
  at KSP_Recall.AttachedOnEditor.AttachedOnEditor.OnStart (PartModule+StartState state) [0x00053] in <76b099de052b4459a15aadc143a40dcf>:0
  at Part.ModulesOnStart () [0x00120] in <48dcb08e2e1542e2af1286b02d2eb072>:0

[Lisias]

Nope, I was wrong. I misconfigured the log, I'm pushing this too much. :(

[LOG 02:12:20.274] [KSP-Recall.AttachedOnEditor] TRACE: OnLoad <NO VESSEL>-Rockomax64.BW:FFFA51E6 True
[LOG 02:12:20.275] [KSP-Recall.AttachedOnEditor] TRACE: OnLoad under merge.
[LOG 02:12:20.275] [KSP-Recall.AttachedOnEditor] TRACE: MergeFrom (ConfigNode) <NO VESSEL>-Rockomax64.BW:FFFA51E6

The OnLoad is there, and the OnLoad under merge log is there too.

I found the problem. The this.part.attachNodes apparently wasn't initialized yet, or AttachedOnEditor is being wrong initialized.

			Log.dbg("{0} {1} {2} {3}", this.originalAttachNodePos.Count, this.originalAttachNodeSize.Count, this.originalAttachNodeOrientation.Count, this.originalAttachNodeOffset.Count);
			Log.dbg("{0}", this.part.attachNodes.Count);

Is generating this log:

[LOG 02:12:20.309] [KSP-Recall.AttachedOnEditor] TRACE: OnStart <NO VESSEL>-Rockomax64.BW:FFFA529A Editor True
[LOG 02:12:20.309] [KSP-Recall.AttachedOnEditor] TRACE: RestoreCurrentAttachmentPoints for <NO VESSEL>-Rockomax64.BW:FFFA529A
[LOG 02:12:20.309] [KSP-Recall.AttachedOnEditor] TRACE: 4 4 4 4
[LOG 02:12:20.309] [KSP-Recall.AttachedOnEditor] TRACE: 2
[ERR 02:12:20.310] Module AttachedOnEditor threw during OnStart: System.ArgumentOutOfRangeException: Index was out of range. Must be non-negative and less than the size of the collection.
Parameter name: index
  at System.ThrowHelper.ThrowArgumentOutOfRangeException (System.ExceptionArgument argument, System.ExceptionResource resource) [0x00029] in <ad04dee02e7e4a85a1299c7ee81c7
9f6>:0
  at System.ThrowHelper.ThrowArgumentOutOfRangeException () [0x00000] in <ad04dee02e7e4a85a1299c7ee81c79f6>:0
  at KSP_Recall.AttachedOnEditor.AttachedOnEditor.RestoreCurrentAttachmentNodes () [0x0021c] in <98d7005d9e7f4d6db4919cc45e57913d>:0
  at KSP_Recall.AttachedOnEditor.AttachedOnEditor.RestoreAttachments () [0x00010] in <98d7005d9e7f4d6db4919cc45e57913d>:0
  at KSP_Recall.AttachedOnEditor.AttachedOnEditor.OnStart (PartModule+StartState state) [0x00053] in <98d7005d9e7f4d6db4919cc45e57913d>:0
  at Part.ModulesOnStart () [0x00120] in <48dcb08e2e1542e2af1286b02d2eb072>:0

For comparison, this is the respective logs for the mk1pod on the same vessel:

[LOG 02:12:20.302] [KSP-Recall.AttachedOnEditor] TRACE: OnStart <NO VESSEL>-mk1pod.v2:FFFA5334 Editor True
[LOG 02:12:20.302] [KSP-Recall.AttachedOnEditor] TRACE: RestoreCurrentAttachmentPoints for <NO VESSEL>-mk1pod.v2:FFFA5334
[LOG 02:12:20.303] [KSP-Recall.AttachedOnEditor] TRACE: 2 2 2 2
[LOG 02:12:20.303] [KSP-Recall.AttachedOnEditor] TRACE: 2
[LOG 02:12:20.303] [KSP-Recall.AttachedOnEditor] TRACE: 0
[LOG 02:12:20.303] [KSP-Recall.AttachedOnEditor] TRACE: 1
[LOG 02:12:20.303] [KSP-Recall.AttachedOnEditor] TRACE: 2
[LOG 02:12:20.303] [KSP-Recall.AttachedOnEditor] TRACE: 3

Where the sequence of 0..3 are markers to detect in which point an exception would happen. The absence of the 0 above means that the thing borked very early - obviously, as the code assumes the same quantity of nodes on this.part.attachNodes and this.original*.

			for(int i = 0; i < this.originalAttachNodePos.Count; ++i)
				this.part.attachNodes[i].position = this.originalAttachNodePos[i];
			Log.dbg("0");

At least I know why this is happening. I will come back to this after some sleep.

[Lisias]

I dreamed a dream, a dream in which I fixed the bug.

Worst. I dreamed it right. 🤣 I really fixed the bug while dreaming about it.

What's happening is simple: Before KSP 1.9.x, the PartModule was pristine after a Merge. On 1.9.0 by some reason the internal data structures were being fed twice.

Interesting enough, RestoreCurrentAttachmentPoints is being called twice, and this is the reason the internal data structures had twice the number of entries than this.part.attachNodes.

[LOG 04:22:37.900] [KSP-Recall.AttachedOnEditor] TRACE: OnAwake <NO VESSEL>-Rockomax64.BW(Clone):FFF995B6
[LOG 04:22:37.907] [KSP-Recall.AttachedOnEditor] TRACE: OnPartAttachmentNodesChanged for InstanceId FFF995B6
[LOG 04:22:37.907] [KSP-Recall.AttachedOnEditor] TRACE: PreserveCurrentAttachmentPoints for <NO VESSEL>-Rockomax64.BW:FFF995B6 hasAttachNodes? True
[LOG 04:22:37.908] [KSP-Recall.AttachedOnEditor] TRACE: OnLoad <NO VESSEL>-Rockomax64.BW:FFF995B6 True
[LOG 04:22:37.909] [KSP-Recall.AttachedOnEditor] TRACE: MergeFrom (ConfigNode) <NO VESSEL>-Rockomax64.BW:FFF995B6
[LOG 04:22:37.942] [KSP-Recall.AttachedOnEditor] TRACE: OnStart <NO VESSEL>-Rockomax64.BW:FFF995B6 Editor True
[LOG 04:22:37.942] [KSP-Recall.AttachedOnEditor] TRACE: RestoreCurrentAttachmentPoints for <NO VESSEL>-Rockomax64.BW:FFF995B6
[LOG 04:22:37.942] [KSP-Recall.AttachedOnEditor] TRACE: RestoreCurrentAttachments <NO VESSEL>-Rockomax64.BW:FFF995B6 from (2.0, 15.3, -0.3) to (1.3, 15.3, -0.3)
[LOG 04:22:37.971] [KSP-Recall.AttachedOnEditor] TRACE: LogCurrentAttachmentNodes for <NO VESSEL>-Rockomax64.BW:FFF995B6 hasAttachNodes? True
[LOG 04:22:37.971] [KSP-Recall.AttachedOnEditor] TRACE: RestoreCurrentAttachmentPoints for <NO VESSEL>-Rockomax64.BW:FFF995B6

Tracking the code and simulating it on head, I finally understood! When you load a craft for merge on KSP >= 1.9, the Update is called and when in Editor, RestoreCurrentAttachmentPoints is called again.

Apparently this is not happening before 1.9.0 - and I think this older behaviour is the right one. Why calling Update while the part is being merged and not attached to the host subassembly yet? It really makes no sense, the damned thing is not "alive" yet.

Curiously, fetching a subassembly from the SubAssemblies from Part Manager doesn't triggers this problem.

DAMN. And I was thinking this was a TweakScale bug all this time!!!! 🤦

[Lisias]

Notes for my future self: it's the enabled that is being set to true when merging crafts, while it's set to false on taking subassemblies from the Part Manager. This... "feature" started to happen on KSP 1.9.0 - before it, enabled was false on merge.