fraschetti / Octoslack

OctoPrint plugin for Slack, Mattermost, Pushbullet, Pushover, Rocket.Chat, Discord, Riot/Matrix, & Microsoft Teams
MIT License
74 stars 34 forks source link

OctoSlack messing up prints (vase mode) #118

Open melyux opened 3 years ago

melyux commented 3 years ago

I was attempting a vase mode print for the first time and noticed some zits on my print, caused by the print head stuttering. Investigation showed that the stuttering wouldn’t happen when printing from SD card, or when printing in safe mode. I tried turning on my plugins by themselves and trying.

The result was... OctoSlack enabled just by itself was enough to cause stuttering in vase mode when printing from my Pi 3B+ OctoPrint. I could turn off OctoSlack and and enable all of the other plugins simultaneously (14 of them), and it would print perfectly. Meaning OctoSlack was solely responsible for the stuttering, which is probably slowness in how fast the Pi is sending the vase mode GCODEs.

Notes: OctoSlack is unconfigured because I hadn’t gotten around to it. So this is happening without any configuration. Vase mode requires sending lots of GCODE rapidly to the printer, so these issues really surface when doing vases.

Picture below: Left is with only OctoSlack enabled, all other plugin disabled Right is with 14 plugins enabled, OctoSlack disabled 405589FC-EE9F-4111-88B0-E106F63BF363

fraschetti commented 3 years ago

Hi @melyux

A bit of background: OctoPrint plugins operate inline with OctoPrint itself. This means when an event fires that a plugin is subscribed to (% complete, g-code processed, etc.), it's wildly important how long any given plugin (or combination of plugins) take to process that event. Priners typically keep a local buffer of commands and for hightly details prints (e.g. not long extrudes in a straight lines), the printer is likely constantly being fed new commands from OctoPrint. Because these plugins operate inline with the main OctoPrint processing thread, if one or more plugins are keeping OctoPrint busy, it may not have enough time to send commands to the printer and eventually the printer is left waiting what to do next. And of course if the printer is waiting and the nozzle is idle, even for a brief moment, it allows unwated filament to ooze out and blemishes to form.

So let's start by take a look at what, if anything, the Octoslack plugin is doing. Please follow the steps below to generate some debug logs if you're willing to kick off another print with the plugin going. The logs will likely give me an idea of what's going on but if you could summarize what you have enabled (what events are enabled, are you using the g-code event feature, etc), that may also help.

Enable DEBUG logging Reproduce the issue Send Octoprint.log Instructions to enable DEBUG logging for Octoslack

Enable DEBUG logging Ensure the following has been added to /home/pi/.octoprint/logging.yaml (or appropriate path for your OctoPrint installation) loggers: octoprint.plugins.Octoslack: level: DEBUG Restart OctoPrint sudo service octoprint restart For OctoPi releases, the log file will be located in: /home/pi/.octoprint/logs/octoprint.log

melyux commented 3 years ago

Sure, I'll give it a try as soon as I can. Thanks for the background crash course. Interesting that plugins block in the main thread in priority of the printing. I guess it makes sense considering how things like OctoLapse work, but doesn't seem to make sense for things like OctoSlack. Is there an option for plugins to spin off in threads instead of blocking the printing thread?

fraschetti commented 3 years ago

Great question - for Octoslack I've already moved as much as possible (image processing, sending messages to slack, etc.) but there is some work I still need to do in the main thread before I can fire up the thread. Most notably is grabbing various printer states (e.g. what's the % complete when the event fired) or evaluate a g-code event to potentially trigger events. Right now I'm not reusing threads so there is a potential optimization there to avoid that startup cost.

The plugin has a ton of DEBUG logging so hopefully we'll be able to take a look to see if the plugin is doing any signifant work or otherwise getting hung up somewhere.

melyux commented 3 years ago

Alright, got an octoprint.log. I tried it again and got the same results: no stuttering all the other plugins, but just Octoslack by itself leads to the nozzle stuttering in vase mode. Again, Octoslack is not configured at all, it's just freshly installed with no configuration whatsoever (i.e. it doesn't send any messages because I haven't set it up). Here's the log with debug for Octoslack on:

