[1.191.105][DS] On server start, server decides to not start with mods

Hello there,

today I got something complicated to report. I already have talked to Inflex about it and he recommended me adding all my findings to this bugreport.

What happened + Backstory

Every now and then (approximately once per month) we notice all of our mods vanishing from our server on scheduled restart. We run a Torch Server mostly for concealment plugins to maintain our 64 slots without the simspeed breaking down. And we run a self written plugin on it that basically kills and restarts the server if the restart process takes longer than 120 seconds.

We assumed to be killing the server too early that it didnt manage to properly save.

However after just a few seconds the world is properly saved and starts to unload. Also after investigating the source code of Torch it doesnt seem to be related to them at first glance.

Our Analysis to the matter

So when it happened again yesterday I was basically on the root-server while it happened and was able to check a few things immediately. To my surprise the mods were still present in the save file (which btw is over a GB in size and therefore not Uploaded here). Also the servers logs (which are attached) revealed that at 20:04:00 when the server started back up the mods indeed were present and being updated.

20:04:03.3884 [DEBUG]  Keen: Error during mod dependencies query: NoConnection
20:04:03.3884 [DEBUG]  Keen:       MyWorkshop.GetItemsBlocking: getting 18 items
20:04:04.8455 [DEBUG]  Keen: Mod query successful
20:04:04.8455 [INFO]   Keen:       Up to date mod: Id = 429053416, title = 'OKI Grand Weapons Bundle'
20:04:04.8455 [INFO]   Keen:       Up to date mod: Id = 514062285, title = 'BuildInfo (extra block&terminal info, air leak finder)'
20:04:04.8455 [INFO]   Keen:       Up to date mod: Id = 523925570, title = 'Skybox Stellar fields'
20:04:04.8455 [INFO]   Keen:       Up to date mod: Id = 525460808, title = 'Reavers (Updated Behavior)'
20:04:04.8455 [INFO]   Keen:       Up to date mod: Id = 642589539, title = 'Tiered Engine Super Pack'
20:04:04.8455 [INFO]   Keen:       Up to date mod: Id = 646796262, title = 'Easy Inventory (Obsolete)'
20:04:04.8455 [INFO]   Keen:       Up to date mod: Id = 657749341, title = 'Automatic Ore Pickup'
20:04:04.8455 [INFO]   Keen:       Up to date mod: Id = 758597413, title = 'Text HUD API'
20:04:04.8455 [INFO]   Keen:       Up to date mod: Id = 805678675, title = 'Tiered Thorium Reactors and Refinery'
20:04:08.0708 [INFO]   Keen: Workshop item with id 946724937 download finished. Result: k_EResultOK
20:04:08.0708 [DEBUG]  Keen: Mod download successful.
20:04:08.0708 [INFO]   Keen:       Up to date mod: Id = 946724937, title = 'PassageIntersections'
20:04:08.0708 [INFO]   Keen:       Up to date mod: Id = 973526550, title = 'Air Traffic'
20:04:08.0708 [INFO]   Keen:       Up to date mod: Id = 1135484957, title = 'Surface Occupation'
20:04:08.0708 [INFO]   Keen:       Up to date mod: Id = 1359954841, title = 'Rotary Airlock'
20:04:08.0708 [INFO]   Keen:       Up to date mod: Id = 1365616918, title = 'Defense Shields - v1.9(62)'
20:04:08.0708 [INFO]   Keen:       Up to date mod: Id = 1400364273, title = 'NPC Programming Extender'
20:04:08.0708 [INFO]   Keen:       Up to date mod: Id = 1521905890, title = 'Modular Encounters Spawner'
20:04:08.0708 [INFO]   Keen:       Up to date mod: Id = 1713051166, title = 'Chillz Floor Pack'
20:04:08.0708 [INFO]   Keen:       Up to date mod: Id = 1728457223, title = 'SmartRotors: Solar'
20:04:08.0728 [INFO]   Keen:       Mod download time: 3.22 seconds
20:04:08.0728 [INFO]   Keen:    Downloading world mods - END
20:04:08.0728 [INFO]   Keen:    Loading session: C:\Games\Space Engineers\PVE Modded\Instance\Saves\Star System
20:04:10.4026 [DEBUG]  Keen:    GC Memory: 1,222,801,864 B
20:04:10.4026 [DEBUG]  Keen:    Process Memory: 1,687,461,888 B
20:04:10.4026 [INFO]   Keen:    Experimental mode: Yes
20:04:10.4026 [INFO]   Keen:    Experimental mode reason: ExperimentalMode, MaxPlayers, PhysicsIterations, SyncDistance, TotalPCU, EnableIngameScripts, StationVoxelSupport
20:04:11.3710 [DEBUG]  Keen:    MyScriptManager.LoadData() - START
20:04:11.3850 [DEBUG]  Keen:    MyScriptManager.LoadData() - END
20:04:11.3850 [DEBUG]  Keen:    MyDefinitionManager.LoadData() - START
20:04:11.3850 [DEBUG]  Keen:    MyDefinitionManager.LoadScenarios() - START
20:04:11.3850 [DEBUG]  Keen:       3432f18cf6a0ef7ea37b6605cc32d86ad11a39fd
20:04:11.4947 [DEBUG]  Keen:       Loading scenarios
20:04:11.4947 [DEBUG]  Keen:    MyDefinitionManager.LoadScenarios() - END
20:04:11.4947 [DEBUG]  Keen:       List of used mods (0) - START
20:04:11.4947 [DEBUG]  Keen:       List of used mods - END

However there are 2 other things that seem odd.

20:04:03.3884 [DEBUG]  Keen: Error during mod dependencies query: NoConnection

However with the summer sale going on at the moment, it wouldn't surprise me if steams servers were not always able to reply to requests.

So to summarize so far:

• Mod Dependincy Download failed
• Mods were present in safe file
• Mods were checked for updates and even updated.

Now to the seconds odd thing.

20:04:11.4947 [DEBUG]  Keen:       List of used mods (0) - START
20:04:11.4947 [DEBUG]  Keen:       List of used mods - END

I would assume the server would not even intend to update the mods if they are not in the save and therefore, it confused me why it decides to not use any of them.

Our Conclusion

As stated before there should not be any scenario of a corrupt save file.

Our Assumption would be if checking mod dependencies fails that mods which are in need of dependencies cannot be seen as working by the server. So they are skipped.

However of all these mods only one needs a dependency that is not in our mods list. So we assume the server itself does not know what mods needs which dependencies. So to "make sure" everything is alright it just does not use any of the mods after updating them.

Which causes corruption of the world because modded blocks vanish without return and on next save, the mods also vanish from the save.

Our Expectation

If for whatever reasons mods cannot be loaded we would expect the server start to fail. I prefer to just try it again and in worst case have the server offline for a few hours than ending up with a corrupted world and a load of unhappy players as their expensive modded blocks are gone.

We were able to recover as we we have 24h of backups. And noticed it immediately, but in case we are not able to rollback immeately but in a few hours new players that join in the mean time will loose their builds.

With our 64 slots the server has a rate of new players joining throughout the day.

Inflex told me you have means to check if there is any code path causing the server to run without loading mods.

I hope you find something and can fix it.

Thank you and I wish you a nice Sunday

LordTylus