octoprint/GPX loses connection with a buffer overflow

[adcurtin]

What were you doing?

1. start a print from octoprint

2. trigger p stop on the printer (e.g. run out of filament)

3. wait an hour, with the printer sending:

Recv: // echo: Waiting for unpause button on the LCD panel
Recv: // echo: Waiting for unpause button on the LCD panel
Recv:  T:227 /230 B:41 /0 T0:227 /230 T1:42 /0 @:0 B@:0
Recv: // echo: Waiting for unpause button on the LCD panel
Recv: // echo: Waiting for unpause button on the LCD panel
Recv:  T:227 /230 B:40 /0 T0:227 /230 T1:42 /0 @:0 B@:0

over and over

4. buffer overflow!

Unexpected error while reading serial port, please consult octoprint.log for details: BufferOverflow: 'Buffer overflow' @ comm.py:_readline:2605
Changing monitoring state from "Printing" to "Offline (Error: BufferOverflow: 'Buffer overflow' @ comm.py:_readline:2605)"
Connection closed, closing down monitor
Closing down send loop

What did you expect to happen?

I expected octoprint to handle this pause, or at least just sit there and wait until I got there to fix the printer

What happened instead?

octoprint disconnected after an hour

Did the same happen when running OctoPrint in safe mode?

No. GPX can't run in safe mode, so I can't connect to the printer.

Version of OctoPrint

Version 1.3.10

Operating System running OctoPrint

octopi Version 0.14.0

Printer model & used firmware incl. version

powerspec 3d pro with sailfish 7.7

Browser and version of browser, operating system running browser

n/a

Link to octoprint.log

https://pastebin.com/9Y8QEzs0

Link to contents of terminal tab or serial.log

https://pastebin.com/rAqaCgwx

I have serial.log, but don't think more than this is necessary.

Link to contents of Javascript console in the browser

n/a

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

n/a

I have read the FAQ.

I filed an issue for this in the octoprint repo as well (here: https://github.com/foosel/OctoPrint/issues/3011) , I'm not sure whether this is an octoprint issue or a GPX issue.

[me0262]

Same issue here. I have the exact same log lines where it's waiting for the unpause button while I'm doing a filament load.

I believe this is a small power surge that comes from the printer when the extruder steppers engage, and it's causing some garbage to be sent over the data line, or no data at all.

I'm going to try to find a USB power blocker since this printer tends to backflow power, especially seen on the LCD when moving the carriage or plate by hand when the unit is off.

Workflow: Cura 5.4.0 Modern Linux AppImage OctoPrint 1.9.2 / Python 3.9.2 / OctoPi* 1.0.0 (build 2023.07.20.144556) (new-camera-stack) / GPX 2.6.8 PowerSpec 3D X (Flashforge Creator / Makerbot clone) / Sailfish 7.7

Terminal output:

Recv:  T:206 /210 B:58 /0 T0:45 /0 T1:206 /210 @:0 B@:0
Recv: // echo: Waiting for unpause button on the LCD panel
Recv: // echo: Waiting for unpause button on the LCD panel
Recv:  T:207 /210 B:58 /0 T0:45 /0 T1:207 /210 @:0 B@:0
Unexpected error while reading serial port, please consult octoprint.log for details: BufferOverflow: 'Buffer overflow' @ comm.py:_readline:4081
Changing monitoring state from "Printing" to "Offline after error"
Connection closed, closing down monitor
Changing monitoring state from "Offline" to "Opening serial connection"
Changing monitoring state from "Opening serial connection" to "Connecting"
Connected to: <octoprint_GPX.gpxprinter.GpxPrinter object at 0x68f72a48>, starting monitor
Recv: start
Send: N0 M110 N0*125
Recv:  Sailfish v7.7
Send: N0 M110 N0*125
Recv: echo: gcode to x3g translation by GPX
Recv: SD init fail
Recv:  T:45 /0 B:51 /0 T0:45 /0 T1:161 /0 @:0 B@:0
Recv:  T:45 /0 B:51 /0 T0:45 /0 T1:161 /0 @:0 B@:0
Recv: ok
Send: N0 M110 N0*125
Changing monitoring state from "Connecting" to "Operational"
Recv: ok
Send: N0 M110 N0*125
Recv: ok
Send: N1 M115*39
Recv: ok PROTOCOL_VERSION:0.1 FIRMWARE_NAME:Sailfish FIRMWARE_VERSION:7.7 FIRMWARE_URL:http://www.sailfishfirmware.com MACHINE_TYPE:r1d EXTRUDER_COUNT:2
Recv: Cap:EMERGENCY_PARSER:1
Send: M21
Recv: ok

Traceback:

2023-09-28 20:11:05,929 - octoprint.server.heartbeat - INFO - Server heartbeat <3
2023-09-28 20:12:32,119 - octoprint.util.comm - INFO - Externally triggered heatup detected
2023-09-28 20:13:55,753 - octoprint.util.comm - ERROR - Unexpected error while reading from serial port
Traceback (most recent call last):
  File "/home/me262/oprint/lib/python3.9/site-packages/octoprint_GPX/gpxprinter.py", line 181, in readline_str
    return self.outgoing.get(timeout=timeout)
  File "/usr/lib/python3.9/queue.py", line 179, in get
    raise Empty
_queue.Empty

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/me262/oprint/lib/python3.9/site-packages/octoprint/util/comm.py", line 4081, in _readline
    ret = self._serial.readline()
  File "/home/me262/oprint/lib/python3.9/site-packages/octoprint_GPX/gpxprinter.py", line 190, in readline
    return self.readline_str().encode('ascii', errors='ignore')
  File "/home/me262/oprint/lib/python3.9/site-packages/octoprint_GPX/gpxprinter.py", line 183, in readline_str
    self._append(gpx.readnext())
gpx.BufferOverflow: Buffer overflow
2023-09-28 20:13:55,800 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Offline after error"
2023-09-28 20:13:55,843 - octoprint.server - INFO - Starting autorefresh of serial port list
2023-09-28 20:13:55,857 - octoprint.plugins.action_command_notification - INFO - Notifications cleared
2023-09-28 20:19:19,529 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Opening serial connection"
2023-09-28 20:19:19,742 - octoprint.plugins.GPX - INFO - [a]

It also looks like this will invariably cause a gpx.Timeout: Timeout error with the exact same traceback.