Driver not robust to instrument's watercolumn(?) failure modes

[lauralindzey]

On our most recent dive (nui044), we had an issue where the driver entirely stopped publishing data in the middle of a survey line.

We did not have suffient logging enabled during the dive to definitively say what caused the problem, but I was able to reproduce a similar issue on the bench with tcpdump running, and found an issue with the driver that could explain it.

(On the bench, we got several-second-long freezes, rather than the several-minute-long one we saw in the dive, and which was terminated by us powering off the sonar at the end of the survey line.)

Sometimes the instrument appears to stop sending WC data in the middle of a packet, causing the driver to entirely block. There are a couple of possible solutions to this, but for this cruise, we're simply planning to turn off watercolumn data. Possible future fixes:

• Add timeouts to the read so it fails rather than blocking if all data is not available
• Run the Range and WaterColumn data in separate threads, using separate io_service objects to service them.
• A different implementation of the disconnectTimer concept might also help with this problem -- right now, its callback isn't called until after the read returns, which is later than would be maximally useful.
• The current scheme for resynchronization simply checks chunks of 24 bytes for whether they match the 0xDEADBEEF preamble and have the correct version. I'm not sure whether it resets when a new TCP packet arrives, or if we need to worry about winding up with an offset and not ever re-synchronizing.
• It doesn't seem to cause any problems, but on restarting the sonar, the data callbacks will often be called with a buffer full of 0's.

Details

I've attached the raw data used while digging into this problem.

Test setup:

1. sonar_gui3.pcap : running driver + Norbit GUI in parallel.
2. sonar_no_gui.pcap : running only the ROS driver, GUI not started.

We originally thought the problem might be due to connecting to the sonar from both the Norbit Windows GUI and the ROS driver at the same time, but it seems to be independent.

For both, we logged all packets using tcpdump:
sudo tcpdump -i any port 2210 or port 2209 or port 2211 -w sonar_no_gui.pcap

And then examined them using wireshark.

I also added some additional debug statements to the code; that version is available in the debug_output branch (https://github.com/lauralindzey/norbit/tree/debug_output)

I've attached excerpts of the roslog output as txt files. The easiest way to find correspondences between them is to search for "set_power" in both -- it will appear in the initial configuration and then again whenever the driver is trying to check whether the connection to the sonar is alive.
To search within packet data using wireshark:

• edit -> Find Packet
• Select "packet bytes" and "string"

Watercolumn data comes in on port 2211, ranges on 2210, and configuration data on 2209.

sonar_gui3

sonar_gui3.txt

In the sonar_gui3 run, the watercolumn packet that is started at 238.736273 is supposed to have
0x00 02 54 c0 = 152678 bytes, but after 11 x 1448 byte packets, there's a [TCP Spurious Retransmission], then no more data.

This header corresponds to the ROS_INFO at 1689328885.569119496.
After a header is received, the driver calls read(...), requesting the number of bytes in the message. This read blocks until 1689328887.803330884, but the bytes it eventually received did not correspond to a full message.

sonar_no_gui

sonar_no_gui.txt

At 1623.563757 in the pcap file the driver queries the current status of power with set_power. This corresponds to the ROS_INFO at 1689330993.920297907.

The header received at 1689330987.923774134 (ROS) corresponds to a packet at 1617.356318 (pcap/wireshark), which is supposed to have 0xc0a4 = 49316 bytes. After 13 x 1448 byte packets ( = 18824 bytes), there's a gap where a range measurement is reported, then a single packet on port 2211, then more range measurements. The ROS driver blocks for 6 seconds, and then after resetting both streams re-sync up.

[lauralindzey]

Unfortunately, the pcap files are too large to upload via github. They can be downloaded from Dropbox here:

https://www.dropbox.com/scl/fo/q7kr35rl0mewbn7ung0vi/h?dl=0&rlkey=lsj6owyx03pykuq26bsdhjrll

[CaptKrasno]

@lauralindzey Thanks for the bug report. Unfortunately, I won't be able to dig deeply into this for a while as I am not currently supported to work on this project. If you end up Implementing/testing one the the solutions you listed I encourage you to make a pull request according to our CONTRIBUTING guidelines.

Looking at your sonar_gui3.txt log it seems there are lots of failed versions/preable failure. In my experience, this is usually an indication of poor network performance.

In the near term, I would suggest double checking your cabling or using a spare whip if you have one. We have had numerous problems with flaky network connections over the whips and connectors supplied by Norbit on Hercules.

[lauralindzey]

Looking at your sonar_gui3.txt log it seems there are lots of failed versions/preable failure. In my experience, this is usually an indication of poor network performance.

Yes -- those correspond to the driver trying to synchronize with the sensor again, and show up whenever a packet is dropped. And when viewing the pcap data with Wireshark, there are long gaps in data to the 2211 port along with warnings about "spurious retransmission" / "duplicate ack".