search

KSP-CKAN / CKAN

The Comprehensive Kerbal Archive Network
https://forum.kerbalspaceprogram.com/index.php?/topic/197082-*
Other
1.96k stars 349 forks source link

[Bug] CKAN.TransactionalKraken: Registry already enlisted #3539

Closed glowingc4 closed 2 years ago

glowingc4 commented 2 years ago

Background

Problem

Everytime i try to install a visual mod it says the code down there, is it the program? or just my bad pc..

Describe the bug

Steps to reproduce

Expected behavior if i try to install any visual mod like realplume stock, EVE, Astronomer, etc. it says the code down there

Log file: CKAN.log

CKAN.TransactionalKraken: Registry already enlisted with tx 2e0d1b0a-82e1-4941-9452-1cfdaaa8c252:10, can't enlist with tx 2e0d1b0a-82e1-4941-9452-1cfdaaa8c252:14
   at CKAN.Registry.EnlistWithTransaction()
   at CKAN.Registry.RegisterModule(CkanModule mod, IEnumerable`1 absolute_files, GameInstance ksp, Boolean autoInstalled)
   at CKAN.ModuleInstaller.Install(CkanModule module, Boolean autoInstalled, Registry registry, HashSet`1& possibleConfigOnlyDirs, String filename)
   at CKAN.ModuleInstaller.InstallList(ICollection`1 modules, RelationshipResolverOptions options, RegistryManager registry_manager, HashSet`1& possibleConfigOnlyDirs, IDownloader downloader, Boolean ConfirmPrompt)
   at CKAN.Main.InstallMods(Object sender, DoWorkEventArgs e)
   at System.ComponentModel.BackgroundWorker.OnDoWork(DoWorkEventArgs e)
   at System.ComponentModel.BackgroundWorker.WorkerThreadStart(Object argument)
HebaruSan commented 2 years ago

See #3502 and #3517 for previous reports that we couldn't continue investigating after the authors stopped responding.

@ohthebiomesyoullgoooooooo, this comment has a link to a test download and instructions for how to use it:

https://github.com/KSP-CKAN/CKAN/issues/3517#issuecomment-1014788274

Please try that and share a link to the log file. Thanks!

glowingc4 commented 2 years ago

I got the error again, see below. 2022-03-03

HebaruSan commented 2 years ago

Yes, that's expected. The point was to generate a log file so we could investigate this.

HebaruSan commented 2 years ago

Please share a link to the log file.

HebaruSan commented 2 years ago

This comment has a link to a test download and instructions for how to use it:

https://github.com/KSP-CKAN/CKAN/issues/3517#issuecomment-1014788274

HebaruSan commented 2 years ago

@ohthebiomesyoullgoooooooo, these comments are not helping us to investigate this issue. We need a log file as requested three times. If you're able to provide this, please do, and we can re-open this.

glowingc4 commented 2 years ago

Okay, i can provide it. i got it working and i need to create the bug.

glowingc4 commented 2 years ago

<?xml version="1.0" encoding="utf-8" ?>

HebaruSan commented 2 years ago

Good try, but that's the wrong file. You want the CKAN.log file.

glowingc4 commented 2 years ago

I found a log in CKAN.txt 2022-03-04 18:41:53 DEBUG CKAN.Registry - Already enlisted with tx 8de9ee4f-6ee1-4c21-916a-5339f1f08402:1

HebaruSan commented 2 years ago

That's closer! But we need the whole file. You can attach it to a comment by clicking this in the bottom of the comment box:

image

glowingc4 commented 2 years ago

CKAN.log

glowingc4 commented 2 years ago

Hello? are you there? or are you just looking in it?

HebaruSan commented 2 years ago

I'm eating dinner and watching The Expanse with my wife, which will take at least another 45 minutes. But thanks, this is the right file.

HebaruSan commented 2 years ago

It looks like the (previous) transaction is calling Registry.Prepare but not Registry.Commit, so Registry thinks it's still active when a new transaction is started.

