Sometimes hangs right before modpack import

[fosspill]

I have been able to successfully import both .ttmp and .ttmp2 modpacks in the new build. However, I the application will occasionally hang after the step "Importing 94/94 mods from modpack...", never reporting a progress percentage. Killing the process and trying again is usually successful. Seems to be 50/50, usually impacting newly installed modpacks.

❯ ./ffmt mpi -t ~/FFXIV_TEX_BACKUPS/Mods/Eyes\ of\ Eorzea\ -\ Buns\ \&\ Lions.ttmp2
Checking backups before proceeding...
All backups present and up to date
WARNING: Found a mod applied by an unknown application, game stability cannot be guaranteed:
Would you like to continue? (y/N)
y
Starting import...
Extracting data from Eyes of Eorzea - Buns & Lions.ttmp2...
Would you like to use the Wizard for importing?
(Y)es, let me select the mods
(N)o, import everything
n

Data extraction successful.
DEBUG: Setting active mods file
DEBUG: Updating active mods
DEBUG: modActiveConfFile = /home/taylor/.config/FFXIV_Modding_Tool/modlist.cgf
DEBUG: About to enter mods foreach loop
DEBUG: Found existing mod
DEBUG: Overwriting existing mod entry
DEBUG: Overwriting existing mod entry
DEBUG: Overwriting existing mod entry
DEBUG: Overwriting existing mod entry
DEBUG: Found existing mod
DEBUG: Overwriting existing mod entry
DEBUG: Overwriting existing mod entry
DEBUG: Found existing mod
DEBUG: Overwriting existing mod entry
DEBUG: Overwriting existing mod entry
DEBUG: Overwriting existing mod entry
DEBUG: Overwriting existing mod entry
DEBUG: Overwriting existing mod entry
DEBUG: Overwriting existing mod entry
DEBUG: Overwriting existing mod entry
DEBUG: Overwriting existing mod entry
DEBUG: Overwriting existing mod entry
DEBUG: Found existing mod
DEBUG: Overwriting existing mod entry
DEBUG: Returning states
Importing 16/16 mods from modpack...

_Originally posted by @taylor85345 in https://github.com/fosspill/FFXIV_Modding_Tool/issues/195#issuecomment-673131325_

[fosspill]

This, to me, sounds like a race condition, maybe within the framework itself somehow.

Assuming that the issue may be this line... Maybe we need to set some timeout and try again? https://github.com/fosspill/FFXIV_Modding_Tool/blob/b3abb3c56023bf895143975b101d35f27f78c1b4/FFXIV_Modding_Tool/Program.cs#L525

[taylor85345]

This happened every other time on my first few runs, but came up less often down the line. After installing ~25 modpacks, several of which I re-installed multiple times do to issues with order of installation, I'd say it happened ~15% of the time

[fosspill]

That definitely makes it sound like a race condition. Sadly neither @shinnova or I have found any good ways of making it reliably happen.

If you see it happen again could you give it a few minutes and see what happens? And; Would you mind testing a few extra builds to helps us narrow down the issue?

[taylor85345]

No problem. Keep 'em coming!

[kainzilla]

EDIT: Oops, just noticed old version always showed 1167/1167 for the example below, it's just the percentage progress counter that never shows / never progresses. I did let the current version run for a very long time before believing it wasn't silently succeeding however. Both current version and test version were encountering this issue pretty reliably for the Hair Refined pack, but

Using the test build that was available under #195 I occasionally see this as well, but I also can't reliably reproduce it either. Perhaps the very large Hair Defined pack might help cause this issue to demonstrate more reliably? https://www.nexusmods.com/finalfantasy14/mods/88

When this issue happened just now for this particular pack, I did notice that it immediately showed "Importing 1167/1167" instead of counting upwards - aside from that message, there didn't appear to be anything else to shed additional light on the issue:

DEBUG: Mod didn't exist yet (Note: This repeated for the 1000+ texture files so my console mostly had this and I missed anything before this)
DEBUG: Found existing mod
DEBUG: Overwriting existing mod entry
DEBUG: Found existing mod
DEBUG: Overwriting existing mod entry
DEBUG: Found existing mod
DEBUG: Overwriting existing mod entry
DEBUG: Returning states
Importing 1167/1167 mods from modpack... (This line immediately showed 1167/1167, with no counting upwards, and no percentage printed below as it usually does)

