Bug? Cancel Gcode + M112 = crash

What is the problem?
As soon as I cancel the print using the plugin "emergency stop simplified", Octoprint just "shuts down" and I get a "not running" page instead. Octoprint.log does not show any errors or notifications that it encountered an error and had to shut down somehow, it literally "disappeared". The octoprint service kept saying that the PID was still alive, although there was no python scripts running anymore (verified using ps).

What did you already try to solve it?
I found out that if I removed the gcode from the "cancel print" option (Settings -> Gcode scripts) the plugin kept working as expected and there is no forced closing of octoprint. It did complain about the serial port being "disconnected", which was expected behaviour since the printer was resetting. Most likely octoprint crashes while writing gcode to a closed serial port.

Logs (octoprint.log, serial.log or output on terminal tab at a minimum, browser error console if UI issue ... no logs, no support!)
I can show logs, but it seems the culprit can not be found in the logs (at least I did not witness any errors or issues in the logs).

The last output from the Serial command is M112, followed by a warning that the serial port is disconnected. The "cancel" gcode does not seem to be executed (most likely error'd while writing to a closed serial).

Additional information about your setup (OctoPrint version, OctoPi version, printer, firmware, browser, operating system, ... as much data as possible)
Ender 3 Printer with modified marlin, supports M112 "Emergency stop" which will trigger a full reset of the printer (including closing the serial port).
Runs: OctoPrint 1.4.0 running on OctoPi 0.17.0

My thought is that Octoprint should threat M112 commands as a fatal "Error" commands and should not execute any Cancel scripts.

The actual logs are more than what is shown in the terminal window. No logs, no support. Not because we are being difficult, but because the logs are our only means of finding out what is going on.

This better?

And here is another one from an earlier date:

That's a big log spanning multiple days. Did the crash happen once in there, or multiple times? On what day, what approximate time did the error occur?

Does it also happen with some of the plugins disabled?

1 Like

Took me a while to find the cause, but here is a way to replicate the issue:

  1. Start a print
  2. Do anything that causes the printer to disconnect the serial port
  3. Profit.

I thought it was happening when I was sending M112, but I found out that if I literally disconnect the printer mid-print, or simply turn it off mid-print it would cause octoprint to close without errors. The reason why I never saw it popping up was because my 3D printer has a modded auto-off function that turns the whole machine off after a print, but the USB would still power the device. As soon as I changed the 3D printer to solely rely on it's own power supply, the issues started to appear even though I turned a lot of plugins off.

EDIT: I think there is a check missing if the serial is still open before sending gcode...

On mobile, so only a quick one, try this...

SSH into the machine and shut down the server from the command line (sudo service octoprint stop on OctoPi). Activate the virtual environment (OctoPi: source ~/oprint/bin/activate). Start OctoPrint from the shell (octoprint serve --debug) and then with it running like this reproduce the issue. Stop with Ctrl+C and share the output from the reproduction time. Restart the server normally (OctoPi: sudo service octoprint restart).

There might be something crashing that for some reason doesn't make its way into the log and this might unearth that.

Printing Motor_Cover.gcode failed. with_image=True with_gif=False chatID= 57069
8329
2020-05-09 12:21:37,923 - octoprint.plugins.filamentrevolutions - INFO - Filamen
t detected!
Segmentation fault

Huh, no idea then, never seen that happen. Segfault is on the python interpreter level, so more or less outside of my direct control. Not sure what could make it go boom. I suggest to try in safe mode.

I was hoping for some stack trace, this is sadly very hard to debug.

dmesg might provide more info about the segfault.

Might have found the cause...

[175317.342167] ch341 1-1.2:1.0: ch341-uart converter detected
[175317.344098] usb 1-1.2: ch341-uart converter now attached to ttyUSB0
[242801.753965] ch341-uart ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
[242801.754089] ch341-uart ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
[242801.843026] usb 1-1.2: USB disconnect, device number 10
[242801.843433] usb 1-1.2: failed to send control message: -19
[242801.843879] ch341-uart ttyUSB0: ch341-uart converter now disconnected from ttyUSB0
[242801.843957] ch341 1-1.2:1.0: device disconnected
[250937.821354] usb 1-1.2: new full-speed USB device number 11 using dwc_otg
[250937.954788] usb 1-1.2: New USB device found, idVendor=1a86, idProduct=7523, bcdDevice= 2.63
[250937.954805] usb 1-1.2: New USB device strings: Mfr=0, Product=2, SerialNumber=0
[250937.954815] usb 1-1.2: Product: USB2.0-Serial

After a lot of looking around, trying several things, I found out that the filament plugin is the culprit...

Octoprint-Filament-Revolutions & Filament-Reloaded have this issue, but there might be more out there.

https://schlierf.info/articles/2016-08-26-RPi.GPIO_SegFault/

Huh. Now that is interesting. Thanks for digging that up.

The Simple Emergency Stop also generates the error