File Delete and FO's causes continuous progress wheel (daemon stop and start needed)

[empakoso]

Before reporting, check if your problem is here: https://github.com/eyal0/OctoPrint-PrintTimeGenius/wiki/Common-problems

Please fill this out:

OctoPrint Version: OctoPrint 1.4.2 Python 3.7.3 OctoPi 0.17.0

PrintTimeGenius Version (if you know):

What did you try: safe mode, individually disabled all plugins, and re enabled all plugins, before and after tested this plugin by enabling and disabling it.

What happened: when deleting a file either the first one or second file from the list, the progress wheel stays spinning continuously. Everything is halted and frozen including my systemd program written to monitor my PSU.

What did you expect to happen: immediate file deletion without any delay. Which works every time is this plugin is disabled.

[eyal0]

That's odd. Is there anything interesting in the log files? https://github.com/eyal0/OctoPrint-PrintTimeGenius/wiki/Common-problems#is-it-working

[credomane]

I'm not 100% sure PrintTimeGenius is python3 compatible or at least that is the obvious conclusion I've come too, for now.

My octoprint has been running flawlessly through various updates on python2 since I set it up about a year ago but I switched to python3 sometime in the past few weeks and within a few days I've been dealing with this exact issue mention here.

I've been going through octoprint safe mode and been enabling plugins a few at a time until I recreated this issue. I've pretty much got it narrowed down to PrintTimeGenius at this point in time.

Once my current print is finished in a couple hours I'm going to uninstall+clean plugin data then reinstall PrintTimeGenius and see if the issue is solved or persists. If it persists I'll start working on getting all the debugging info I can get you.

Looking at the PrintTimeGenius logs w/o debugging enabled I do see that it is running a script using the python2 binary instead of the python3 binary that everything is installed with. I've also noticed that my print estimation times are absolutely terrible now even after clearing all the compensation data. Easily 16hours off for even a 30 minute print.

"/home/pi/oprint/bin/python2" "/home/pi/oprint/lib/python2.7/site-packages/octoprint_PrintTimeGenius/analyzers/analyze_progress.py"

[Will4567]

Happening with octopi 0.18.0 and with both octoprint 1.6.0 and 1.6.1. Python is showing as 3.7.3 and I've never upgraded python, I think it came with python 3.x builtin to the octopi 0.18.0 that I'm using. When I disable this plugin I can delete all day. With it enabled, it locks the web server/octoprint randomly after usually 1-10 deletions. I can reboot with : sudo service octoprint restart That fixes it until next time. setting the plugin to debug logging and checking both main octoprint log and print time genius engine log doesn't seem to show any relevant entries.

[credomane]

Python isn't in my list of "well" known languages so sarge is even lesser understood. Having said that isn't this a possible infinite loop if sarge fails to create a process? Say like the command is invalid because it points to a non existent executable? https://github.com/eyal0/OctoPrint-PrintTimeGenius/blob/591d4ea23840a2728831586ef44f4dcb237a64b8/octoprint_PrintTimeGenius/init.py#L312-L315

I've been looking over PTG trying to find anything to explain this bug. So far I haven't had the bug return after deleting PTG and all of its plugin data then reinstalling. I notice that the analyzer commands now point to the correct place and use the correct python executable.

"/home/pi/oprint/bin/python" "/home/pi/oprint/lib/python3.7/site-packages/octoprint_PrintTimeGenius/analyzers/analyze_progress.py"

I'm going to try changing the python executable in the command to something non-existent and see if the bug returns.

[eyal0]

Ah, interesting. It's possible that you were pointing to the wrong version of python?

OctoPrint settings all have defaults, including for plugins. A configuration value is only stored on disk if it is different from the default. The correct value for the command to analyze files is something like:

"/home/pi/oprint/bin/python" "/home/pi/oprint/lib/python3.7/site-packages/octoprint_PrintTimeGenius/analyzers/analyze_progress.py" marlin-calc "{gcode}"

So long as that isn't changed in the settings then it won't show up in the config. And when you upgrade python, it'll automatically take the new default, which is the new version of python.

But if you modified the config then it would have stored the path to the old location and then, after you upgraded, it would have kept that old path. So perhaps that is the issue?

I'm not sure about infinite loops around that bit with sarge. I, too, don't know much about sarge. I used sarge because it is what other parts of OctoPrint use. I would expect that sarge would throw an error and not enter and infinite loop there. If you're curious to debug it then I would suggest putting some sort of print into there to see if it is printing out a bunch of stuff. Like:

logger.info("Waiting for sarge")

And then see what happens?

I'm not sure of a better way for the config to handle modifications and python upgrades at the same time.

[credomane]

I changed the python binary to the non-existent python2 binary. This is the result in the PTG log file:

