Write an internal Self Check Mechanism
Lisias opened this issue · 37 comments
Oukey, it's TweakScale hunt season again, as it appears.
ModuleManagerWatchDog is apparently being targeted on a character assassination campaign, prompting people to remove this very important KSP healthiness tool.
(TL;DR: this is a LIE. MMWD never removes MM/Forum if it's already installed, protecting it from being overruled by older versions or even my own fork - on the other hand, if the user have my fork installed, MMWD does the same for it).
And now I have evidences that Module Manager (Forum) is not yelling anymore when a Reflection Exception is detected on loading, allowing users to load KSP when TweakScale was prevented from being loaded due the bug on the KSP's Assembly Loader/Resolver
that happens when something else borks on loading a dependency.
This should not be happening - at very least, Module Manager (should) yells when it detects a Reflection Exception while listing the installed Assemblies!
So something had changed somewhere and I did some tests:
This is the KSP.log
of a test session made on KSP 1.12.5 with (Forum) Module Manager 4.2.3 and latest TweakScale installed, but propositaly without 999_Scale_Redist.dll
on GameData
: KSP.log . No Warning or error of any kind were displayed, and if the user loads its savegame, TweakScale will not work and they will lose it.
This is the KSP.log
of a test session made on KSP 1.12.5 with (Forum) Module Manager 4.2.2 on the same circumstances above, and I'm pretty sure 4.2.2 used to display a Message about Incompatible Add'Ons (what was wrong, by the way) when a Reflection Exception happens: KSP.log. Again, no message!
Hell. This is the KSP.log
of a test session made on KSP 1.8.1 with (Forum) Module Manager 4.1.2 on the same circumstances. This was the very first Module Manager to yell (besides diagnosing it incorrectly) about it.
KSP.log
There's something smelling here, but there's nothing I can do about it. Past Evidences. Mirror Page 1, Page 2.
So I will need to cook a Self Defense measure on TweakScale to prevent users from being screwed by KSP's stupidity on handling DLL's dependency problems.
The tool should:
- Check if the tool is correctly installed. If no, yell
- Check if Module Manager Watch Dog is installed. If yes, quit (as the problem was already handled, not rarely fixed).
- Check if there's a Module Manager is installed. If no, yell
- Check if my fork of Module Manager is installed. If yes, quit (as the problem was already reported).
- Check for all of the following:
- Check if
999_Scale_Redist.dll
is present,- if it's on the
GameData
directory and - if it's correctly loaded,
- ( )
if it's functional.
- if it's on the
- Check if
Scale.dll
is present,-
if it's on the[edit: task dropped. TS already checks for this]GameData/TweakScale/Plugins
directory and - if it's correctly loaded,
- ( )
if it's functional.
-
- Barks if anyone of these are false, closing KSP and opening a Support Page where the problem is described and possible solutions are offered.
- Check if
- TweakScale should check for the presence of the tool and yell if not found, as a measure against tampering.
- Known Issues page on lisias.net
Since this tool is to be distributed with TweakScale, there's no possible use case in which it will be present on the user's GameData
without TweakScale being present.
KSP's running environment is not healthy neither safe. There's not other option but to assume KSP as an untrustworthy runtime environment where things just changes without notice.
A quick prototype is available on
https://ksp.lisias.net/add-ons/TweakScale/WatchDog/KNOWN_ISSUES
This (and some other pages linked by it) needs some polishing, but this will be a fight to be fought another day.
Interesting enough, MMWD (the very tool being slandered, motivating this issue) could be easily adapted to do this check by adding TweakScale
as a client for Scale_Redist
.
But since this tool is (was?) jeopardized in Forum, it's not wise to rely on it for this. So, yeah, "Keep Checking".
Implemented on commit bf735fc .
Known Issues (linked from the Error Dialog) still WiP.
Tampering prevention implemented on commit 499431f
--- -- - EDIT
Entertaining grammars made slightly less entertaining...
Well, proper MMWD handling implemented (or fixed) on commit 2bd4b04
Não tenho certeza em como checar se os Assemblies estão "funcionais". Na hora de especificar a tarefa, pareceu uma boa idéia mas agora na hora de implementar estou imaginando como diabos checar isso...
A link to Reddit was removed from the OP, as I just realised that may be another case for the #314 - however, the problem being fixed by itself is still suspicious.
Holy Molly… Now even my own fork of ModuleManager is not detecting Reflection Exceptions anymore. (deep sigh).
So I fired up KSP 1.12.5 with the latest Modular Management and TweakScale (and nothing more), and intentionally removed 999_Scale_Redist.dll
from the GameData
. And no barking from MM/L.
Checking the KSP.log
, I realised that there's no Reflection Exception anymore being triggered! That infamous Assembly Loader/Resolver
vanished from my rig.
I'm not going to miss that crap, but hell… That Monkey Patching thingy appears to be being applied again (see net-lisias-ksp/KSP-Recall#71 ) and this raises some important issues: to which extent this thingy can inject code on KSP unattended? What happens if TT2 loses interest on keeping the needed infra structure alive? What happens if KSP¹ is sold to someone else that so decides to inject some cripto mining assembly, or something similarly nasty?
NOW I'm worried. I just fired up the same test again:
- KSP 1.12.5
- Latest Module Manager (no matter which, but my fork has a nice popup message)
- KSPe
- KSP-Recall
- TweakScale + Companions + ModuleManagerWatchDog
- Remove
GameData/999_Scale_Redist.dll
.
But now the "expected behaviour" is back! Out of the blue…
For the sake of completude, follows the KSP.log from same test made on the last comment, but using Forum MM instead of my fork:
For the sake the yet more completude, the same test rig used above but this time completely removing TweakScale Companion. No change on the behaviour, the presence or absence of a Companion is not the trigger for the problem on this test bed.
For the sake the yet more completude, the same test rig used above but this time completely removing TweakScale Companion. No change on the behaviour, the presence or absence of a Companion is not the trigger for the problem on this test bed.
This log file is truncated.
Hey I just noticed something in the logs linked here: #312 (comment)
[LOG 14:38:51.919] AssemblyLoader: Loading assembly at /Users/lisias/Workspaces/KSP/runtime/1.12.5/GameData/TweakScale/Plugins/Scale.dll
[LOG 14:38:52.106] AssemblyLoader: KSPAssembly 'Scale' V2.4.0
[LOG 14:38:52.106] AssemblyLoader: KSPAssemblyDependency 'KSPe.Light.TweakScale' V2.4.0
[LOG 14:38:52.109] AssemblyLoader: Loading assemblies
[WRN 14:38:52.112] AssemblyLoader: Assembly 'Scale' has not met dependency 'KSPe.Light.TweakScale' V2.4.0
[WRN 14:38:52.112] AssemblyLoader: Assembly 'Scale' is missing 1 dependencies
This could actually explain the whole thing. I was trying to reproduce this test, and noticed that when I installed tweakscale and MM/L I had WAY more DLLs installed than were shown in this log. It seems like not everything in here was installed correctly.
Further, missing a KSPAssemblyDependency would mean that the assembly will not be loaded at all and will cause no further exceptions to be thrown.
For the sake the yet more completude, the same test rig used above but this time completely removing TweakScale Companion. No change on the behaviour, the presence or absence of a Companion is not the trigger for the problem on this test bed.
KSP.logThis log file is truncated.
Working on it.
[…]
This could actually explain the whole thing. I was trying to reproduce this test, and noticed that when I installed tweakscale and MM/L I had WAY more DLLs installed than were shown in this log. It seems like not everything in here was installed correctly. Further, missing a KSPAssemblyDependency would mean that the assembly will not be loaded at all and will cause no further exceptions to be thrown.
You see, I just realised you have a point. I finally managed to create a test bed where the absence of the 999_Scale_Redist.dll
didn't triggered the MM message.
The key here is the ModuleManagerWatchDog
. I removed MMWD too this time.
new log, nearly identical to yours (and not truncated this time): KSP.log
Oukey, I'm redoing all the tests from this issue, and started with the latest one. I got the very same results.
- KSP 1.12.5
- KSPe 2.5.3.5
- KSP Recall 0.4.0.1
- TweakScale 2.4.7.4
- Purposely not installing
999_Scale_Redist.dll
onGameData
(or removing it if existent)
- Purposely not installing
- Forum Module Manager 4.3.2
- And nothing more.
Monitoring the KSP's process TCP connections, I got:
time,,interface,state,bytes_in,bytes_out,rx_dupe,rx_ooo,re-tx,rtt_avg,rcvsize,tx_win,tc_class,tc_mgt,cc_algo,P,C,R,W,
19:53:10.818502,KSP.28002,,,14172,8292,0,0,0,,,,,,,,,,,
19:53:10.810235,tcp4 192.168.200.103:55797<->40.113.111.34.bc.googleusercontent.com:443,en0,Established,5699,1310,0,0,0,13.62 ms,131072,68864,BE,-,cubic,-,-,-,-,
19:53:10.810142,tcp4 192.168.200.103:55798<->168.172.107.34.bc.googleusercontent.com:443,en0,Established,4372,2777,0,0,0,14.69 ms,131072,71424,BE,-,cubic,-,-,-,-,
19:53:10.810049,tcp4 192.168.200.103:55807<->8.78.190.35.bc.googleusercontent.com:443,en0,Established,4101,4205,0,0,0,14.56 ms,131072,76288,BE,-,cubic,-,-,-,-,
Module Manager didn't triggered the Reflection Exception message.
KSP.log until the Main Menu is shown.
Now, the very same test bed but using my MM fork, 4.2.3.1 instead of Forum's.
NOW the Reflection Exception is being shown, as desired. However, we have a different TCP connection landscape:
time,,interface,state,bytes_in,bytes_out,rx_dupe,rx_ooo,re-tx,rtt_avg,rcvsize,tx_win,tc_class,tc_mgt,cc_algo,P,C,R,W,
20:04:51.767693,KSP.28219,,,10042,4088,0,0,0,,,,,,,,,,,
20:04:51.759153,tcp4 192.168.200.103:55944<->40.113.111.34.bc.googleusercontent.com:443,en0,Established,5670,1310,0,0,0,17.44 ms,131072,68864,BE,-,cubic,-,-,-,-,
20:04:51.758945,tcp4 192.168.200.103:55945<->168.172.107.34.bc.googleusercontent.com:443,en0,Established,4372,2778,0,0,0,16.66 ms,131072,71424,BE,-,cubic,-,-,-,-,
There's not connection to 8.78.190.35.bc.googleusercontent.com
anymore.
KSP.log.zip until the Warning message is displayed, when so I clicked on the OK button and closed KSP.
Log excerpts of interest:
[LOG 20:05:12.888] [ModuleManager] INFO: Calling KSPe.ModuleManagerSupport.ModuleManagerAddToModList()
[LOG 20:05:12.896] [ModuleManager] INFO: Calling KSP-Recall.ModuleManagerSupport.ModuleManagerAddToModList()
[ERR 20:05:12.901] [ModuleManager] ERROR: Add to mod list threw an exception in loading Scale, Version=2.4.7.4, Culture=neutral, PublicKeyToken=null at Exception
[EXC 20:05:12.935] ReflectionTypeLoadException: Exception of type 'System.Reflection.ReflectionTypeLoadException' was thrown.
System.Reflection.Assembly.GetTypes () (at <9577ac7a62ef43179789031239ba8798>:0)
ModuleManager.ModListGenerator.GetAdditionalModsFromStaticMethods (ModuleManager.Logging.IBasicLogger logger) (at <bb771ee7c78a424985a1e41a7e3f4a09>:0)
UnityEngine.DebugLogHandler:LogException(Exception, Object)
KSPe.Util.Log.UnityLogDecorator:UnityEngine.ILogHandler.LogException(Exception, Object)
ModuleManager.UnityLogHandle.InterceptLogHandler:LogException(Exception, Object)
UnityEngine.Debug:LogException(Exception)
KSPe.Util.Log.UnityLogger:logException(String, Exception)
KSPe.Util.Log.Logger:error(Exception, String, Object[])
ModuleManager.Logging.ModLogger:Exception(String, Exception)
ModuleManager.ModListGenerator:GetAdditionalModsFromStaticMethods(IBasicLogger)
ModuleManager.<Run>d__13:MoveNext()
UnityEngine.SetupCoroutine:InvokeMoveNext(IEnumerator, IntPtr)
[LOG 20:05:12.940] [ModuleManager] ERROR: **FATAL** Intercepted a ReflectionTypeLoadException. List of broken DLLs:
Scale 2.4.7.4 GameData/TweakScale/Plugins/Scale.dll at LogException:0
<…>
[LOG 20:05:12.952] [ModuleManager] INFO: "Houston, we have a Problem!" was displayed with message Intercepted a ReflectionTypeLoadException. List of broken DLLs:
Scale 2.4.7.4 GameData/TweakScale/Plugins/Scale.dll
Oukey, I have remembrance and evidence (somewhere buried on the issue tracking and my archives) that both Forum MM and MM/L used to present the exact same behaviour on this use case, so we have some divergence here.
Since the KSP instalment is exactly the same, the only difference being the Module Manager fork being used, we have a deterministic trigger for the problem.
However, we have an extra TCP connection when Forum MM is used (the the expected behaviour is not reproduced).
Of course, some change on my Fork may be the reason for it keep working as expected, but it's worth to mention that when Forum MM is used, we had an extra TCP connection. This weird behaviour may suggest Monkey Patching, but don't rule out other possibilities.
— — EDIT — —
The correlation between that extra TCP connection when using the Forum MM is not a proof, it's just a correlation that may suggest that the presence of Forum MM triggered something that leaded to a new TCP connection.
Other explanations are still possible - like some telemetry that is just send eventually, and by plain chance was sent while testing the rig using Forum MM.
Well, right now I have a well defined test rig that behaves differently when using Forum MM and my Fork.
The piece of code involved is:
- ~~Forum MM: ~~
My Fork:
The key now is trying to understand what was changed on my fork that made it imune to the problem (i.e., not complaining about the Reflection Exceptions).
HOWEVER, on Oct 7 I commented above that even my own Fork wasn't complaining anymore.
So this is a nice opportunity to reproduce exactly that instalment (good thing I provided the log) and try it again.
The testing environment involved is:
KSP 1.12.5KSPe 2.5.3.3MM /L 4.2.3.1TweakScale (couldn't determine the version due the borked startup, but I will use 2.4.7.4 as it was released on that very day and I probably got the problem on the smoke tests)
The Test Session gave me the following results:
time,,interface,state,bytes_in,bytes_out,rx_dupe,rx_ooo,re-tx,rtt_avg,rcvsize,tx_win,tc_class,tc_mgt,cc_algo,P,C,R,W,
20:39:52.549753,KSP.28861,,,10042,4079,0,0,0,,,,,,,,,,,
20:39:52.541419,tcp4 192.168.200.103:56151<->40.113.111.34.bc.googleusercontent.com:443,en0,Established,5670,1309,0,0,0,13.81 ms,131072,68864,BE,-,cubic,-,-,-,-,
20:39:52.541225,tcp4 192.168.200.103:56152<->168.172.107.34.bc.googleusercontent.com:443,en0,Established,4372,2770,0,0,0,13.91 ms,131072,71424,BE,-,cubic,-,-,-,-,
The Houston message was displayed as expected.
KSP.log* until I clicked on the OK button, when so KSP was closed and a webpage was called.
NOW we have a properly documented evidence that the VERY SAME KSP INSTALMENT behaved differently on Oct 7 than it's behaving now.
Again, Monkey Patching is not the only explanation for this - but right now, it's the one that best fits.
Note: Refer to net-lisias-ksp/KSP-Recall#71 for the reason Monkey Patching is being cogitated.
— EDIT —
* I had borked the original run, forgot KSP-Recall installed. Redid the test properly and updated the log ~~
— EDIT —
I had borked again. I will just ditch this Test Session and do a new one.
Your october 7 logs did not have kspe.light.tweakscale installed, while your most recent one does.
VERY SAME KSP INSTALMENT behaved differently on Oct 7 than it's behaving now.
but it’s not the same installment. You have more DLLs installed here than you did in the oct. 7 logs.
VERY SAME KSP INSTALMENT behaved differently on Oct 7 than it's behaving now.
but it’s not the same installment. You have more DLLs installed here than you did in the oct. 7 logs.
Damnit. I forgot to remove KSP Recall. Redoing the tests.
The log on comment #312 (comment) was updated.
Well, right now I have a well defined test rig that behaves differently when using Forum MM and my Fork.
The piece of code involved is:
- Forum MM: https://forum.kerbalspaceprogram.com/topic/50533-18x-112x-module-manager-423-july-03th-2023-fireworks-season/
- My Fork: https://github.com/net-lisias-ksp/ModuleManager
The key now is trying to understand what was changed on my fork that made it imune to the problem (i.e., not complaining about the Reflection Exceptions).
HOWEVER, on Oct 7 I commented above that even my own Fork wasn't complaining anymore.
So this is a nice opportunity to reproduce exactly that instalment (good thing I provided the log) and try it again.
The testing environment involved is:
- KSP 1.12.5
- KSPe 2.5.3.3
- MM /L 4.2.3.1
- TweakScale (couldn't determine the version due the borked startup, but I will use 2.5.0.60 as it was the one available on that day - and don't use
KSPe.Light
that it's missing on the originalKSP.log
)
The Test Session gave me the following results:
time,,interface,state,bytes_in,bytes_out,rx_dupe,rx_ooo,re-tx,rtt_avg,rcvsize,tx_win,tc_class,tc_mgt,cc_algo,P,C,R,W,
08:55:43.479589,KSP.33586,,,14143,8763,0,0,0,,,,,,,,,,,
08:55:43.471402,tcp4 192.168.200.103:57674<->40.113.111.34.bc.googleusercontent.com:443,en0,Established,5670,1309,0,0,0,14.72 ms,131072,68864,BE,-,cubic,-,-,-,-,
08:55:43.471306,tcp4 192.168.200.103:57675<->168.172.107.34.bc.googleusercontent.com:443,en0,Established,4372,2773,0,0,0,14.53 ms,131072,71424,BE,-,cubic,-,-,-,-,
08:55:43.471189,tcp4 192.168.200.103:57676<->8.78.190.35.bc.googleusercontent.com:443,en0,Established,4101,4681,0,0,0,19.53 ms,131072,76288,BE,-,cubic,-,-,-,-,
The Houston message was displayed as expected.
KSP.log until I clicked on the OK button, when so KSP was closed and a webpage was called.
NOW we have a properly documented evidence that the VERY SAME KSP INSTALMENT behaved differently on Oct 7 than it's behaving now.
Again, Monkey Patching is not the only explanation for this - but right now, it's the one that best fits.
Note: Refer to net-lisias-ksp/KSP-Recall#71 for the reason Monkey Patching is being cogitated.
Additionally, I got the 3rd TCP connection this time - something I wasn't getting on the borked test run above.
Your october 7 logs did not have kspe.light.tweakscale installed, while your most recent one does.
Damnit. Tunnel Vision. This also means that I was running TweakScale 2.5 in Oct7, as this is the release that uses KSPe (full blown), not the Light version.
(sigh). Thanks for the heads up, I'm redoing the tests again.
Ok. This is the test run similar to this one, but removing KSPe.Light.TweakScale
.
And… the Houston
was suppressed! Finally something to work with!!!
time,,interface,state,bytes_in,bytes_out,rx_dupe,rx_ooo,re-tx,rtt_avg,rcvsize,tx_win,tc_class,tc_mgt,cc_algo,P,C,R,W,
11:33:58.822431,KSP.36081,,,10042,4082,0,0,0,,,,,,,,,,,
11:33:58.813428,tcp4 192.168.200.103:58911<->40.113.111.34.bc.googleusercontent.com:443,en0,Established,5670,1309,0,0,0,15.28 ms,131072,68864,BE,-,cubic,-,-,-,-,
11:33:58.813341,tcp4 192.168.200.103:58912<->168.172.107.34.bc.googleusercontent.com:443,en0,Established,4372,2773,0,0,0,21.38 ms,131072,71424,BE,-,cubic,-,-,-,-,
KSP.log, until the Main Menu when KSP was closed.
Now we have the following landscape:
- TweakScale 2.5.0.60, without KSPe.Light, is triggering the Houston as expected.
- TweakScale 2.5.0.60, with KSPe.Light, is triggering the Houston as expected.
- TweakScale 2.4.7.4, with KSPe.Light, is also triggering the Houston as expected.
- TweakScale 2.4.7.4, without KSPe.Light, is NOT triggering the Houston as expected.
Apparently, whatever is happening, is being triggered when an Add'On linked against KSPe.Light fails to be loaded and KSPe.Light is not present.
(TweakScale 2.5.x is not linked to KSPe.Light.TweakScale)
I will redo again the tests for 2.5.0.60 and 2.4.7.4 with KSPe.Light just to see what happens, and have all the logs on the same comment.
I just remembered an issue from 2021, also involving Module Manager, where (apparently) a reboot solved the issue.
But analysing that case with newly available knowledge, it's not impossible that I had had my first contact with Monkey Patching and wasn't aware. March 26, 2021 was a Saturday, and the problem was reproduced on the previous Thursday.
For the sake of cross-reference, a good part of the exchange about this problem is also happening on Reddit:
The scale.dll that you used in the new test (nov. 28th) and the one from the october 7th log are different:
Oct. 7:
[LOG 14:38:51.919] AssemblyLoader: Loading assembly at /Users/lisias/Workspaces/KSP/runtime/1.12.5/GameData/TweakScale/Plugins/Scale.dll
[LOG 14:38:52.106] AssemblyLoader: KSPAssembly 'Scale' V2.4.0
[LOG 14:38:52.106] AssemblyLoader: KSPAssemblyDependency 'KSPe.Light.TweakScale' V2.4.0
[LOG 14:38:52.109] AssemblyLoader: Loading assemblies
[WRN 14:38:52.112] AssemblyLoader: Assembly 'Scale' has not met dependency 'KSPe.Light.TweakScale' V2.4.0
[WRN 14:38:52.112] AssemblyLoader: Assembly 'Scale' is missing 1 dependencies
Nov. 28th:
[LOG 08:55:16.884] AssemblyLoader: Loading assembly at /Users/lisias/Workspaces/KSP/runtime/1.12.5/GameData/TweakScale/Plugins/Scale.dll
[LOG 08:55:16.887] AssemblyLoader: KSPAssembly 'Scale' V2.5.0
[LOG 08:55:16.887] AssemblyLoader: KSPAssemblyDependency 'KSPe' V2.5.00
[LOG 08:55:16.887] AssemblyLoader: KSPAssemblyDependency 'KSPe.UI' V2.5.0
The scale.dll that you used in the new test (nov. 28th) and the one from the october 7th log are different:
So I was, indeed, smoke testing TweakScale 2.4.7.4 - but I just don't remember why I had deleted KSPe.Light.TweakScale
so, because the 2.4 series have a hard dependency on it.
In a way or another, the previous test with 2.4.7.4 where I leaked the KSPe.Light
is now somewhat useful, as now I will benchmark it with 2.4.7.4 without KSPe.Light
.
We now have determined that:
- TweakScale 2.5.0.60, without
KSPe.Light
, is triggering theHouston
as expected. - TweakScale 2.4.7.4, with
KSPe.Light
, is also triggering theHouston
as expected.
Now we will check 2.4.7.4 without KSPe.Light
.
TweakScale 2.4 shows the Houston only when KSPe.Light.TweakScale is absent,
I think this was supposed to say "is present "
TweakScale 2.5 Beta appears to be immune to the problem.
Right, because all of its KSPAssemblyDependencies are satisfied:
[LOG 12:46:44.421] AssemblyLoader: Loading assembly at /Users/lisias/Workspaces/KSP/runtime/1.12.5/GameData/TweakScale/Plugins/Scale.dll
[LOG 12:46:44.424] AssemblyLoader: KSPAssembly 'Scale' V2.5.0
[LOG 12:46:44.424] AssemblyLoader: KSPAssemblyDependency 'KSPe' V2.5.0
[LOG 12:46:44.424] AssemblyLoader: KSPAssemblyDependency 'KSPe.UI' V2.5.0
So the AssemblyLoader loads it, and it is in the list of loaded assemblies when ModuleManagerAddToModList is called, which then triggers the ReflectionTypeLoadException and the Houston message:
[ERR 12:46:50.356] [ModuleManager] ERROR: Add to mod list threw an exception in loading Scale, Version=2.5.0.60, Culture=neutral, PublicKeyToken=null at Exception:0
[EXC 12:46:50.360] ReflectionTypeLoadException: Exception of type 'System.Reflection.ReflectionTypeLoadException' was thrown.
System.Reflection.Assembly.GetTypes () (at <9577ac7a62ef43179789031239ba8798>:0)
ModuleManager.ModListGenerator.GetAdditionalModsFromStaticMethods (ModuleManager.Logging.IBasicLogger logger) (at <bb771ee7c78a424985a1e41a7e3f4a09>:0)
UnityEngine.DebugLogHandler:LogException(Exception, Object)
KSPe.Util.Log.UnityLogDecorator:UnityEngine.ILogHandler.LogException(Exception, Object)
ModuleManager.UnityLogHandle.InterceptLogHandler:LogException(Exception, Object)
UnityEngine.Debug:LogException(Exception)
KSPe.Util.Log.UnityLogger:logException(String, Exception)
KSPe.Util.Log.Logger:error(Exception, String, Object[])
ModuleManager.Logging.ModLogger:Exception(String, Exception)
ModuleManager.ModListGenerator:GetAdditionalModsFromStaticMethods(IBasicLogger)
ModuleManager.<Run>d__13:MoveNext()
UnityEngine.SetupCoroutine:InvokeMoveNext(IEnumerator, IntPtr)
As I explained here, because your code is using System.AppDomain.CurrentDomain.GetAssemblies()
and not the AssemblyLoader's loadedAssemblies list, you are enumerating Scale.dll in the cases where 999_scale_redist is missing - which will throw ReflectionTypeLoadExceptions.
This doesn't explains why TS 2.4.7.4 with KSPe.Light triggers the Houston, while without it does not - remembering that the thing already failed by the absence of 999_Scale_Redist.dll.
Yes, it does. Scale.dll 2.4.7.4 has a KSPAssemblyDependency attribute - it declares that it requires KSPe.Light.TweakScale. When KSPe.Light.TweakScale isn't present, the AssemblyLoader completely ignores Scale.dll and will not load it. That's why there's no further exceptions being thrown, and no Houston message.
You zeroed in on the problem! Kudos and thank you!
The problem is that KSP is using only the Assembly's KSPAssembly
and KSPAssemblyDependency
and not the C#'s metadata for dependencies check.
I had to remove Scale_Redist
from the KSPAssemblyDependency
because somewhere in the no so distant past (KSP 1.8, perhaps - lots of things changed when they migrated to Unity 2019), someone made the less than happy decision to check dependencies using the DLL's file name, instead of the Assembly's name itself. This broke Scale_Redist
utterly, because I moved the DLL to GameData
renaming it to 999_Scale_Redist.dll
to guarantee that file would be the first to be loaded due another less than ideal implementation of versioning check that was preserving only the first Assembly being loaded and ignoring any duplicate (being them newer or not).
We had posted at the same time! :D
My guess here was slightly wrong - I no longer think
System.AppDomain.CurrentDomain.GetAssemblies()
is signifficantly different from the AssemblyLoader's loadedAssemblies list. The difference is that in one case the missing KSPAssemblyDependency prevented the dll from being loaded at all, and in the other case all the declared dependencies were satisfied.
You nailed it.
Monkey Patching is completely ruled out for this case, I will update all the documentation where I mentioned it.
(we still have evidences of possible monkey patching here and perhaps here - but they are a far cry from being a smoking gun by themselves)
You nailed it.
Heh I just updated that comment again - there is one difference between System.AppDomain.CurrentDomain.GetAssemblies()
and the AssemblyLoader's list - and it comes into play when a hard-referenced dependency wasn't found (i.e. the cases where you remove 999_scale_redist). In that case, the Scale.dll assembly will NOT be in the AssemblyLoader's list but it WILL be in the System.AppDomain.CurrentDomain.GetAssemblies()
list. I think this explains some of the differences you see, depending on other mods that might be using one of these or the other.
As I tried to explain here and #312 (comment) this is completely expected behavior based on the way the AssemblyLoader and KSPe work. It doesn't have anything to do with monkey patching.
This doesn't explains why TS 2.4.7.4 with KSPe.Light triggers the Houston, while without it does not - remembering that the thing already failed by the absence of 999_Scale_Redist.dll.
On the other hand, I agree that this makes the Monkey Patching hypothesis unnecessary and, so, ruled out by Occam's razor.
If you suspect the network traffic is interesting, I'd really suggest using wireshark to see what the actual contents are.
Because this is yet one more test to be made on my already nearly exhausted free time to use on this problem. So I prefer to do the essential tests first in the hope to have a diagnosis first and, if failed, then I would start to monitor the ethernet traffic.
This doesn't explains why TS 2.4.7.4 with KSPe.Light triggers the Houston, while without it does not - remembering that the thing already failed by the absence of 999_Scale_Redist.dll.
Yes, it does. Scale.dll 2.4.7.4 has a KSPAssemblyDependency attribute - it declares that it requires KSPe.Light.TweakScale. When KSPe.Light.TweakScale isn't present, the AssemblyLoader completely ignores Scale.dll and will not load it. That's why there's no further exceptions being thrown, and no Houston message.
Oukey, again the same Test Bed using:
- KSP 1.12.5
- KSPe 2.5.3.3
- MM /L 4.2.3.1
But with variations on TweakScale. Follows the results:
- TweakScale 2.5.0.60, without
999_Scale_Redist.dll
and withKSPe.Light.TweakScale
- We got a "Houston"
- KSP-TS25-KSPeLight.log.zip
- TweakScale 2.5.0.60, without
999_Scale_Redist.dll
and withoutKSPe.Light.TweakScale
- We got a "Houston"
- KSP-TS25.log.zip
- TweakScale 2.4.7.4, without
999_Scale_Redist.dll
and withKSPe.Light.TweakScale
- We got a "Houston"
- KSP-TS24-KSPeLight.log.zip
- TweakScale 2.4.7.4, without
999_Scale_Redist.dll
and withoutKSPe.Light.TweakScale
- NO "Houston"
- KSP-TS24.log.zip
- TweakScale 2.4.7.4, with
999_Scale_Redist.dll
and withoutKSPe.Light.TweakScale
- NO "Houston"
- KSP-TS24-Redist.log.zip
TweakScale 2.5 Beta appears to be immune to the problem.
TweakScale 2.4 shows the Houston only when KSPe.Light.TweakScale is absent, the Scale_Redist absence doesn't triggers a "Houston".