search

fieldOfView / Cura-OctoPrintPlugin

Cura plugin which enables printing directly to OctoPrint and monitoring the process
GNU Affero General Public License v3.0
494 stars 74 forks source link

Octoprint busy #136

Open tablatronix opened 4 years ago

tablatronix commented 4 years ago

I get this alot and have to restart cura.

Let me know what you need to debug, thanks..

Screen Shot 2019-11-29 at 12 09 23 PM

https://github.com/Ultimaker/Cura/issues/6733

fieldOfView commented 4 years ago

Thanks for “transferring” the issue here.

First step is to check if the printer is indeed connected and not printing or in an error state. Can you “jog” the printhead through the web interface? And through Cura?

tablatronix commented 4 years ago

Yeah printer was fine, afaik. If I figure out how to reproduce I will post, but it seems random.

fieldOfView commented 4 years ago

Are you sure that the OctoPrint instance is not actually still in the "cancelling" state? If you eg cancel a print while heating up, the heating up needs to finish before the printer accepts new commands. Thus the printer is not actually ready to print another print.

tablatronix commented 4 years ago

Nope, I wonder if this has to do with the preheat plugin, I started using that more often.

How can I debug, can I manually check the api socket connection

fieldOfView commented 4 years ago

A cura.log is useful (Help -> Show configuration folder -> cura.log). Please upload it somewhere (eg pastebin.com) and share a link here; it is too large to paste into a comment here.

When it happens again, please open http://octopi/api/printer?apikey=yourapikey in a browser and post the response here.

tablatronix commented 4 years ago

Will do thanks!

Jzooor commented 4 years ago

This issue happens to me quite frequently if the computer I had sent the print job from goes into standby during a print. The print will complete, and Octoprint itself will be idle but if I wake up my computer and try to start a new print Cura will show the message above. The monitor page will also show a print still in progress. If I queue the job and then jump over to Octoprint right away, the job I sent will already be waiting to print and I just have to click start. The monitor page will just keep on showing the values that were last updated before the computer went to sleep. I've tried reconnecting to octoprint in the manage printers and the web cam image shows up, but the temp and progress values remain stuck. Only way to recover seems to be to restart Cura.

fieldOfView commented 4 years ago

@tablatronix could it be that your computer coming out of sleep/standby is also involved in your case?

marcelrv commented 4 years ago

I experience exactly the same. Will try to do digging in the logfiles to see if something stands out.

fieldOfView commented 4 years ago

@marcelrv, @tablatronix and @Jzooor, what OS do you use, and what version of Cura?

marcelrv commented 4 years ago

Cura 4.4 on Win10 in my case

tablatronix commented 4 years ago

osx, previous version, have not upgraded to latest yet, 4.4.?

I have not had the issue in a while, it is definitely something we are doing, I just cannot figure out exactly when it happens. If I had to guess its something like open cura, print, disconnect printer, reconnect printer, try to print again. Ill try to find reproducible test, and grab logs next time it happens.

Jzooor commented 4 years ago

I am on Win10. On Cura 4.4.1 now, but I have not run any long enough prints to have my PC go to sleep since updating from 4.3.

marcelrv commented 4 years ago

I had the issue again. The first print it was fine, the 2nd print I get a busy Here I have the output of http://octopi/api/printer?apikey=yourapikey at time of the busy. Win10. On Cura 4.4.1, OctoPrint 1.3.12 running on OctoPi 0.16.0

{
  "sd": {
    "ready": true
  }, 
  "state": {
    "flags": {
      "cancelling": false, 
      "closedOrError": false, 
      "error": false, 
      "finishing": false, 
      "operational": true, 
      "paused": false, 
      "pausing": false, 
      "printing": false, 
      "ready": true, 
      "resuming": false, 
      "sdReady": true
    }, 
    "text": "Operational"
  }, 
  "temperature": {
    "bed": {
      "actual": 25.45, 
      "offset": 0, 
      "target": 0.0
    }, 
    "tool0": {
      "actual": 18.28, 
      "offset": 0, 
      "target": 0.0
    }
  }
}
fieldOfView commented 4 years ago