The ffmt process stayed in this state, but didn't appear to progress. ffmt process was in a 'sleeping' status when checking KDE System Activity manager, but was pegged at 100% utilization of a single CPU core when this was occurring. I waited a good long period of time to make sure that the process wasn't secretly succeeding in the background (since Hair Defined is large), but it didn't appear to succeed after a reasonably long waiting period.

If I see any test builds in here I'll be happy to try them and provide any feedback I can. Cheers!

[taylor85345]

I can confirm that I encountered basically the same behavior as @kainz0r, with this issue mostly occuring on large modpack imports. I am confident that Hair Refined hung up on at least two import attempts.

There were also a couple of instances where using Ctrl+C to cancel the command left the hanging ffmt process running in the background with the CPU pegged at 100%, and I had to kill it manually from htop.

[fosspill]

Been running tests for an hour or so now and: The test ran around 20 times with 0 of them getting stuck on the latest test build. This was specifically a simple modpack, however, while the hair one is a wizard one.

Will keep trying to reproduce so we can troubleshoot properly.

Update: I've ran over 200 tests now and none has failed with our current test build. Again with simple modpack, so wizard still isn't excluded

[shinnova]

This is a build that will exit out if import would have ran successfully, for ease of testing. @taylor85345 and @kainz0r, could you test to see if you can still reproduce the freeze?

For reference, a successful import will quit like this:

Checking backups before proceeding...
All backups present and up to date
Starting import...
Extracting data from 001Chromatized Maps.ttmp2...
Data extraction successful.
Importing 1555/1555 mods from modpack...
0%ERROR: Quitting because import would have ran successfully

[fosspill]

@shinnova I managed to get a freeze with the test build! It seems to confirm that Wizard modpacks is the issue

Update: So, this has been a bit of a rollercoaster but it seems like the root cause is found. The only question left is; can the wizard import fail if you answer a question with Y instead of just Enter

[kainzilla]

@shinnova I wasn't able to individually reproduce the freeze with that testing version so far, I did a big batch import of all the modpacks I use (58 packs including large wizard packs like Hair Defined / Face Defined) three times , and it didn't get stuck while processing them.

[fosspill]

Thank you kainz0r! We've been able to reproduce it with the current test build and narrowed it down to it being dotnet keeping the thread locked too long when using readkey. We've added a 1sec delay in a separate test build and it seems to now only freeze 1/20 times.

Possible fixes that we see so far:

• Read user input async
• Keep an artificial delay
• Add artificial delay only after the user presses "Enter"...?
• Force the user to actually press a proper key as that instantly unblocks
• Maybe we could somehow run a separate thread that would give the initialization of a new thread a timeout.

[taylor85345]

I am fairly confident that I had at least one instance of a freeze after entering Y in the wizard and going through the selection process, but I don't have it recorded anywhere. Don't know if that is still helpful. Will advise if I am able to recreate.

[fosspill]

Indeed, the timing changes slightly between the options which changes the likelyhood of crash it seems.

[taylor85345]

Just had a small Wizard pack freeze up after indicating Y and going through the selection process. Allowed it to sit for ~10 minutes before killing the process.

[fosspill]

Thank you again! We are slowly, line-by-line, going through parts of the xivmoddingframework to see if we can find the actual root cause of the locking. I think it may be that the caching worker is started and stopped too quickly under certain circumstances, but still digging through it. Will hopefully have a new test build out in a few hours

[shinnova]

@kainz0r @taylor85345 could you try with this latest test build?

Fair warning: it will still quit once import would have succeeded, and is filled to the brim with debug messages, so it can become quite spammy if something goes wrong. But, if we are right, it should resolve the freezing issue. Local testing has had 0 failures with this build.

If something does go wrong, try deleting your mod_cache.db and try again, your cache may have been corrupted and the framework doesn't check for that. If you can still reproduce the freezing after deleting the cache, we'll have to dig even deeper.

[kainzilla]

@shinnova I did give the version you posted a try, and it didn't hang during the process of mass-importing all my mods on 3x testing runs, and then a few additional re-runs on Hair Defined pack.

I'm not 100% certain that's helpful as the prior debug build also wasn't hanging on my system even though the issue was still present, but at least here I haven't been able to reproduce the hang yet.

[taylor85345]

I've also tested with a fair number of modpacks, and have not encountered any issues.

[fosspill]

Perfect! New version is out with all the fixes, and hopefully no more crashes!

[taylor85345]

Installed from AUR, and so far so good!

[kainzilla]

Same here, so far this version is working great over quite a few mod installs, resets, etc. It's looking good - thanks again!