OctoPrint-M73Progress icon indicating copy to clipboard operation
OctoPrint-M73Progress copied to clipboard

No M73 updates, an hour into print.

Open andritolion opened this issue 3 years ago • 34 comments

Even an hour into the print, there doesn't seem to have been any M73 updates sent to the printer, from what I could tell from watching the terminal. Any idea why that might be? Here's the last 1500 lines that I watched in the OctoPrint terminal, looking for any M73s.

OctoPrint 1.6.1, OctoPi 0.18.0, running on Raspberry Pi 4 Model B Rev 1.4

No M73 log.txt

andritolion avatar Jul 30 '21 09:07 andritolion

Done some investigating, and a quick 15 minute print shows the M73 info very soon after starting. Could it be that the print (which is 13 hours long) is too large for the plugin to handle? (IMO, updated M73 info should be sent every 30 seconds or so... Or whenever it changes or when it loads for the first time.)

andritolion avatar Jul 30 '21 12:07 andritolion

The plugin does not decide when the progress bar is updated. It responds to the on_print_progress() hook, which is triggered by OctoPrint itself. Long prints should not be a problem, as long as you're not printing from the SD-card.

  • Did you restart OctoPrint after installation?
  • Has the problem happened again since?
  • Are you using the progress_from_time setting? (i.e. in combination with PrintTimeGenius)

cesarvandevelde avatar Jul 30 '21 14:07 cesarvandevelde

  • I have restarted OctoPrint and the whole machine several times as a part of routine testing on my end.
  • Yes, the problem still occurs when beginning a 14 hour long print. However, I have noticed that during some time I was sleeping, the time and percent came on and was sent to the printer. Not good timing though.
  • Yes, I am using the progress_from_time setting with this plugin. The ability this plugin has to show percent and values that are closer to the number PrintTimeGenius provides is important to me. I have briefly used the Detailed Progress plugin (in conjunction with the DisplayLayerProgress plugin with all features that output M73 disabled, that plugin was only used for layer progress, height progress, and time to filament change data in Detailed Progress), but from what I could tell, it did not use PrintTimeGenius percentages or time remaining, so I disabled the M73 features in Detailed Progress (only used it for the M117 ticker) and replaced the features with this plugin. Detailed Progress did immediately show the time remaining and frequently update the percentage, however.

andritolion avatar Jul 30 '21 17:07 andritolion

Octoprint always uses the builtin progress estimation algorithm for the on_print_progress() hook, even if a more accurate estimate (i.e. PrintTimeGenius) is available. Why it does this I don't know, but my workaround involves calculating progress based on the elapsed time and the total time. This behavior is enabled through the progress_from_time option.

My guess is that there is an edge case where on_print_progress() gets called before the PrintTimeGenius estimate is computed. If this is the case, it would only happen for longer prints and more complex prints. It would not occur the second time the same file is printed, as estimates are cached by PrintTimeGenius. I tend to print smaller (< 8h) mechanical parts, so that could explain why I have not run into the issue you're describing.

Can you check the following, preferably with related plugins (DisplayLayerProgress, Detailed Progress) disabled?

  • The issue should not occur for small prints
  • The issue should occur the first time a complex file gets printed, but not the second time (due to caching)
  • Were there exceptions logged to octoprint.log?

cesarvandevelde avatar Jul 31 '21 16:07 cesarvandevelde

Apologies for the late reply. Been recovering from a lack of sleep recently.

  • Yes, I can confirm that the issue is not present on short prints.
  • This issue has still re-occurred, even after the same model was printed multiple times.
  • No, I don't believe there were any exceptions logged to octoprint.log, but feel free to inspect it if you like.

These tests were performed with any plugins that could interfere disabled. I have run the test for an hour and 10 minutes, the whole time, the Remaining field unfilled. Attached are some relevant photos and a copy of my octoprint.log.

octoprint.log IMG_20210802_025557 IMG_20210802_025530 2021-08-02 (11)

andritolion avatar Aug 02 '21 10:08 andritolion

Sorry for the wait. I gave your last log a closer look, and it shows that DisplayETAPlugin is throwing a bunch of errors. Maybe that's causing issues downstream. Can you try disabling it?

I've also prepared a test version that includes debug logging and extra checks for potential edge cases: octoprint_m73progress_debug.zip

To install, uninstall the existing plugin first, then upload the zip file in the OctoPrint plugin manager. This version will output a plugin_m73progress.log file. Can you reproduce the issue and then add the Octoprint log and the plugin log here?

cesarvandevelde avatar Aug 05 '21 16:08 cesarvandevelde

Here are the requested logs along with a couple pictures.

octoprint.log plugin_m73progress.log

2021-08-05 (34)

IMG_20210805_224315

andritolion avatar Aug 06 '21 05:08 andritolion

It seems to be quite inconsistent. On this 17 hour print, longer than the other file, it shown the time remaining on the printer display within 10 minutes. IMG_20210807_192143

2021-08-07 (8)

andritolion avatar Aug 08 '21 02:08 andritolion

