Communication stuck

What is the problem?
On Octoprint 1.3.12, my printer fails every ~second print because of communication issues.

OctoPrint introduced detection of endless resend requests in 1.3.12, but I'm not sure if it takes the firmware setting "ignore consecutive resend requests of the same line" into account. It looks like it doesn't and thus disconnects my printer, failing the print. Also, OctoPrint reacted to every resend request by sending the line again, seemingly ignoring the firmware setting again.

From the logs of a correctly resolved communication issue it looks like it takes a little above a half second before the printer acknowledges that the line was sent successfully. During this time, the resend request flood already triggered the new feature in 13.12, disconnecting the printer.

Note: Most resend requests get resolved in a few milliseconds, I'm not sure why occasionally it takes so long. Is it normal to have ~1000 resend requests over ~ 1.6 million lines or is that too high?

What did you already try to solve it?

Changing the power source of the raspberry, changing the data cable between raspberry and arduino.
Switching firmware detection between automatic and selecting the features manually.
Next i'm trying to downgrade to 1.3.11 and look if it prints normally (it did in the past).

Logs (octoprint.log, serial.log or output on terminal tab at a minimum, browser error console if UI issue ... no logs, no support!)

Here is an example communication issue which lead to a failed print:
serial.log:

2019-12-07 10:24:36,035 - Send: N11417 G1 X204.969 Y156.610*46
2019-12-07 10:24:36,080 - Recv: T:206.10 /206 B:50.00 /50 B@:32 @:170 T0:206.10 /206 @0:170 T1:-20.00 /0 @1:0
2019-12-07 10:24:36,313 - Recv: ok 11414
2019-12-07 10:24:36,319 - Send: N11418 G1 X222.797 Y144.639*34
2019-12-07 10:24:36,326 - Recv: ok 11415
2019-12-07 10:24:39,619 - Recv: ok 11416
2019-12-07 10:24:39,634 - Recv: Error:Wrong checksum
2019-12-07 10:24:39,634 - Send: N11419 G1 X221.579 Y143.615*43
2019-12-07 10:24:39,638 - Recv: 
2019-12-07 10:24:39,645 - Send: N11420 G1 X223.135 Y141.723*41
2019-12-07 10:24:39,655 - Recv: Resend:11417
2019-12-07 10:24:39,673 - Recv: ok
2019-12-07 10:24:39,677 - Recv: 
2019-12-07 10:24:39,681 - Recv: Resend:11417
2019-12-07 10:24:39,682 - Send: N11417 G1 X204.969 Y156.610*46
2019-12-07 10:24:39,730 - Recv: ok
2019-12-07 10:24:39,734 - Recv: 
2019-12-07 10:24:39,738 - Send: N11417 G1 X204.969 Y156.610*46
2019-12-07 10:24:39,751 - Recv: Resend:11417
2019-12-07 10:24:39,768 - Recv: ok
2019-12-07 10:24:39,773 - Recv: 
2019-12-07 10:24:39,773 - Send: N11417 G1 X204.969 Y156.610*46
2019-12-07 10:24:39,775 - Recv: Resend:11417
2019-12-07 10:24:39,792 - Recv: ok
2019-12-07 10:24:39,794 - Send: N11417 G1 X204.969 Y156.610*46
2019-12-07 10:24:39,795 - Recv: T:205.76 /206 B:50.00 /50 B@:27 @:170 T0:205.76 /206 @0:170 T1:-20.00 /0 @1:0
2019-12-07 10:24:39,803 - Recv: 
2019-12-07 10:24:39,806 - Recv: Resend:11417
2019-12-07 10:24:39,808 - Recv: ok
2019-12-07 10:24:39,810 - Send: N11417 G1 X204.969 Y156.610*46
2019-12-07 10:24:39,810 - Recv: 
2019-12-07 10:24:39,813 - Recv: Resend:11417
2019-12-07 10:24:39,819 - Recv: ok
2019-12-07 10:24:39,821 - Send: N11417 G1 X204.969 Y156.610*46
2019-12-07 10:24:39,823 - Recv: 
2019-12-07 10:24:39,825 - Recv: Resend:11417
2019-12-07 10:24:39,831 - Recv: ok
2019-12-07 10:24:39,834 - Send: N11417 G1 X204.969 Y156.610*46
2019-12-07 10:24:39,836 - Recv: 
2019-12-07 10:24:39,838 - Recv: Resend:11417
2019-12-07 10:24:39,840 - Recv: ok
2019-12-07 10:24:39,842 - Send: N11417 G1 X204.969 Y156.610*46
2019-12-07 10:24:39,843 - Recv: 
2019-12-07 10:24:39,846 - Recv: Resend:11417
2019-12-07 10:24:39,849 - Recv: ok
2019-12-07 10:24:39,851 - Recv: 
2019-12-07 10:24:39,851 - Send: N11417 G1 X204.969 Y156.610*46
2019-12-07 10:24:39,853 - Recv: Resend:11417
2019-12-07 10:24:39,857 - Recv: ok
2019-12-07 10:24:39,859 - Recv: T:205.76 /206 B:50.00 /50 B@:30 @:170 T0:205.76 /206 @0:170 T1:-20.00 /0 @1:0
2019-12-07 10:24:39,866 - Send: N11417 G1 X204.969 Y156.610*46
2019-12-07 10:24:39,868 - Recv: 
2019-12-07 10:24:39,871 - Recv: Resend:11417
2019-12-07 10:24:39,872 - Printer keeps requesting line 11417 again and again, communication stuck
2019-12-07 10:24:39,875 - Changing monitoring state from "Printing" to "Error: Printer keeps requesting line 11417 again and again, communication stuck"
2019-12-07 10:24:39,884 - Send: M112
2019-12-07 10:24:39,887 - Send: N11421 M112*38
2019-12-07 10:24:39,889 - Send: N11422 M104 T0 S0*37
2019-12-07 10:24:39,908 - Send: N11423 M104 T1 S0*37
2019-12-07 10:24:39,911 - Send: N11424 M140 S0*103
2019-12-07 10:24:39,920 - Changing monitoring state from "Error: Printer keeps requesting line 11417 again and again, communication stuck" to "Offline (Error: Printer keeps requesting line 11417 again and again, communication stuck)"
2019-12-07 10:24:39,940 - Connection closed, closing down monitor

