Octoprint Not Honoring Resend

[dornadigital]

What is the problem?

I've been having repeated issues with my Ender 3 and Octopi. From what remnants of the log I have, it looks like first there's a series of Unknown command errors, possibly indicating a communication error. Then the printer sends a 'Resend' request, and Octoprint honors this a few times, but then ignores future resends and keeps sending the subsequent lines. This eventually leads to an error, as Octoprint recognizes that numerous resend requests have occurred, but does not ever resend.

My initial impulse is that the line following the Recv: Resend: should be the resend, but I admit that I am unfamiliar with much of the communication protocol.

I'm concerned about the Unknown command errors, and will continue to try different cables and find a new power supply unless somebody has another idea. I'm also concerned about Octoprint seemingly giving up on resends after a certain point.

resend error.log (12.7 KB)

This happens rather consistently, at different stages of the same gcode.

What did you already try to solve it?

Tried different projects to see if something was wrong with the gcode.
Swapped data cable.
Looked into swapping the power cable/supply, but the other supply I found was .1V too few, and I got warnings about under-voltage.

Have you tried running in safe mode?

I have.

Did running in safe mode solve the problem?

It did not. Seems to be the same behavior.

Systeminfo Bundle

octoprint-systeminfo-20221219142844.zip (590.5 KB)

Additional information about your setup

OctoPrint version, OctoPi version, printer, firmware, browser, operating system, ... as much data as possible

octoprint.version : 1.8.6
env.plugins.pi_support.octopi_version : 0.18.0
Octopi running on Raspberry Pi 3
Printer: Ender 3 Pro with updated motherboard.

I haven't made any adjustments to my setup in some time.

[Ewald_Ikemann]

Hello @dornadigital !

The reason is, that the printer receives rubbish.

like here

Send: N27414 G1 X94.022 Y149.623 E1092.6971*83
Recv: echo:Unknown command: "éû\x84J#Þ]}G\x99U@]\x0eæ\x02!> 8	Ur]utÐQÇðª1ª\x83\x9dâ®\x97Í°ö\x05\x05ný\x8d\x9d\x1e}Ú\x8aù¬\x99P]LÉ0\x9e \x9dY@\x9dW\x185¢\x1c\x1a¦«\x8d?\x04¶!W\x0cS\x05±\x9aÑ-ǯØ\x8e"

or here

Send: N27411 G1 F1500 X104.022 Y149.699 E1092.46419*58
Recv: echo:Unknown command: "\x9d\x14Þ¨¶¢å¸#9V\x19\x11\x91l¦\x93Z\x86I\x01Ñ\x94KD\x97ìj\x82¡ÎËò®·T\x9a!\x15[ S¶ø2Êôz¢¹PQ\x15\x83Ä\x8c@3â\x88t¦·¨\x99-\x9bÜUÝ\x979~:\x8aâ\xff\x18\x16µ\x1e9æ\x8b\x0eø\x88\x19!#\x81qû\x9dß"

The reason for that is a bad USB connection.

You may have a look on this thread:

Ender 3 V2 / Pi3b+ or Pi4 : lot of "unknown commmand" and UTF8 chars (Electro Magnetic Interferences)

What is the problem? Lot of messages "Recv:echo:Unknown Command" with UTF-8 chars Overall quality of my print are bad, compared to prints ran from SD Card. One of my print stopped, the printed kept requesting a re-send of a line, communication was stuck. One of my print became crazy, rolled back the extruded at a very high speed, retracting all the filament. The serial.log shows a strange behaviour : printer and Octoprint are sending and receiving at the same time. What did you already try …

[dornadigital]

Yeah, I'll certainly keep trying different usb cables, and investigate the mainboard if need-be. Doesn't explain the way Octoprint ignores the resend commands, which makes me think something else is going on.

[Ewald_Ikemann]

Octoprint resends:

Send: N27417 G1 X91.973 Y148.528 E1092.75189*106
Recv: Error:checksum mismatch, Last Line: 27410
Recv: Resend: 27411
Recv: ok
Send: N27411 G1 F1500 X104.022 Y149.699 E1092.46419*58
Recv: echo:Unknown command: "\x9d\x14Þ¨¶¢å¸#9V\x19\x11\x91l¦\x93Z\x86I\x01Ñ\x94KD\x97ìj\x82¡ÎËò®·T\x9a!\x15[ S¶ø2Êôz¢¹PQ\x15\x83Ä\x8c@3â\x88t¦·¨\x99-\x9bÜUÝ\x979~:\x8aâ\xff\x18\x16µ\x1e9æ\x8b\x0eø\x88\x19!#\x81qû\x9dß"

That there other linenubers (27412 to 27417) is because of the input buffer of the printer.

So resending makes no sense as long the printer receives rubbish. The resend will go on until OctoPirnt cancels the connection:

Printer keeps requesting line 27411 again and again, communication stuck
Changing monitoring state from "Printing" to "Error"

[dornadigital]

I understand the reason for the cancellation. I'm still confused regarding why lines 27413 to 27417 appear.

Would it be correct to say that the output in this log is not an accurate representation of the order of operations? I was reading this log as a representation of chronological order, which states:

Octoprint sends 412
Printer sends request for 411
Octoprint sends 413

With your suggestion of buffering, it sounds like what you're saying happens is:

Octoprint sends 411, 412, 413, 414, and 415 as a group
Printer can't read 411, attempts to process 412, sends request for 411
Octoprint sends 411, 412, 413, 414, and 415 as a group

[Charlie_Powell]

The root of the issue is that there is so much garbage on the connection that it is impossible to recover.

The log is completely chronological, and OctoPrint only sends one gcode at a time. With this section:

Send: N27412 G1 X103.27 Y149.699 E1092.4817*93
Recv: echo:Unknown command: ".699 E1092.4817"
Recv: ok
Send: N27413 G1 X94.798 Y149.699 E1092.67895*111
Recv: echo:Unknown command: "9.699 E1092.67895"
Recv: ok
Send: N27414 G1 X94.022 Y149.623 E1092.6971*83
Recv: echo:Unknown command: "éû\x84J#Þ]}G\x99U@]\x0eæ\x02!> 8	Ur]utÐQÇðª1ª\x83\x9dâ®\x97Í°ö\x05\x05ný\x8d\x9d\x1e}Ú\x8aù¬\x99P]LÉ0\x9e \x9dY@\x9dW\x185¢\x1c\x1a¦«\x8d?\x04¶!W\x0cS\x05±\x9aÑ-ǯØ\x8e"
Recv: ok
Send: N27415 G1 X93.272 Y149.396 E1092.71535*101
Recv: echo:Unknown command: "148.528 E1092.75189"
Recv: ok
Send: N27416 G1 X92.58 Y149.025 E1092.73363*81
Recv: echo:Unknown command: "¸DÑ[4G5||U"
Recv: ok
Send: N27417 G1 X91.973 Y148.528 E1092.75189*106
Recv: Error:checksum mismatch, Last Line: 27410
Recv: Resend: 27411
Recv: ok
Send: N27411 G1 F1500 X104.022 Y149.699 E1092.46419*58
Recv: echo:Unknown command: "\x9d\x14Þ¨¶¢å¸#9V\x19\x11\x91l¦\x93Z\x86I\x01Ñ\x94KD\x97ìj\x82¡ÎËò®·T\x9a!\x15[ S¶ø2Êôz¢¹PQ\x15\x83Ä\x8c@3â\x88t¦·¨\x99-\x9bÜUÝ\x979~:\x8aâ\xff\x18\x16µ\x1e9æ\x8b\x0eø\x88\x19!#\x81qû\x9dß"
Recv: ok

Part of the issue here is that it doesn't look like the printer received enough information from lines 27412 to 27417 to determine that the lines were being sent corrupted. Line numbers and checksums are actually optional in many firmwares and they are only checked when it can tell that one has been sent. When it finally is able to read enough of a line again (27417) it realises that lines have been missed and asks for 27411 again. Yet there is still so much crap being received that it just processes it with an unknown command & sends 'ok' (a blatant lie...)

OctoPrint is doing exactly what the printer asked it to here, it's resending the lines that it was asked to resend, which are met with an OK - so it moves on to the next line. Just so many communication errors that are not recoverable.

You are still using Creality's firmware on your printer that has known bugs already, so don't be surprised if the resending logic is equally broken. You already need a plugin to work around malformed temperature reporting. If you can, try updating the firmware, but even firmware likely won't fix the severe communication issues.

[dornadigital]

As I said, I understand that the error state is caused by communication issues.

I already have the plugin for temperature message. This log is from a safe-mode run.