2021-06-12 21:41:35,535 - octoprint.plugins.action_command_notification - INFO - Got a notification: Printing...
2021-06-12 21:43:48,258 - octoprint.plugins.Octoslack - DEBUG - Progress: 1 - IntervalPct: 25
2021-06-12 21:43:48,277 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:48 PM
2021-06-12 21:44:26,651 - octoprint.plugins.Octoslack - DEBUG - Progress: 2 - IntervalPct: 25
2021-06-12 21:44:26,870 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:24:58 PM
2021-06-12 21:45:35,665 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2021-06-12 21:45:35,939 - octoprint.plugins.Octoslack - DEBUG - Progress: 3 - IntervalPct: 25
2021-06-12 21:45:35,962 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:10 PM
2021-06-12 21:46:53,146 - octoprint.plugins.Octoslack - DEBUG - Progress: 4 - IntervalPct: 25
2021-06-12 21:46:53,168 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:34 PM
2021-06-12 21:47:31,471 - octoprint.plugins.Octoslack - DEBUG - Progress: 5 - IntervalPct: 25
2021-06-12 21:47:31,497 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:24:59 PM
2021-06-12 21:48:33,005 - octoprint.plugins.Octoslack - DEBUG - Progress: 6 - IntervalPct: 25
2021-06-12 21:48:33,025 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:24:53 PM
2021-06-12 21:49:10,694 - octoprint.plugins.Octoslack - DEBUG - Progress: 7 - IntervalPct: 25
2021-06-12 21:49:10,711 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:01 PM
2021-06-12 21:49:34,971 - octoprint.plugins.Octoslack - DEBUG - Progress: 8 - IntervalPct: 25
2021-06-12 21:49:35,020 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:24:59 PM
2021-06-12 21:49:59,252 - octoprint.plugins.Octoslack - DEBUG - Progress: 9 - IntervalPct: 25
2021-06-12 21:49:59,270 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:04 PM
2021-06-12 21:50:24,042 - octoprint.plugins.Octoslack - DEBUG - Progress: 10 - IntervalPct: 25
2021-06-12 21:50:24,060 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:08 PM
2021-06-12 21:50:47,847 - octoprint.plugins.Octoslack - DEBUG - Progress: 11 - IntervalPct: 25
2021-06-12 21:50:47,864 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:11 PM
2021-06-12 21:51:12,141 - octoprint.plugins.Octoslack - DEBUG - Progress: 12 - IntervalPct: 25
2021-06-12 21:51:12,181 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:16 PM
2021-06-12 21:51:35,902 - octoprint.plugins.Octoslack - DEBUG - Progress: 13 - IntervalPct: 25
2021-06-12 21:51:35,920 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:19 PM
2021-06-12 21:52:00,708 - octoprint.plugins.Octoslack - DEBUG - Progress: 14 - IntervalPct: 25
2021-06-12 21:52:00,727 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:23 PM
2021-06-12 21:52:24,482 - octoprint.plugins.Octoslack - DEBUG - Progress: 15 - IntervalPct: 25
2021-06-12 21:52:24,520 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:27 PM
2021-06-12 21:52:48,232 - octoprint.plugins.Octoslack - DEBUG - Progress: 16 - IntervalPct: 25
2021-06-12 21:52:48,275 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:31 PM
2021-06-12 21:53:12,454 - octoprint.plugins.Octoslack - DEBUG - Progress: 17 - IntervalPct: 25
2021-06-12 21:53:12,505 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:35 PM
2021-06-12 21:53:36,205 - octoprint.plugins.Octoslack - DEBUG - Progress: 18 - IntervalPct: 25
2021-06-12 21:53:36,225 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:38 PM
2021-06-12 21:54:00,480 - octoprint.plugins.Octoslack - DEBUG - Progress: 19 - IntervalPct: 25
2021-06-12 21:54:00,499 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:42 PM
2021-06-12 21:54:24,225 - octoprint.plugins.Octoslack - DEBUG - Progress: 20 - IntervalPct: 25
2021-06-12 21:54:24,247 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:45 PM
2021-06-12 21:54:48,540 - octoprint.plugins.Octoslack - DEBUG - Progress: 21 - IntervalPct: 25
2021-06-12 21:54:48,563 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:49 PM
2021-06-12 21:55:12,279 - octoprint.plugins.Octoslack - DEBUG - Progress: 22 - IntervalPct: 25
2021-06-12 21:55:12,297 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:52 PM
2021-06-12 21:55:36,063 - octoprint.plugins.Octoslack - DEBUG - Progress: 23 - IntervalPct: 25
2021-06-12 21:55:36,081 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:56 PM
2021-06-12 21:56:00,340 - octoprint.plugins.Octoslack - DEBUG - Progress: 24 - IntervalPct: 25
2021-06-12 21:56:00,388 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:25:59 PM
2021-06-12 21:56:24,570 - octoprint.plugins.Octoslack - DEBUG - Progress: 25 - IntervalPct: 25
2021-06-12 21:56:24,662 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:02 PM
2021-06-12 21:56:48,870 - octoprint.plugins.Octoslack - DEBUG - Progress: 26 - IntervalPct: 25
2021-06-12 21:56:48,921 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:05 PM
2021-06-12 21:57:13,209 - octoprint.plugins.Octoslack - DEBUG - Progress: 27 - IntervalPct: 25
2021-06-12 21:57:13,240 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:09 PM
2021-06-12 21:57:37,472 - octoprint.plugins.Octoslack - DEBUG - Progress: 28 - IntervalPct: 25
2021-06-12 21:57:37,509 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:12 PM
2021-06-12 21:58:02,240 - octoprint.plugins.Octoslack - DEBUG - Progress: 29 - IntervalPct: 25
2021-06-12 21:58:02,289 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:17 PM
2021-06-12 21:58:26,462 - octoprint.plugins.Octoslack - DEBUG - Progress: 30 - IntervalPct: 25
2021-06-12 21:58:26,509 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:20 PM
2021-06-12 21:58:50,729 - octoprint.plugins.Octoslack - DEBUG - Progress: 31 - IntervalPct: 25
2021-06-12 21:58:50,766 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:23 PM
2021-06-12 21:59:15,519 - octoprint.plugins.Octoslack - DEBUG - Progress: 32 - IntervalPct: 25
2021-06-12 21:59:15,555 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:27 PM
2021-06-12 21:59:39,761 - octoprint.plugins.Octoslack - DEBUG - Progress: 33 - IntervalPct: 25
2021-06-12 21:59:39,778 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:30 PM
2021-06-12 22:00:04,005 - octoprint.plugins.Octoslack - DEBUG - Progress: 34 - IntervalPct: 25
2021-06-12 22:00:04,071 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:34 PM
2021-06-12 22:00:28,820 - octoprint.plugins.Octoslack - DEBUG - Progress: 35 - IntervalPct: 25
2021-06-12 22:00:28,841 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:37 PM
2021-06-12 22:00:35,672 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2021-06-12 22:00:53,568 - octoprint.plugins.Octoslack - DEBUG - Progress: 36 - IntervalPct: 25
2021-06-12 22:00:53,608 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:41 PM
2021-06-12 22:01:18,831 - octoprint.plugins.Octoslack - DEBUG - Progress: 37 - IntervalPct: 25
2021-06-12 22:01:18,880 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:45 PM
2021-06-12 22:01:43,091 - octoprint.plugins.Octoslack - DEBUG - Progress: 38 - IntervalPct: 25
2021-06-12 22:01:43,126 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:49 PM
2021-06-12 22:02:07,877 - octoprint.plugins.Octoslack - DEBUG - Progress: 39 - IntervalPct: 25
2021-06-12 22:02:07,925 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:51 PM
2021-06-12 22:02:33,198 - octoprint.plugins.Octoslack - DEBUG - Progress: 40 - IntervalPct: 25
2021-06-12 22:02:33,234 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:26:57 PM
2021-06-12 22:02:58,445 - octoprint.plugins.Octoslack - DEBUG - Progress: 41 - IntervalPct: 25
2021-06-12 22:02:58,494 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:27:00 PM
2021-06-12 22:03:23,242 - octoprint.plugins.Octoslack - DEBUG - Progress: 42 - IntervalPct: 25
2021-06-12 22:03:23,295 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:27:05 PM
2021-06-12 22:03:49,105 - octoprint.plugins.Octoslack - DEBUG - Progress: 43 - IntervalPct: 25
2021-06-12 22:03:49,155 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:27:09 PM
2021-06-12 22:04:14,981 - octoprint.plugins.Octoslack - DEBUG - Progress: 44 - IntervalPct: 25
2021-06-12 22:04:15,016 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:27:13 PM
2021-06-12 22:04:40,851 - octoprint.plugins.Octoslack - DEBUG - Progress: 45 - IntervalPct: 25
2021-06-12 22:04:40,903 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:27:19 PM
2021-06-12 22:05:08,129 - octoprint.plugins.Octoslack - DEBUG - Progress: 46 - IntervalPct: 25
2021-06-12 22:05:08,146 - octoprint.plugins.action_command_notification - INFO - Got a notification: ETA is 10:27:26 PM