I need a Cura.log to know what is going on. See Help -> Show configuration folder. Please upload cura.log somewhere and post a link here (as the file may be sizeable).

fieldOfView commented 4 years ago

I happened to come across this video which exhibits a similar issue: https://youtu.be/IwUz0kfMrSA?t=712

crysxd commented 4 years ago

I encounter the same issue regularly. It can be "fixed" by going to Preferences > Printer > Connect OctoPrint and then clicking "Disconnect" followed by "Connect". The following extract from the cura.log shows how I tried to start a print but got the message "OctoPrint busy" and then completed above steps. After this I could start the print without issues.

I will try to confirm @marcelrv observation the next time. For me it seems like the plugin caches the old state and does not refresh it. Could we add an extra state check before this message is shown? 

2020-03-02 21:16:06,046 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [398]: file:///Applications/Ultimaker Cura.app/Contents/MacOS/resources/qml/ActionButton.qml:79:9: QML Label: Binding loop detected for property "width"
2020-03-02 21:16:06,049 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [398]: file:///Applications/Ultimaker Cura.app/Contents/MacOS/resources/qml/ActionButton.qml:79:9: QML Label: Binding loop detected for property "width"
2020-03-02 21:16:06,056 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [398]: file:///Applications/Ultimaker Cura.app/Contents/MacOS/resources/qml/ActionButton.qml:79:9: QML Label: Binding loop detected for property "width"
2020-03-02 21:16:06,060 - DEBUG - [MainThread] CuraEngineBackend.CuraEngineBackend._onSlicingFinishedMessage [663]: Slicing took 4.4107348918914795 seconds
2020-03-02 21:16:06,060 - DEBUG - [MainThread] CuraEngineBackend.CuraEngineBackend._onSlicingFinishedMessage [664]: Number of models per buildplate: {0: 6}
2020-03-02 21:16:06,061 - DEBUG - [MainThread] CuraEngineBackend.CuraEngineBackend._onSlicingFinishedMessage [678]: See if there is more to slice...
2020-03-02 21:16:06,064 - DEBUG - [Thread-3] CuraEngineBackend.ProcessSlicedLayersJob.run [70]: Processing new layer for build plate 0...
2020-03-02 21:16:06,389 - DEBUG - [MainThread] UM.Backend.Backend._logSocketState [181]: Socket state changed to Closing
2020-03-02 21:16:06,392 - DEBUG - [MainThread] UM.Backend.Backend._onSocketError [203]: Socket debug: Arcus Error (13): Closing socket because other side requested close.
2020-03-02 21:16:06,395 - DEBUG - [MainThread] UM.Backend.Backend._logSocketState [183]: Socket state changed to Closed
2020-03-02 21:16:06,415 - DEBUG - [MainThread] CuraEngineBackend.CuraEngineBackend._onBackendQuit [829]: Backend quit with return code 0. Resetting process and socket.
2020-03-02 21:16:06,548 - DEBUG - [Thread-3] CuraEngineBackend.ProcessSlicedLayersJob.run [250]: Processing layers took 0.48334598541259766 seconds
2020-03-02 21:16:06,559 - DEBUG - [MainThread] CuraEngineBackend.CuraEngineBackend._onProcessLayersFinished [859]: See if there is more to slice(2)...
2020-03-02 21:16:56,159 - DEBUG - [MainThread] OctoPrintPlugin.OctoPrintOutputDevice.requestWrite [374]: Tried starting a print, but current state is printing
2020-03-02 21:16:56,180 - INFO - [MainThread] UM.TaskManagement.HttpRequestManager._processRequest [308]: Request [b08b3d23e6124a039df13c740d272f74] started
2020-03-02 21:16:56,256 - DEBUG - [MainThread] UM.TaskManagement.HttpRequestManager._processNextRequestsInQueue [279]: No more requests to process, stop
2020-03-02 21:16:56,830 - INFO - [MainThread] UM.TaskManagement.HttpRequestManager._onRequestFinished [369]: Request [b08b3d23e6124a039df13c740d272f74] finished.
2020-03-02 21:16:56,834 - DEBUG - [MainThread] UM.TaskManagement.HttpRequestManager._processNextRequestsInQueue [279]: No more requests to process, stop
2020-03-02 21:16:56,834 - INFO - [MainThread] SliceInfoPlugin.SliceInfo._onRequestFinished [275]: SliceInfo sent successfully
2020-03-02 21:16:58,243 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [398]: file:///Applications/Ultimaker Cura.app/Contents/MacOS/resources/qml/RoundedRectangle.qml:68: TypeError: Cannot read property of null
2020-03-02 21:17:01,707 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [398]: file:///Applications/Ultimaker Cura.app/Contents/Resources/qml/UM/Dialog.qml:86:13: QML Loader: Binding loop detected for property "active"
2020-03-02 21:17:02,320 - DEBUG - [MainThread] OctoPrintPlugin.DiscoverOctoPrintAction.testApiKey [215]: Trying to access OctoPrint instance at http://192.168.1.100:80/ with the provided API key.
2020-03-02 21:17:02,654 - DEBUG - [MainThread] OctoPrintPlugin.DiscoverOctoPrintAction._onRequestFinished [418]: API key accepted by OctoPrint.
2020-03-02 21:17:04,330 - DEBUG - [MainThread] cura.PrinterOutput.NetworkedPrinterOutputDevice._createNetworkManager [305]: Creating network manager
2020-03-02 21:17:04,346 - INFO - [MainThread] UM.OutputDevice.OutputDeviceManager.addOutputDevice [156]: Output Device Ender3 already added
2020-03-02 21:17:04,347 - DEBUG - [MainThread] OctoPrintPlugin.OctoPrintOutputDevice.connect [303]: Connection with instance Ender3 with url http://192.168.1.100:80/ started
2020-03-02 21:17:04,352 - DEBUG - [MainThread] cura.PrinterOutput.NetworkedPrinterOutputDevice._createNetworkManager [305]: Creating network manager
2020-03-02 21:17:04,354 - DEBUG - [MainThread] OctoPrintPlugin.OctoPrintOutputDevice.connect [303]: Connection with instance Ender3 with url http://192.168.1.100:80/ started
2020-03-02 21:17:04,414 - INFO - [MainThread] UM.OutputDevice.OutputDeviceManager.addOutputDevice [156]: Output Device Ender3 already added
2020-03-02 21:17:04,417 - INFO - [MainThread] UM.OutputDevice.OutputDeviceManager.addOutputDevice [156]: Output Device Ender3 already added
2020-03-02 21:17:04,421 - INFO - [MainThread] UM.OutputDevice.OutputDeviceManager.addOutputDevice [156]: Output Device Ender3 already added
2020-03-02 21:17:04,879 - DEBUG - [MainThread] OctoPrintPlugin.OctoPrintOutputDevice._onRequestFinished [741]: Set OctoPrint camera url to http://192.168.1.100:80/webcam/?action=stream
2020-03-02 21:17:06,597 - DEBUG - [MainThread] UM.Controller.setActiveStage [149]: Setting active stage to MonitorStage
2020-03-02 21:17:06,600 - DEBUG - [MainThread] UM.Controller.setActiveView [91]: Setting active view to SolidView
2020-03-02 21:17:06,651 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [398]: file:///Applications/Ultimaker Cura.app/Contents/MacOS/resources/qml/PrinterOutput/HeatedBedBox.qml:211: Error: Cannot assign [undefined] to QString
2020-03-02 21:17:06,707 - INFO - [MainThread] UM.TaskManagement.HttpRequestManager._processRequest [308]: Request [9e6a317d97d34404a2b0f955af9f555a] started
2020-03-02 21:17:06,712 - DEBUG - [MainThread] UM.TaskManagement.HttpRequestManager._processNextRequestsInQueue [279]: No more requests to process, stop
2020-03-02 21:17:07,207 - INFO - [MainThread] UM.TaskManagement.HttpRequestManager._onRequestFinished [369]: Request [9e6a317d97d34404a2b0f955af9f555a] finished.
2020-03-02 21:17:07,211 - DEBUG - [MainThread] UM.TaskManagement.HttpRequestManager._processNextRequestsInQueue [279]: No more requests to process, stop
2020-03-02 21:17:07,212 - INFO - [MainThread] SliceInfoPlugin.SliceInfo._onRequestFinished [275]: SliceInfo sent successfully
2020-03-02 21:17:08,706 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [398]: file:///Applications/Ultimaker Cura.app/Contents/MacOS/resources/qml/RoundedRectangle.qml:68: TypeError: Cannot read property of null
2020-03-02 21:17:09,531 - DEBUG - [MainThread] OctoPrintPlugin.OctoPrintOutputDevice._onRequestFinished [772]: Resource created on OctoPrint instance: http://192.168.1.100/api/files/local/CE3_6677a13f-2efa-4d92-88b5-be24003c29e2.gcode