2021-06-01 19:46:37,730 Running: "/home/pi/oprint/bin/python2" "/home/pi/oprint/lib/python3.7/site-packages/octoprint_PrintTimeGenius/analyzers/analyze_progress.py" marlin-calc "/home/pi/.octoprint/uploads/tools/DrillGuide_0.3mm_PLA_ENDER3_2h44m.gcode" ""
2021-06-01 19:46:37,736 Waiting for Sarge process...
2021-06-01 19:46:38,252 Waiting for Sarge process...
2021-06-01 19:46:38,753 Waiting for Sarge process...
2021-06-01 19:46:39,254 Waiting for Sarge process...
2021-06-01 19:46:39,761 Waiting for Sarge process...
--SNIP--
2021-06-01 19:52:40,885 Waiting for Sarge process...
2021-06-01 19:52:41,386 Waiting for Sarge process...
2021-06-01 19:52:41,887 Waiting for Sarge process...
2021-06-01 19:52:42,389 Waiting for Sarge process...
2021-06-01 19:52:42,890 Waiting for Sarge process...

It didn't lock up my web interface, at least not yet, but it is definitely an infinite loop.

[edit]
Not even 5 minutes later I take that back. My web interface is locked up now...

[edit2]
Hmm....I did a "fix" and after 5 seconds of waiting on the sarge process to start the while loop terminates BUT the web interface will lock up after a couple more minutes if I try to delete a file. It seems like if the analyze process fails for whatever reason then the web interface is doomed.

        # Wait for sarge to begin
        count = 0
        while (not sarge_job.processes or not sarge_job.processes[0]) and count < 10:
          logger.debug("Waiting for Sarge process...");
          count = count + 1
          time.sleep(0.5)

Now the log shows this:

2021-06-01 20:09:02,926 Running: "/home/pi/oprint/bin/python2" "/home/pi/oprint/lib/python3.7/site-packages/octoprint_PrintTimeGenius/analyzers/analyze_progress.py" marlin-calc "/home/pi/.octoprint/uploads/tools/DrillGuide_0.3mm_PLA_ENDER3_2h44m.gcode" ""
2021-06-01 20:09:02,943 Waiting for Sarge process...
2021-06-01 20:09:03,468 Waiting for Sarge process...
2021-06-01 20:09:03,984 Waiting for Sarge process...
2021-06-01 20:09:04,492 Waiting for Sarge process...
2021-06-01 20:09:05,000 Waiting for Sarge process...
2021-06-01 20:09:05,502 Waiting for Sarge process...
2021-06-01 20:09:06,005 Waiting for Sarge process...
2021-06-01 20:09:06,511 Waiting for Sarge process...
2021-06-01 20:09:07,017 Waiting for Sarge process...
2021-06-01 20:09:07,534 Waiting for Sarge process...
2021-06-01 20:09:08,052 Failed to run '"/home/pi/oprint/bin/python2" "/home/pi/oprint/lib/python3.7/site-packages/octoprint_PrintTimeGenius/analyzers/analyze_progress.py" marlin-calc "/home/pi/.octoprint/uploads/tools/DrillGuide_0.3mm_PLA_ENDER3_2h44m.gcode" ""'
Traceback (most recent call last):
  File "/home/pi/oprint/lib/python3.7/site-packages/octoprint_PrintTimeGenius/__init__.py", line 321, in _do_analysis
    process = psutil.Process(sarge_job.processes[0].pid)
AttributeError: 'NoneType' object has no attribute 'pid'

[edit3]
I've noticed that all files the analyze failed on have a permanent flashing star like the analyze is in progress when it actually isn't. Trying to delete any file with "in-progress" analyze equals web interface lock up.

[eyal0]

Nice find.

I could just add a counter to the loop and throw an error if we fail. That would be easy enough and solve this problem. Plus, it would report a nice error to the user.

[credomane]

I did added a counter to the loop and let the analyzer fail out during my testing. The octoprint process still ends up in a wonky state and trying to interact with the file manager locks up the web interface until you restart the octoprint service. Probably because I didn't do any clean up for a failed analyze but my knowledge of python has already been put to the test figuring this much out. So I have no idea what needs to be done to make things not go sideways if the analyze process fails to start.

[timur-tabi]

I might be impacted by this bug as well. It seems whenever I try to delete a file from the web interface, I get the spinning progress wheel and Octoprint effectively crashes. The only clue I have that this plugin might be the culprit is this log file:

$ cat plugin_PrintTimeGenius_engine.log 2023-01-28 17:45:18,607 Abort requested but will be ignored due to settings.

[credomane]

OctoPrint settings all have defaults, including for plugins. A configuration value is only stored on disk if it is different from the default.

I guess I missed this originally. I never changed the actual command. The only setting I've ever changed in PrintTimeGenius was to check the checkbox to enable "Use Slic3r PE M73 time remaining" which seems to have been enough trigger the saving of the command paths. Which was fine until upgrading OctoPrint from python2 to python3.

The proper fix would be to verify the path to the python executable is valid before trying to execute it and some error handling if it is not and/or maybe provide a method to reset the path to defaults?