Yet another unexpected Misbehaviour, this time on `PartModule.OnSave`
Lisias opened this issue · 13 comments
On Forum, fellow Kerbonauts GoAhead and Professor K are reporting yet a new misbehaviour related to TweakScale.
since latest release i can't switch vessels and also the exit menue doesn't work anymore.
switching back to version 21 seems to work again
A.
So this is related to .22 for sure.
Additionally,
I'm seeing the same thing here. Same NullReferenceException errors and all. What brought it to my notice first was that F5 Quicksave stopped working, then I realized I couldn't switch back to the space center or even exit to main menu. Rolling Tweakscale back to v21 resolved the issue for me as well.
K.
LogFile from Ahead: KSP.GoAhead.zip
Problem. THE DAMNED THING IS WORKING ON MY INITIAL TEST BED, started with 1.4.3.
So this may be KSP specific - exactly what I dunno, it may be, indeed, something triggeed by TweakScale - but KSP 1.4.3 works on a minimalistic check, so I this is going to need some digging.
Oukey. Download fest.
First, I need to check if the downloads files are right - just do get this idea from my head.
So I downloaded all 2.4.6.22 files from github, CurseForge and SpaceDock and binary compared with my signed reference here. They are binary matches, so I didn't messed up the uploads.
So I can use my reference binaries for the testing.
KSP 1.4.3:
- Loaded the same savegame I used for development.
- Fired up the test craft (with the ScaleType screwed) from #288
- launched it from VAB.
- copied it to SPH, and launched it from there too
- Switched between them using
[and] - QuickSaved
- QuickLoaded
- Exit to Main Menu
- Reloaded the game again.
- Quit the whole game.
- Fired it up again, loaded the savegame, selected one of them and switched between the vessels.
Everything worked fine. Not a single Exception was logged on the KSP.log.
THIS IS NOT ON TWEAKSCALE [ edit: wrong! see #290 ]
Redid the tests for 1.11.2:
- Loaded the same savegame I used for development.
- Fired up the test craft (with the ScaleType screwed) from #288
- launched it from VAB.
- copied it to SPH, and launched it from there too
- Switched between them using
[and] - QuickSaved
- QuickLoaded
- Switched between them using
[and] - Quit the whole game.
NOT A SINGLE MISBEHAVIOUR OR EXCEPTION DETECTED.
Evidences: 1.11.2.zip
Evidences for the 1.4.3 test run (KSP.log and savegame)
Redid the tests for 1.7.3, but slightly simplified:
- Loaded the same savegame I used for development.
- Fired up the test craft (with the ScaleType screwed) from #288
- launched it from VAB.
- copied it to SPH, and launched it from there too
- Switched between them using
[and] - QuickSaved
- QuickLoaded
- Quit the whole game.
NOT A SINGLE MISBEHAVIOUR OR EXCEPTION DETECTED.
Evidences: 1.7.3.zip
Redid the tests for 1.12.5:
- Loaded the same savegame I used for development.
- Fired up the test craft (with the ScaleType screwed) from #288
- launched it from VAB.
- copied it to SPH, and launched it from there too
- Switched between them using
[and] - QuickSaved
- QuickLoaded
- Switched between them using
[and] - Quit the whole game.
NOT A SINGLE MISBEHAVIOUR OR EXCEPTION DETECTED.
Evidences: 1.12.5.zip
Well… Now I'm worried.
The first time I tried the problem I fired up my Acceptance test rig, that it's a "pristine" test rig never used to development neither testings other than a Smoke Test done before kicking things trough the door - what now and then I fail to do, I admit.
While the other rigs are instrumented for development and debugging, on the ACP rig only things that would be used by users are installed, including downloading them from the same places.
And on that ACP rig, while doing this test by the first time (before even the 1.4.3 ones), I got this on the Player.log after a CTD (!!!):
probeCoreSphere.v2 Exploded!! - blast awesomeness: 0
(Filename: ./Runtime/Export/Debug/Debug.bindings.h Line: 35)
0 libmonobdwgc-2.0.dylib 0x0000000109ad2731 mono_handle_native_crash + 242
1 libmonobdwgc-2.0.dylib 0x0000000109a32b59 mono_sigsegv_signal_handler + 220
2 libsystem_platform.dylib 0x00007fff795e0b5d _sigtramp + 29
3 ??? 0x0000000000000000 0x0 + 0
4 UnityPlayer.dylib 0x0000000102af5098 _ZN4FMOD12DSPWaveTable4readEPPfPiPj16FMOD_SPEAKERMODEij + 1496
5 UnityPlayer.dylib 0x0000000102adc4d4 _ZN4FMOD9DSPFilter4readEPPfPiPj16FMOD_SPEAKERMODEij + 324
6 UnityPlayer.dylib 0x0000000102adc4d4 _ZN4FMOD9DSPFilter4readEPPfPiPj16FMOD_SPEAKERMODEij + 324
7 UnityPlayer.dylib 0x0000000102adc4d4 _ZN4FMOD9DSPFilter4readEPPfPiPj16FMOD_SPEAKERMODEij + 324
8 UnityPlayer.dylib 0x0000000102adc4d4 _ZN4FMOD9DSPFilter4readEPPfPiPj16FMOD_SPEAKERMODEij + 324
9 UnityPlayer.dylib 0x0000000102adc4d4 _ZN4FMOD9DSPFilter4readEPPfPiPj16FMOD_SPEAKERMODEij + 324
10 UnityPlayer.dylib 0x0000000102adc4d4 _ZN4FMOD9DSPFilter4readEPPfPiPj16FMOD_SPEAKERMODEij + 324
11 UnityPlayer.dylib 0x0000000102adc4d4 _ZN4FMOD9DSPFilter4readEPPfPiPj16FMOD_SPEAKERMODEij + 324
12 UnityPlayer.dylib 0x0000000102adc4d4 _ZN4FMOD9DSPFilter4readEPPfPiPj16FMOD_SPEAKERMODEij + 324
13 UnityPlayer.dylib 0x0000000102adc4d4 _ZN4FMOD9DSPFilter4readEPPfPiPj16FMOD_SPEAKERMODEij + 324
14 UnityPlayer.dylib 0x0000000102af4617 _ZN4FMOD12DSPSoundCard4readEPvPj16FMOD_SPEAKERMODEij + 135
15 UnityPlayer.dylib 0x0000000102b046d0 _ZN4FMOD6Output3mixEPvj + 640
16 UnityPlayer.dylib 0x0000000102b45882 _ZN4FMOD15OutputCoreAudio10renderProcEPvPjPK14AudioTimeStampjjP15Audi
oBufferList + 50
17 CoreAudio 0x000000010bdf087f _ZN15AUConverterBase9RenderBusERjRK14AudioTimeStampjj + 729
18 CoreAudio 0x000000010bf0c2d7 _ZN6AUBase11DoRenderBusERjRK14AudioTimeStampjP15AUOutputElementjR15Au
I'm going to double check this again on the ACP rig.
Fellow Kerbonaut GoAHead sent me new logs from their rig:
I'm going to analyse them now. Trying to reproduce the problem on my rig is fruitless.
Oukey, the 1.12.5.acp one didn't borked neither - it passed trough with flying colours.
The CTD appears to be unrelated - and probably some idiocy on MacOS (mis)handling memory. It had happened before.
First things first, the user is experiencing trouble from inside TweakScale's OnSave. From their Player.log, I got:
[FLIGHT GLOBALS]: Switching To Vessel SSTO-MK3-Science-Duna ----------------------
(Filename: C:\buildslave\unity\build\Runtime/Export/Debug/Debug.bindings.h Line: 35)
Flight globals not ready - Setting active vessel at frame 17568
(Filename: C:\buildslave\unity\build\Runtime/Export/Debug/Debug.bindings.h Line: 35)
Targetron Error: Failed to draw vessel listing
at TweakScale.TweakScale.OnSave (ConfigNode node) [0x00007] in <cf1abb1b50de40fe83042990f01ebf6f>:0
at PartModule.Save (ConfigNode node) [0x00131] in <4b449f2841f84227adfaad3149c8fdba>:0
at ProtoPartModuleSnapshot..ctor (PartModule module) [0x000d2] in <4b449f2841f84227adfaad3149c8fdba>:0
at ProtoPartSnapshot..ctor (Part PartRef, ProtoVessel protoVessel, System.Boolean preCreate) [0x00420] in <4b449f2841f84227adfaad3149c8fdba>:0
at ProtoPartSnapshot..ctor (Part PartRef, ProtoVessel protoVessel) [0x00000] in <4b449f2841f84227adfaad3149c8fdba>:0
at ProtoVessel..ctor (Vessel VesselRef, System.Boolean preCreate) [0x001e3] in <4b449f2841f84227adfaad3149c8fdba>:0
at ProtoVessel..ctor (Vessel VesselRef) [0x00000] in <4b449f2841f84227adfaad3149c8fdba>:0
at Vessel.BackupVessel () [0x00022] in <4b449f2841f84227adfaad3149c8fdba>:0
at FlightState..ctor () [0x00264] in <4b449f2841f84227adfaad3149c8fdba>:0
at Game.Updated (GameScenes startSceneOverride) [0x0001a] in <4b449f2841f84227adfaad3149c8fdba>:0
at GamePersistence.SaveGame (System.String saveFileName, System.String saveFolder, SaveMode saveMode, GameScenes startScene) [0x00045] in <4b449f2841f84227adfaad3149c8fdba>:0
at FlightGlobals.setActiveVessel (Vessel v, System.Boolean force, System.Boolean clearDeadVessels) [0x00244] in <4b449f2841f84227adfaad3149c8fdba>:0
at FlightGlobals.SetActiveVessel (Vessel v) [0x0002a] in <4b449f2841f84227adfaad3149c8fdba>:0
at Targetron.Targetron.DrawTargeter (System.Int32 windowID) [0x00992] in <9a958599057743649ef7094cabf37bdd>:0
(Filename: C:\buildslave\unity\build\Runtime/Export/Debug/Debug.bindings.h Line: 35)
However, this doesn't necessarily means TweakScale is at fault here - in fact, all the evidences I have suggests it isn't.
The problem blew up under the Targetron's nose, a thingy that I don't have installed here.
Looking on the KSP.log, I found:
[LOG 19:48:54.782] Load(Assembly): Targetron/Plugins/Targetron
[LOG 19:48:54.782] AssemblyLoader: Loading assembly at D:\SPIELE\Kerbal Space Program\GameData\Targetron\Plugins\Targetron.dll
[LOG 19:48:54.783] AssemblyLoader: KSPAssembly 'Targetron' V1.7.0
So, yeah, it's a 3rd party. It doesn't makes it the culprit neither, I sounds more like an innocent bystander getting hit by splash damage done by someone else.
So I kept digging, and found this one:
[LOG 20:03:56.171] [KSPI]: ThermalNozzleController OnRescale was called with factor 2.2
[LOG 20:03:56.181] [KSPI]: Created new ResourceOvermanager for resource WasteHeat with ID 1d045367-73c8-4036-b182-033a42e7dcbe
[LOG 20:03:56.183] [TweakScale] ERROR: Exception on rescale while ¬TSGenericUpdater: System.NullReferenceException: Object reference not set to an instance of an object
at FNPlugin.Propulsion.ThermalEngineController.UpdateIspEngineParams (System.Double atmosphereIspEfficiency, System.Double performanceBonus) [0x00135] in <86331f4099874379b99eba8db4d
at FNPlugin.Propulsion.ThermalEngineController.OnRescale (TweakScale.ScalingFactor factor) [0x00058] in <86331f4099874379b99eba8db4dc4cd3>:0
at TweakScale.TweakScale.CallUpdaters () [0x000bb] in <cf1abb1b50de40fe83042990f01ebf6f>:0 at error:0
Well, this is the kind of error that really screws up TweakScale, as it's thread gets killed and it leaves a lot of unfinished business left behind - and this will screwup the OnSave for sure, as it depends on a healthy environment to run.
The suspect, now, appears to be FNPlugin. Kept digging, and found:
[LOG 20:04:09.252] [KSPI]: FNSolarPanelWasteHeatModule Force Activated bluedog.OGO.SolarPanel.Basic
[ERR 20:04:09.256] Module ModuleDeployableSolarPanel threw during OnStart: System.NullReferenceException: Object reference not set to an instance of an object
at (wrapper dynamic-method) ModuleDeployableSolarPanel.ModuleDeployableSolarPanel.OnStart_Patch0(ModuleDeployableSolarPanel,PartModule/StartState)
at Part.ModulesOnStart () [0x00120] in <4b449f2841f84227adfaad3149c8fdba>:0
So it appears that the whole FN* thingy from BDB is at stake here.
I found another corrence of an exception affecting TweakScale:
[LOG 20:04:47.687] [KSPI]: InterstellarReactor.OnRescale called with 2.2
[LOG 20:04:47.687] [KSPI]: ThermalNozzleController OnRescale was called with factor 2.2
[LOG 20:04:47.687] [TweakScale] ERROR: Exception on rescale while ¬TSGenericUpdater: System.NullReferenceException: Object reference not set to an instance of an object
at FNPlugin.Propulsion.ThermalEngineController.UpdateIspEngineParams (System.Double atmosphereIspEfficiency, System.Double performanceBonus) [0x00135] in <86331f4099874379b99eba8db4d
at FNPlugin.Propulsion.ThermalEngineController.OnRescale (TweakScale.ScalingFactor factor) [0x00058] in <86331f4099874379b99eba8db4dc4cd3>:0
at TweakScale.TweakScale.CallUpdaters () [0x000bb] in <cf1abb1b50de40fe83042990f01ebf6f>:0 at error:0
This time the stack dump is being more detailed, mentioning InterstellarReactor.OnRescale . Good, now I have something to work with.
And, finally, another evidence suggesting Targetron is, indeed, innocent on this one:
[LOG 20:05:04.489] ScaleModList: listSize 1517 maxListSize 1606
[EXC 20:05:04.721] NullReferenceException: Object reference not set to an instance of an object
TweakScale.TweakScale.OnSave (ConfigNode node) (at <cf1abb1b50de40fe83042990f01ebf6f>:0)
PartModule.Save (ConfigNode node) (at <4b449f2841f84227adfaad3149c8fdba>:0)
ProtoPartModuleSnapshot..ctor (PartModule module) (at <4b449f2841f84227adfaad3149c8fdba>:0)
ProtoPartSnapshot..ctor (Part PartRef, ProtoVessel protoVessel, System.Boolean preCreate) (at <4b449f2841f84227adfaad3149c8fdba>:0)
ProtoPartSnapshot..ctor (Part PartRef, ProtoVessel protoVessel) (at <4b449f2841f84227adfaad3149c8fdba>:0)
ProtoVessel..ctor (Vessel VesselRef, System.Boolean preCreate) (at <4b449f2841f84227adfaad3149c8fdba>:0)
ProtoVessel..ctor (Vessel VesselRef) (at <4b449f2841f84227adfaad3149c8fdba>:0)
Vessel.BackupVessel () (at <4b449f2841f84227adfaad3149c8fdba>:0)
FlightState..ctor () (at <4b449f2841f84227adfaad3149c8fdba>:0)
Game.Updated (GameScenes startSceneOverride) (at <4b449f2841f84227adfaad3149c8fdba>:0)
(wrapper dynamic-method) Game.Game.Updated_Patch2(Game)
FlightDriver+<PostInit>d__34.MoveNext () (at <4b449f2841f84227adfaad3149c8fdba>:0)
UnityEngine.SetupCoroutine.InvokeMoveNext (System.Collections.IEnumerator enumerator, System.IntPtr returnValueAddress) (at <12e76cd50cc64cf19e759e981cb725af>:0)
UnityEngine.DebugLogHandler:LogException(Exception, Object)
ModuleManager.UnityLogHandle.InterceptLogHandler:LogException(Exception, Object)
UnityEngine.Debug:CallOverridenDebugHandler(Exception, Object)
[LOG 20:05:06.020] Unpacking SSTO-Beluga-MK3_satellite
It's not mentioned this time, meaning that the trigger of the problem is, indeed, inside TweakScale.
Right now, my best guess is the FNPlugin. Something changed somewhere that it's screwing with it that, by its turn, ends up screwing TweakScale.
Oukey, things were WAY simpler than I tough.
My guesses while working on this issue was something else borking while handling its OnLoad, what would break the chain of events inside KSP that would call TweakScae's OnLoad eventually, and so some internal TweakScale data would not be initialised, and then such unitialised data would blow up something on TS's OnSave.
Well, I was right and I was wrong at the same time.
In fact, something was aborting a correct OnLoad handling of TweakScale, but such trigger wasn't another module (this happened in the past, it only didn't happened today). The reason for a OnLoad premature abort is a Rogue Duplicate module, a problem TweakScale had to cope with in 2019, if memory serves me well.
I had completely forgot about the TweakScaleRogueDuplicate stunt, and when I reworked the ScaleType Migration Code recently I ended up injecting this problem on commit cb7f210 . The this.type overwritting is needed to update older craft and sfs files to help preventing false positives on migration detections.
So, yeah. Phantoms from the past coming back from the grave to haunt me…
This misbehaviour was fixed by #290 . The Test Cases described above were executed with success with that code.
Marking this as DUPLICATE for #290 , as that code solved this one.
Also, gladly closing this crap for good. :)