OctoPrint randomly changes from "Printing" to "Offline"

[worgarside]

I've been having problems with my Prusa i3 stopping randomly part way through prints recently when printing through OctoPrint. Overnight it went from printing perfectly running multiple plugins (including recording via Octolapse) to crashing partway through a print. I've tried disabling all plugins - I did keep Octolapse but I wasn't using it - and rebooting etc. but it's happened upwards of a dozen times now. When I print directly from the SD card the prints come out fine.

For the last print this happened on, the only plugins installed were Octolapse (not recording though, camera not even connected) and Pusbullet. It stopped after literally 3 minutes of the first layer. Nothing else is running on the pi - I feel like I've tried everything I can think of short of reinstalling OctoPi and starting from scratch.

What were you doing?

1. Uploaded a print to the local storage
2. Set it to print
3. Waited for it to finish

What did you expect to happen?

For the print to finish

What happened instead?

OctoPrint changed from "Printing" to "Offline"

Did the same happen when running OctoPrint in safe mode?

Currently testing in safe mode. Will update accordingly.

Have tested in safe mode, the same error occurred. The print head abruptly stopped moving after ~50 minutes but the heating remained on. I have attached a photo of this instance at the end.

Version of OctoPrint

1.3.10

Operating System running OctoPrint

OctoPi 0.15.1

Printer model & used firmware incl. version

Genuine Prusa i3 Mk3 running Prusa-Firmware 3.4.1

Browser and version of browser, operating system running browser

Chrome v71 on Windows 10

Link to octoprint.log

Original log:
https://gist.github.com/worgarside/730f1b650feba984267b31bb76302cd6

The print was started at 2019-02-09 08:57:27,818 (right at the bottom of the log)

Safe Mode log:
https://gist.github.com/worgarside/d14c3c6c4ce97233498fe19a9be07b90
I've removed the part of this log that was included in the previous one for simplicity's sake. The first line of this log is the last line of the previous to show continuity.

Link to contents of terminal tab or serial.log

Unfortunately no terminal output captured.

Link to contents of Javascript console in the browser

Nothing to report here. Have attached it for the sake of it though:

packed_core.js?b0051d71:12677 ... dependency resolution done
packed_core.js?b0051d71:12981 Initial application setup done, connecting to server...
packed_core.js?b0051d71:10717 Connected to the server
packed_core.js?b0051d71:10687 Safe mode is active. Third party plugins are disabled and cannot be enabled.
packed_core.js?b0051d71:12959 Finalizing application startup
packed_core.js?b0051d71:12843 Going to bind 27 view models...
packed_core.js?b0051d71:12896 Did not bind view model SoftwareUpdateViewModel to target #softwareupdate_confirmation_dialog since it does not exist
packed_core.js?b0051d71:12896 Did not bind view model SoftwareUpdateViewModel to target #wizard_plugin_softwareupdate since it does not exist
packed_core.js?b0051d71:2443 User worgarside logged in
packed_core.js?b0051d71:12935 ... binding done
packed_core.js?b0051d71:12955 Application startup complete

Screenshot(s)/video(s) showing the problem:

This was after the safe mode test

https://photos.app.goo.gl/g9awg2q1sDqs9GPh8

This was ~15-20 mins after the crash. I manually raised the print head and the hot end and bed were both still being heated.

I have read the FAQ.

[worgarside]

As a secondary test, I've uploaded a G-code file to the SD card via the OctoPrint web interface and printed it without issue. This leads me to believe it could be a comms issue between the Pi and the printer? I've tried to connect via USB cable instead but get the following after ~10s so haven't been unable to progress any further down that avenue.

Communication timeout while idle, trying to trigger response from printer. Configure long running commands or increase communication timeout if that happens regularly on specific commands or long moves.

I'm also unable to control anything while OctoPrint does say it's connected.

[foosel]

I fear in order to be able to analyse this I'll really need a serial.log or at the very least the terminal output. Please enable serial logging, reproduce the issue, then provide the resulting log.

[worgarside]

I've just run it again (with a different G-code) and the Serial logging turned on. I've attached the G-code, hopefully that might help. Unfortunately the terminal output for this one didn't autoscroll and has buffered/hidden the rest of the output.

I did manage to get the serial log though, so I've attached that too.

G-code: https://gist.github.com/worgarside/2070626a5a0e6c5450f300d852daef9e

Serial log: https://gist.github.com/worgarside/0448b5b48dcd5b186d7d72d8f20dc958