Here is the corresponding octoprint.log:

2019-12-07 10:24:39,664 - octoprint.util.comm - INFO - Got a resend request from the printer: requested line = 11417, current line = 11421
| Last lines in terminal:
| Send: :G90
| Send: N11413 G1 Z2.985 F360*47
| Recv: ok 11411
| Send: N11414 G1 X202.832 Y158.045 F3600*79
| Recv: ok 11412
| Send: N11415 G1 X202.283 Y156.053*36
| Recv: ok 11412
| Send: N11416 G1 X204.637 Y155.409*34
| Recv: ok 11413
| Send: N11417 G1 X204.969 Y156.610*46
| Recv: T:206.10 /206 B:50.00 /50 B@:32 @:170 T0:206.10 /206 @0:170 T1:-20.00 /0 @1:0
| Recv: ok 11414
| Send: N11418 G1 X222.797 Y144.639*34
| Recv: ok 11415
| Recv: ok 11416
| Send: N11419 G1 X221.579 Y143.615*43
| Recv: Error:Wrong checksum
| Recv: 
| Send: N11420 G1 X223.135 Y141.723*41
| Recv: Resend:11417
2019-12-07 10:24:39,685 - octoprint.util.comm - INFO - Got a resend request from the printer: requested line = 11417, current line = 11421
| Last lines in terminal:
| Recv: ok 11412
| Send: N11415 G1 X202.283 Y156.053*36
| Recv: ok 11412
| Send: N11416 G1 X204.637 Y155.409*34
| Recv: ok 11413
| Send: N11417 G1 X204.969 Y156.610*46
| Recv: T:206.10 /206 B:50.00 /50 B@:32 @:170 T0:206.10 /206 @0:170 T1:-20.00 /0 @1:0
| Recv: ok 11414
| Send: N11418 G1 X222.797 Y144.639*34
| Recv: ok 11415
| Recv: ok 11416
| Send: N11419 G1 X221.579 Y143.615*43
| Recv: Error:Wrong checksum
| Recv: 
| Send: N11420 G1 X223.135 Y141.723*41
| Recv: Resend:11417
| Recv: ok
| Recv: 
| Recv: Resend:11417
| Send: N11417 G1 X204.969 Y156.610*46
2019-12-07 10:24:39,753 - octoprint.util.comm - INFO - Got a resend request from the printer: requested line = 11417, current line = 11421
| Last lines in terminal:
| Recv: ok 11413
| Send: N11417 G1 X204.969 Y156.610*46
| Recv: T:206.10 /206 B:50.00 /50 B@:32 @:170 T0:206.10 /206 @0:170 T1:-20.00 /0 @1:0
| Recv: ok 11414
| Send: N11418 G1 X222.797 Y144.639*34
| Recv: ok 11415
| Recv: ok 11416
| Send: N11419 G1 X221.579 Y143.615*43
| Recv: Error:Wrong checksum
| Recv: 
| Send: N11420 G1 X223.135 Y141.723*41
| Recv: Resend:11417
| Recv: ok
| Recv: 
| Recv: Resend:11417
| Send: N11417 G1 X204.969 Y156.610*46
| Recv: ok
| Recv: 
| Send: N11417 G1 X204.969 Y156.610*46
| Recv: Resend:11417
2019-12-07 10:24:39,788 - octoprint.util.comm - INFO - Got a resend request from the printer: requested line = 11417, current line = 11421
| Last lines in terminal:
| Send: N11418 G1 X222.797 Y144.639*34
| Recv: ok 11415
| Recv: ok 11416
| Send: N11419 G1 X221.579 Y143.615*43
| Recv: Error:Wrong checksum
| Recv: 
| Send: N11420 G1 X223.135 Y141.723*41
| Recv: Resend:11417
| Recv: ok
| Recv: 
| Recv: Resend:11417
| Send: N11417 G1 X204.969 Y156.610*46
| Recv: ok
| Recv: 
| Send: N11417 G1 X204.969 Y156.610*46
| Recv: Resend:11417
| Recv: ok
| Recv: 
| Send: N11417 G1 X204.969 Y156.610*46
| Recv: Resend:11417
2019-12-07 10:24:39,873 - octoprint.util.comm - WARNING - Printer keeps requesting line 11417 again and again, communication stuck
2019-12-07 10:24:39,875 - octoprint.util.comm - INFO - Changing monitoring state from "Printing" to "Error: Printer keeps requesting line 11417 again and again, communication stuck"
2019-12-07 10:24:39,882 - octoprint.util.comm - INFO - Force-sending M112 to the printer
2019-12-07 10:24:39,921 - octoprint.util.comm - INFO - Changing monitoring state from "Error: Printer keeps requesting line 11417 again and again, communication stuck" to "Offline (Error: Printer keeps requesting line 11417 again and again, communication stuck)"
2019-12-07 10:24:40,150 - tornado.access - WARNING - 409 GET /api/printer (127.0.0.1) 24.24ms
2019-12-07 10:24:40,445 - octoprint.util.comm - INFO - Firmware didn't send an 'ok' with their resend request. That's a known bug with some firmware variants out there. Simulating an ok to continue...