2022-03-04 18:53:03 INFO CKAN.ModuleInstaller - Installed RecoveryController 0.0.4.1
2022-03-04 18:53:03 DEBUG CKAN.Registry - Registering module RecoveryController 0.0.4.1
2022-03-04 18:53:03 DEBUG CKAN.Registry - Already enlisted with tx fb315af8-b63d-489e-b72a-cd266f542342:8
2022-03-04 18:53:03 INFO CKAN.RegistryManager - Saving CKAN registry at C:/Games/Kerbal Space Program/CKAN\registry.json
2022-03-04 18:53:21 DEBUG CKAN.Registry - Registry prepared to commit transaction
2022-03-04 18:56:12 DEBUG CKAN.Registry - Started with MakingHistory-DLC 1.12.0, BreakingGround-DLC 1.7.0, xScienceContinued 6.0.0.9, TextureReplacer v4.5.3, DistantObject v2.1.1.6, PlanetShine 0.2.6.6, Scatterer-sunflare 3:v0.0831, PoodsCalmNebulaSkybox v1.3.0, ClickThroughBlocker 1:0.1.10.17, ZeroMiniAVC 1:1.1.0.2, ToolbarController 1:0.1.9.6, SpaceTuxLibrary 0.0.8.4, DistantObject-default v2.1.1.6, PlanetShine-Config-Default 0.2.6.6, CameraTools v1.20.0, MechJeb2 2.12.3.0, Toolbar 1:1.8.0.7, HotSpot 0.9.0, WarpDrive 0.9.4.2, ReentryParticleEffect 1.9.1.1, DeadlyReentry 1:v.7.9.0, HullcamVDSContinued 0.2.2, CactEyeCommunityRefocused 1.5.2.7, RecoveryController 0.0.4.1, CustomBarnKit 1.1.22.0, KSP-Recall v0.2.2.1, Trajectories v2.4.3, FMRSContinued 1.2.9.2, TarsierSpaceTechnologyWithGalaxies 1:7.13, KAS 1.10, KIS 1.29, CommunityCategoryKit v5.2.0.0, RealisticAtmospheres 1.3.2, Kopernicus 2:release-1.12.1-83, ModularFlightIntegrator 1.2.10.0, OuterPlanetsMod 2:2.2.10, CommunityTerrainTexturePack 1:1.0.4, CommNetAntennasExtension 2.1.6, ScienceSituationInfo 1:1.3.5, CommunityPartsTitles 0.9.1, CommNetAntennasInfo 3.1.2, CommNetAntennasConsumptor 3.5.5, RemoteTechRedevAntennas 0.1.1, TweakScale v2.4.6.8, SpaceXLegs 2.9.2, removing ClickThroughBlocker, and keeping MakingHistory-DLC 1.12.0, BreakingGround-DLC 1.7.0, xScienceContinued 6.0.0.9, TextureReplacer v4.5.3, DistantObject v2.1.1.6, PlanetShine 0.2.6.6, Scatterer-sunflare 3:v0.0831, PoodsCalmNebulaSkybox v1.3.0, ZeroMiniAVC 1:1.1.0.2, ToolbarController 1:0.1.9.6, SpaceTuxLibrary 0.0.8.4, DistantObject-default v2.1.1.6, PlanetShine-Config-Default 0.2.6.6, CameraTools v1.20.0, MechJeb2 2.12.3.0, Toolbar 1:1.8.0.7, HotSpot 0.9.0, WarpDrive 0.9.4.2, ReentryParticleEffect 1.9.1.1, DeadlyReentry 1:v.7.9.0, HullcamVDSContinued 0.2.2, CactEyeCommunityRefocused 1.5.2.7, RecoveryController 0.0.4.1, CustomBarnKit 1.1.22.0, KSP-Recall v0.2.2.1, Trajectories v2.4.3, FMRSContinued 1.2.9.2, TarsierSpaceTechnologyWithGalaxies 1:7.13, KAS 1.10, KIS 1.29, CommunityCategoryKit v5.2.0.0, RealisticAtmospheres 1.3.2, Kopernicus 2:release-1.12.1-83, ModularFlightIntegrator 1.2.10.0, OuterPlanetsMod 2:2.2.10, CommunityTerrainTexturePack 1:1.0.4, CommNetAntennasExtension 2.1.6, ScienceSituationInfo 1:1.3.5, CommunityPartsTitles 0.9.1, CommNetAntennasInfo 3.1.2, CommNetAntennasConsumptor 3.5.5, RemoteTechRedevAntennas 0.1.1, TweakScale v2.4.6.8, SpaceXLegs 2.9.2; our dlls are 666-ModuleManagerWatchDog, Interstellar-Redist, ModuleManager, KerbalEngineer

The line after "prepared to commit" should start with "Committing registry tx" (and that pattern is present in several other places in the log), but instead we have a 2.9 minute delay followed by some FindReverseDependencies instrumentation.

Checking the documentation for explanations, maybe other enlistees called PreparingEnlistment.ForceRollback, or maybe an exception was thrown? But then we should have had Registry.Rollback called, and it wasn't. Maybe their Prepare never returns?

HebaruSan commented 2 years ago

Conversation locked due to repeated unproductive comments and resultant notification spam. We are analyzing the log file, and we don't know how long that will take. If that allows us to determine a code fix, we will create a pull request for it. If we need more information, we will create a new debug component to generate more logs and unlock the conversation.

HebaruSan commented 2 years ago

For background, the transaction IDs in the log all start with the same lower case UUID, then end with a colon and an incrementing number. The one noted above that apparently never ends is :8, which is an attempt to install some mods. TransactionalKraken is thrown by :9 and :10.

