search

fieldOfView / Cura-OctoPrintPlugin

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

Print not always starting after upload #233

Closed tablatronix closed 2 years ago

tablatronix commented 3 years ago

I have been having this happen maybe 20% of the time all of a sudden.

I upload walk away come back and its not even heating.

OctoPrint 1.6.0 Python 2.7.16 OctoPi 0.15.1 Latest cura and plugin

128

195

tablatronix commented 3 years ago

Could this be a conflict with the auto select plugin ? Although I have always had it enabled

tablatronix commented 3 years ago

Ah I may have found the issue, I had recently turned on 'turn on with tasmota', and that might have been causing an issue as tasmota has also been failing on my device.

Gonna test now and see if its gone

fieldOfView commented 3 years ago

I'm going to assume this was a third party issue. If not, I'll reopen this.

tablatronix commented 3 years ago

It still does it now and then, have not found any obvious reason yet. Maybe it happens more after a cancelled print, not sire though

fieldOfView commented 3 years ago

tasmota has also been failing on my device.

Is that also still an issue?

tablatronix commented 3 years ago

I turned that off and stopped using tasmota, so I have no more info if that was working or not. Sorry

tablatronix commented 3 years ago

I am getting back into this, I am still having this issue, print job never actually starts. Going to be looking into this again to figure it out.

I have started turning plugins off, but its still present, so going to delete and readd my printer to cura with a fresh octoprint connection and test some more.

fieldOfView commented 3 years ago

Do you have Print Time Genius installed on the Pi?

To diagnose this, I need a Cura.log and the OctoPrint logs, both including the same time of an upload that did not autostart.

tablatronix commented 3 years ago

Crap I meant to grab them and forgot and they rolled over, I will get them this weekend!

I do not have print time genius but I DO have printjobhistory... hmm

fieldOfView commented 3 years ago

I can't do much without logs. I'm closing this for now, feel free to ask me to reopen the issue if you have logs for me.

tablatronix commented 3 years ago

I collected logs all weekend didn't see anything useful ill pack em up in a bit

tablatronix commented 3 years ago

I will run these again with the autoselect plugin disabled, I had it off for a while and it made no difference, But it could be a race condition between the 2 "selects" api:none? not sure.

I will just post this one for now and keep looking ,

cura doesn't seem to log anything but the upload.. I do not see any logging for the api calls to print etc ?

cura.log

2021-10-02 17:22:05,286 - WARNING - [MainThread] UM.Qt.QtApplication.__onQmlWarning [421]: file:///Applications/Ultimaker Cura.app/Contents/MacOS/resources/qml/PrintSetupSelector/Custom/QualitiesWithIntentMenu.qml:168:25: QML Binding: Not restoring previous value because restoreMode has not been set.
This behavior is deprecated.
You have to import QtQml 2.15 after any QtQuick imports and set
the restoreMode of the binding to fix this warning.
In Qt < 6.0 the default is Binding.RestoreBinding.
In Qt >= 6.0 the default is Binding.RestoreBindingOrValue.

2021-10-02 17:22:05,848 - INFO - [MainThread] SliceInfoPlugin.SliceInfo._onRequestFinished [293]: SliceInfo sent successfully
2021-10-02 17:22:15,048 - DEBUG - [MainThread] cura.AutoSave._onTimeout [64]: Autosaving preferences, instances and profiles took 0.027232885360717773 seconds
2021-10-02 17:22:17,896 - DEBUG - [MainThread] OctoPrintPlugin.OctoPrintOutputDevice._onUploadFinished [1127]: Resource created on OctoPrint instance: http://octopi.local/api/files/local/CE3_Body1.gcode
2021-10-02 17:29:20,502 - DEBUG - [MainThread] UM.Controller.setActiveStage [180]: Setting active stage to PrepareStage
2021-10-02 17:29:20,525 - DEBUG - [MainThread] cura.Machines.Models.NozzleModel._update [28]: Updating NozzleModel.
2021-10-02 17:29:31,051 - DEBUG - [MainThread] cura.AutoSave._onTimeout [64]: Autosaving preferences, instances and profiles took 0.02830791473388672 seconds
2021-10-02 18:41:32,035 - DEBUG - [MainThread] cura.TaskManagement.OnExitCallbackManager.triggerNextCallback [51]: No more on-app-exit callbacks to process. Tell the app to exit.
2021-10-02 18:41:32,037 - INFO - [MainThread] cura.CuraApplication.closeApplication [609]: Close application
2021-10-02 18:41:32,039 - INFO - [MainThread] UM.Logger.info [128]: Initializing Active Machine...
2021-10-02 18:41:32,116 - DEBUG - [MainThread] cura.Machines.Models.NozzleModel._update [28]: Updating NozzleModel.
2021-10-02 18:41:32,118 - DEBUG - [MainThread] cura.Machines.Models.NozzleModel._update [28]: Updating NozzleModel.
2021-10-02 18:41:32,133 - DEBUG - [MainThread] cura.Machines.Models.NozzleModel._update [28]: Updating NozzleModel.
2021-10-02 18:41:32,135 - DEBUG - [MainThread] cura.Machines.Models.NozzleModel._update [28]: Updating NozzleModel.
2021-10-02 18:41:32,217 - DEBUG - [MainThread] UM.Qt.QtApplication.windowClosed [485]: Shutting down cura
2021-10-02 18:41:32,266 - DEBUG - [MainThread] CuraEngineBackend.CuraEngineBackend._terminate [354]: Attempting to kill the engine process

octoprint.log

(Upload and nothing happens)

