CRSF frame parsing timeout repeatedly expires thus dropping all frames

[britannio]

Is there an existing issue for this bug?

• I have searched the issues and there is no existing issue for this bug.

What development environment are you using?

PlatformIO

What board are you using?

Raspberry Pi Pico RP2040

What part of CRSF for Arduino is this bug related to?

RC Channels

Current behaviour

When I set up the library to get rc channel data, the callback will run but the channel data never changes.
I only encounter this issue when my Pi Pico is connected to the Adafruit PiCowbell CAN Bus.

Expected behaviour

The rc data should update as normal.

Steps to reproduce

I'm unsure how to reproduce this issue without the mentioned hardware.

Additional information

Removing the following lines fixes the issue.

CRSFforArduino/src/SerialReceiver/CRSF/CRSF.cpp

Lines 78 to 87 in 26952d5

	/* Reset the frame position if the frame time has expired. */
	if (currentTime - frameStartTime > timePerFrame)
	{
	framePosition = 0;
	if (currentTime < frameStartTime)
	{
	frameStartTime = currentTime;
	}
	}

So the frame expires before it is fully parsed, causing framePosition to be reset to 0 mid-way through parsing a frame and thus the CRC check will fail.

[britannio]

While I'm here, is it necessary to run the rc channels callback upon parsing a frame with a different frame type such as a telemetry frame? Likewise for link statistics.
https://github.com/ZZ-Cat/CRSFforArduino/blob/Main-Trunk/src/SerialReceiver/SerialReceiver.cpp#L297

[britannio]

CRSFforArduino/src/SerialReceiver/CRSF/CRSF.cpp

Line 66 in 26952d5

void CRSF::setFrameTime(uint32_t baudRate, uint8_t packetCount)

Increasing the timeout here may fix the issue but is the timeout necessary?

[ZZ-Cat]

...is the timeout necessary?

Oh gods, you have my intrusive thoughts in a nutshell, here. 😆

The time-out is calculated based on the number of possible size of CRSF packets (which is 64 bytes), the number of packets that are expected to be received, and the baud rate.
From what I understand of the protocol, a timeout of approximately 1500 µS is required to receive all bytes before the buffer is reset.
If an incomplete packet is received, it is assumed that the connection between your receiver and your target (EG development board) is either janky or broken... at least this is the theory behind it.

Removing the time-out altogether may fix your Issue. However, without the timeout, CRSF for Arduino will have no way of knowing the time difference between each byte received. This could create more issues than what your issue is trying to solve, here. It's more likely that my implementation of the time-out could do with a re-factor, as it was derived from Betaflight's implementation, and it's more likely that calling it in the context of the main loop() could be coming back to bite me here, because Betaflight's timeout is executed within interrupt context.

---

Increasing the timeout here may fix the issue but is the timeout necessary?

If you expand that function, you will see the calculation I am using:

timePerFrame = ((1000000 * packetCount) / (baudRate / (CRSF_FRAME_SIZE_MAX - 1)))

Punch that into your calculator with packetCount at 10 and baudRate of 420000, this yields 1500 µS exactly.
Full disclosure, I have no idea where the Betaflight devs even got 1500 µS from, because it makes zero sense.
You can increase the timePerFrame by passing in a packetCount higher than 10 when you use setFrameTime().

If you set the packetCount to 12, it will set the timePerFrame to 1800 µS. This may work for you.

---

While I'm here, is it necessary to run the rc channels callback upon parsing a frame with a different frame type such as a telemetry frame? Likewise for link statistics.

What do you mean by this? Could you elaborate on this a little more?

[britannio]

What do you mean by this? Could you elaborate on this a little more?

Each invocation of CRSF::receiveFrames() parses a single frame. The frame has a frame type and the ones accepted by the library are:

• CRSF_FRAMETYPE_RC_CHANNELS_PACKED
• CRSF_FRAMETYPE_LINK_STATISTICS

If the received frame is RC_CHANNELS_PACKED then the callback set in CRSFforArduino::setRcChannelsCallback should be invoked.
Likewise, if the frame is LINK_STATISTICS then the CRSFforArduino::setLinkStatisticsCallback callback should be invoked.
But right now the callbacks are being invoked irrespective of the frame type or whether the CRC check for the current frame passes.

If this change is made, the failsafe flag may need to be moved as it only relies on link statistics data.

[ZZ-Cat]

Each invocation of CRSF::receiveFrames() parses a single frame. The frame has a frame type and the ones accepted by the library are:

* `CRSF_FRAMETYPE_RC_CHANNELS_PACKED`

* `CRSF_FRAMETYPE_LINK_STATISTICS`

If the received frame is RC_CHANNELS_PACKED then the callback set in CRSFforArduino::setRcChannelsCallback should be invoked. Likewise, if the frame is LINK_STATISTICS then the CRSFforArduino::setLinkStatisticsCallback callback should be invoked. But right now the callbacks are being invoked irrespective of the frame type or whether the CRC check for the current frame passes.

Interesting. 🤔
Yea, nah. It shouldn't be doing that, and I will look into it.
At this time, my focus is primarily with #103 (which has taken priority). So, it may be some time before I sort this issue out.

[kallaspriit]

I can also confirm this on RP2040 with earlephilhower core.

Added some debugging:

/* Reset the frame position if the frame time has expired. */
if (currentTime - frameStartTime > timePerFrame)
{
    Serial.print("Timeout: ");
    Serial.print(currentTime - frameStartTime);
    Serial.print(" > ");
    Serial.print(timePerFrame);
    Serial.print(", start time:");
    Serial.print(frameStartTime);
    Serial.print(", current time:");
    Serial.println(currentTime);

    framePosition = 0;

    if (currentTime < frameStartTime)
    {
        frameStartTime = currentTime;
    }
}

And getting logs like:

Frame timeout: 1537 > 1512, start time:16301044, current time:16302581
Frame timeout: 15541 > 1512, start time:16302581, current time:16318122
Frame timeout: 1552 > 1512, start time:16318122, current time:16319674
Frame timeout: 1568 > 1512, start time:16319674, current time:16321242
Frame timeout: 23980 > 1512, start time:16321242, current time:16345222
Frame timeout: 1525 > 1512, start time:16345222, current time:16346747
Frame timeout: 1534 > 1512, start time:16346747, current time:16348281

The timeout logic in CRSF::receiveFrames does not make much sense to me. The frameStartTime should be set to currentTime when the framePosition == 0 before the frame expire check? Otherwise is also counts time between frames? And when the frame time has expired then we should set framePosition = 0; and also frameStartTime = currentTime;?

Anyway when I changed the code to this the constant expiring problem disappeared.

bool CRSF::receiveFrames(uint8_t rxByte)
    {
        static uint8_t framePosition = 0;
        static uint32_t frameStartTime = 0;
        const uint32_t currentTime = micros();

        /* Reset the frame start time if the frame position is 0. */
        if (framePosition == 0)
        {
            frameStartTime = currentTime;
        }

        /* Reset the frame position if the frame time has expired. */
        if ((currentTime - frameStartTime) > timePerFrame)
        {
            framePosition = 0;
            frameStartTime = currentTime;
        }

        /* Assume the full frame length is 5 bytes until the frame length byte is received. */
        const int fullFrameLength = framePosition < 3 ? 5 : min(rxFrame.frame.frameLength + CRSF_FRAME_LENGTH_ADDRESS + CRSF_FRAME_LENGTH_FRAMELENGTH, (int)CRSF_FRAME_SIZE_MAX);

        if (framePosition < fullFrameLength)
        {
            /* Store the received byte in the frame buffer. */
            rxFrame.raw[framePosition] = rxByte;
            framePosition++;

            if (framePosition >= fullFrameLength)
            {
                /* Frame is complete, calculate the CRC and check if it is valid. */
                const uint8_t crc = calculateFrameCRC();

                if (crc == rxFrame.raw[fullFrameLength - 1])
                {
                    switch (rxFrame.frame.type)
                    {
                        case crsfProtocol::CRSF_FRAMETYPE_RC_CHANNELS_PACKED:
                            if (rxFrame.frame.deviceAddress == CRSF_ADDRESS_FLIGHT_CONTROLLER)
                            {
                                memcpy(&rcChannelsFrame, &rxFrame, CRSF_FRAME_SIZE_MAX);
                                rcFrameReceived = true;
                            }
                            break;

#if CRSF_LINK_STATISTICS_ENABLED > 0
                        case CRSF_FRAMETYPE_LINK_STATISTICS:
                            if ((rxFrame.frame.deviceAddress == CRSF_ADDRESS_FLIGHT_CONTROLLER) && (rxFrame.frame.frameLength == CRSF_FRAME_ORIGIN_DEST_SIZE + CRSF_FRAME_LINK_STATISTICS_PAYLOAD_SIZE))
                            {
                                crsf_payload_link_statistics_t linkStatisticsPayload;
                                memcpy(&linkStatisticsPayload, rxFrame.frame.payload, sizeof(crsf_payload_link_statistics_t));

                                linkStatistics.rssi = (linkStatisticsPayload.active_antenna ? linkStatisticsPayload.uplink_rssi_2 : linkStatisticsPayload.uplink_rssi_1);
                                linkStatistics.lqi = linkStatisticsPayload.uplink_link_quality;
                                linkStatistics.snr = linkStatisticsPayload.uplink_snr;
                                linkStatistics.tx_power = (linkStatisticsPayload.uplink_tx_power < 9) ? tx_power_table[linkStatisticsPayload.uplink_tx_power] : 0;
                            }
                            break;
#endif
                    }
                }

                /* Clear the frame buffer and reset the frame position. */
                memset(rxFrame.raw, 0, CRSF_FRAME_SIZE_MAX);
                framePosition = 0;
                return true;
            }
        }

        return false;
    }

But the rabbit hole goes deeper and this still fails in a more complex firmware with lots going on on both cores (I've got I2C devices, interrupts, other Uarts in use etc). I haven't been able to quite pinpoint what exactly is causing this but somehow one can't expect that reading from UART is always as fast and deterministic.

Somehow it seems to work fine without the timeout check, not sure in which condition would it break everything without it?

Also currently the timeout in CRSFforArduino is 1512. In betaflight it's 1750.

#define CRSF_TIME_NEEDED_PER_FRAME_US 1750

Increasing to timePerFrame = 1750; improves the situation but still getting quite a few.

Anyway food for thought, should take a harder look at the Betaflight code and compare. For now I guess I just have to include a modified version of the library in my codebase without the timeout check (or with relaxed timeout value) and hope stuff does not break in some conditions.

Maybe You can test this and add a counter for these expire events if logging to console might be causing too much delay by itself and see how many of these events are you getting normally. Not sure if this is just a RP2040 issue or a more general problem but it seems that lots of valid frames get thrown away.