Full log: https://drive.google.com/open?id=1DcNmdTyLtWEIG5g01o2pdphRPICKNrjv

crysxd commented 4 years ago

Ok, just happend again. Here is the output of /api/printer. I also spotted that the "Monitor" tab is stuck. The printer is done but there it shows the print progress 33%. I'm pretty sure that's when my MacBook went to standby as I didn't use it anymore. Could the connection crash in that case and not be resumed?

{
  "sd": {
    "ready": false
  }, 
  "state": {
    "flags": {
      "cancelling": false, 
      "closedOrError": false, 
      "error": false, 
      "finishing": false, 
      "operational": true, 
      "paused": false, 
      "pausing": false, 
      "printing": false, 
      "ready": true, 
      "resuming": false, 
      "sdReady": false
    }, 
    "text": "Operational"
  }, 
  "temperature": {
    "bed": {
      "actual": 33.75, 
      "offset": 0, 
      "target": 0.0
    }, 
    "tool0": {
      "actual": 25.45, 
      "offset": 0, 
      "target": 0.0
    }
  }
}
fieldOfView commented 4 years ago

The issue seems to be that the plugin stops receiving updates from OctoPrint, or that those updates have stale information. Since OctoPrint is showing correct data in your browser, and since your logs don't show anything that would suggest the plugin is no longer receiving any updates, I'm going to have to make a version that does more logging to know what is going on.

