Repository navigation
Survive a serial port that is absent at startup or disappears while running - #85
Open
ssharma0704 wants to merge 4 commits into
Open
ssharma0704 wants to merge 4 commits into
ssharma0704 wants to merge 4 commits into
Conversation
After boot or a USB re-enumeration the serial device can be briefly absent. connect() called sys.exit(1) on the first failed open, and main() then referenced node before assignment in the except and finally blocks, masking the real error with an UnboundLocalError. Under a launch file with on_exit=Shutdown() this took the whole stack down and systemd restart-looped it. - UART connect: retry the serial open for up to 30 s, then raise ConnectionError instead of calling sys.exit(1). - main(): retry node.setup() up to 6 times, 2 s apart, then raise. - main(): initialise node to None and guard the except/finally cleanup so a failed startup reports its real cause.
The retry loop added in e8b0a5e could never work. Two reasons, both measured on hardware: - setup() began by constructing NodeParameters, which declares all 25 parameters, so attempt 2 onwards always failed with "Parameter(s) already declared" and the real cause scrolled off above five misleading errors. Parameters are now declared once in __init__. - SensorService.configure() called sys.exit(1) on the first failed chip-ID read. SystemExit is a BaseException, so "except Exception" in the retry loop never saw it and the process left at attempt 1. It now raises ConnectionError and lets the caller decide. A retry must also not build a second set of publishers and services, so the connector and SensorService are created once and a later attempt re-runs configure() alone. This matters most right after the port reset that rover-bno055.service runs before every start: the BNO055 needs about a second after power is restored, and a node that opens the port too early used to die instead of waiting two seconds and asking again. Verified on a MITI: against a port that never answers the node now makes 6 real attempts 2 s apart, each reporting "did not answer the chip-ID read", then exits 1 for the service to restart.
read_data() caught every exception, logged a warning and returned, so a node whose sensor had gone away stayed alive at the query rate forever, publishing nothing. Nothing escalated, and because Restart=always only acts when a process exits, the service could not help either: an external watchdog was the only thing that noticed, 30 to 75 s later. It now counts consecutive failed reads and exits 1 after about 3 s of them, derived from data_query_frequency so no new parameter is needed. BusOverRunException and ZeroDivisionError keep their early return and do not count, because "data fusion not ready" is normal on a cold start and must not be mistaken for a missing sensor. Verified on a MITI by unbinding ftdi_sio under the running node: reads failed with TransmissionException, the node exited at 300/300 after 3.0 s, and the service restarted it, reset the port and had the IMU publishing again 11 s after the port disappeared. The driver was untouched throughout.
A sensor that goes away fails every read until the threshold, which at 100 Hz meant 300 near-identical warnings in about 3 s and 403 journal lines for a single event. On a robot whose journal already turns over in hours, that is noise competing with the evidence. The first failure, every 50th, and the last one before giving up are reported; the rest are counted silently. The error line and the exit are unchanged, so recovery behaves exactly as before. Verified on a MITI by unbinding ftdi_sio under the running node: 7 warnings at failures 1, 50, 100, 150, 200, 250 and 300, then the same error and the same recovery - one restart, port reset, publishing again. The whole event now costs 61 journal lines instead of 403.
This branch has not been deployed
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The serial device can be briefly absent after boot or a USB re-enumeration, and it can also disappear while the node is running. This PR handles both, and fixes two faults that made the first attempt at it ineffective. All of it is measured on hardware (FT232H bridge, UART, Jetson, Humble); details under each commit.
connect()andmain()retry instead of exiting (first commit)connect()calledsys.exit(1)on the first failed open, andmain()then referencednodebefore assignment in itsexceptandfinallyblocks, masking the real error with anUnboundLocalError. Under a launch file withon_exit=Shutdown()this took the whole stack down and the service restart-looped it.ConnectionErrorinstead ofsys.exit(1).main(): retrynode.setup()up to 6 times, 2 s apart, then raise.main(): initialisenodetoNoneand guard theexcept/finallycleanup so a failed startup reports its real cause.Make that retry actually reach its later attempts (second commit)
Testing the above on hardware showed the retry loop could never succeed, for two independent reasons:
setup()began by constructingNodeParameters, which declares all 25 parameters, so attempt 2 onwards always failed withParameter(s) already declared— and that error also pushed the real cause off the top of the log.SensorService.configure()calledsys.exit(1)on the first failed chip-ID read.SystemExitderives fromBaseException, soexcept Exceptionin the retry loop never saw it and the process left at attempt 1, without retrying at all.Parameters are now declared once in
__init__,configure()raisesConnectionErrorand lets the caller decide, and the connector andSensorServiceare constructed once so a later attempt re-runsconfigure()alone rather than creating a second set of publishers and services.This matters most straight after a USB re-enumeration: the BNO055 needs about a second after power is restored, and a node that opened the port too early used to die instead of waiting two seconds and asking again.
Measured: against a port that never answers, the node now makes 6 real attempts 2 s apart, each reporting
did not answer the chip-ID read: Unexpected length of READ-request response: 0, then exits 1. Before, it exited at attempt 1.Exit after a run of failed reads instead of publishing nothing (third commit)
This one is a different failure and is separable, so please say if you would rather it came as its own PR.
read_data()caught every exception, logged a warning and returned, so a node whose sensor had gone away stayed alive at the query rate forever, publishing nothing. Nothing escalated, and a supervisor configured to restart on exit cannot help a process that never exits.It now counts consecutive failed reads and exits 1 after roughly 3 s of them, derived from
data_query_frequencyso no new parameter is needed.BusOverRunExceptionandZeroDivisionErrorkeep their earlyreturnand deliberately do not count, because "data fusion not ready" is normal on a cold start and must not be mistaken for a missing sensor.Measured by unbinding
ftdi_siounder the running node: reads failed withTransmissionException, the node exited after 3.0 s, and its supervisor had it publishing again 11 s after the port disappeared. Before this commit the topic stayed silent indefinitely. 60 s of normal running produces no spurious exit, so the counter resets correctly on good reads.Report a run of failed reads as one event (fourth commit)
Also separable; say if you would rather it came on its own.
The commit above is correct but noisy: a sensor that has gone away fails every read until the threshold, which at a 100 Hz query rate meant about 300 near-identical warnings in 3 s, and 403 journal lines for a single event. On a machine whose journal turns over in hours that is noise competing with the evidence.
The first failure, every fiftieth, and the last one before giving up are now reported; the rest are counted silently. The error line and the exit are unchanged, so recovery behaves exactly as before.
Measured on the same hardware by unbinding
ftdi_siounder the running node: 7 warnings, at failures 1, 50, 100, 150, 200, 250 and 300, then the same error and the same recovery - one restart, port reset, publishing again. The whole event costs 61 journal lines instead of 403.A note on
data_query_frequency, which may interest you more than these commitsWhile testing the above I measured this node's actual timing, and the default configuration is worse than it looks. With
data_query_frequency: 100anduart_timeout: 0.1, the timer is asked to fire every 10 ms while each read takes about 20 ms, so the loop never catches up and a single serial read timeout adds its full 100 ms to the next gap instead of being absorbed. Measured on a BNO055 over an FT232H at 115200 baud, stationary and healthy, differencing the publisher's own header stamps over 150 s and 7403 messages: p50 gap 16 ms, p99 128 ms, p99.9 224 ms, worst 720 ms, with 279 gaps over 100 ms. The long gaps are quantised in 100 ms units, which is theuart_timeoutvalue.Setting
data_query_frequency: 40anduart_timeout: 0.03gave a worst gap of 96 ms with no gap over 100 ms across 11,636 messages, no failed reads and no restarts, reproduced on a second robot to within 0.1 ms on every percentile. The published rate falls from 49 to 39 Hz and the median gap doubles, which is a good trade for anything fusing the data. For completeness:uart_timeout: 0.02is too tight and breaks it outright - 6.3 Hz, gaps over 8 s, repeated read failures.That is a configuration change rather than a code one, so it is not in this PR, but the upstream comment near the timer already warns that "frequencies around 30Hz and above might cause performance impacts" and cites ros2/rclpy#520. The shipped default of 100 is well past that, and it may be worth revisiting the recommended value.