delayed notifications on pushover

[jon-daemon]

I use octoprint 1.4 on orange pi zero and I experience delayed notifications. See this log file I received the print started notification at 14:17 and finished notification at 14:58 In the log you can see it was started and finished a few minuted earlier. What could be the issue. What should I investigate?

[fraschetti]

Hi @jon-daemon

There's not much within Octoslack that could add a delay other than if OctoPrint itself is behind on emitting events internally or if Pushover is somehow lagging. I'd suggest enabling the Octoslack debug below to see if it can tell us anything. The timestamps in the log will give us an indication of how long it took the plugin to send the Pushover event and get a reponse from when OctoPrint first fired its internal event.

1. Enable DEBUG logging
2. Reproduce the issue
3. 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

[jon-daemon]

Here is a log from today You can see for example that I started a new job at 17:05. At 17:06 I got the cancel notification from the previous job. The started notification for the new job arrived at 17:09 I have pause command (M0) in my gcode so I can clean the nozzle and prepare the bed. You can see it paused at 17:06:59 and I resumed at 17:07:05. Could this cause this issue. This wasn't an issue in the past. I have installed a few new plugins in the last month but I'm not sure when this delay started.

[fraschetti]

Hi @jon-daemon

The 17:02 - 17:06 window was rather busy with the cancel+start events overlapping but there is some suspicious log data there. Instead I focused on the end of the print job at 17:33 where only one printer event is in play.

Here are the relevant log messages with annotations:

2020-04-22 17:33:23,946 - octoprint.plugins.Octoslack - DEBUG - Event: PrintDone, NotificationEnabled: True, CommandEnabled: False, Payload: ...

At 17:33:23 OctoPrint fires the PrintDone event which kicks off the Octoslack logic

2020-04-22 17:33:24,282 - octoprint.plugins.Octoslack - DEBUG - Pushover msg title: ➖ Print finished successfully 👍🏻

At 17:33:24 we can see Octoslack has completed all its internal work (query device temperature, fetch & upload camera snapshots, etc.) and is generating the Pushover payload.

2020-04-22 17:33:24,292 - octoprint.plugins.Octoslack - DEBUG - Pushover msg retry: None

At 17:33:24 we see the last Octoslack log message before we execute the logic to actually transmit the Pushover message over the network. At this point < 2 seconds has passed since OctoPrint emitted its internal PrintDone event.

2020-04-22 17:37:48,445 - octoprint.plugins.Octoslack - DEBUG - Pushover push response: {"status": 1, "request": "9bdd021c-5f1e-47d7-99d2-8691e874522d"}

At 17:37:48 we finally see the response from the Pushover call. 17:37:48 - 17:33:24 = 4 mins, 24 seconds. I don't really have an answer for this issue other than a networking issue (either your network or the device) or an issue with Pushover itself. I'd put my money on Pushover either having performance issues or you're being rate limited b/c of either your current or previous Pushover message send rates.

I'm sorry I don't have a better answer for you but the logs don't show an obvious issue with the code. If you notice something interisting in the logs or a pattern in the behaviour (does it always happen? only at certain times of day? only on certain events?), please let me know.

Two unrelated and likely irrelevant observations:

1. All attempts to query for the snapshot images are failing - if you don't have a local camera, you can disable capturing snapshots on the event configs to remove the "Snapshot error" message text.

2. Your Orange Pi Zero OS apparently doesn't support the same local command to query for the device's temperature. You can avoid some internal overhead (and error messages in the OctoPrint logs) by disabling "Include RasPi temp" at the very top of the Octoslack config dialog.

[jon-daemon]

I found the problem. It was indeed a network issue. I couldn't even ping from the terminal. I found that armbian was configured to use ipv6. I switched to ipv4 in armbian configuration and it works fine. I don't know why it was working fine in the past. My ISP was acquired by another company and they replaced my router. Maybe my router was the issue. Thanks for your time.