crysxd commented 4 years ago

Feel free to send me stuff to test, the issue seems very common on my machine although I'm still not 100% sure what's the teigger

tablatronix commented 4 years ago

I thought I had a way to reproduce the other day but it started working.. lol I did notice I have more issues when I restart octoprint for plugin updates etc, if that helps. Of course cura stays open during etc..

crysxd commented 4 years ago

@fieldOfView I added logs to _update(self) and _onRequestFinished(self, reply: QNetworkReply). When the UI is stuck _update(self) is still called every 2s and the requests to /job and /printer are still executed with a 200 response.

This means there must be some issue when handling the response and updating the UI.

I'm pretty sure by now that this issue is caused by the laptop going into standby for some time (maybe more than 10 minutes?).

fieldOfView commented 4 years ago

I am still none the wiser how this can happen (especially after your helpful debugging, @crysxd), but I do have a hunch. When it happens again, could you try disconnecting the printer via the OctoPrint web interface, waiting 15 seconds, and connecting again? Does that restore a sane status in Cura?

crysxd commented 4 years ago

I will try! Thanks for your support and engagement 👍

fieldOfView commented 4 years ago

It seems more and more issues prop up that may have the same underlying mechanism, so your feedback and debugging is much appreciated.

crysxd commented 4 years ago