The following shows a communication issue which gets resolved correctly:

2019-12-06 13:11:58,502 - Send: N33418 G1 X192.959 Y34.880 E0.1044*102
2019-12-06 13:11:59,056 - Recv: ok 33415
2019-12-06 13:11:59,061 - Send: N33419 G1 X193.609 Y35.551 E0.1272*107
2019-12-06 13:11:59,064 - Recv: X_OFFSET:0.000 Y_OFFSET:0.000 Z_OFFSET:0.000
2019-12-06 13:11:59,066 - Recv: ok 33416
2019-12-06 13:11:59,070 - Send: N33420 G1 X194.487 Y36.503 E0.1589*101
2019-12-06 13:11:59,143 - Recv: T:204.58 /206 B:50.00 /50 B@:23 @:160 T0:204.58 /206 @0:160 T1:-20.00 /0 @1:0
2019-12-06 13:11:59,252 - Recv: ok 33417
2019-12-06 13:11:59,258 - Send: N33421 G1 X196.414 Y38.661 E0.2296*111
2019-12-06 13:11:59,355 - Recv: Error:Wrong checksum
2019-12-06 13:11:59,361 - Recv: 
2019-12-06 13:12:00,791 - Recv: Resend:33418
2019-12-06 13:12:00,811 - Recv: ok
2019-12-06 13:12:00,842 - Send: N33418 G1 X192.959 Y34.880 E0.1044*102
2019-12-06 13:12:00,849 - Recv: Error:Wrong checksum
2019-12-06 13:12:00,858 - Recv: 
2019-12-06 13:12:00,865 - Recv: Resend:33418
2019-12-06 13:12:00,872 - Recv: ok
2019-12-06 13:12:00,877 - Send: N33418 G1 X192.959 Y34.880 E0.1044*102
2019-12-06 13:12:00,881 - Recv: 
2019-12-06 13:12:00,887 - Recv: Resend:33418
2019-12-06 13:12:00,892 - Recv: ok
2019-12-06 13:12:00,896 - Send: N33418 G1 X192.959 Y34.880 E0.1044*102
2019-12-06 13:12:00,898 - Recv: 
2019-12-06 13:12:00,900 - Recv: Resend:33418
2019-12-06 13:12:00,902 - Recv: ok
2019-12-06 13:12:00,904 - Send: N33418 G1 X192.959 Y34.880 E0.1044*102
2019-12-06 13:12:00,906 - Recv: 
2019-12-06 13:12:00,907 - Recv: Resend:33418
2019-12-06 13:12:00,909 - Recv: ok
2019-12-06 13:12:00,911 - Send: N33418 G1 X192.959 Y34.880 E0.1044*102
2019-12-06 13:12:00,912 - Recv: 
2019-12-06 13:12:00,914 - Recv: Resend:33418
2019-12-06 13:12:00,915 - Recv: ok
2019-12-06 13:12:00,918 - Send: N33418 G1 X192.959 Y34.880 E0.1044*102
2019-12-06 13:12:00,919 - Recv: T:204.75 /206 B:50.00 /50 B@:23 @:160 T0:204.75 /206 @0:160 T1:-20.00 /0 @1:0
2019-12-06 13:12:00,927 - Recv: 
2019-12-06 13:12:00,928 - Recv: Resend:33418
2019-12-06 13:12:00,930 - Recv: ok
2019-12-06 13:12:00,932 - Send: N33418 G1 X192.959 Y34.880 E0.1044*102
2019-12-06 13:12:00,933 - Recv: 
2019-12-06 13:12:00,934 - Recv: Resend:33418
2019-12-06 13:12:00,937 - Recv: ok
2019-12-06 13:12:00,938 - Send: N33418 G1 X192.959 Y34.880 E0.1044*102
2019-12-06 13:12:00,940 - Recv: 
2019-12-06 13:12:00,941 - Recv: Resend:33418
2019-12-06 13:12:00,943 - Recv: ok
2019-12-06 13:12:00,945 - Send: N33418 G1 X192.959 Y34.880 E0.1044*102
2019-12-06 13:12:00,947 - Recv: ok 33418
2019-12-06 13:12:00,949 - Send: N33419 G1 X193.609 Y35.551 E0.1272*107
2019-12-06 13:12:00,950 - Recv: skip 33418
2019-12-06 13:12:00,951 - Recv: ok
2019-12-06 13:12:00,953 - Send: N33420 G1 X194.487 Y36.503 E0.1589*101
2019-12-06 13:12:00,955 - Recv: skip 33418
2019-12-06 13:12:00,956 - Recv: ok
2019-12-06 13:12:00,958 - Send: N33421 G1 X196.414 Y38.661 E0.2296*111
2019-12-06 13:12:00,959 - Recv: skip 33418
2019-12-06 13:12:00,961 - Recv: ok
2019-12-06 13:12:00,964 - Send: N33422 G1 X198.385 Y40.970 E0.3038*106
2019-12-06 13:12:00,966 - Recv: skip 33418
2019-12-06 13:12:00,967 - Recv: ok
2019-12-06 13:12:00,970 - Send: N33423 G1 X199.480 Y42.302 E0.3460*108
2019-12-06 13:12:00,972 - Recv: skip 33418
2019-12-06 13:12:00,974 - Recv: ok
2019-12-06 13:12:00,977 - Send: N33424 G1 X200.510 Y43.600 E0.3865*111
2019-12-06 13:12:00,979 - Recv: skip 33418
2019-12-06 13:12:00,981 - Recv: ok
2019-12-06 13:12:00,983 - Send: N33425 G1 X201.442 Y44.831 E0.4242*106
2019-12-06 13:12:00,985 - Recv: skip 33418
2019-12-06 13:12:00,986 - Recv: ok
2019-12-06 13:12:00,989 - Send: N33426 G1 X202.056 Y45.692 E0.4501*109
2019-12-06 13:12:00,991 - Recv: skp 33418
2019-12-06 13:12:00,992 - Recv: ok
2019-12-06 13:12:00,995 - Send: N33427 G1 X202.647 Y46.570 E0.4759*105
2019-12-06 13:12:00,996 - Recv: ok 33419
2019-12-06 13:12:00,999 - Send: N33428 G1 X203.125 Y47.325 E0.4978*110
2019-12-06 13:12:01,000 - Recv: ok 33420

Additional information about your setup (OctoPrint version, OctoPi version, printer, firmware, browser, operating system, ... as much data as possible)
OctoPrint 1.3.12
OctoPi 0.14.0
Custom Printer: Arduino Due with RADDS Shield
Firmware: Repetier-Firmware 1.0.3

Hi!

I've checked the complained checksums, but they are ok.
It seems that the printer firmware calculates the checksum wrong under certain circumstances.
You may recompile the firmware and bring it to the board again.

1 Like

Could it also be an error while exchanging the data? So that the printer correctly identifies it as a broken line. It then sends multiple resend requests (because repetier-firmware does that). And somehow, every few hours, it takes up to a second before the printer receives and interprets the first resent line from octoprint - during which the resend requests triggered the new feature.
This is my interpretation of what's going on here, I'm not sure if it's correct. I'll try to reupload the firmware after printing for a few hours on 1.3.11.

By the way, how do you calculate the checksums? Is it using Fletcher's algorithm?

Here's the reprap section for checksums.

The checksum "cs" for a G-code string "cmd" (including its line number) is computed by exor-ing the bytes in the string up to and not including the * character

1 Like