Octoprint: [1.3.11rc3] Server freezes when cancelling a print from SD

Created on 16 Apr 2019  ·  59Comments  ·  Source: OctoPrint/OctoPrint

Hello,

I create this problem because it is 2 times that I encounter the problem with the RC2 and RC3
I can not produce it easily, it's pretty random :(

here is the problem :
when I cancel the impression from the interface, it happens that the print continues, at this time the octoprint does not answer anymore, I am forced to restart from the command line because it becomes unreachable.

in the logs I see this:

2019-04-16 16:51:32,796 - octoprint.util.comm - INFO - Changing monitoring state from "Printing from SD" to "Cancelling"
2019-04-16 16:51:32,802 - octoprint.plugins.XXX- INFO - Print cancelling because : nothing
2019-04-16 16:51:32,804 - octoprint.printer.standard.job - INFO - Print job cancelled - origin: sdcard, path: xyzcal~1.gco, owner: _api, user: devildant
2019-04-16 16:51:32,819 - octoprint.plugins.shutdownprinter - INFO - Print cancelled
2019-04-16 16:51:32,905 - octoprint.util.comm - INFO - Pausing print job due to command M25

after this log nothing is logged, and octoprint does not work anymore

(i use SD printing)

bug done needs testing unreproduced
Source
picture devildant

All 59 comments

Sorry @foosel , i'm a magnet for randomly bug :(

devildant picture devildant on 16 Apr 2019

canceled like 30 test prints today, no problems.

its normal that the print continues till the buffer is cleaned. after that the printer and octoprint works fine again.

check ur cancel gcode.

reloxx13 picture reloxx13 on 23 Apr 2019

hello, it's very very random, this is produced 3 times for me since the release of the RC2, it had never happened before the RC2.
I did not test the RC1.
I will continue my test, if I have more information, in the log / usage CPU, I will update this issue.

for the cancel gcode (octoprint settings) :

; disable motors
M84

;disable all heaters
{% snippet 'disable_hotends' %}
{% snippet 'disable_bed' %}
;disable fan
M106 S0

however, when I encounter the problem, it does not go so far.
it's just a complete freeze of octoprint and the printer is not notified for stopping printing

devildant picture devildant on 23 Apr 2019

Can you please provide more details and full logs?

I'd need a full octoprint.log and a serial.log, and I'll also need more information on what specifically you are doing - from your few lines of log up there it sounds like you are cancelling via the printer's controller, not from OctoPrint? I'm completely unclear on the exact steps involved...

Also please make sure it isn't caused by some third party plugin you have installed - judging by those few log lines you have quite some that get activated on a print cancel.

foosel picture foosel on 23 Apr 2019

Hello @foosel,
the cancel has been done octoprint side and not printer side directly.
(even if sometimes it happens to me to do printer side, but I avoid, because sometimes there are failures, and the status is not transmitted correctly to octoprint.)

the octoprint.log : 