Believe it or not, this issue does not occur any longer for me (or at least it seems like). The only thing I can imagine causing this is that I migrated my Octoprint server from a native installation on a Raspberry to Docker running on the same Raspberry.

I'll keep my eyes open and will try your fix if it occurs again. Let me know if I can do something else (let me check the logs actually, maybe I see something).

fieldOfView commented 4 years ago

Interesting... That could still also point to network stability as a cause. ~Or is the docker instance running on the same hardware?~ Edit: Reading is hard.

crysxd commented 4 years ago

I doubt that it's a network issue as the logs sho that the requests are still performed with valid HTTP responses

WhiskeyTang0F0xtr0t commented 4 years ago

I know this is an older thread, but this has been happening to me for a while and wanted to drop a note here. On a whim I unchecked "Automatically discover local Octoprint instances" and it hasn't happened since.

fieldOfView commented 4 years ago

@WhiskeyTang0F0xtr0t thanks for reporting that, because I still have no way to reproduce this issue.

I take it you manually added your OctoPrint instance?

WhiskeyTang0F0xtr0t commented 4 years ago

Yessir.

fieldOfView commented 4 years ago

Is that because automatic discovery just never seemed to work for you, or do you have a configuration where bonjour cannot work, eg due to needing https or basic authentication?

WhiskeyTang0F0xtr0t commented 4 years ago

Bonjour works fine and I'm using a .local hostname in the plugin config. I was troubleshooting and noticed the list kept flickering, so I figured I would disable it since it wasn't needed and don't want unnecessary polling.

SteveDC2 commented 4 years ago

Old thread but still happening on 4.5.0 for me

I am getting this issue too. I tried disconnecting and re-connecting with Octoprint within Cura... no dice. I have 2 printers though and I had just switched from slicing for one printer, then set it printing and switched to the second printer and sliced then tried to "print with Octoprint" and now keep getting the error.

So, ensuring I had printer 2 selected I sliced then added to the que, then selected "open octoprint" and it opened my FIRST printer preview!!!

Before this I went to check the API key for printer 2 and it didn't match what the web view of printer 2 Octoprint displayed. I copied the key from printer 2 octoprint instance to the printer 2 Cura octoprint setup page and it STILL would not print (i.e. still gave printer busy).

Then I deleted the model, re-loaded, re-sliced and BAM... I could then print to octoprint on printer 2. Before this I had not changed the model. I only switched between printers to print the same model on both printers.

This feels like bad caching to me. For me something is not correctly switching between printers correctly. I will try to keep an eye on this and see if I can be more scientific with how I get it into the messed up state.

Side note.... my PC HAD been sleeping after a print I set going last night so could still be linked to sleep somehow.

BR, Steve

Eibwen commented 3 years ago

This occurred for me in the following manor:

Printer: Ender 3

  1. Have octoprint and cura all in a ready state
  2. Forgot to turn the primary power supply On on the printer (so it was being powered via the USB connection only)
  3. Hit "Print with Octoprint" in Cura
  4. The printer tries to start heating up, but that pulls the voltage down from the USB so it soft-crashes the USB connection at very least
  5. Turn on the power supply, and via the printer's interface Abort Job
  6. Via the OctoPrint web interface, it shows "Disconnected" and the print job aborted
  7. Via OctoPrint web interface, re-establish the connection
  8. Go back to Cura, it seems in a good state
  9. Press "Print with Octoprint" and get this error

(I have not specifically tried to reproduce that, but it happened to me at least twice with that same pattern. But I can attempt to verify those reproduction steps and/or share logs if that would be helpful)

From that state:

So from that behavior, it seems like the Cura Plugin is anticipating OctoPrint is in a bad state, but not automatically trying to call the API calls to get it back into sync. So my suggestion would be whenever that error shows up, your application could try to automatically disconnect and reconnect? Or some other way to basically reset to make sure all the data is consistent?

I'm assuming your plugin is keeping some state which doesn't seem to get updated, even though OctoPrint itself had it's state corrected