[worgarside]

I thought it might've been a hardware problem, so I tried a few different things:

• A different Pi (Pi 3B+, same microSD card)
• Changing the jumper cables between the Pi and the printer
• Using the USB cable that came with the printer
• Using a different USB cable

but the error still occurs on all of these.

My next attempt was to install OctoPrint onto Raspbian rather than using OctoPi, but I couldn't get the Pi to see the printer serial port. (I checked the user groups etc. and ran ls -l /dev to see if it changed when the printer was plugged in). I haven't gotten any further with this.

I'm going to wipe my microSD card tonight and put a fresh OctoPi onto it and see if that helps at all.

[foosel]

Uhm... I do not see a "random switch to Offline" in that serial.log. According to the log the print was happily progressing.

[worgarside]

The preview on GitHub is truncated, not sure if you viewed the full raw file or not - the switch off is at 2019-02-09 16:00:02,977:

2019-02-09 15:59:57,541 - Send: N19010 G1 E-0.04000 F2100.00000*56
2019-02-09 15:59:58,294 - Recv: ok
2019-02-09 15:59:58,306 - Send: N19011 G1 Z2.000 F10800.000*55
2019-02-09 15:59:58,330 - Recv: ok
2019-02-09 15:59:58,335 - Send: N19012 G1 X96.782 Y64.134*36
2019-02-09 15:59:59,197 - Recv: ok
2019-02-09 15:59:59,202 - Send: N19013 G1 Z1.400*115
2019-02-09 16:00:00,051 - Recv: ok
2019-02-09 16:00:00,056 - Send: N19014 G1 E0.80000 F2100.00000*29
2019-02-09 16:00:00,915 - Recv: ok
2019-02-09 16:00:00,926 - Send: N19015 M105*43
2019-02-09 16:00:00,936 - Recv: ok T:210.1 /210.0 B:60.1 /60.0 T0:210.1 /210.0 @:87 B@:21 P:37.0 A:40.2
2019-02-09 16:00:00,945 - Send: N19016 M204 S1250*95
2019-02-09 16:00:00,950 - Recv: ok
2019-02-09 16:00:00,955 - Send: N19017 G1 F11054.3*108
2019-02-09 16:00:01,773 - Recv: ok
2019-02-09 16:00:01,778 - Send: N19018 G1 X97.479 Y63.437 E0.03334*101
2019-02-09 16:00:01,788 - Recv: ok
2019-02-09 16:00:01,792 - Send: N19019 G1 X98.363 Y63.437 E0.02991*99
2019-02-09 16:00:02,631 - Recv: ok
2019-02-09 16:00:02,643 - Send: N19020 G1 X98.363 Y78.537 E0.51112*103
2019-02-09 16:00:02,959 - Connection closed, closing down monitor
2019-02-09 16:00:02,977 - Changing monitoring state from "Printing" to "Offline"
2019-02-09 16:00:03,072 - Changing monitoring state from "Offline" to "Detecting serial port"
2019-02-09 16:00:03,122 - Serial port list: ['/dev/ttyAMA0']
2019-02-09 16:00:03,122 - Connecting to: /dev/ttyAMA0
2019-02-09 16:00:03,134 - Changing monitoring state from "Detecting serial port" to "Opening serial port"
2019-02-09 16:00:03,144 - Connected to: Serial<id=0x6df68650, open=True>(port='/dev/ttyAMA0', baudrate=115200, bytesize=8, parity='N', stopbits=1, timeout=10.0, xonxoff=False, rtscts=False, dsrdtr=False), starting monitor
2019-02-09 16:00:03,165 - Starting baud rate detection...
2019-02-09 16:00:03,169 - Changing monitoring state from "Opening serial port" to "Detecting baudrate"
2019-02-09 16:00:04,175 - Trying baudrate: 115200
2019-02-09 16:00:04,186 - Recv: ok
2019-02-09 16:00:04,191 - Send: N0 M110 N0*125
2019-02-09 16:00:04,198 - Changing monitoring state from "Detecting baudrate" to "Operational"
2019-02-09 16:00:04,215 - Send: N0 M110 N0*125
2019-02-09 16:00:04,225 - Recv: ok
2019-02-09 16:00:04,227 - Recv: ok
2019-02-09 16:00:04,231 - Send: N1 M115*39
2019-02-09 16:00:04,238 - Send: N2 M21*18
2019-02-09 16:00:04,256 - Recv: FIRMWARE_NAME:Prusa-Firmware 3.4.1 based on Marlin FIRMWARE_URL:https://github.com/prusa3d/Prusa-Firmware PROTOCOL_VERSION:1.0 MACHINE_TYPE:Prusa i3 MK3 EXTRUDER_COUNT:1 UUID:00000000-0000-0000-0000-000000000000
2019-02-09 16:00:04,263 - Recv: ok
2019-02-09 16:00:04,269 - Recv: echo:SD card ok
2019-02-09 16:00:04,287 - Send: M20
2019-02-09 16:00:04,695 - Recv: ok
2019-02-09 16:00:04,697 - Recv: Begin file list
2019-02-09 16:00:04,711 - Recv: PICAME~1.GCO 6599769
2019-02-09 16:00:04,713 - Recv: PICAME~2.GCO 6056957
2019-02-09 16:00:04,718 - Recv: XAXISB~1.GCO 9606581
2019-02-09 16:00:04,720 - Recv: THUMB_~1.GCO 8058644
2019-02-09 16:00:04,721 - Recv: End file list
2019-02-09 16:00:04,724 - Recv: ok
2019-02-09 16:00:09,199 - Send: M105
2019-02-09 16:00:09,210 - Recv: ok T:209.8 /210.0 B:60.2 /60.0 T0:209.8 /210.0 @:90 B@:12 P:36.9 A:40.3
2019-02-09 16:00:12,708 - Recv: fsensor_autoload_check_start - autoload ENABLED
2019-02-09 16:00:12,714 - Recv: 
2019-02-09 16:00:14,200 - Send: M105
2019-02-09 16:00:14,210 - Recv: ok T:209.6 /210.0 B:59.9 /60.0 T0:209.6 /210.0 @:92 B@:68 P:37.0 A:40.2
2019-02-09 16:00:15,542 - Recv: fsensor_autoload_check_stop - autoload DISABLED
2019-02-09 16:00:15,551 - Recv: 
2019-02-09 16:00:16,202 - Send: M105
2019-02-09 16:00:16,210 - Recv: ok T:209.7 /210.0 B:59.9 /60.0 T0:209.7 /210.0 @:90 B@:59 P:36.9 A:40.4
2019-02-09 16:00:18,203 - Send: M105
2019-02-09 16:00:18,213 - Recv: ok T:210.6 /210.0 B:59.7 /60.0 T0:210.6 /210.0 @:75 B@:80 P:37.1 A:40.4
2019-02-09 16:00:18,221 - Recv: fsensor_autoload_check_start - autoload ENABLED
2019-02-09 16:00:18,222 - Recv: 
2019-02-09 16:00:18,790 - Recv: fsensor_autoload_check_stop - autoload DISABLED
2019-02-09 16:00:18,793 - Recv: 
2019-02-09 16:00:19,882 - Recv: fsensor_autoload_check_start - autoload ENABLED
2019-02-09 16:00:19,891 - Recv: 
2019-02-09 16:00:20,206 - Send: M105
2019-02-09 16:00:20,214 - Recv: ok T:212.2 /210.0 B:59.9 /60.0 T0:212.2 /210.0 @:52 B@:48 P:37.0 A:40.2
2019-02-09 16:00:20,454 - Recv: fsensor_autoload_check_stop - autoload DISABLED
2019-02-09 16:00:20,458 - Recv: 
2019-02-09 16:00:20,533 - Recv: fsensor_autoload_check_start - autoload ENABLED
2019-02-09 16:00:20,535 - Recv: 
2019-02-09 16:00:20,566 - Recv: fsensor_autoload_check_stop - autoload DISABLED
2019-02-09 16:00:20,568 - Recv: 
2019-02-09 16:00:20,644 - Recv: fsensor_autoload_check_start - autoload ENABLED
2019-02-09 16:00:20,646 - Recv: 
2019-02-09 16:00:20,679 - Recv: fsensor_autoload_check_stop - autoload DISABLED
2019-02-09 16:00:20,681 - Recv: 
2019-02-09 16:00:22,208 - Send: M105
2019-02-09 16:00:22,218 - Recv: ok T:213.1 /210.0 B:60.0 /60.0 T0:213.1 /210.0 @:41 B@:34 P:37.1 A:40.4
2019-02-09 16:00:24,027 - Recv: fsensor_autoload_check_start - autoload ENABLED
2019-02-09 16:00:24,031 - Recv: 
2019-02-09 16:00:24,211 - Send: M105
2019-02-09 16:00:24,220 - Recv: ok T:214.3 /210.0 B:60.0 /60.0 T0:214.3 /210.0 @:27 B@:26 P:37.2 A:40.5
2019-02-09 16:00:26,213 - Send: M105
2019-02-09 16:00:26,222 - Recv: ok T:214.6 /210.0 B:60.1 /60.0 T0:214.6 /210.0 @:25 B@:23 P:37.0 A:40.5
2019-02-09 16:00:28,216 - Send: M105
2019-02-09 16:00:28,228 - Recv: ok T:213.9 /210.0 B:60.1 /60.0 T0:213.9 /210.0 @:38 B@:19 P:37.0 A:40.4
2019-02-09 16:00:30,218 - Send: M105
2019-02-09 16:00:30,230 - Recv: ok T:213.0 /210.0 B:60.1 /60.0 T0:213.0 /210.0 @:52 B@:18 P:36.9 A:40.3
2019-02-09 16:00:32,220 - Send: M105
2019-02-09 16:00:32,230 - Recv: ok T:212.1 /210.0 B:60.2 /60.0 T0:212.1 /210.0 @:62 B@:15 P:36.8 A:40.5
2019-02-09 16:00:34,223 - Send: M105
2019-02-09 16:00:34,233 - Recv: ok T:211.5 /210.0 B:60.2 /60.0 T0:211.5 /210.0 @:69 B@:17 P:36.9 A:40.4
2019-02-09 16:00:36,224 - Send: M105
2019-02-09 16:00:36,234 - Recv: ok T:210.6 /210.0 B:60.1 /60.0 T0:210.6 /210.0 @:77 B@:26 P:36.8 A:40.5
2019-02-09 16:00:38,227 - Send: M105
2019-02-09 16:00:38,237 - Recv: ok T:210.9 /210.0 B:60.0 /60.0 T0:210.9 /210.0 @:68 B@:54 P:36.8 A:40.4```

[foosel]

Argh, I overlooked that it was truncated. Thanks for the heads-up.

Yeah, so, that looks like someone had called "disconnect" and then "connect" right away. Do you use any third party applications with OctoPrint that could be causing this? I suggest to set the tornado.access logger to INFO level (Settings > Logging > Logging Levels) to enable request logging so we can see if this is being caused by a call on the API (e.g. the web interface or a third party client) or something internal. Also set octoprint.util.comm to DEBUG to get some additional log entries that might (or might not) help.

[worgarside]

Oh!!! So I noticed that when the Pi started up, it was never automatically connected to the printer (despite having the box checked). I actually saw this issue with OctoPi earlier which might solve it anyway.

However - my solution was to cron a simple Python script that would ping /api/connection on the Pi to make sure it was connected every hour! The disconnection in the serial log is 2 seconds past the hour - do you think it could be this?? Maybe pinging /api/connection forces a re-connection rather than simply ensuring it's connected, as I'd hoped.

Might seem like a weird thing to cron, but I have been logging temps etc. with Home Assistant and I hated having empty gaps when the printer wasn't connected.

I'm going to turn off the cron, then leave it on a test an see whether it prints the full thing, will report back later.

[foosel]

Maybe pinging /api/connection forces a re-connection rather than simply ensuring it's connected, as I'd hoped.

That depends on what exactly you've done with "pinging" it. If you are just calling GET, it shouldn't be causing this. If you are POSTing the connect command, well, there's the reason for your sudden reconnects.

[worgarside]

Yes, I'm POSTing it :( I can't believe I've wasted this much time, I'm so sorry! I didn't realise that POSTing it would cause it to disconnect.

I'm fairly new to world of APIs - just so I'm clear, the reconnection part of POST /api/connect isn't mentioned in the docs: is this something I should've known instinctively?

[worgarside]

I ran a 6 hour print overnight last night and it completed (with all previous plugins inc. Octolpase) just fine :) Happy to close this issue now @foosel if you want :)

[foosel]

I can't believe I've wasted this much time, I'm so sorry! I didn't realise that POSTing it would cause it to disconnect.

Don't worry about it, just glad this is solved. :)

just so I'm clear, the reconnection part of POST /api/connect isn't mentioned in the docs: is this something I should've known instinctively?

No, this is something that definitely should have been documented, which I have done in the above commit. Already live here: http://docs.octoprint.org/en/master/api/connection.html#issue-a-connection-command

Happy to close this issue now @foosel if you want :)

Happily closing :D