If the log is fully chronological, then Octoprint is NOT resending the lines that it was asked to resend:
Send: N27411 G1 F1500 X104.022 Y149.699 E1092.4641958
Recv: echo:Unknown command: "ß± .þSÔ\x80\x9aC\x19X\x12\x02Ë\x88\x8a¢\x04¾\x86ÑG\xff\x16}]K\x92ôîºâz¬>UPÜ\x97×Ñ\x87\x11Ã4"
Recv: ok
Send: N27412 G1 X103.27 Y149.699 E1092.481793
Recv: echo:Unknown command: "\x98dXä"
Recv: ok
Send: N27413 G1 X94.798 Y149.699 E1092.67895111
Recv: Error:Line Number is not Last Line Number+1, Last Line: 27410
Recv: Resend: 27411
Recv: ok
Recv: echo:Unknown command: "×\x14\x97"
Recv: ok
Send: N27414 G1 X94.022 Y149.623 E1092.697183
Recv: echo:Unknown command: "Y146.479 E1092.80668"
Recv: ok
Send: N27415 G1 X93.272 Y149.396 E1092.71535101
Recv: Error:Line Number is not Last Line Number+1, Last Line: 27410
Recv: Resend: 27411
Recv: ok
Send: N27416 G1 X92.58 Y149.025 E1092.7336381
Recv: echo:Unknown command: "ï\x9e¶\x8dt[ðië\x1b\x95oê=ë\x9cs\x13\x1cxâ\x7f\x8f ÂÂyÎ HÞÀ\x17\x1b|DpÏÇ\x88È{\x8a¢ê¯e¼"
Recv: ok
Send: N27417 G1 X91.973 Y148.528 E1092.75189106
Recv: echo:Unknown command: "27412 G1 X103.27 Y149.699 E1092.4817"
Recv: ok
Send: N27418 G1 X91.476 Y147.921 E1092.7701698
Recv: Error:Line Number is not Last Line Number+1, Last Line: 27410
Recv: Resend: 27411
Recv: ok
Recv: echo:Unknown command: "Єh"
Recv: ok
Send: N27419 G1 X91.105 Y147.229 E1092.7884497
Recv: echo:Unknown command: "22 Y149.623 E1092.6971"
Recv: ok
Send: N27420 G1 X90.878 Y146.479 E1092.80668108
Recv: Error:Line Number is not Last Line Number+1, Last Line: 27410
Recv: Resend: 27411

Note how even though the printer sent Resend: 27411, Octoprint sent lines 27412 through 27420. I see this pattern repeated numerous times throughout the log.

I have not updated firmware or adjusted settings, and the failure rate is 100% even though I've never seen this error before. I do not believe it is the firmware. I will continue to try different cables, but the odd behavior from Octoprint concerns me.

[Charlie_Powell]

I will admit that I hadn't looked into the log further than the first couple of communication errors, perhaps assuming it was more of the same.

I understand what you are saying better now - and am kind of wondering the same thing, why OctoPrint seemingly ignores the resend requests. It doesn't do it all the time, but maybe about 2/3rds of the time.

@dornadigital

If the log is fully chronological, then Octoprint is NOT resending the lines that it was asked to resend:

I'll agree with that.

Looking at the octoprint.log & matching it up, it provides an explanation:

2022-12-19 10:55:52,919 - octoprint.util.comm - INFO - Ignoring resend request for line 27411, that still originates from lines we sent before we got the first resend request

If you could enable serial.log now, that might be helpful to capture the full extent of the log. It would show the full communication, timestamped, so we could get the complete picture.

I am not sure if the explanation from the log fully satisfies me - the line does not originate from 'before the first resend request'. I suspect there could be a catch with handling repeated resend requests in the communication layer somewhere, and I'm not quite familiar with the logic there. Either way, you won't get good results printing, so still look into fixing the interference

[Ewald_Ikemann]

Lets have a look on this sequence from the octoprint.log:

2022-12-18 20:07:26,162 - octoprint.util.comm - INFO - Got a resend request from the printer: requested line = 145443, current line = 145462
| Last lines in terminal:
| Recv: echo:Unknown command: ""
| Recv: ok
| Send: N145456 G0 X108.689 Y83.924*37
| Recv: echo:Unknown command: ""
| Recv: ok
| Send: N145457 G1 F2400 E3471.67868*3
| Recv: echo:Unknown command: ""
| Recv: ok
| Send: N145458 G0 F12000 X108.248 Y83.924*119
| Recv: echo:Unknown command: ""
| Recv: ok
| Send: N145459 G1 F1500 X102.762 Y78.437 E3471.85933*50
| Recv: echo:Unknown command: ""
| Recv: ok
| Send: N145460 G0 F12000 X102.762 Y79.003*114
| Recv: echo:Unknown command: ""
| Recv: ok
| Send: N145461 G1 F1500 X108.248 Y84.49 E3472.03998*12
| Recv: Error:checksum mismatch, Last Line: 145442
| Recv: Resend: 145443
2022-12-18 20:07:26,209 - octoprint.util.comm - INFO - Got a resend request from the printer: requested line = 145443, current line = 145462
| Last lines in terminal:
| Recv: echo:Unknown command: ""
| Send: N145450 G1 F1500 X108.248 Y83.358 E3471.66453*48
| Recv: ok
| Recv: echo:Unknown command: ""
| Recv: ok
| Recv: echo:Unknown command: ""
| Send: N145451 G0 F12000 X108.248 Y82.793*125
| Recv: ok
| Recv: echo:Unknown command: ""
| Recv: ok
| Recv: echo:Unknown command: ""
| Send: N145452 G1 F1500 X107.818 Y82.363 E3471.67868*62
| Recv: ok
| Recv: echo:Unknown command: ""
| Recv: ok
| Send: N145453 G1 F2400 E3466.67868*1
| Recv: echo:Unknown command: ""
| Recv: ok
| Recv: Error:Line Number is not Last Line Number+1, Last Line: 145442
| Recv: Resend: 145443
2022-12-18 20:07:26,249 - octoprint.util.comm - INFO - Got a resend request from the printer: requested line = 145443, current line = 145462
| Last lines in terminal:
| Send: N145444 G1 F1500 X106.838 Y80.817 E3471.36334*54
| Recv: echo:Unknown command: ""
| Recv: ok
| Recv: echo:Unknown command: ""
| Recv: ok
| Recv: echo:Unknown command: ""
| Recv: ok
| Send: N145445 G0 F12000 X106.838 Y81.383*125
| Recv: echo:Unknown command: ""
| Recv: ok
| Recv: echo:Unknown command: ""
| Recv: ok
| Send: N145446 G1 F1500 X102.762 Y77.306 E3471.49756*59
| Recv: echo:Unknown command: ""
| Recv: ok
| Recv: echo:Unknown command: ""
| Recv: ok
| Send: N145447 G0 F12000 X102.762 Y77.872*119
| Recv: Error:checksum mismatch, Last Line: 145442
| Recv: Resend: 145443
2022-12-18 20:07:26,262 - octoprint.util.comm - INFO - Ignoring resend request for line 145443, that still originates from lines we sent before we got the first resend request
2022-12-18 20:07:26,272 - octoprint.util.comm - INFO - Ignoring resend request for line 145443, that still originates from lines we sent before we got the first resend request

OctoPrint send it's lines: 145456, 145457, ... 145460.
All lines are ok.

And suddenly the firmware requests a line from the "past": 145443.
Obviously OctoPrint resent that line because the next section Last lines in terminal starts with line 145450.
After this then again (Line 145444)

Keep in mind, that the ok does not include a syntax check of the received line. It's the ok for the next line: G-code - RepRap

At a certain point this happens:

2022-12-18 20:07:26,262 - octoprint.util.comm - INFO - Ignoring resend request for line 145443, that still originates from lines we sent before we got the first resend request

OctoPrint shows it's good will and resends 145443 and gets a resend request for exactly that line at once:

2022-12-18 20:07:26,331 - octoprint.util.comm - INFO - Got a resend request from the printer: requested line = 145443, current line = 145462
| Last lines in terminal:
| Recv: ok
| Send: N145458 G0 F12000 X108.248 Y83.924*119
| Recv: ok
| Recv: ok
| Send: N145459 G1 F1500 X102.762 Y78.437 E3471.85933*50
| Recv: Error:Line Number is not Last Line Number+1, Last Line: 145442
| Recv: Resend: 145443
| Recv: ok
| Recv: echo:Unknown command: "02.762 Y79.003"
| Send: N145460 G0 F12000 X102.762 Y79.003*114
| Recv: ok
| Recv: Error:Line Number is not Last Line Number+1, Last Line: 145442
| Recv: Resend: 145443
| Send: N145461 G1 F1500 X108.248 Y84.49 E3472.03998*12
| Recv: ok
| Recv: echo:Unknown command: "38 Y80.817 E3471.36334"
| Send: N145443 G0 F12000 X102.762 Y76.74*76
| Recv: ok
| Recv: Error:Line Number is not Last Line Number+1, Last Line: 145442
| Recv: Resend: 145443
2022-12-18 20:07:26,342 - octoprint.util.comm - INFO - Ignoring resend request for line 145443, that still originates from lines we sent before we got the first resend request

BTW: a regular serial.log would quite handy in this case

[dornadigital]

Even in the segment you highlighted, Octoprint doesn't resend 145443 until several lines later.