System won't start after upgrade if local plugin is enabled

[gunstr]

I have had the IPN validation plugin installed locally and running for a few month now.

The version information was:
InvenTree-Version: 0.11.0 dev
Django Version: 3.2.18
Commit Hash: 86f4a8294
Commit Date: 2023-03-21

Today I upgraded to the latest development version but then the system will not start if the plug in is enabled. The Supervisor status is OK:

But the system is not responding and if I look in the cluster.err.log the logging stops after Loading plugin ValidateUniqueIPN :

If I disable the plugin before the upgrade the system starts as it should and the log also continues to be populated as below

I know there has been recent changes related to plugins but what I can find nothing that should prevent local installation in the src/InvenTree/plugins/ folder. I have spent the full day now to try to sort this out, but I cannot figure out what I have missed. Any suggestions?

[matmair]

It seems to run on master for me. Can you try a higher log level?

[matmair]

Version Information:

InvenTree-Version: 0.12.0 dev
Django Version: 3.2.19
Commit Hash: 2e8fb2a
Commit Date: 2023-06-18
Commit Branch: master
Database: sqlite3
Debug-Mode: True
Deployed using Docker: False
Platform: macOS-13.4-arm64-arm-64bit
Installer: GIT

Active plugins: [{'name': 'InvenTreeBarcode', 'slug': 'inventreebarcode', 'version': '2.0.0'}, {'name': 'InvenTreeCoreNotificationsPlugin', 'slug': 'inventreecorenotificationsplugin', 'version': '1.0.0'}, {'name': 'ValidateUniqueIPN', 'slug': 'ipn_validator', 'version': '0.1'}, {'name': 'ShopifyPlugin', 'slug': 'shopify', 'version': '0.0.6a0'}]

[gunstr]

The log level is already set to DEBUG:

But I noticed another strange thing, after the upgrade I cannot open the "About" dialog... I get this error:

Can it be related?

As a test I restarted again with a copy of my working system and deleted the plugin before i did the upgrade and I still get the "About" error above.

Full version info för my working copy:

Version Information:

InvenTree-Version: 0.11.0 dev
Django Version: 3.2.18
Commit Hash: 86f4a8294
Commit Date: 2023-03-21
Database: mysql
Debug-Mode: True
Deployed using Docker: False
Active plugins: [{'name': 'InvenTreeBarcode', 'slug': 'inventreebarcode', 'version': '2.0.0'}, {'name': 'InvenTreeCoreNotificationsPlugin', 'slug': 'inventreecorenotificationsplugin', 'version': '1.0.0'}, {'name': 'Brother Labels', 'slug': 'brother', 'version': '0.5.0'}]

Then I upgrade to the master commit 2e8fb2a

If I click the "show error information" there is a lot of info, but this is a screenshot of the beginning:

I have not a clue if this is related to the plugin problem and how to approach this...

Another thing I have noticed is a warning when I run 'invoke update':

Applying part.0109_auto_20230517_1048...System check identified some issues:
WARNINGS:
company.Address: (models.W036) MySQL does not support unique constraints with conditions.
HINT: A constraint won't be created. Silence this warning if you don't care about it.

If you have any suggestions it's very appreciated.

[SchrodingersGat]

@gunstr thanks for repoting the additional errors - I have raised an issue for each. But, most likely not the cause of what you are seeing here.

[SchrodingersGat]

• Ref: [Bug] 'str' object has no attribiute 'removeprefix' #5071
• Ref: [CI] Migration issues with MySQL #5070

[matmair]

@gunstr We require python 3.9 or higher; see here.
removeprefix is a std lib function of str starting in 3.9. Please update your version of python as you are using an unsupported version (3.8.10)

[gunstr]

I have narrowed down the problem a bit. The last commit I can apply is 2ed7eef.
If I apply the next commit 58a33c2 (Switch from git to dulwich) the system will not respond at all as long as the plug in is enabled.

[gunstr]

