Repository navigation
Fix teensytoany read failures after timeout - #51
Conversation
There was a problem hiding this comment.
i really doubt the usefulness of any changes to this file.
There was a problem hiding this comment.
all tests added in this file have been removed
|
The link to the upstream source that is relevant is showing in fact, that reading byte by byte can be broken mid message. |
|
As mentioned IRL, i would be pretty interested to see if this 200 line change could be a 20 line fix by redefining For example: Every character received might reset the timeout. |
|
I have implemented the per byte timeout and verified the fix still works on real hardware. I believe The resynchronization is also important since it is a failsafe that allows communication to recover in the unlikely event something does cause a teensy to stall past the timeout. |
| except ValueError: | ||
| pass | ||
| if error is None: | ||
| # The reply may still be on its way, or belong to another command. |
There was a problem hiding this comment.
i just don't see why it might belong to another command. in which case would this happen?
There was a problem hiding this comment.
I am updating the comment to clarify what happens there. This will happen in the case that the teensy takes longer than the timeout window to reply.
There was a problem hiding this comment.
My question is: how can that happen our firmware should NOT be that slow, and it should take it us to complete its tasks, and reply quickly, it should NOT be taking a long unpredictable time to respond.
| if returned.endswith('\n'): | ||
| try: | ||
| error = int(returned_list[0]) | ||
| except ValueError: | ||
| pass | ||
| if error is None: |
There was a problem hiding this comment.
| if returned.endswith('\n'): | |
| try: | |
| error = int(returned_list[0]) | |
| except ValueError: | |
| pass | |
| if error is None: | |
| if returned.endswith('\n'): | |
| error = int(returned_list[0]) | |
| else: |
I'm just not convinced any of these "else" paths are actually triggered.
There was a problem hiding this comment.
It never happened when testing real teensys, but it can be recreated artificially. It would be rare, but it could happen where the teensy could get held up by an I2C or SPI transaction that times out (200ms). This only gives 5ms for the teensy to respond to the serial command. The branch where the resync fails would be even rarer, requiring the teensy to still be connected but stop responding.
There was a problem hiding this comment.
a hung bus on an i2c transaction is a real concern thx for flagging that.
Can we be defensive about this in firmware? As in, add a i2c timeout in firmware of like 5-20 ms?
I would rather "fix" this concern in the firmware itself (which we control) rather than hack around this at this level.
| # The reply may still be on its way, or belong to another command. | ||
| recovery = ("" if self._resynchronize() else | ||
| "; replies are out of step, power cycle the device") | ||
| raise TeensyToAnyReplyError( | ||
| f"Failed to read a response for command: {data} " | ||
| f"(got {returned!r}){recovery}") |
There was a problem hiding this comment.
im ok with this, since we will be able to monitor that this actually gets triggered. I don't believe we will ever see the resynchronization get triggered. were you able to trigger it?
"safety" that doesn't get exercised, is more problematic since it stops future creativity for "fear" of breaking a usecase that doesn't exist.
There was a problem hiding this comment.
The resync was never triggered in testing real hardware, but in the artificial case where the reply takes longer than 205ms the resync is needed. Its rare, but it could happen. My thought process is I would rather have failsafes in place to account for things that might happen that are outside of our control. Maybe a flaky cable/connection or unstable hardware could cause a brief delay. Only 1 late reply is needed to desync everything and require a restart. Over the course of a several hour timelapse, or in use of many different systems over the course of months, I wouldn't be surprised if it happens at least once.
There was a problem hiding this comment.
excessive failsafes are really problematic since it triggers one of two behaviors:
- Increased in bloat, and slower code. Nobody can "trigger" a failsafe to happen, and thus nobody understands how they can redesign it.
- Completely ignoring them when they want to redesign the system in the future.
Both are quite dangerous, and I want to make sure people take your changes seriously.
I am ok with the addition of TeensyToAnyReplyError since it allows people to observe the issue.
However, I would like you to add a call to warning.warn for the other ValueError so that it can be observed, at least in the terminal.
I would also like to add a note that we would revisit its need in 6 months from today in April 2027 to assess its usefulness.
There was a problem hiding this comment.
One way you can test your desync, in actual hardware is
# setup GPIO 13 (the LED on the teensy) as output, set it off
teensy.gpio_pin_mode(13, 'OUTPUT')
teensy.gpio_digital_write(13, 0)
pytest.assert_raises(TeensyToAnyReplyError):
teensy.gpio_digital_pulse(13, 1, duration=400E-3)
teensy.gpio_digital_write(13, 1)
sleep(3)
teensy.gpio_digital_write(13, 0)
teesny.gpio_pin_mode(13, 'INPUT')
which should create a 400 ms pulse, triggering a timeout, and causing the whole command chain to be desync'ed.
I think this is a useful test since it relies on real behavior from the protocol.
Today, I don't think that our code uses try/except on every teensy command, so the error, which used to be ValueError ... int.... will just become TeensyToAnyReplyError which has the same effect (in my mind) of generally crashing the sotware of generally crashing the sotware , but it is more understandable what it does.
There was a problem hiding this comment.
Beyond this example that proves that today's API, when "correctly used" can trigger this error (i think it an), i think it would be good to dive deeper in your claim that I2C could trigger that timeout, even if by "inspection" of the underlying source code of the teensy firmware. Though this investation should not block these changes from getting merged.
There was a problem hiding this comment.
Quick update: I am currently testing this and I am reliably able to trigger the desync with the 400ms pulse. I am also testing what happens after an I2C timeout. A full I2C timeout hasn't caused a desync just yet, but the full delay has hit 205ms several times. 1 more ms of delay would trigger the serial timeout and cause a desync.
|
|
||
| def _ask(self, data, *, size=1024, decode=True) -> str: | ||
| # Drop anything a late reply to an earlier command left behind. | ||
| self._serial.reset_input_buffer() |
There was a problem hiding this comment.
i just don't think that this code gets triggered.
There was a problem hiding this comment.
It seems this is mostly redundant if the resync is left in. There is a niche case were this would be needed, if a reply shows up after a resync has cleared the buffer.
There was a problem hiding this comment.
I'm asking people to think of "not harmfull" and approve changes that follow that essence.
Unfortunately, I feel like this call is harmful since it takes an action that cannot be observed. There is no way to know how many bytes have been cleared.
If there is an error in our protocol, it is important that it be loud (as it was today) to ensure that we can observe it.
The fact that a reply can show up after a resync is a problem in and of itself.
Basically, our protocol is as follows:
- The user sends a message
- The reply is expected to happen quickly. In at most 10s of ms.
- The host side waits for the appropriate amount of time
If that is broken, we should adjust the amount of time we wait for it.
We do in general "adjust this time" when we do "long pulses" (and perhaps there is a better way to initiate a pulse)
but the protocol, and teensytoany in general, does not support multiple in-flight messages at the same time.
One transmit, one receive.
If there is a flaw, we don't really know if the message was received, or if it was received correctly. THe only "safe" assumption for any downstream user would be to stop, and to restart the system, which should presumably go through a safer procedure where we do flush buffers on startup (since we cannot assume that other applications flushed their commands)
https://github.com/ramonaoptics/python-teensytoany/blob/main/teensytoany/teensytoany.py#L420
So ultimately, because it takes an action that cannot be observed, i think we should remove it, unless we can prove that it is necessary to take on.
| # Unlike pyserial's read_until, which gives the whole line one deadline, | ||
| # the timeout restarts with every byte: a reader held up past the | ||
| # deadline still gets the rest of a reply that has already arrived. | ||
| data = bytearray() | ||
| while len(data) < size: | ||
| byte = self._serial.read(1) | ||
| data += byte | ||
| if not byte or byte == LF: | ||
| break | ||
| data = bytes(data) |
There was a problem hiding this comment.
Lets define this a as a function at the top of the file with the signature
def read_until(serial, LF, size):
so that it reads just as the old code did.
|
Added the changes we discussed and tested on real hardware. |
Problem
_askwrites one command and reads one line back with pyserial'sread_until, which gives the whole line a single deadline and checks it after every byte. If the reading thread is held up past that deadline, for example while another thread holds the GIL, the reply has already arrived, but the thread reads one byte ("0"), sees the deadline has passed and returns. The\nstays in the buffer.From then on, every command reads the reply meant for the one before it. A write command accepts the lone
"0"silently, so the first visible error is one command later:ValueError: invalid literal for int() with base 10: '\n', followed byTypeError: int() can't convert non-string with explicit basewhen a read command gets a bare acknowledgement. Some shifted replies parse cleanly with the wrong value, and nothing brings the stream back. The device itself replies on time throughout.A 0.1 s pulse uses half of the 0.205 s timeout before the device replies, so a stall of about 105 ms during a pulse is enough.
Changes
_readreads one byte at a time withread(1), whose timeout restarts with every byte, instead ofread_until. A reader that was held up still gets the rest of a reply that has already arrived._askclears the input buffer before each command, dropping anything left by a late reply to an earlier command.versionround trip succeeds, and raises the newTeensyToAnyReplyError. This covers a reply the device sends after the timeout, which the per-byte timeout can't.TeensyToAnyReplyErrorsubclassesRuntimeError, so existingexcept RuntimeErrorhandlers still catch it. A reply carrying an error code from the device is raised as before, without resynchronizing, since the replies are still in step.Testing
pytest,pylint,isortandflake8pass.TeensyToAnyReplyError. Without theversioncheck, a reply more than about 0.4 s late could still be read by the next command.Cost
read_untilalready did internally.🤖 Generated with Claude Code