2021-10-02 22:20:26,915 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2021-10-02 22:20:44,687 - octoprint.plugins.discovery - DEBUG - Sending NOTIFY alive via 192.168.100.53
2021-10-02 22:21:44,345 - octoprint.plugins.discovery - DEBUG - Sending NOTIFY alive via 192.168.100.53
2021-10-02 22:22:13,198 - octoprint.plugins.pi_support - DEBUG - Retrieving throttle state via "/usr/bin/vcgencmd get_throttled"
2021-10-02 22:22:14,451 - octoprint.plugins.discovery - DEBUG - Sending NOTIFY alive via 192.168.100.53
2021-10-02 22:22:17,717 - octoprint.filemanager.analysis - INFO - Starting analysis of local:CE3_Body1.gcode
2021-10-02 22:22:17,724 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python2 -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 --bed-z=0.0 /home/pi/.octoprint/uploads/CE3_Body1.gcode
2021-10-02 22:22:17,747 - octoprint.plugins.autoselect - INFO - Selecting CE3_Body1.gcode on local that was just uploaded
2021-10-02 22:22:17,813 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: CE3_Body1.gcode, owner: _api, user: _api
2021-10-02 22:22:17,846 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: CE3_Body1.gcode, owner: None, user: None
2021-10-02 22:22:17,948 - octoprint.plugins.preheat - DEBUG - Event received: FileAdded
2021-10-02 22:22:18,015 - octoprint.plugins.preheat - DEBUG - Event received: UpdatedFiles
2021-10-02 22:22:18,059 - octoprint.plugins.preheat - DEBUG - Event received: MetadataAnalysisStarted
2021-10-02 22:22:21,484 - octoprint.plugins.preheat - DEBUG - Event received: FileSelected
2021-10-02 22:22:24,337 - octoprint.plugins.preheat - DEBUG - Event received: FileSelected
2021-10-02 22:22:24,364 - octoprint.plugins.preheat - DEBUG - Event received: Upload
2021-10-02 22:22:34,483 - octoprint.plugins.shutdownprinter - INFO - eventView
2021-10-02 22:22:34,651 - octoprint.plugins.preheat - DEBUG - Event received: SettingsUpdated
2021-10-02 22:22:39,064 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from https://plugins.octoprint.org/plugins.json
2021-10-02 22:22:44,659 - octoprint.plugins.discovery - DEBUG - Sending NOTIFY alive via 192.168.100.53
---> I CLICK START HERE
2021-10-02 22:23:05,421 - octoprint.util.comm - INFO - Starting job on behalf of user shawn
2021-10-02 22:23:05,431 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting"
2021-10-02 22:23:05,455 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: CE3_Body1.gcode, owner: shawn, user: shawn
2021-10-02 22:23:05,501 - octoprint.plugins.preheat - DEBUG - Event received: PrinterStateChanged
2021-10-02 22:23:05,508 - octoprint.plugins.PrintJobHistory - INFO - Try reading Temperature from PreHeat-Plugin...
2021-10-02 22:23:05,550 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0

and.. octoprint log for one that starts!

Upload and Auto Starting
2021-10-03 04:40:15,929 - octoprint.plugins.discovery - DEBUG - Sending NOTIFY alive via 192.168.100.53
2021-10-03 04:40:34,128 - octoprint.filemanager.analysis - INFO - Starting analysis of local:CE3_Body2.gcode
2021-10-03 04:40:34,135 - octoprint.filemanager.analysis - INFO - Invoking analysis command: /home/pi/oprint/bin/python2 -m octoprint analysis gcode --speed-x=6000 --speed-y=6000 --max-t=10 --throttle=0.0 --throttle-lines=100 --bed-z=0.0 /home/pi/.octoprint/uploads/CE3_Body2.gcode
2021-10-03 04:40:34,156 - octoprint.plugins.autoselect - INFO - Selecting CE3_Body2.gcode on local that was just uploaded
2021-10-03 04:40:34,226 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: CE3_Body2.gcode, owner: None, user: None
2021-10-03 04:40:34,236 - octoprint.printer.standard.job - INFO - Print job selected - origin: local, path: CE3_Body2.gcode, owner: _api, user: _api
2021-10-03 04:40:34,289 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting"
2021-10-03 04:40:34,304 - octoprint.printer.standard.job - INFO - Print job started - origin: local, path: CE3_Body2.gcode, owner: None, user: None
2021-10-03 04:40:34,344 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2021-10-03 04:40:34,375 - octoprint.plugins.preheat - DEBUG - Event received: FileAdded
2021-10-03 04:40:34,414 - octoprint.plugins.preheat - DEBUG - Event received: UpdatedFiles
2021-10-03 04:40:34,453 - octoprint.plugins.preheat - DEBUG - Event received: MetadataAnalysisStarted
2021-10-03 04:40:34,584 - octoprint.util.comm - INFO - Changing monitoring state from "Starting" to "Printing"
2021-10-03 04:40:34,623 - octoprint.plugins.preheat - DEBUG - Event received: FileSelected
2021-10-03 04:40:34,839 - octoprint.plugins.preheat - DEBUG - Event received: FileSelected
2021-10-03 04:40:34,882 - octoprint.plugins.preheat - DEBUG - Event received: Upload
fieldOfView commented 3 years ago

Thanks for the excerpts, but I would really rather have full files. Then I can also see eg what plugins you have (on both ends).

tablatronix commented 3 years ago

I didn't see anything sensitive in there, had to make sure.

Archive.zip

I am about to reimage my octopi So I will try to test with a new stock install

tablatronix commented 3 years ago

Ok I disabled the 3 suspect plugins, and its working good today so far, printing serially all day, I am on 4th and its working 100% I will narrow them down later.

I suspect printhistory plugin