Sorry, I have missed the python 3.9 requirment :-(
I will upgrade, might solve the plugin problem also...

[gunstr]

Now I have upgraded to Python3.9.17 but the problem with loading the plugin is still there. It works fine up to commit 2ed7eef but when I upgrade to 58a33c2 it leaves the system in the same state as described above.

This is before the upgrade:

Version Information:
InvenTree-Version: 0.12.0 dev
Django Version: 3.2.19
Commit Hash: 2ed7eef
Commit Date: 2023-06-05
Database: mysql
Debug-Mode: True
Deployed using Docker: False
Active plugins: [{'name': 'InvenTreeBarcode', 'slug': 'inventreebarcode', 'version': '2.0.0'}, {'name': 'InvenTreeCoreNotificationsPlugin', 'slug': 'inventreecorenotificationsplugin', 'version': '1.0.0'}, {'name': 'ValidateUniqueIPN', 'slug': 'ipn_validator', 'version': '0.1'}]

One thing I noted on the terminal log is that during 'invoke update' it stops for around half a minute each time it reaches the Loading plugin ValidateUniqueIPN and then it continues 'Loaded plugin ValidateUniqueIPN` - like a timeout. But when I boot the system it's unresponsive and the logging in the cluster.err.log stops completely (I have waited for at least 5min) --> UPDATE - I just noticed that the logging in the cluster.err.log actually continues after some minutes, but the web page is still not responding after 20min now,

[gunstr]

@matmair When you got the plugin working with the latest master where did you install it? As I never managed to find out why it's not discovered when I point towards an "external" folder I have put it just under src/InvenTree/plugins/. Could that be a reason why I cannot get it to work and you can?

[matmair]

I have cloned it into plugins. You are probably missing an init.py at some level. You need one at every level till the file in which the plugin class is defined.

[gunstr]

I just cannot get my arms around what is going on here... I have before just copied the 'validate_ipn_unique' folder to the 'src/InvenTree/plugins/' and as the problem starts when applying the commit where Dulwich is added I thougt it might be so that I had to clone the complete git repo as you do. I tried but with the same result - as soon as I enable the plugin the InvenTree web pages do no longer load - just this little round circle.

Do you know if there are any OS related prerequisites for Dulwich I might have missed? I'm running the system on a barebone Ubuntu 20.04 as a VM but it's all updated to latest status.

I found in the 'server.err.log' that it's actually never starting if the plugin is enabled. Below is a section of the log when booting with the plugin enabled. So there is obiously a timeout that happens. And if you see in the attached complete log it's just restarting over and over again - forever...

Loaded plugin `InvenTreeCoreNotificationsPlugin`
Loaded plugin `InvenTreeCoreNotificationsPlugin`
Loading plugin `ValidateUniqueIPN`
Loading plugin `ValidateUniqueIPN`
Loading plugin `ValidateUniqueIPN`
[2023-06-20 10:49:09 +0000] [918] [CRITICAL] WORKER TIMEOUT (pid:1049)
[2023-06-20 10:49:09 +0000] [918] [CRITICAL] WORKER TIMEOUT (pid:1057)
[2023-06-20 10:49:09 +0000] [918] [CRITICAL] WORKER TIMEOUT (pid:1058)
[2023-06-20 12:49:09 +0200] [1049] [INFO] Worker exiting (pid: 1049)
[2023-06-20 12:49:09 +0200] [1057] [INFO] Worker exiting (pid: 1057)
[2023-06-20 12:49:09 +0200] [1058] [INFO] Worker exiting (pid: 1058)
[2023-06-20 10:49:10 +0000] [918] [WARNING] Worker with pid 1049 was terminated due to signal 9
[2023-06-20 10:49:10 +0000] [1461] [INFO] Booting worker with pid: 1461
[2023-06-20 10:49:10 +0000] [918] [WARNING] Worker with pid 1058 was terminated due to signal 9
[2023-06-20 10:49:10 +0000] [918] [WARNING] Worker with pid 1057 was terminated due to signal 9
[2023-06-20 10:49:10 +0000] [1462] [INFO] Booting worker with pid: 1462
[2023-06-20 10:49:11 +0000] [1463] [INFO] Booting worker with pid: 1463
2023-06-20 10:49:11,395 INFO Loading SECRET_KEY from '/home/inventree/src/InvenTree/secret_key.txt'
2023-06-20 10:49:11,403 DEBUG Configuring database backend:
2023-06-20 10:49:11,403 INFO DB_ENGINE: django.db.backends.mysql
2023-06-20 10:49:11,403 INFO DB_NAME: inventree

server.err.log - plugin enabled.txt
server.err.log - plugin not enabled.txt

[SchrodingersGat]

From those logs, it looks like the server is resource constrained, and the workers are being killed off. Might be getting stuck in a loop?

@matmair any comments about the link to dulwich?

[matmair]

In my tests, it was actually much lighter than the previous function.

[gunstr]

@SchrodingersGat Seems correct, question is why...

The VM was configured with 1CPU and 4GB ram, this is the load with the plugin not enabled:

The same config with the plugin enabled:

Reconfigured with 4CPU and 8GB ram

So although the VM was a bit under dimentioned it's not the root cause. As you suggest it's rather that it's gettgin stuck in a loop. Any suggestion how to identify where?

[wolflu05]

Have you already tested other plugins so we can sort out if it's specific to this plugin.

[matmair]

@gunstr can you try installing python-dulwich and report back?

[gunstr]

Tests I have done:

1. sudo apt install python3-dulwich - still ends up in the same loop with the plugin enabled
2. Disabled the validate_ipn_unique installed from src/InvenTree/plugins/ folder and enabled the CustomValidator in the samples folder. System works as it should - no loop.
3. Moved the CustomValidator from the samples folder to the src/InvenTree/plugins/ . When the plugin is enabled the system goes into the same loop with WORKER TIMEOUTs during boot. If I revert back to commit 2ed7eef it again works with no issues.

Conclutions:

1. The problem only happens when any of the two plugins are loaded from the src/InvenTree/plugins/ folder --> likely not a problem with the plugin as such
2. @matmair has tested the same with no issues --> likely the root cause is in my installation or system configuration

[gunstr]

Continue testing....

1. Applied the 'dulwich' commit 58a33c2 again
2. None of the two plugins currently in 'src/InvenTree/plugins/' starts correctly
3. Moved back the CustomValidator to the samples folder - can again be enabled with no issues
4. Copied validate_ipn_unique.py to the same samples forlder - does not work. Deleted the file again.
5. Commented out all code for the CustomValidator in validation_sample.py and instead added the code from validate_ipn_unique.py - and now it works!!!

What is really the root cause I do not know... Both files have the same permissions, are coded with UTF-8 and Unix LF but some kind of difference between those two files are bringing the system into the endless loop if I do not just reuse the existing file. Could it be something low level git related that is not visible just looking at the actual files?

And when the same files are located in 'src/InvenTree/plugins/' it does not work at all. One difference between the two locations is obviously that the 'src/InvenTree/plugins/' is untracked by git - could be an idication for something related to git also here?

[SchrodingersGat]

I think I can replicate this.

1. Take file validation_sample.py from the plugin sample directory
2. Drop it into ./InvenTree/plugins/
3. Change the "slug" (so it does not conflict with the existing sample)
4. Reload server and attempt to activate new plugin
5. The server takes a long time to get back up (multiple minutes). Could easily be causing the worker to time out.

[SchrodingersGat]

Putting the plugin into the "external" plugins directory also has this issue. It seems to happen for any plugin, not just the validation sample. Some simple profiling shows that it is taking ~75 seconds to load a plugin from either the internal or external "plugins" directory.

[SchrodingersGat]

Issue opened here - #5081

[matmair]

I will look into this