Sorry for the late reply; paid work took priority. I took a closer look at your logs, and it seems that on_print_progress() never gets called. I've prepared another debug version to check this: octoprint_m73progress_debug2.zip. Best to delete the existing logs (octoprint.log and plugin_m73progress.log) before trying, so that nothing gets mixed up.

If this is the case, the problem is caused outside of the plugin. The root of the problem might be a conflicting plugin, so the next step would be to try with all other plugins disabled.

cesarvandevelde avatar Aug 13 '21 08:08 cesarvandevelde

No worries! Life happens. I have disabled all third-party plugins minus M73 Progress and PrintTimeGenius, and the issue can still be reproduced. Here's a copy of the log files.

octoprint.log plugin_m73progress.log 2021-08-13 (7) 2021-08-13 (8) IMG_20210813_063352

andritolion avatar Aug 13 '21 13:08 andritolion

Well, the logs confirm that on_print_progress() is not getting called, so the root cause must lie outside of the plugin. I think this issue may have to get kicked up to OctoPrint itself. Out of curiosity, can you try disabling PrintTimeGenius as well? The plugin should fall back on OctoPrint's built-in time estimate.

cesarvandevelde avatar Aug 13 '21 13:08 cesarvandevelde

Alright. I'm disabling PrintTimeGenius and will get back to you in an hour.

andritolion avatar Aug 13 '21 13:08 andritolion

Immediately after starting the print, the time remaining is set.

andritolion avatar Aug 13 '21 14:08 andritolion

However, it doesn't seem like the time remaining info is actually updated once set. Nearly an hour into print, and it still says 11:55 remaining. octoprint.log plugin_m73progress.log

2021-08-13 (10)

IMG_20210813_075711

andritolion avatar Aug 13 '21 15:08 andritolion

Yup, exactly the same situation as before: on_print_progress does not get called.

I've created a minimal plugin that does nothing more than write the progress to a log file: OctoPrint-ProgressTest.zip. If the problem can be reproduced with Octoprint + this plugin (no other 3rd party plugins), then the next step would be opening an issue in the Octoprint repository.

cesarvandevelde avatar Aug 14 '21 10:08 cesarvandevelde

is it possible to enable the //#define LCD_SET_PROGRESS_MANUALLY on Ender3? I tried but got this error

 #error "LCD_PROGRESS_BAR requires a character LCD."

antonioreyna avatar Aug 16 '21 07:08 antonioreyna

is it possible to enable the //#define LCD_SET_PROGRESS_MANUALLY on Ender3? I tried but got this error

 #error "LCD_PROGRESS_BAR requires a character LCD."

You need custom firmware in order to be able to have progress updates on the Ender 3v2. Check out Jyers firmware. https://github.com/Jyers/Marlin/ Not sure about the original Ender 3 though.

Also, sorry for the delay, Cesar. With classes and everything starting up now, I've had limited time to test the minimal plugin, or print anything in general. I'll try to install it when I get home.

andritolion avatar Aug 16 '21 16:08 andritolion

Sorry for the delay. Never got a chance to test it until today. I was able to reproduce the issue with only the plugin provided. plugin_progresstest.log octoprint.log IMG_20210821_105645 2021-08-21 (1) 2021-08-21

andritolion avatar Aug 21 '21 18:08 andritolion

No worries about the delay, and thanks for trying out the many test scenarios. The last test shows that the root cause of the bug is OctoPrint itself, not one of the plugins. I think it's best to open a new issue in the OctoPrint repo with a link to this discussion. If you want, I'll write up the issue, just let me know...

cesarvandevelde avatar Aug 22 '21 13:08 cesarvandevelde

Alright. I'll also attach the gcode file in both issues to see if someone else can repro it. The issue seems to be influenced by the particular gcode file being printed. (Packed in a ZIP, else GitHub complains.) CE3_Display_holder_Ender_3V2_without_logo.zip

andritolion avatar Aug 22 '21 13:08 andritolion

@cesarvandevelde I did some testing on this for @andritolion and we suspect the issue is with the on_print_progress but not because it's not working, because it is. The issue is that even with PTG installed, the on_print_progress callback is still done on a file size based progress estimate for the increments, not the time based one of PTG. I see that you are calculating the time based progress in your callback, but that callback only gets called on the internal file based increment. PTG overrides the progress bar in the UI, not in the server side code. One way you could get around this is instead of using on_print_progress use your own RepeatedTimer thread and then use sef._printer.get_current_data().

jneilliii avatar Dec 26 '21 20:12 jneilliii

That's exactly right. The on_print_progress hook gets called every 1% increment of the file progress, but the plugin calculates the progress value based on the PTG time estimate.

The root cause of the issue is that on_print_progress does not get called at all. In the case of the 17h print, the first update should occur after 1% file progress (roughly 17 * 60 * 0,01 = 10min). However, the report says that nothing happened after 1 hour had elapsed... To me, this suggests that the problem is caused by an OctoPrint bug.

cesarvandevelde avatar Dec 27 '21 00:12 cesarvandevelde

I ran the file for quite some time with the virtual printer and it did increment though.