2019-04-15 18:50:50,152 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 18:50:50,157 - octoprint.server - INFO - --- Log roll over detected ---------------------------------------------------
2019-04-15 18:50:50,158 - octoprint.server - INFO - OctoPrint 1.3.11rc3
2019-04-15 18:50:50,168 - octoprint.plugin.core - INFO - 25 plugin(s) registered with the system:
|  Action Command Prompt Support (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/action_command_prompt
|  Announcement Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/announcements
|  Anonymous Usage Tracking (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/tracking
|  Application Keys Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/appkeys
|  Auth Docker (1.0.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_authdocker
|  Backup & Restore (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/backup
|  Core Wizard (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/corewizard
|  Custom Control Editor (0.2.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_customControl
|  DeleteAfterPrint Plugin (1.3.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_DeleteAfterPrint
|  Discovery (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/discovery
|  Dragon Order (0.1.3) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_dragon_order
|  EEPROM Marlin Editor Plugin (1.2.1) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_eeprom_marlin
|  Enclosure Plugin (4.12) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_enclosure
|  Error Tracking (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/errortracking
|  Firmware Updater (1.2.0) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_firmwareupdater
| !Force Login (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/forcelogin
|  Logging (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/logging
|  Pi Support Plugin (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pi_support
|  Plugin Manager (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/pluginmanager
|  Printer Safety Check (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/printer_safety_check
|  sd Switch Fast Copy (1.0.2) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_sdswitchfastcopy
|  Shutdown Printer (1.0.2) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_shutdownprinter
|  Software Update (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/softwareupdate
|  TP-Link Smartplug (0.9.13) = /home/pi/oprint/local/lib/python2.7/site-packages/octoprint_tplinksmartplug
|  Virtual Printer (bundled) = /home/pi/oprint/lib/python2.7/site-packages/octoprint/plugins/virtual_printer
2019-04-15 18:50:50,195 - octoprint.environment - INFO - Detected environment is Python 2.7.13 under Linux (linux2). Details:
|  hardware:
|    cores: 4
|    freq: 1200.0
|    ram: 918192128
|  os:
|    id: linux
|    platform: linux2
|  plugins:
|    pi_support:
|      model: Raspberry Pi 3 Model B Rev 1.2
|      octopi_version: 0.15.1
|  python:
|    pip: 9.0.3
|    version: 2.7.13
|    virtualenv: /home/pi/oprint
2019-04-15 18:50:50,196 - octoprint.server - INFO - ------------------------------------------------------------------------------
2019-04-15 19:05:50,154 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 19:20:50,158 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 19:35:50,162 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 19:50:50,166 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 20:05:50,169 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 20:20:50,173 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 20:35:50,176 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 20:50:50,181 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 21:05:50,183 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 21:20:50,188 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 21:35:50,191 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 21:50:50,196 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 22:05:50,199 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 22:20:50,203 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 22:35:50,206 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 22:50:50,210 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 23:05:50,213 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 23:20:50,216 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 23:35:50,220 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-15 23:50:50,224 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 00:05:50,228 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 00:20:50,232 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 00:35:50,235 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 00:50:50,239 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 01:05:50,243 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 01:20:50,247 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 01:35:50,251 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 01:50:50,254 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 02:05:50,258 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 02:20:50,262 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 02:35:50,266 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 02:50:50,270 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 03:05:50,273 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 03:20:50,277 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 03:35:50,281 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 03:50:50,284 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 04:05:50,288 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 04:20:50,291 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 04:35:50,293 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 04:50:50,296 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 05:05:50,299 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 05:20:50,303 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 05:35:50,308 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 05:50:50,312 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 06:05:50,315 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 06:20:50,319 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 06:35:50,322 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 06:50:50,326 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 07:05:50,330 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 07:20:50,335 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 07:35:50,339 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 07:50:50,343 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 08:05:50,347 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 08:20:50,350 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 08:35:50,352 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 08:50:50,355 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 09:05:50,358 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 09:20:50,362 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 09:35:50,366 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 09:50:50,370 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 10:05:50,374 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 10:20:50,378 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 10:35:50,380 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 10:50:50,383 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 11:05:50,388 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 11:20:50,391 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 11:35:50,394 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 11:50:50,397 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 12:05:50,401 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 12:20:50,405 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 12:35:50,409 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 12:50:50,412 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 13:05:50,415 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 13:20:50,419 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 13:35:50,422 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 13:50:50,425 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 14:05:50,429 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 14:20:50,434 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 14:35:50,436 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 14:50:50,440 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 15:05:50,443 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 15:20:50,448 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 15:35:50,451 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 15:50:50,456 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 16:05:50,460 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 16:08:40,512 - octoprint.server.api - INFO - Actively logging in user devildant from 192.168.1.10
2019-04-16 16:08:43,877 - octoprint.server.util.sockjs - INFO - New connection from client: 192.168.1.10
2019-04-16 16:08:44,253 - octoprint.server.util.flask - INFO - Passively logging in user devildant from 192.168.1.10
2019-04-16 16:08:45,647 - octoprint.plugins.tplinksmartplug - INFO - ImmutableMultiDict([('checkStatus', u'192.168.1.43')])
2019-04-16 16:08:46,061 - octoprint.plugins.sdswitchfastcopy - INFO - test mount OK
2019-04-16 16:08:46,421 - octoprint.plugins.announcements - INFO - Loaded channel _important from https://octoprint.org/feeds/important.xml in 0.24s
2019-04-16 16:08:46,989 - octoprint.plugins.announcements - INFO - Loaded channel _releases from https://octoprint.org/feeds/releases.xml in 0.27s
2019-04-16 16:08:47,276 - octoprint.plugins.announcements - INFO - Loaded channel _blog from https://octoprint.org/feeds/octoblog.xml in 0.2s
2019-04-16 16:08:47,655 - octoprint.plugins.announcements - INFO - Loaded channel _plugins from https://plugins.octoprint.org/feed.xml in 0.3s
2019-04-16 16:08:47,958 - octoprint.plugins.announcements - INFO - Loaded channel _octopi from https://octoprint.org/feeds/octopi.xml in 0.18s
2019-04-16 16:08:49,970 - octoprint.plugins.softwareupdate - INFO - Saved version cache to disk
2019-04-16 16:08:51,342 - octoprint.plugins.sdswitchfastcopy - INFO - test mount OK
2019-04-16 16:08:53,339 - octoprint.server.util.sockjs - INFO - User devildant logged in on the socket from client 192.168.1.10
2019-04-16 16:08:53,432 - octoprint.plugins.tplinksmartplug - INFO - ImmutableMultiDict([('checkStatus', u'192.168.1.43')])
2019-04-16 16:09:03,326 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Detecting serial port"
2019-04-16 16:09:03,336 - octoprint.plugins.sdswitchfastcopy - INFO - Print stat change : DETECT_SERIAL
2019-04-16 16:09:03,357 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial port" to "Opening serial port"
2019-04-16 16:09:03,364 - octoprint.plugins.sdswitchfastcopy - INFO - Print stat change : OPEN_SERIAL
2019-04-16 16:09:03,369 - octoprint.util.comm - INFO - Changing monitoring state from "Opening serial port" to "Detecting baudrate"
2019-04-16 16:09:03,374 - octoprint.plugins.sdswitchfastcopy - INFO - Print stat change : DETECT_BAUDRATE
2019-04-16 16:09:04,390 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-04-16 16:09:04,458 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting baudrate" to "Operational"
2019-04-16 16:09:04,475 - octoprint.plugins.sdswitchfastcopy - INFO - Print stat change : OPERATIONAL
2019-04-16 16:09:04,490 - octoprint.util.comm - INFO - M110 detected, setting current line number to 0
2019-04-16 16:09:04,516 - octoprint.plugins.firmwareupdater - INFO - Got CONNECTED event
2019-04-16 16:09:04,521 - octoprint.plugins.firmwareupdater - INFO - Run postflash flag is not set
2019-04-16 16:09:09,256 - octoprint.util.comm - INFO - Printer reports firmware name "Marlin TH3D U1.R2.7"
2019-04-16 16:09:09,280 - octoprint.util.comm - INFO - Firmware states that it supports temperature autoreporting
2019-04-16 16:09:09,437 - octoprint.util.comm - INFO - Firmware states that it supports temperature autoreporting
2019-04-16 16:13:14,351 - octoprint.util.comm - INFO - Printer seems to support the busy protocol, will adjust timeouts and set busy interval accordingly
2019-04-16 16:13:51,778 - octoprint.util.comm - INFO - Telling the printer to set the busy interval to our "communicationBusy" timeout - 1s = 2s
2019-04-16 16:20:50,463 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 16:23:41,172 - octoprint.filemanager.analysis - INFO - Starting analysis of local:Ultimate_Bed_Level_(2).gcode
2019-04-16 16:23:41,182 - 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 /home/pi/.octoprint/uploads/Ultimate_Bed_Level_(2).gcode
2019-04-16 16:23:43,122 - octoprint.filemanager.analysis - INFO - Analysis of entry local:Ultimate_Bed_Level_(2).gcode finished, needed 1.95s
2019-04-16 16:23:45,316 - octoprint.plugins.sdswitchfastcopy - INFO - sd card module start
2019-04-16 16:23:56,728 - octoprint.printer.standard.job - INFO - Print job selected - origin: sdcard, path: ultima~1.gco, owner: _api, user: _api
2019-04-16 16:23:56,738 - octoprint.plugins.DeleteAfterPrint - INFO - File selected
2019-04-16 16:23:56,736 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting print from SD"
2019-04-16 16:23:56,744 - octoprint.printer.standard.job - INFO - Print job started - origin: sdcard, path: ultima~1.gco, owner: _api, user: _api
2019-04-16 16:23:56,747 - octoprint.plugins.sdswitchfastcopy - INFO - Print stat change : STARTING
2019-04-16 16:23:56,757 - octoprint.plugins.DeleteAfterPrint - INFO - Printing started. Detailed progress started.{'origin': 'sdcard', 'name': u'ultima~1.gco', 'file': u'ultima~1.gco', 'owner': '_api', 'path': u'ultima~1.gco', 'user': '_api', 'size': 76218, 'filename': u'ultima~1.gco'}
2019-04-16 16:23:56,775 - octoprint.plugins.shutdownprinter - INFO - Print started
2019-04-16 16:23:56,829 - octoprint.util.comm - INFO - Changing monitoring state from "Starting print from SD" to "Printing from SD"
2019-04-16 16:35:50,465 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 16:38:17,746 - octoprint.util.comm - INFO - Changing monitoring state from "Printing from SD" to "Finishing"
2019-04-16 16:38:17,757 - octoprint.plugins.sdswitchfastcopy - INFO - Print stat change : FINISHING
2019-04-16 16:38:17,758 - octoprint.printer.standard.job - INFO - Print job done - origin: sdcard, path: ultima~1.gco, owner: _api
2019-04-16 16:38:17,764 - octoprint.plugins.DeleteAfterPrint - INFO - Printing succesfull!
2019-04-16 16:38:17,805 - octoprint.plugins.sdswitchfastcopy - INFO - Receive done event
2019-04-16 16:38:17,811 - octoprint.util.comm - INFO - Changing monitoring state from "Finishing" to "Operational"
2019-04-16 16:38:17,823 - octoprint.plugins.sdswitchfastcopy - INFO - Print stat change : OPERATIONAL
2019-04-16 16:38:22,833 - octoprint.plugins.sdswitchfastcopy - INFO - delete file : ultima~1.gco
2019-04-16 16:38:24,847 - octoprint.printer.standard.job - INFO - Print job deselected - user: n/a
2019-04-16 16:40:49,976 - octoprint.plugins.shutdownprinter - INFO - Starting abort shutdown printer timer.
2019-04-16 16:40:55,623 - octoprint.plugins.shutdownprinter - INFO - Shutdown aborted.
2019-04-16 16:43:31,278 - octoprint.filemanager.analysis - INFO - Starting analysis of local:xyzCalibration_cube_(9).gcode
2019-04-16 16:43:31,281 - 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 /home/pi/.octoprint/uploads/xyzCalibration_cube_(9).gcode
2019-04-16 16:43:35,550 - octoprint.plugins.sdswitchfastcopy - INFO - sd card module start
2019-04-16 16:43:35,824 - octoprint.filemanager.analysis - INFO - Analysis of entry local:xyzCalibration_cube_(9).gcode finished, needed 4.55s
2019-04-16 16:43:47,339 - octoprint.printer.standard.job - INFO - Print job selected - origin: sdcard, path: xyzcal~1.gco, owner: _api, user: _api
2019-04-16 16:43:47,347 - octoprint.plugins.DeleteAfterPrint - INFO - File selected
2019-04-16 16:43:47,363 - octoprint.util.comm - INFO - Changing monitoring state from "Operational" to "Starting print from SD"
2019-04-16 16:43:47,386 - octoprint.printer.standard.job - INFO - Print job started - origin: sdcard, path: xyzcal~1.gco, owner: _api, user: _api
2019-04-16 16:43:47,410 - octoprint.plugins.sdswitchfastcopy - INFO - Print stat change : STARTING
2019-04-16 16:43:47,426 - octoprint.plugins.DeleteAfterPrint - INFO - Printing started. Detailed progress started.{'origin': 'sdcard', 'name': u'xyzcal~1.gco', 'file': u'xyzcal~1.gco', 'owner': '_api', 'path': u'xyzcal~1.gco', 'user': '_api', 'size': 462724, 'filename': u'xyzcal~1.gco'}
2019-04-16 16:43:47,437 - octoprint.plugins.shutdownprinter - INFO - Print started
2019-04-16 16:43:47,473 - octoprint.util.comm - INFO - Changing monitoring state from "Starting print from SD" to "Printing from SD"
2019-04-16 16:50:50,468 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-04-16 16:51:32,796 - octoprint.util.comm - INFO - Changing monitoring state from "Printing from SD" to "Cancelling"
2019-04-16 16:51:32,802 - octoprint.plugins.sdswitchfastcopy - INFO - Print cancelling because : nothing
2019-04-16 16:51:32,804 - octoprint.printer.standard.job - INFO - Print job cancelled - origin: sdcard, path: xyzcal~1.gco, owner: _api, user: devildant
2019-04-16 16:51:32,819 - octoprint.plugins.shutdownprinter - INFO - Print cancelled
2019-04-16 16:51:32,905 - octoprint.util.comm - INFO - Pausing print job due to command M25

the plugin octoprint.plugins.sdswitchfastcopy is still in DEV, it is the plugin that I create to replace the system of copy on the sd of the printer :)

on the other hand I do not have a serial log before the 22/04 :( I did not think about the save mb)
as soon as it happens I will save them.
ps all the plugin that log the cancel status are mine, but it's just an event recovery (sdswitchfastcopy and shutdownprinter)

devildant picture devildant on 23 Apr 2019

Have you only have that happen while printing from SD? Or has it also happened when printing via OctoPrint directly?

From the looks of that log it's never reaching Operational state again, probably due to something in the printer communication being wonky. For that I'd need a serial.log to dig deeper.

And is that really all in the log? Nothing that follows after?

foosel picture foosel on 23 Apr 2019

I have not been printing from USB for a long time, I could have tried, I'll do tests.
otherwise for octoprint log, I have nothing else after, as octoprint was completely freeze (web page no response), I restarted the service (i waited 10min before restart).
I'm going to do some cancellation tests to reproduce, but that happens a little when that wants.
this is 3 times in all that I have the problem, but I have a lot of difficulty to reproduce it.
I'm sorry I forgot to save the serial.log file. I hope to reproduce quickly to transmit you the missing log

devildant picture devildant on 23 Apr 2019
👍1

I restarted the service (i waited 10min before restart).

How did you restart it? Could you still SSH into the machine? Was the service still running? Since there are not even heartbeat messages anymore, either it crashed hard, or it ran into some kind of deadlock. In any case, this is very strange.

I hope to reproduce quickly to transmit you the missing log

❤

foosel picture foosel on 24 Apr 2019

yes, I performed a restart service under SSH. on this side pi worked, not slow in SSH.
Hmm, I did not think to check if the service was still launched....
I really have to reproduce, the problem, so I could give you all the missing info.
I will do a maximum of test, I should have more time in the weekend.
hoping that I can quickly reproduce the problem.
I blame myself for not having thought about the serial.log and the status of the service, rrrr.

devildant picture devildant on 24 Apr 2019

I blame myself for not having thought about the serial.log and the status of the service, rrrr.

Don't beat yourself up over that, it happens :) Btw, even the contents of the terminal tab help in such cases, it doesn't always have to be a full blown serial.log. So if you don't have that enabled at the point of encountering an issue, copy the terminal tab contents. Even if you can't reproduce the issue with enabled serial.log there's at least the last 300 lines of printer communication to work with then.

foosel picture foosel on 24 Apr 2019

ok it's noted, I'm going to work hard to reproduce the problem :)

devildant picture devildant on 24 Apr 2019

hello @foosel ,
the problem is reproduced,I am testing the prower loss, and after a recovery the problem is reproduced (the other 3 times it's was with normal use without power loss)
cmd ps -ef : 

pi       14319     1 14 11:51 ?        00:14:23 /home/pi/oprint/bin/python2 /home/pi/oprint/bin/octoprint serve --host=0.0.0.0 --port=5000

it's ok octoprint is run but no response.

log file :
serial (16).log
octoprint.-.2019-04-27T154138.086.log

devildant picture devildant on 27 Apr 2019

ps : for test recovery i turn off printer power (the pi was not affected)

devildant picture devildant on 27 Apr 2019

Thank you for the logs. Could you please clarify what you mean with "testing the power loss" and "after recovery"? Is that a firmware feature here?

Could you also please point out what parts of the serial.log refer to what situation? I'm trying to make sense of it but it's a bit confusing at the moment.

foosel picture foosel on 2 May 2019

Also, just to make sure it isn't caused by one of your plugins, please run in safe mode and make sure the problem persists there. I don't actually think it's a plugin problem, but it would be really bad if I now spent a day or more looking into this and then it turned out to be one after all.

foosel picture foosel on 2 May 2019

Looking at this a bit closer it might be a dead lock issue between sendingLock and jobLock due the M25 now causing a call to setPause even for SD prints (which is a change compared to 1.3.10).

Right now I'm unable to see how there could be a deadlock here though, but that is about the only thing that might cause the described symptoms.

foosel picture foosel on 2 May 2019

Hello @foosel, yes I was testing the power loss recovery of marlin (with manual turnoff /on printer)
for the serial.log file, this is the end of the file in the last lines.
as part of my test I tested different command, to see if I could manage the recovery from octoprint (I plan to create a plugin to manage the recovery of printing after error or loss of power).

I recovered the log just after the server crash, so that is for octoprint.log and serial.log, we must aim for the last lines.

2019-04-27 13:29:06,122 - Connection closed, closing down monitor
2019-04-27 13:29:06,126 - Changing monitoring state from "Printing from SD" to "Offline"
2019-04-27 13:29:23,341 - Changing monitoring state from "Offline" to "Detecting serial port"
2019-04-27 13:29:23,361 - Serial port list: ['/dev/ttyUSB0']
2019-04-27 13:29:23,362 - Connecting to: /dev/ttyUSB0
2019-04-27 13:29:23,371 - Changing monitoring state from "Detecting serial port" to "Opening serial port"
2019-04-27 13:29:23,375 - Connected to: Serial<id=0x6ed007b0, open=True>(port='/dev/ttyUSB0', baudrate=115200, bytesize=8, parity='N', stopbits=1, timeout=10.0, xonxoff=False, rtscts=False, dsrdtr=False), starting monitor
2019-04-27 13:29:23,376 - Starting baud rate detection...
2019-04-27 13:29:23,376 - Changing monitoring state from "Opening serial port" to "Detecting baudrate"
2019-04-27 13:29:24,384 - Trying baudrate: 115200
2019-04-27 13:29:24,398 - Send: N0 M110 N0*125
2019-04-27 13:29:24,466 - Recv: start
2019-04-27 13:29:24,476 - Changing monitoring state from "Detecting baudrate" to "Operational"
2019-04-27 13:29:24,502 - Recv: echo: External Reset
2019-04-27 13:29:24,511 - Send: N0 M110 N0*125
2019-04-27 13:29:24,523 - Recv: Marlin TH3D U1.R2.7
2019-04-27 13:29:24,529 - Recv: 
2019-04-27 13:29:24,536 - Recv: echo: Last Updated:  | Author: (TH3D)
2019-04-27 13:29:24,543 - Recv: echo:Compiled: Apr 27 2019
2019-04-27 13:29:24,552 - Recv: echo: Free Memory: 1289  PlannerBufferBytes: 1232
2019-04-27 13:29:24,569 - Recv: echo:V55 stored settings retrieved (655 bytes; crc 17969)
2019-04-27 13:29:24,580 - Recv: echo:  G21    ; (mm)
2019-04-27 13:29:24,587 - Recv: echo:  M149 C ; Units in Celsius
2019-04-27 13:29:24,595 - Recv: 
2019-04-27 13:29:24,599 - Recv: echo:Steps per unit:
2019-04-27 13:29:24,602 - Recv: echo:  M92 X80.00 Y80.00 Z400.00 E415.00
2019-04-27 13:29:24,605 - Recv: echo:Maximum feedrates (units/s):
2019-04-27 13:29:24,609 - Recv: echo:  M203 X500.00 Y500.00 Z15.00 E50.00
2019-04-27 13:29:24,612 - Recv: echo:Maximum Acceleration (units/s2):
2019-04-27 13:29:24,616 - Recv: echo:  M201 X1000 Y300 Z100 E5000
2019-04-27 13:29:24,619 - Recv: echo:Acceleration (units/s2): P<print_accel> R<retract_accel> T<travel_accel>
2019-04-27 13:29:24,624 - Recv: echo:  M204 P250.00 R1000.00 T250.00
2019-04-27 13:29:24,627 - Recv: echo:Advanced: Q<min_segment_time_us> S<min_feedrate> T<min_travel_feedrate> X<max_x_jerk> Y<max_y_jerk> Z<max_z_jerk> E<max_e_jerk>
2019-04-27 13:29:24,629 - Recv: echo:  M205 Q25000 S0.00 T0.00 X11.00 Y11.00 Z0.40 E5.00
2019-04-27 13:29:24,632 - Recv: echo:Home offset:
2019-04-27 13:29:24,636 - Recv: echo:  M206 X0.00 Y0.00 Z0.00
2019-04-27 13:29:24,640 - Recv: echo:Auto Bed Leveling:
2019-04-27 13:29:24,643 - Recv: echo:  M420 S0 Z0.00
2019-04-27 13:29:24,647 - Recv: echo:  G29 W I0 J0 Z0.20000
2019-04-27 13:29:24,651 - Recv: echo:  G29 W I1 J0 Z0.06400
2019-04-27 13:29:24,654 - Recv: echo:  G29 W I2 J0 Z0.11100
2019-04-27 13:29:24,657 - Recv: echo:  G29 W I0 J1 Z0.19200
2019-04-27 13:29:24,661 - Recv: echo:  G29 W I1 J1 Z0.02800
2019-04-27 13:29:24,663 - Recv: echo:  G29 W I2 J1 Z0.11250
2019-04-27 13:29:24,668 - Recv: echo:  G29 W I0 J2 Z0.27050
2019-04-27 13:29:24,671 - Recv: echo:  G29 W I1 J2 Z0.07050
2019-04-27 13:29:24,675 - Recv: echo:  G29 W I2 J2 Z0.13300
2019-04-27 13:29:24,679 - Recv: echo:Material heatup parameters:
2019-04-27 13:29:24,682 - Recv: echo:  M145 S0 H200 B60 F0
2019-04-27 13:29:24,685 - Recv: echo:  M145 S1 H240 B100 F0
2019-04-27 13:29:24,689 - Recv: echo:PID settings:
2019-04-27 13:29:24,693 - Recv: echo:  M301 P23.87 I4.35 D32.75
2019-04-27 13:29:24,696 - Recv: echo:  M304 P61.56 I3.81 D248.39
2019-04-27 13:29:24,700 - Recv: echo:Z-Probe Offset (mm):
2019-04-27 13:29:24,704 - Recv: echo:  M851 Z-1.27
2019-04-27 13:29:24,707 - Recv: echo:Filament load/unload lengths:
2019-04-27 13:29:24,711 - Recv: echo:  M603 L60.00 U120.00
2019-04-27 13:29:29,195 - Recv: echo:SD card ok
2019-04-27 13:29:29,216 - Recv: ok
2019-04-27 13:29:29,225 - Send: N1 M115*39
2019-04-27 13:29:29,288 - Recv: FIRMWARE_NAME:Marlin TH3D U1.R2.7 SOURCE_CODE_URL: PROTOCOL_VERSION:1.0 MACHINE_TYPE:CR-10S EXTRUDER_COUNT:1 UUID:
2019-04-27 13:29:29,295 - Recv: Cap:SERIAL_XON_XOFF:0
2019-04-27 13:29:29,310 - Recv: Cap:EEPROM:1
2019-04-27 13:29:29,316 - Recv: Cap:VOLUMETRIC:0
2019-04-27 13:29:29,322 - Recv: Cap:AUTOREPORT_TEMP:1
2019-04-27 13:29:29,334 - Recv: Cap:PROGRESS:0
2019-04-27 13:29:29,339 - Recv: Cap:PRINT_JOB:1
2019-04-27 13:29:29,345 - Recv: Cap:AUTOLEVEL:1
2019-04-27 13:29:29,353 - Recv: Cap:Z_PROBE:1
2019-04-27 13:29:29,359 - Recv: Cap:LEVELING_DATA:1
2019-04-27 13:29:29,366 - Recv: Cap:BUILD_PERCENT:1
2019-04-27 13:29:29,372 - Recv: Cap:SOFTWARE_POWER:0
2019-04-27 13:29:29,377 - Recv: Cap:TOGGLE_LIGHTS:0
2019-04-27 13:29:29,383 - Recv: Cap:CASE_LIGHT_BRIGHTNESS:0
2019-04-27 13:29:29,394 - Recv: Cap:EMERGENCY_PARSER:0
2019-04-27 13:29:29,399 - Recv: Cap:AUTOREPORT_SD_STATUS:0
2019-04-27 13:29:29,403 - Recv: Cap:THERMAL_PROTECTION:1
2019-04-27 13:29:29,406 - Recv: ok
2019-04-27 13:29:29,410 - Send: M21
2019-04-27 13:29:29,448 - Recv: echo:SD card ok
2019-04-27 13:29:29,451 - Recv: ok
2019-04-27 13:29:29,455 - Send: M115
2019-04-27 13:29:29,509 - Recv: FIRMWARE_NAME:Marlin TH3D U1.R2.7 SOURCE_CODE_URL: PROTOCOL_VERSION:1.0 MACHINE_TYPE:CR-10S EXTRUDER_COUNT:1 UUID:
2019-04-27 13:29:29,515 - Recv: Cap:SERIAL_XON_XOFF:0
2019-04-27 13:29:29,518 - Recv: Cap:EEPROM:1
2019-04-27 13:29:29,522 - Recv: Cap:VOLUMETRIC:0
2019-04-27 13:29:29,525 - Recv: Cap:AUTOREPORT_TEMP:1
2019-04-27 13:29:29,531 - Recv: Cap:PROGRESS:0
2019-04-27 13:29:29,534 - Recv: Cap:PRINT_JOB:1
2019-04-27 13:29:29,538 - Recv: Cap:AUTOLEVEL:1
2019-04-27 13:29:29,542 - Recv: Cap:Z_PROBE:1
2019-04-27 13:29:29,545 - Recv: Cap:LEVELING_DATA:1
2019-04-27 13:29:29,549 - Recv: Cap:BUILD_PERCENT:1
2019-04-27 13:29:29,552 - Recv: Cap:SOFTWARE_POWER:0
2019-04-27 13:29:29,555 - Recv: Cap:TOGGLE_LIGHTS:0
2019-04-27 13:29:29,558 - Recv: Cap:CASE_LIGHT_BRIGHTNESS:0
2019-04-27 13:29:29,562 - Recv: Cap:EMERGENCY_PARSER:0
2019-04-27 13:29:29,566 - Recv: Cap:AUTOREPORT_SD_STATUS:0
2019-04-27 13:29:29,569 - Recv: Cap:THERMAL_PROTECTION:1
2019-04-27 13:29:29,573 - Recv: ok
2019-04-27 13:29:29,576 - Send: M20
2019-04-27 13:29:29,605 - Recv: Begin file list
2019-04-27 13:29:29,608 - Recv: XYZCAL~1.GCO 444353
2019-04-27 13:29:29,612 - Recv: XYZCAL~2.GCO 444353
2019-04-27 13:29:29,615 - Recv: XYZCAL~3.GCO 444353
2019-04-27 13:29:29,618 - Recv: XYZCAL~4.GCO 444353
2019-04-27 13:29:29,622 - Recv: XYZCAL~5.GCO 444353
2019-04-27 13:29:29,625 - Recv: XYZCAL~6.GCO 444353
2019-04-27 13:29:29,629 - Recv: End file list
2019-04-27 13:29:29,636 - Recv: ok
2019-04-27 13:29:29,640 - Send: M155 S2
2019-04-27 13:29:29,653 - Recv: ok
2019-04-27 13:29:29,657 - Send: M105
2019-04-27 13:29:29,671 - Recv: ok T:198.18 /0.00 B:73.04 /0.00 @:0 B@:0
2019-04-27 13:29:29,680 - Send: M155 S2
2019-04-27 13:29:29,695 - Recv: ok
2019-04-27 13:29:29,827 - Send: M504
2019-04-27 13:29:29,854 - Recv: echo:EEPROM OK
2019-04-27 13:29:29,859 - Recv: ok
2019-04-27 13:29:29,865 - Send: M501
2019-04-27 13:29:29,927 - Recv: echo:V55 stored settings retrieved (655 bytes; crc 17969)
2019-04-27 13:29:29,930 - Recv: echo:  G21    ; (mm)
2019-04-27 13:29:29,933 - Recv: echo:  M149 C ; Units in Celsius
2019-04-27 13:29:29,936 - Recv: 
2019-04-27 13:29:29,940 - Recv: echo:Steps per unit:
2019-04-27 13:29:29,942 - Recv: echo:  M92 X80.00 Y80.00 Z400.00 E415.00
2019-04-27 13:29:29,945 - Recv: echo:Maximum feedrates (units/s):
2019-04-27 13:29:29,949 - Recv: echo:  M203 X500.00 Y500.00 Z15.00 E50.00
2019-04-27 13:29:29,952 - Recv: echo:Maximum Acceleration (units/s2):
2019-04-27 13:29:29,956 - Recv: echo:  M201 X1000 Y300 Z100 E5000
2019-04-27 13:29:29,959 - Recv: echo:Acceleration (units/s2): P<print_accel> R<retract_accel> T<travel_accel>
2019-04-27 13:29:29,962 - Recv: echo:  M204 P250.00 R1000.00 T250.00
2019-04-27 13:29:29,969 - Recv: echo:Advanced: Q<min_segment_time_us> S<min_feedrate> T<min_travel_feedrate> X<max_x_jerk> Y<max_y_jerk> Z<max_z_jerk> E<max_e_jerk>
2019-04-27 13:29:29,972 - Recv: echo:  M205 Q25000 S0.00 T0.00 X11.00 Y11.00 Z0.40 E5.00
2019-04-27 13:29:29,975 - Recv: echo:Home offset:
2019-04-27 13:29:29,978 - Recv: echo:  M206 X0.00 Y0.00 Z0.00
2019-04-27 13:29:29,981 - Recv: echo:Auto Bed Leveling:
2019-04-27 13:29:29,985 - Recv: echo:  M420 S0 Z0.00
2019-04-27 13:29:29,988 - Recv: echo:  G29 W I0 J0 Z0.20000
2019-04-27 13:29:29,991 - Recv: echo:  G29 W I1 J0 Z0.06400
2019-04-27 13:29:29,994 - Recv: echo:  G29 W I2 J0 Z0.11100
2019-04-27 13:29:29,998 - Recv: echo:  G29 W I0 J1 Z0.19200
2019-04-27 13:29:30,000 - Recv: echo:  G29 W I1 J1 Z0.02800
2019-04-27 13:29:30,004 - Recv: echo:  G29 W I2 J1 Z0.11250
2019-04-27 13:29:30,007 - Recv: echo:  G29 W I0 J2 Z0.27050
2019-04-27 13:29:30,011 - Recv: echo:  G29 W I1 J2 Z0.07050
2019-04-27 13:29:30,013 - Recv: echo:  G29 W I2 J2 Z0.13300
2019-04-27 13:29:30,017 - Recv: echo:Material heatup parameters:
2019-04-27 13:29:30,020 - Recv: echo:  M145 S0 H200 B60 F0
2019-04-27 13:29:30,023 - Recv: echo:  M145 S1 H240 B100 F0
2019-04-27 13:29:30,026 - Recv: echo:PID settings:
2019-04-27 13:29:30,030 - Recv: echo:  M301 P23.87 I4.35 D32.75
2019-04-27 13:29:30,033 - Recv: echo:  M304 P61.56 I3.81 D248.39
2019-04-27 13:29:30,036 - Recv: echo:Z-Probe Offset (mm):
2019-04-27 13:29:30,039 - Recv: echo:  M851 Z-1.27
2019-04-27 13:29:30,042 - Recv: echo:Filament load/unload lengths:
2019-04-27 13:29:30,045 - Recv: echo:  M603 L60.00 U120.00
2019-04-27 13:29:30,048 - Recv: ok
2019-04-27 13:29:30,330 - Recv: echo:enqueueing "M420 S0"
2019-04-27 13:29:30,336 - Recv: echo:enqueueing "M190 S75"
2019-04-27 13:29:30,343 - Recv: echo:enqueueing "M109 S225"
2019-04-27 13:29:30,348 - Recv: echo:enqueueing "G28 R0 X Y"
2019-04-27 13:29:30,355 - Recv: echo:Bed Leveling Arr��t
2019-04-27 13:29:30,361 - Recv: echo:Fade Height Arr��t
2019-04-27 13:29:30,367 - Recv:  T:197.56 /0.00 B:72.91 /75.00 @:0 B@:0 W:?
2019-04-27 13:29:31,322 - Recv:  T:196.36 /0.00 B:72.77 /75.00 @:0 B@:0 W:?
2019-04-27 13:29:31,690 - Recv:  T:196.08 /0.00 B:72.75 /75.00 @:0 B@:0
2019-04-27 13:29:32,328 - Recv:  T:195.28 /0.00 B:72.76 /75.00 @:0 B@:0 W:?
2019-04-27 13:29:33,320 - Recv:  T:194.18 /0.00 B:72.66 /75.00 @:0 B@:0 W:?
2019-04-27 13:29:33,702 - Recv:  T:193.72 /0.00 B:72.54 /75.00 @:0 B@:0
2019-04-27 13:29:34,326 - Recv:  T:193.01 /0.00 B:72.47 /75.00 @:0 B@:0 W:?
2019-04-27 13:29:35,333 - Recv:  T:191.79 /0.00 B:72.32 /75.00 @:0 B@:4 W:?
2019-04-27 13:29:35,701 - Recv:  T:191.51 /0.00 B:72.27 /75.00 @:0 B@:19
2019-04-27 13:29:36,340 - Recv:  T:190.57 /0.00 B:72.22 /75.00 @:0 B@:43 W:?
2019-04-27 13:29:37,331 - Recv:  T:189.48 /0.00 B:72.10 /75.00 @:0 B@:74 W:?
2019-04-27 13:29:37,699 - Recv:  T:189.22 /0.00 B:72.09 /75.00 @:0 B@:82
2019-04-27 13:29:38,404 - Recv:  T:188.44 /0.00 B:72.04 /75.00 @:0 B@:96 W:?
2019-04-27 13:29:39,330 - Recv:  T:187.14 /0.00 B:71.89 /75.00 @:0 B@:121 W:?
2019-04-27 13:29:39,697 - Recv:  T:186.61 /0.00 B:72.13 /75.00 @:0 B@:111
2019-04-27 13:29:40,336 - Recv:  T:186.04 /0.00 B:71.80 /75.00 @:0 B@:127 W:?
2019-04-27 13:29:41,343 - Recv:  T:184.33 /0.00 B:71.95 /75.00 @:0 B@:127 W:?
2019-04-27 13:29:41,694 - Recv:  T:184.25 /0.00 B:71.95 /75.00 @:0 B@:127
2019-04-27 13:29:42,334 - Recv:  T:183.39 /0.00 B:71.90 /75.00 @:0 B@:127 W:?
2019-04-27 13:29:43,341 - Recv:  T:182.50 /0.00 B:72.03 /75.00 @:0 B@:127 W:?
2019-04-27 13:29:43,692 - Recv:  T:182.24 /0.00 B:72.08 /75.00 @:0 B@:127
2019-04-27 13:29:44,332 - Recv:  T:181.18 /0.00 B:72.19 /75.00 @:0 B@:124 W:?
2019-04-27 13:29:45,339 - Recv:  T:180.26 /0.00 B:72.32 /75.00 @:0 B@:122 W:?
2019-04-27 13:29:45,690 - Recv:  T:180.02 /0.00 B:72.36 /75.00 @:0 B@:122
2019-04-27 13:29:46,345 - Recv:  T:179.58 /235.00 B:72.58 /75.00 @:127 B@:113 W:?
2019-04-27 13:29:47,336 - Recv:  T:178.17 /235.00 B:72.82 /75.00 @:127 B@:107 W:?
2019-04-27 13:29:47,704 - Recv:  T:177.94 /235.00 B:73.14 /75.00 @:127 B@:90
2019-04-27 13:29:48,342 - Recv:  T:177.88 /235.00 B:73.23 /75.00 @:127 B@:90 W:?
2019-04-27 13:29:49,334 - Recv:  T:178.46 /235.00 B:73.67 /75.00 @:127 B@:75 W:?
2019-04-27 13:29:49,702 - Recv:  T:178.67 /235.00 B:73.76 /75.00 @:127 B@:73
2019-04-27 13:29:50,340 - Recv:  T:179.79 /225.00 B:74.15 /75.00 @:127 B@:55 W:4
2019-04-27 13:29:51,331 - Recv:  T:181.06 /225.00 B:74.47 /75.00 @:127 B@:47 W:3
2019-04-27 13:29:51,699 - Recv:  T:181.66 /225.00 B:74.62 /75.00 @:127 B@:41
2019-04-27 13:29:52,337 - Recv:  T:182.52 /225.00 B:74.89 /75.00 @:127 B@:32 W:2
2019-04-27 13:29:53,345 - Recv:  T:184.47 /225.00 B:75.39 /75.00 @:127 B@:11 W:1
2019-04-27 13:29:53,697 - Recv:  T:185.42 /225.00 B:75.55 /75.00 @:127 B@:4
2019-04-27 13:29:54,336 - Recv:  T:186.56 /225.00 B:75.70 /75.00 @:127 B@:3 W:0
2019-04-27 13:29:55,151 - Recv:  T:188.20 /225.00 B:75.99 /75.00 @:127 B@:0 W:?
2019-04-27 13:29:55,694 - Recv:  T:188.98 /225.00 B:76.21 /75.00 @:127 B@:0
2019-04-27 13:29:56,157 - Recv:  T:189.48 /225.00 B:76.69 /75.00 @:127 B@:0 W:?
2019-04-27 13:29:57,149 - Recv:  T:193.92 /225.00 B:76.39 /75.00 @:127 B@:0 W:?
2019-04-27 13:29:57,692 - Recv:  T:192.87 /225.00 B:77.21 /75.00 @:127 B@:0
2019-04-27 13:29:58,155 - Recv:  T:194.83 /225.00 B:76.75 /75.00 @:127 B@:0 W:?
2019-04-27 13:29:59,147 - Recv:  T:197.47 /225.00 B:76.95 /75.00 @:127 B@:0 W:?
2019-04-27 13:29:59,690 - Recv:  T:197.87 /225.00 B:77.21 /75.00 @:127 B@:0
2019-04-27 13:30:00,154 - Recv:  T:199.12 /225.00 B:77.21 /75.00 @:127 B@:0 W:?
2019-04-27 13:30:01,145 - Recv:  T:200.73 /225.00 B:77.60 /75.00 @:127 B@:0 W:?
2019-04-27 13:30:01,704 - Recv:  T:201.74 /225.00 B:77.62 /75.00 @:127 B@:0
2019-04-27 13:30:02,152 - Recv:  T:203.09 /225.00 B:77.64 /75.00 @:127 B@:0 W:?
2019-04-27 13:30:03,158 - Recv:  T:204.51 /225.00 B:77.82 /75.00 @:127 B@:0 W:?
2019-04-27 13:30:03,701 - Recv:  T:205.31 /225.00 B:77.76 /75.00 @:127 B@:0
2019-04-27 13:30:04,150 - Recv:  T:206.25 /225.00 B:77.76 /75.00 @:127 B@:0 W:?
2019-04-27 13:30:05,155 - Recv:  T:209.26 /225.00 B:77.78 /75.00 @:127 B@:0 W:?
2019-04-27 13:30:05,700 - Recv:  T:210.43 /225.00 B:77.71 /75.00 @:127 B@:0
2019-04-27 13:30:06,147 - Recv:  T:211.09 /225.00 B:77.68 /75.00 @:127 B@:0 W:?
2019-04-27 13:30:07,153 - Recv:  T:213.01 /225.00 B:77.60 /75.00 @:127 B@:0 W:?
2019-04-27 13:30:07,696 - Recv:  T:213.83 /225.00 B:77.59 /75.00 @:127 B@:0
2019-04-27 13:30:08,144 - Recv:  T:214.61 /225.00 B:77.58 /75.00 @:127 B@:0 W:?
2019-04-27 13:30:09,150 - Recv:  T:215.99 /225.00 B:77.45 /75.00 @:91 B@:0 W:?
2019-04-27 13:30:09,710 - Recv:  T:217.92 /225.00 B:77.35 /75.00 @:75 B@:3
2019-04-27 13:30:10,157 - Recv:  T:219.53 /225.00 B:77.33 /75.00 @:60 B@:1 W:?
2019-04-27 13:30:11,148 - Recv:  T:221.56 /225.00 B:77.18 /75.00 @:45 B@:4 W:?
2019-04-27 13:30:11,708 - Recv:  T:221.65 /225.00 B:77.14 /75.00 @:52 B@:4
2019-04-27 13:30:12,155 - Recv:  T:222.23 /225.00 B:77.05 /75.00 @:50 B@:7 W:?
2019-04-27 13:30:13,162 - Recv:  T:223.21 /225.00 B:76.97 /75.00 @:47 B@:6 W:?
2019-04-27 13:30:13,705 - Recv:  T:223.17 /225.00 B:76.90 /75.00 @:53 B@:7
2019-04-27 13:30:14,171 - Recv:  T:223.84 /225.00 B:76.88 /75.00 @:46 B@:5 W:4
2019-04-27 13:30:15,160 - Recv:  T:224.42 /225.00 B:76.75 /75.00 @:44 B@:7 W:3
2019-04-27 13:30:15,703 - Recv:  T:225.56 /225.00 B:76.68 /75.00 @:28 B@:8
2019-04-27 13:30:16,166 - Recv:  T:224.29 /225.00 B:76.66 /75.00 @:53 B@:6 W:2
2019-04-27 13:30:17,186 - Recv:  T:224.33 /225.00 B:76.58 /75.00 @:56 B@:5 W:1
2019-04-27 13:30:17,701 - Recv:  T:225.38 /225.00 B:76.49 /75.00 @:40 B@:7
2019-04-27 13:30:18,165 - Recv:  T:225.19 /225.00 B:76.37 /75.00 @:45 B@:13 W:0
2019-04-27 13:30:19,698 - Recv:  T:225.13 /225.00 B:76.10 /75.00 @:49 B@:19
2019-04-27 13:30:20,737 - Recv: echo:busy: processing
2019-04-27 13:30:20,741 - Printer seems to support the busy protocol, will adjust timeouts and set busy interval accordingly
2019-04-27 13:30:20,748 - Send: M113 S2
2019-04-27 13:30:21,696 - Recv:  T:226.56 /225.00 B:75.97 /75.00 @:27 B@:15
2019-04-27 13:30:22,735 - Recv: echo:busy: processing
2019-04-27 13:30:23,709 - Recv:  T:224.46 /225.00 B:75.75 /75.00 @:64 B@:18
2019-04-27 13:30:24,507 - Recv: X:0.00 Y:0.00 Z:0.00 E:0.00 Count X:0 Y:0 Z:0
2019-04-27 13:30:24,515 - Recv: echo:Bed Leveling Arr��t
2019-04-27 13:30:24,536 - Recv: echo:Fade Height Arr��t
2019-04-27 13:30:24,558 - Recv: X:0.00 Y:0.00 Z:0.00 E:0.00 Count X:0 Y:0 Z:0
2019-04-27 13:30:24,565 - Recv: echo:Origine Z Premier
2019-04-27 13:30:24,571 - Recv: ok
2019-04-27 13:30:25,706 - Recv:  T:224.55 /225.00 B:75.56 /75.00 @:63 B@:20
2019-04-27 13:30:26,402 - Recv: X:0.00 Y:0.00 Z:0.00 E:0.00 Count X:0 Y:0 Z:0
2019-04-27 13:30:26,415 - Recv: X:0.00 Y:0.00 Z:7.00 E:0.00 Count X:0 Y:0 Z:0
2019-04-27 13:30:27,697 - Recv:  T:225.00 /225.00 B:75.42 /75.00 @:57 B@:21
2019-04-27 13:30:28,400 - Recv: echo:busy: processing
2019-04-27 13:30:29,710 - Recv:  T:224.55 /225.00 B:75.26 /75.00 @:66 B@:25
2019-04-27 13:30:30,398 - Recv: echo:busy: processing
2019-04-27 13:30:31,708 - Recv:  T:225.63 /225.00 B:75.08 /75.00 @:48 B@:30
2019-04-27 13:30:32,395 - Recv: echo:busy: processing
2019-04-27 13:30:33,705 - Recv:  T:225.81 /225.00 B:74.97 /75.00 @:0 B@:36
2019-04-27 13:30:34,392 - Recv: echo:busy: processing
2019-04-27 13:30:35,718 - Recv:  T:225.06 /225.00 B:74.94 /75.00 @:2 B@:35
2019-04-27 13:30:35,959 - Recv: X:87.00 Y:150.00 Z:5.00 E:0.00 Count X:6960 Y:12000 Z:2000
2019-04-27 13:30:37,716 - Recv:  T:222.95 /225.00 B:74.85 /75.00 @:0 B@:0
2019-04-27 13:30:37,956 - Recv: echo:busy: processing
2019-04-27 13:30:39,731 - Recv:  T:221.47 /225.00 B:74.80 /75.00 @:55 B@:41
2019-04-27 13:30:39,954 - Recv: echo:busy: processing
2019-04-27 13:30:40,658 - Recv: X:87.00 Y:150.00 Z:5.00 E:0.00 Count X:6960 Y:12000 Z:2000
2019-04-27 13:30:41,729 - Recv:  T:220.09 /225.00 B:74.73 /75.00 @:89 B@:41
2019-04-27 13:30:42,655 - Recv: echo:busy: processing
2019-04-27 13:30:43,726 - Recv:  T:219.06 /225.00 B:74.67 /75.00 @:125 B@:42
2019-04-27 13:30:44,653 - Recv: echo:busy: processing
2019-04-27 13:30:45,724 - Recv:  T:220.09 /225.00 B:74.70 /75.00 @:121 B@:38
2019-04-27 13:30:46,651 - Recv: echo:busy: processing
2019-04-27 13:30:47,722 - Recv:  T:222.37 /225.00 B:74.72 /75.00 @:100 B@:37
2019-04-27 13:30:48,664 - Recv: echo:busy: processing
2019-04-27 13:30:49,735 - Recv:  T:223.88 /225.00 B:74.76 /75.00 @:88 B@:35
2019-04-27 13:30:50,692 - Recv: File deleted:bin
2019-04-27 13:30:50,695 - Recv: echo:Now fresh file: XYZCAL~6.GCO
2019-04-27 13:30:50,703 - Recv: File opened: XYZCAL~6.GCO Size: 444353
2019-04-27 13:30:50,706 - Recv: File selected
2019-04-27 13:30:50,720 - Recv: X:87.00 Y:150.00 Z:5.00 E:0.00 Count X:6960 Y:12000 Z:2000
2019-04-27 13:30:50,816 - Recv: X:1.40 Y:20.00 Z:0.30 E:0.00 Count X:6960 Y:12000 Z:1992
2019-04-27 13:30:50,822 - Recv: X:1.40 Y:20.00 Z:1.00 E:0.00 Count X:6960 Y:12000 Z:1980
2019-04-27 13:30:51,590 - Send: M27
2019-04-27 13:30:51,727 - Recv:  T:228.19 /225.00 B:74.81 /75.00 @:19 B@:34
2019-04-27 13:30:53,133 - Recv: echo:busy: processing
2019-04-27 13:30:53,724 - Recv:  T:228.13 /225.00 B:75.00 /75.00 @:18 B@:23
2019-04-27 13:30:55,291 - Recv: echo:busy: processing
2019-04-27 13:30:55,722 - Recv:  T:227.44 /225.00 B:75.12 /75.00 @:24 B@:18
2019-04-27 13:30:57,288 - Recv: echo:busy: processing
2019-04-27 13:30:57,720 - Recv:  T:227.44 /225.00 B:75.32 /75.00 @:16 B@:9
2019-04-27 13:30:59,285 - Recv: echo:busy: processing
2019-04-27 13:30:59,734 - Recv:  T:225.56 /225.00 B:75.44 /75.00 @:39 B@:5
2019-04-27 13:31:01,732 - Recv:  T:223.71 /225.00 B:75.49 /75.00 @:66 B@:4
2019-04-27 13:31:02,579 - Recv: echo:busy: processing
2019-04-27 13:31:03,729 - Recv:  T:222.01 /225.00 B:75.49 /75.00 @:98 B@:4
2019-04-27 13:31:04,579 - Recv: echo:busy: processing
2019-04-27 13:31:05,727 - Recv:  T:221.70 /225.00 B:75.46 /75.00 @:111 B@:6
2019-04-27 13:31:06,573 - Recv: echo:busy: processing
2019-04-27 13:31:07,725 - Recv:  T:222.23 /225.00 B:75.33 /75.00 @:111 B@:12
2019-04-27 13:31:07,805 - Recv: SD printing byte 1377/444353
2019-04-27 13:31:07,810 - Changing monitoring state from "Operational" to "Starting print from SD"
2019-04-27 13:31:07,835 - Recv: ok
2019-04-27 13:31:07,842 - Send: M27
2019-04-27 13:31:09,722 - Recv:  T:223.30 /225.00 B:75.13 /75.00 @:102 B@:22
2019-04-27 13:31:10,026 - Recv: echo:busy: processing
2019-04-27 13:31:11,225 - Recv: SD printing byte 1524/444353
2019-04-27 13:31:11,252 - Recv: ok
2019-04-27 13:31:11,257 - Changing monitoring state from "Starting print from SD" to "Printing from SD"
2019-04-27 13:31:11,265 - Send: M27
2019-04-27 13:31:11,368 - Recv: SD printing byte 1643/444353
2019-04-27 13:31:11,372 - Recv: ok
2019-04-27 13:31:11,627 - Send: M27
2019-04-27 13:31:11,735 - Recv:  T:224.82 /225.00 B:74.94 /75.00 @:83 B@:30
2019-04-27 13:31:12,205 - Recv: SD printing byte 1852/444353
2019-04-27 13:31:12,218 - Recv: ok
2019-04-27 13:31:12,629 - Send: M27
2019-04-27 13:31:13,223 - Recv: SD printing byte 2298/444353
2019-04-27 13:31:13,229 - Recv: ok
2019-04-27 13:31:13,630 - Send: M27
2019-04-27 13:31:13,733 - Recv:  T:228.06 /225.00 B:74.77 /75.00 @:27 B@:37
2019-04-27 13:31:14,245 - Recv: SD printing byte 2743/444353
2019-04-27 13:31:14,252 - Recv: ok
2019-04-27 13:31:14,632 - Send: M27
2019-04-27 13:31:15,253 - Changing monitoring state from "Printing from SD" to "Cancelling"
2019-04-27 13:31:15,280 - Recv: SD printing byte 3191/444353
2019-04-27 13:31:15,288 - Recv: ok

for the plugins, I can try, but I have not made a new installation since I switched to RC.
on the other hand, the problem seems to arise that very very rarely.

However, I realized that the pi was sometimes underfed and I found the cause of the problem, a USB hub become defective.
I took it off yesterday. I will try to reproduce the problem.
even if I do not remember seeing the icon on octoprint at the time of the crash.

devildant picture devildant on 2 May 2019

Looking at this a bit closer it might be a dead lock issue between sendingLock and jobLock due the M25 now causing a call to setPause even for SD prints (which is a change compared to 1.3.10).

Right now I'm unable to see how there could be a deadlock here though, but that is about the only thing that might cause the described symptoms.

I forgot to call it back, but the problem occurs every time, when I cancel from the octoprint interface for printing via SD.
at the moment the information is never transmitted to the printer, it continues to print, and octoprint is frozen

devildant picture devildant on 2 May 2019

What about safe mode? I cannot reproduce this at all so far. I can imagine there might be some deadlock in there, but looking at intensely I'm not able to spot it. Reproduction would help, but I can't seem to get that.

edit I've now stared some more at the possible code lines and as far as I can see there cannot be a deadlock after all. So I'm at a loss here. I'd like you to see if you can reproduce this issue in safe mode. If you cannot, it must be something in your plugins. If you can, that'll at least confirm that it's NOT something external but indeed something in the code.

foosel picture foosel on 3 May 2019

Hello foosel, I will try in safe mode.
however before I would like to reproduce it without my usb hub (failing), because maybe a under power supply cause at the time of cancellation, could explain the bug encountered.
because even for me this bug is very very difficult to reproduce.
and I'm still looking for the conditions of this bug
but I will not forget to test in safe mode, I promise you :)

devildant picture devildant on 3 May 2019

I also tried to analyze the logs.
image
in the case of the bug, the M25 command never seems to arrive serial.log

I looked in the logs the cases that works
image
M25 correctly send to the printer

devildant picture devildant on 3 May 2019

would there be any reason in the code that would prevent sending the order to the printer?
because finally, if the command is not sent but octoprint wait are back it is normal that it blocks, right?

devildant picture devildant on 3 May 2019

in the case of the bug, the M25 command never seems to arrive serial.log

That's what I figured, which is why my initial suspicion was a deadlock. But I went over the whole code several times and can't see any place where that makes sense, so before I continue to spend hours on hunting for that I'd prefer to fully rule out and third party plugin issues and also hardware issues.

would there be any reason in the code that would prevent sending the order to the printer?

If it hasn't received back an ok, or if it's deadlocked.

because finally, if the command is not sent but octoprint wait are back it is normal that it blocks, right?

It would be normal that it doesn't continue sending stuff to the printer, but it would not be normal that you can't even reach the server anymore (which I understand is happening for you). So - stuck comms, yes, but still with a usable web interface and anything that doesn't involve talking to the printer still working completely fine. Also a server heartbeat getting logged to the log every couple of minutes.

foosel picture foosel on 6 May 2019

I'd also really like to get to the bottom of this by Wednesday, because this is currently blocking the release of 1.3.11 (or 1.3.11rc4), so the earlier you can test safe mode, the better.

foosel picture foosel on 6 May 2019

hello @foosel, I tried to reproduce this week end without my hub defective, and with a 3a power supply, and I have not yet succeeded in reproducing the problem.
but hey, it's very difficult to produce, the 3 times that happened to me it's by chance.
I'll continue the tests tonight, I'll make you a return tomorrow

devildant picture devildant on 6 May 2019
❤1

I'll continue the tests tonight

In safe-mode please ;)

jubaleth picture jubaleth on 6 May 2019

I attract this kind of bug, shitty life ^^

devildant picture devildant on 6 May 2019

I'll continue the tests tonight

In safe-mode please ;)

yes I will try, but the only plugin that touches the event (status printer change) are my plugin in dev, my plugin shutdown printer, and the plugin enclosure, but this is only the receipt of event.

what annoys me the most is not to find the logic of prodution of the bug

devildant picture devildant on 6 May 2019

Just to add another data point. I started and cancelled 2 SD card prints (started from the printer and cancelled from OctoPrint), and it behaved well.

kazibole picture kazibole on 6 May 2019

me also most of the time it works without worry, but 1/1000 i encounter the problem.
Currently, I am in safe mode, no errors encountered at the moment.
but it was also the case for this weekend in normal mode.
it makes me crazy ^^

devildant picture devildant on 6 May 2019

Ok, how about the following... you continue to test in safe mode until Friday. If the issue still hasn't returned then, we'll consider it a plugin problem. Otherwise I'll do another deep dive and see if I can find a reason until Wednesday. Considering that so far you appear to be the only one able to reproduce this, it should not be THAT big of an issue if this is an actual issue in core after all and makes it into stable, but I'd still like to reduce the risk of that happening as much as possible.

Currently I don't feel comfortable releasing stable with you only having checked in safe mode for two days now... It's a tricky situation.

foosel picture foosel on 8 May 2019

hello @foosel ,
I would like to continue the tests a few days, if possible.
see what that gives, but as I do not have the keys to reproduce the problem, it is pure chance.
I will continue to test in safe mode.
at the same time, I also modified my plugins so that they do not log anymore at the reception of the events.
(As java dev, I had already seen file writing problems, which sometimes caused crashes of the application).
I also corrected my power supply problem (PI), increasing the amperage of the power supply (3a) and putting in place an external USB hub with power supply (I have 4 usb to connect).
strategically, it would have been wiser to test each change, but I do not want to block the release :)

this kind of bug, it's always on me that it falls :(

devildant picture devildant on 8 May 2019

hello @foosel, I have not reproduced for the moment in safe mode, I will test again with my plugins.
I do not want to block the RC4 anymore (or the release 1.3.11).
what I propose is to leave for the moment this open issue, the time that I do more test, if I have new I will update the subject.
in the meantime I think you can switch to the RC4 or the final release.

devildant picture devildant on 11 May 2019

Ok... will move ahead with 1.3.11 stable then but leave this open. I have a feeling it might really be something in your plugin(s).

foosel picture foosel on 13 May 2019

I ask myself a question, I installed a USB UPS with a nut server.
I wonder if this could not be the cause of my problem.
I will test with the unplugged UPS

devildant picture devildant on 13 May 2019

because looking at the log, the serial.log never gets the M25 command.
I produced a similar bug during a development test.
I ran a subprocess that did not complete (umount command) and octoprint crashed

devildant picture devildant on 13 May 2019

I added threads in my plugin because I execute shell commands (mount, umount, copy, delete)
However, none of these actions are performed during the cancellation, but in case of doubt ..., because I managed to generate the problem with a sub-process (which not stopped, deadlock).

p = subprocess.Popen(["sudo",  "umount", path])
p.communicate()
p.wait()

according to the documentation with the function communicate the deadlocks should not happen.
and during the ocotprint crash, I did not see any of my orders blocking too long.

I will test with a limited number of plugins.

devildant picture devildant on 14 May 2019

Yesterday I updated to Octoprint 1.3.11, I'm using Klipper firmware. I can't cancel the SD prints anymore, behavior looks similar to the issues reported in this thread. Unfortunately it seems that I didn't have serial.log enabled. This is fully reproducible on my environment, happens all the time.

Also after pressing cancel, the octoprint seems to hang/die and the web interface doesn't respond, even though printing still continues.

These are the last lines in log file:

2019-05-15 13:59:42,682 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-05-15 13:59:45,343 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 18021}
2019-05-15 14:11:45,386 - octoprint.util.comm - INFO - Changing monitoring state from "Printing from SD" to "Cancelling"
2019-05-15 14:11:45,391 - octoprint.filemanager.analysis - INFO - Starting analysis of local:TT_FirebayStik_bottom.gcode
2019-05-15 14:11:45,407 - 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 /home/pi/.octoprint/uploads/TT_FirebayStik_bottom.gcode
2019-05-15 14:11:45,419 - octoprint.printer.standard.job - INFO - Print job cancelled - origin: sdcard, path: tt_firebaystik_bottom.gcode, owner: dummy, user: dummy
2019-05-15 14:11:45,497 - octoprint.util.comm - INFO - Pausing print job due to command M25
2019-05-15 14:13:06,456 - octoprint.filemanager.analysis - INFO - Analysis of entry local:TT_FirebayStik_bottom.gcode finished, needed 81.07s
2019-05-15 14:13:06,733 - octoprint.plugins.tracking - INFO - Sent tracking event print_cancelled, payload: {'origin': 'sdcard', 'file': '6523fcc7141db0154530ba36ca83ede418febc55', 'elapsed': 3493}
2019-05-15 14:13:06,996 - octoprint.plugins.tracking - INFO - Sent tracking event print_failed, payload: {'origin': 'sdcard', 'reason': 'cancelled', 'file': '6523fcc7141db0154530ba36ca83ede418febc55', 'elapsed': 3493}
2019-05-15 14:14:42,684 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2019-05-15 14:14:43,047 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 18921}

Jartza picture Jartza on 15 May 2019

@Jartza please enable serial.log, reproduce, then provide the full octoprint.log and serial.log.

foosel picture foosel on 15 May 2019

@Jartza please enable serial.log, reproduce, then provide the full octoprint.log and serial.log.

I will try, funnily it failed for me already 5 times today, but after enabling serial log, I can't reproduce... will try again.

Jartza picture Jartza on 15 May 2019

after enabling serial log, I can't reproduce...

Ewwww.... that sounds like it might be a race condition and that is very worrying.

foosel picture foosel on 16 May 2019

Hello,
me on my side, I still can not isolate the problem.
what I notice is that the M25 command does not arrive at the printer.
9/10 the cancel works, but 1/10 octoprint crash, however the serial log seems to continue to be filled.
it makes me think of a problem that I met some years ago on a synology server.
At the time it was the log rotation system that randomly crashed php-fpm.
I can not help but find similarity with the problem encountered.
i use marlin 1.1.9 (TH3D 2.7) and "OctoPrint 1.3.11 running on OctoPi 0.15.1"

devildant picture devildant on 16 May 2019

Hello,

the problem is produced again, this time:

  • pause print
  • cancel print
    as in my previous logs, nothing after the "octoprint.util.comm - INFO - Pause print job due to command M25"

best regards

devildant picture devildant on 15 Jun 2019

Hello,
the bug continues to occur randomly.
by dint of looking at the log, I notice one thing.
During this accident, I noticed that the M27 command was sent a few milliseconds before.
if the M27 command responds exactly when sending the M25 command, can it not create an inconsistency that would crash / freeze octoprint ?
this will explain the fact that it is very hard to reproduce the problem

devildant picture devildant on 27 Jun 2019

I also remarked remarkably, during the development of my plugin, that the threads were not written in the logs.
I try to give all the tracks that come to me :(

devildant picture devildant on 27 Jun 2019

WOW, I'M NOT THE ONLY ONE ! I'm setting up a new printer with klipper, and get this almost everytime I cancel a print, and nothing in the logs ... I'm printing with virtual sdcard, and the last message I get is something like "your printer reported an error, print will be cancelled. Message : 'sd busy'" (but I'm already cancelling the print so double canceling ? oO).

Then I have to /etc/init.d/octoprint restart, cause I get no answer from the webserver (but it is still there as a process)

aschor picture aschor on 22 Sep 2019

@aschor can you please share your logs (octoprint.log and serial.log) anyhow?

foosel picture foosel on 23 Sep 2019

@foosel probably not before tomorrow, if I can reproduce it. But I'm pretty sure it almost always happens when I cancel during the pre-heat of the printer (M109 or M190), where the printer actually does not answer to any Gcode command. MAYBE I hit multiple times the "cancel" button because the temperature continues to rise...

aschor picture aschor on 23 Sep 2019

@foosel here it is : a server freeze when cancelling a (retraction) test print : it did NOT cancel, the file finished while octoprint webui was (and still is) unresponsive : https://gofile.io/?c=01ADZo

aschor picture aschor on 24 Sep 2019

What this shows is that once again the M27 came just 10ms before the switch to cancelling state. So maybe @devildant is on to something here.

The only thing that could explain the server hanging so it doesn't even response to anything anymore would be some kind of deadlock 🤔

foosel picture foosel on 25 Sep 2019
👍1

Good news. I tracked it down I think and am looking at a fairly obvious deadlock now, if the conditions and timing are just right. Problem is that right now I'm not 100% sure how to solve it, but I'm sure I'll figure it out.

image

foosel picture foosel on 25 Sep 2019

Should be fixed by the above commit. Funnily enough this is now both a confirmed and unreproduced bug - I couldn't get it to reproduce even once, but based on the code it should be this. I've pushed the fix to the maintenance branch. Should another RC for 1.3.12 still be needed (unlikely based on current feedback though) I'll see about merging into that release, otherwise it'll have to wait until the next maintenance release.

It would be great though if those of you who can more or less reliably reproduce it would give the maintenance branch with the fix a test and see if the issue is solved indeed. It should but without being able to reproduce it myself the solution is purely theoretical at this point.

foosel picture foosel on 26 Sep 2019

hello @foosel , I do not have the time to test yet, however if I find a moment, I'll make you a return.
however, it may take some time since I do not systematically reproduce the bug (which always happens a few ms after the M27)
in any case the "trigger" seems to me to be a good track
thanks for the work :)

devildant picture devildant on 26 Sep 2019

hello @foosel, I tested multiple times to cancel prints with the maintenance branch, and I did NOT get any lockup, I think that's fixed now 👍

However ... I have to cancel the print 2 times :

  • first time, the print stops, then I get an error and I cannot launch a new print, octoprint still thinks it is printing : "Error reported by printer
    Your printer's firmware reported an error. Due to that the ongoing print job will be cancelled. Reported error: SD busy"
  • I hit a second time the cancel button, and THEN I get de "print" button enabled again, and I can continue. (my firmware is klipper)
aschor picture aschor on 8 Oct 2019

@aschor would you have a serial.log for that by any chance? Without one I don't think I'll be able to debug that.

foosel picture foosel on 8 Oct 2019

@foosel

serial.log

here you are, just cancelled a print (twice). As I see it I jump from "Cancelling" to "Operational" then for no reason from "Operational" to "Starting print from SD" (that twice).

on my 2nd cancellation, I stay at "operational"

aschor picture aschor on 8 Oct 2019

Ah. That looks like a different issue. That's more a problem with the SD print detection code in place for when people start an SD print from the printer controller causing a problem here. I'll have to take a look at that, but it merits a new ticket.

foosel picture foosel on 9 Oct 2019

This is now tracked in #3301

foosel picture foosel on 9 Oct 2019

1.4.0 has been released.

foosel picture foosel on 4 Mar 2020
👍1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

JohnOCFII picture JohnOCFII  ·  5Comments
mrcg picture mrcg  ·  5Comments
foosel picture foosel  ·  4Comments
ModischFabrications picture ModischFabrications  ·  3Comments
foosel picture foosel  ·  5Comments