bug: some MAVLink messages have CRC errors

[clydemcqueen]

Bug description

I have found that some MAVLink2 messages generated by BlueOS, sent via mavlink2rest, and written to a tlog file by QGC, and read by pymavlink, have bad CRC values. I am not exactly sure where the bug lies, but I thought I'd share my findings to see if others can help narrow it down.

Steps to reproduce

I am looking at ~20 tlog files from 3 different BlueROV2 systems:

• R1, upgraded to Navigator + BlueOS, with a Ping sonar
• R2, Pixhawk + Companion, with a Ping sonar and WL UGPS
• R4, Navigator + BlueOS, with a Ping sonar and WL UGPS

I created a Python tool to help me examine BAD_DATA messages, and found a few patterns:

• Just about every tlog file generated by a system running BlueOS has BAD_DATA messages, in contrast to the Companion system, where I haven't found any (but I don't have a ton of data to look at yet)
• The most common BAD_DATA messages are 132 (DISTANCE_SENSOR) and 232 (GPS_INPUT).
• I am also seeing a few 259, 260, 262 and 269 (camera messages).
• A few appear to come from QGC (sysid==255) but the vast majority appear to come from BlueOS (sysid==1 and compid<>1).

Here is a typical run of the tool I'm using:

$ tlog_bad_data.py -r .
Processing 4 files
-------------------
Results for ./2023_05_04/tlog/2023-05-04 10-20-04.tlog
msg_id 259 count 1
msg_id 260 count 1
msg_id 262 count 1
msg_id 269 count 1
4 BAD_DATA messages, 4 of them were CRC errors
-------------------
Results for ./2023_05_04/tlog/2023-05-04 10-41-19.tlog
msg_id 21 count 4
msg_id 77 count 4
msg_id 132 count 1730
msg_id 232 count 15
msg_id 259 count 3
msg_id 260 count 3
msg_id 262 count 3
msg_id 269 count 3
1765 BAD_DATA messages, 1765 of them were CRC errors
-------------------
Results for ./2023_05_04/tlog/2023-05-04 11-18-48.tlog
msg_id 21 count 2
msg_id 76 count 2
msg_id 77 count 4
msg_id 132 count 1382
msg_id 232 count 83
msg_id 259 count 2
msg_id 260 count 2
msg_id 262 count 2
msg_id 269 count 2
1481 BAD_DATA messages, 1481 of them were CRC errors
-------------------
Results for ./2023_05_04/tlog/2023-05-04 19-02-21.tlog
msg_id 21 count 1
msg_id 77 count 1
msg_id 132 count 3268
msg_id 259 count 2
msg_id 260 count 2
msg_id 262 count 2
msg_id 269 count 2
3278 BAD_DATA messages, 3278 of them were CRC errors

FYI that I am running a patched version of pymavlink, without this patch pymavlink will get confused by the BAD_DATA messages and crash.

Primary pain point(s)

At the moment this just makes log analysis a challenge. (I haven't yet traced these messages through ArduSub to see if they are causing problems in ArduSub.)

Prerequisites

• I have checked to make sure that a similar request has not already been filed or fixed.

[clydemcqueen]

I am tracing this down as time permits. I can reproduce the problem by calling mavlink2rest using curl. E.g., this will generate a "bad" message:

curl --verbose http://127.0.0.1:6040/mavlink -H "accept: application/json" --data \
'{
    "header": {
        "system_id": 1,
        "component_id": 194,
        "sequence": 52
    },
    "message": {
        "type": "DISTANCE_SENSOR",
        "time_boot_ms": 201509,
        "min_distance": 20,
        "max_distance": 5000,
        "current_distance": 2325,
        "mavtype": {"type": "MAV_DISTANCE_SENSOR_ULTRASOUND"},
        "id": 1,
        "orientation": {"type": "MAV_SENSOR_ROTATION_PITCH_270"},
        "covariance": 255,
        "horizontal_fov": 0.52,
        "vertical_fov": 0.52,
        "quaternion": [0, 0, 0, 0],
        "signal_quality": 0
    }
}'

Pymavlink is happy to receive and unpack this message live, but it barfs when reading the QGC-generated tlog file that contains this message. So I think it's a bug in QGC. If you don't mind, I'll keep this issue open as I continue isolating the problem.

[clydemcqueen]

OK, I think I have figured this out. This occurs when you send a MAVLink2 message with trailing 0's. For DISTANCE_SENSOR messages, this happens when signal_quality is 0.

Then:

• mavlink2rest does not truncate the zeros as required. The CRC is correct, but only if the zeros are included.
• pymavlink will happily parse the message with the trailing zeros and the corresponding CRC.
• QGC will truncate the message without re-computing the CRC. The truncated message (with the old CRC) is written to the tlog file.
• pymavlink will crash when reading the tlog file with the truncated messages.

[clydemcqueen]

The QGC bug is actually a pymavlink bug: ArduPilot/pymavlink#237