The previous transaction, :7, removes some mods. Interestingly, it has a lot of errors about missing files:

2022-03-04 18:49:45 INFO CKAN.ModuleInstaller - Failure in locating file C:/Games/Kerbal Space Program/GameData/EnvironmentalVisualEnhancements : Could not find file 'C:\Games\Kerbal Space Program\GameData\EnvironmentalVisualEnhancements'.
2022-03-04 18:49:45 INFO CKAN.ModuleInstaller - Failure in locating file C:/Games/Kerbal Space Program/GameData/EnvironmentalVisualEnhancements/button.png : Could not find a part of the path 'C:\Games\Kerbal Space Program\GameData\EnvironmentalVisualEnhancements\button.png'.
2022-03-04 18:49:45 INFO CKAN.ModuleInstaller - Failure in locating file C:/Games/Kerbal Space Program/GameData/EnvironmentalVisualEnhancements/EnvironmentalVisualEnhancements.version : Could not find a part of the path 'C:\Games\Kerbal Space Program\GameData\EnvironmentalVisualEnhancements\EnvironmentalVisualEnhancements.version'.
[...]
2022-03-04 18:50:04 INFO CKAN.ModuleInstaller - Failure in locating file C:/Games/Kerbal Space Program/GameData/AstronomersVisualPack : Could not find file 'C:\Games\Kerbal Space Program\GameData\AstronomersVisualPack'.
2022-03-04 18:50:04 INFO CKAN.ModuleInstaller - Failure in locating file C:/Games/Kerbal Space Program/GameData/AstronomersVisualPack/AstronomersVisualPack.version : Could not find a part of the path 'C:\Games\Kerbal Space Program\GameData\AstronomersVisualPack\AstronomersVisualPack.version'.
2022-03-04 18:50:04 INFO CKAN.ModuleInstaller - Failure in locating file C:/Games/Kerbal Space Program/GameData/AstronomersVisualPack/AVP_Configs : Could not find a part of the path 'C:\Games\Kerbal Space Program\GameData\AstronomersVisualPack\AVP_Configs'.
[...]
2022-03-04 18:50:04 INFO CKAN.ModuleInstaller - Failure in locating file C:/Games/Kerbal Space Program/GameData/Scatterer : Could not find file 'C:\Games\Kerbal Space Program\GameData\Scatterer'.
2022-03-04 18:50:04 INFO CKAN.ModuleInstaller - Failure in locating file C:/Games/Kerbal Space Program/GameData/Scatterer/icon : Could not find a part of the path 'C:\Games\Kerbal Space Program\GameData\Scatterer\icon'.
2022-03-04 18:50:04 INFO CKAN.ModuleInstaller - Failure in locating file C:/Games/Kerbal Space Program/GameData/Scatterer/icon/icon.png : Could not find a part of the path 'C:\Games\Kerbal Space Program\GameData\Scatterer\icon\icon.png'.
[...]
2022-03-04 18:50:05 INFO CKAN.ModuleInstaller - Failure in locating file C:/Games/Kerbal Space Program/GameData/999_KSP-Recall : Could not find file 'C:\Games\Kerbal Space Program\GameData\999_KSP-Recall'.
2022-03-04 18:50:05 INFO CKAN.ModuleInstaller - Failure in locating file C:/Games/Kerbal Space Program/GameData/999_KSP-Recall/CHANGE_LOG.md : Could not find a part of the path 'C:\Games\Kerbal Space Program\GameData\999_KSP-Recall\CHANGE_LOG.md'.
2022-03-04 18:50:05 INFO CKAN.ModuleInstaller - Failure in locating file C:/Games/Kerbal Space Program/GameData/999_KSP-Recall/KSP-Recall.cfg : Could not find a part of the path 'C:\Games\Kerbal Space Program\GameData\999_KSP-Recall\KSP-Recall.cfg'.

So maybe an unstated step in reproducing this is to install mods with CKAN, then delete some of those files manually before uninstalling them in CKAN? Too bad the steps to reproduce weren't described (and presumably the "manual changes" question in the issue template wasn't answered accurately).

HebaruSan commented 2 years ago

The Failure in locating... message comes from here, presumably thrown by File.GetAttributes:

https://github.com/KSP-CKAN/CKAN/blob/46e989046980183772f5ae03dad65ec8ff43c80f/Core/ModuleInstaller.cs#L724-L771

Might be good to probe that a bit more. If the file_transaction.Delete line is throwing instead, then maybe some internal state of the transaction system could be getting corrupted for the next transaction? It's definitely thrown before that, because the Removing... message on the previous line isn't in the log.

HebaruSan commented 2 years ago

This is probably but not certainly fixed in the v1.31.0 release. Closing for now; if it still happens with the latest CKAN, please let us know and we can re-open this.