jneilliii avatar Dec 27 '21 00:12 jneilliii

IMO, running a RepeatedTimer thread that updates the info every 60 seconds would be a better implementation, as even though the percentage isn't changing, the time remaining countdown would be kept up to date. Additionally, the info should also be sent immediately at print start (and maybe 1 or 2 seconds after, as it doesn't seem PTG can get the time ready immediately, even if it's preanalyzed), so that the time estimate will be immediately visible upon starting the print, and not after a minute. And yes, it does eventually increment, but after approximately 1 hour, 20 minutes. Apologies if that wasn't clear from my previous messages.

andritolion avatar Dec 27 '21 02:12 andritolion

Thanks for clarifying; I was under the impression that the hook was not getting called at all. I agree that a periodic timer implementation would be better, but I can't make make any promises w.r.t. timeframe. Pull requests are welcome though, in case someone wants to have a crack at it...

cesarvandevelde avatar Dec 27 '21 21:12 cesarvandevelde

Send in E time I am having a similar issue of the M73 plugin not displaying the progress. Just an empty bar:

It is showing E: and R: (elapsed and remaining) times on my : BBT TF35 Dual display which I use as the LCD12864

Configuration_adv.h, which was working, as I normally use, modified to suit update for Marlin-bugfix-2.1.2 #define SET_PROGRESS_MANUALLY // Protomaker Sprint Show Progress using OctoPrint and M73 Plugin

It was working before

So far as I am aware it stopped working when I updated to

Marlin-bugfix-2.1.2, this changed the LCD12864 lay out a bit

OctoPrint 1.8.7 Python 3.9.2 OctoPi 1.0.0

Above updated to this

Thanking you

ProtomakerSprint avatar Mar 08 '23 17:03 ProtomakerSprint

LCD_PROGRESS_BAR

Have you the correct printer set Configuration_adv.h says:-

#if EITHER(HAS_MARLINUI_HD44780, IS_TFTGLCD_PANEL) //#define LCD_PROGRESS_BAR

in my case in Configuration.h I use and leave the above uncommitted

#define REPRAP_DISCOUNT_FULL_GRAPHIC_SMART_CONTROLLER // Protomaker Sprint TFT35 Dual display

ProtomakerSprint avatar Mar 09 '23 13:03 ProtomakerSprint

LCD_PROGRESS_BAR

Have you the correct printer set Configuration_adv.h says:-

#if EITHER(HAS_MARLINUI_HD44780, IS_TFTGLCD_PANEL) //#define LCD_PROGRESS_BAR

in my case in Configuration.h I use and leave the above uncommitted

#define REPRAP_DISCOUNT_FULL_GRAPHIC_SMART_CONTROLLER // Protomaker Sprint TFT35 Dual display

LCD_PROGRESS_BAR

Have you the correct printer set Configuration_adv.h says:-

#if EITHER(HAS_MARLINUI_HD44780, IS_TFTGLCD_PANEL) //#define LCD_PROGRESS_BAR

in my case in Configuration.h I use and leave the above uncommitted

#define REPRAP_DISCOUNT_FULL_GRAPHIC_SMART_CONTROLLER // Protomaker Sprint TFT35 Dual display

ProtomakerSprint avatar Mar 09 '23 13:03 ProtomakerSprint

@ProtomakerSprint Your issue is unrelated to this discussion, and the cause is likely outside this plugin.

That being said, please refer to the Marlin documentation for M73:

  • LCD_SET_PROGRESS_MANUALLY is required.
  • USE_M73_REMAINING_TIME since v2.0.0
  • Test by sending M73 P25 R43 manually.

cesarvandevelde avatar Mar 11 '23 10:03 cesarvandevelde

I am using Marlin; my guide to gcode says M73 not available, set percentage build M73 P25 R43 manually did noting at all, no change on display

SanityCheck.h states:- #error "LCD_SET_PROGRESS_MANUALLY is now SET_PROGRESS_MANUALLY."

in Configuration_adv.h I have:- // Add the G-code 'M73' to set / report the current job progress #define SET_REMAINING_TIME true // Protomaker Sprint SET_PROGRESS_PERCENT, SET_REMAINING_TIME, SET_INTERACTION_TIME to be enabled."

#define SET_PROGRESS_MANUALLY // Protomaker Sprint Show Progress using OctoPrint and M73 Plugin #if ENABLED(SET_PROGRESS_MANUALLY) //#define SET_PROGRESS_PERCENT // Add 'P' parameter to set percentage done, otherwise use Marlin's estimate //#define SET_REMAINING_TIME // Add 'R' parameter to set remaining time, otherwise use Marlin's estimate //#define SET_INTERACTION_TIME // Add 'C' parameter to set time until next filament change or other user interaction #if ENABLED(SET_INTERACTION_TIME) #define SHOW_INTERACTION_TIME // Display time until next user interaction ('C' = filament change) #endif //#define M73_REPORT // Report progress to host with 'M73' #endif

Thanking You

ProtomakerSprint avatar Mar 16 '23 23:03 ProtomakerSprint