Serial Logs Read As Expected? #330
Comments
|
Naturally as I wrote that the resend error appeared again. I should have predicted that earlier. My question stands, for now at least. It's related to #166 actually. I'm not convinced the server strictly waits for ACK (assuming swallow is disabled). |
|
The regular M105 right now isn't sent with line numbers (as are other commands not streamed from the GCODE file being printed), at least not unless "Send checksum with every command" is checked. This log looks fine to me so far, so if you don't mind I'll close this since the M105-without-line-number is already in focus for #166. |
|
Oops! I don't know if it's ready to be closed. The logs I posted don't look fine, so we disagree. Please let me try to rephrase the question/issue as a classic bug report. If you agree then maybe this issue should be re-opened or re-posted with a better title. Issue: For all supported RepRap firmwares, OctoPrint should wait to receive an ACK until sending the next GCode or MCode command. Expected: Actual: |
|
(sorry if I'm a bit slow in comprehension right now, though days behind me) Do I understand correctly that you expect OctoPrint to wait for the ok with temperature information (that actually acknowledges the M105) before sending the next command after the M105? If so, I might be missing something here, but wouldn't that completely cancel out the command buffer on the firmware side? So basically you have A therefore you'll never have a direct ok due to the buffer, which I understand is intentional (then again, I'm open to learn things). Or do I still misunderstand? Because this is exactly what I'm seeing in your log excerpt. |
|
yes, exactly. it needs to wait for the "T:" back from M105 (but if you trusted the code from Cura...you might think otherwise) this is a hard and fast rule. the buffering that happens on the firmware side - the sender is oblivious to it. the only thing the sender has to work with is an ACK, which happens to be spec'ed horribly and has an inconsistent format and TTL behavior. |
|
Sorry I missed some points. The firmware buffer does never gets cancelled out by subsequent commands. The only way to cancel the buffer would be to send a GCode command and I don't think one has been defined for that. In the current status quo, the only way to clear the firmware's buffer is to reset the control board, as far as I know. We always receive an ACK whether command is buffered or not. The ACK isn't always one line. For M140 and M190 (wait to reach target) the ACK takes many minutes to be received, with kilobytes of intermittent data (as you know). For error responses, there may or may not be an "OK". For other multiline responses like M115 there is still an ACK, thankfully. As for the buffer - an unbuffered command gets executed immediately. A buffered command goes in the buffer and gets executed FIFO-style - when and if there are no unbuffered commands to execute. It's important to note that a buffered command is ACK'ed as soon as it's received just like an unbuffered command; but instead of being executed immediately it's buffered. The caller has no way of knowing when the buffered command was executed nor the result. Does that make sense? |
|
Hm, I guess I have to do another firmware reading session then. I so far was under the impression that commands aren't ACKd before entering the buffer, but after being executed. I'll reopen this, we should think of a more descriptive name though. Really appreciate the discussion! |
|
From what I saw in reading the Firmwares Code is that they read the data one byte at a time from the hardware interface. They then put it in a buffer and read it from there once a complete line has arrived. If this buffer is big enough then sending a new command before receiving the ACK will work. But this is more like an unintended feature. If the bandwidth of the serial line is an issue this is a way to squeeze out the last bit of performance. Unbuffered fast commands like reading the temperature will be executed and send the OK with the data. The problem is Movement commands. For calculating speeds for the movement the firmware has to know the next movement. For the last movement the speed at the end of the move has to be 0. But if another move follows the end speed can be faster. Therefore the firmware usually has a Movement buffer where it stores all the incoming move commands. In this situation the Firmware has to send a OK once the movement has been put into the Queue, so that the Host will send the next G-Code. With the moves in the Queue the firmware can then calculate the speed and does not have to stop after each move. I hope this helps. |
|
Current implementation in Note that due to the nature of printer firmware buffering (we are not only talking the ring buffer used by the planner but also the command buffer into which data read from serial is temporarily stored before being processed AND the any RX buffers on the serial interface itself, which can range from 0 to 128 bytes depending on firmware & board) the log might still read differently than expected (if a specific bug in Marlin is present a G1 acknowledgement will overtake a M105 acknowledgement for example, even if it was sent afterwards but in the same chunk of the rx buffer). See also this patch and this discussion on G+. Also important to know: a ping-pong communication like defined by the "protocol" - while working - does not fully utilize the aforementioned rx buffer on the printer side, so reduced possible performance (the planner buffer gets used fully, the rx buffer doesn't). However, for now that's the best correct thing that the comm layer can do and will have to make do until |
branch: OctoPrint-Devel
commit: 2f3c3c0
I've been watching #166 because our machines experience the resend problem, apparently randomly and occasionally. I experienced the issue today and tried to track down some useful info, but it remains elusive and I haven't had time to try an earlier proposal I outlined. Then I saw some weird stuff and I think it could be related to 166, but since I'm not sure I decided to post a new issue.
After experiencing the issue I simply disconnected and reconnected, which causes the MEGA to restart. Then the print was able to start successfully and the print job is running now. As the print started I monitored the serial log to see if I could observe the error getting repeated. Instead, the print runs successfully (of course).
But the serial log confuses me. Does below look as expected? I don't get the M105's followed by line numbers. Is that being caused by some multithreaded logging tasks competing for priority?
2013-12-16 12:53:45,171 - SERIAL - DEBUG - Send: N648 G1 X127.833 Y74.376 E308.29885_80
2013-12-16 12:53:45,296 - SERIAL - DEBUG - Recv: ok
2013-12-16 12:53:45,302 - SERIAL - DEBUG - Send: M105
2013-12-16 12:53:45,309 - SERIAL - DEBUG - Recv: ok
2013-12-16 12:53:45,322 - SERIAL - DEBUG - Send: N649 G1 X128.650 Y75.193 E308.37640_85
2013-12-16 12:53:45,455 - SERIAL - DEBUG - Recv: ok
2013-12-16 12:53:45,467 - SERIAL - DEBUG - Send: N650 G1 X128.650 Y171.301 E314.82604_98
2013-12-16 12:53:45,615 - SERIAL - DEBUG - Recv: ok
2013-12-16 12:53:45,632 - SERIAL - DEBUG - Send: N651 G1 X120.849 Y179.101 E315.56639_97
2013-12-16 12:53:45,684 - SERIAL - DEBUG - Recv: ok T:238.8 /240.0 B:101.9 /105.0 @:127 B@:127
2013-12-16 12:53:45,703 - SERIAL - DEBUG - Send: N652 G1 X81.817 Y179.101 E318.18578_82
2013-12-16 12:53:45,720 - SERIAL - DEBUG - Recv: ok
2013-12-16 12:53:45,760 - SERIAL - DEBUG - Send: N653 G1 X81.690 Y178.975 E318.19783_95
2013-12-16 12:53:45,790 - SERIAL - DEBUG - Recv: ok
2013-12-16 12:53:45,839 - SERIAL - DEBUG - Send: N654 G1 X81.227 Y179.086 E318.22984_85
2013-12-16 12:53:45,863 - SERIAL - DEBUG - Recv: ok
2013-12-16 12:53:45,886 - SERIAL - DEBUG - Send: N655 G1 X80.192 Y179.250 E318.30015_83
2013-12-16 12:53:47,781 - SERIAL - DEBUG - Recv: ok
2013-12-16 12:53:47,802 - SERIAL - DEBUG - Send: N656 G1 X78.783 Y179.361 E318.39496_84
2013-12-16 12:53:47,809 - SERIAL - DEBUG - Recv: ok
2013-12-16 12:53:47,822 - SERIAL - DEBUG - Send: N657 G1 X78.261 Y179.381 E318.43003_87
2013-12-16 12:53:47,887 - SERIAL - DEBUG - Recv: ok
2013-12-16 12:53:47,900 - SERIAL - DEBUG - Send: N658 G1 X59.739 Y179.381 E319.67305_81
2013-12-16 12:53:47,906 - SERIAL - DEBUG - Recv: ok
2013-12-16 12:53:47,919 - SERIAL - DEBUG - Send: N659 G1 X59.217 Y179.361 E319.70812_92
2013-12-16 12:53:53,298 - SERIAL - DEBUG - Recv: ok
2013-12-16 12:53:53,303 - SERIAL - DEBUG - Send: M105
2013-12-16 12:53:53,309 - SERIAL - DEBUG - Recv: ok
2013-12-16 12:53:53,322 - SERIAL - DEBUG - Send: N660 G1 X57.808 Y179.250 E319.80292*82
The text was updated successfully, but these errors were encountered: