wpantund framing errors

[Stuart Longland]

Hi all,

I'm trying to fine-tune a NCP built around a CC2538+CC2592 to act as a
border router.

I've managed to crank the baud rate of the serial link up to 230400bps.
Nowhere near the dizzying heights of the nRF52840 which seem to happily
scream along at 460800, but still reasonable. We're limited in our
hardware because we need hardware that can punch an RF signal through a
couple of concrete floors.

The Fanstel USB840X looked promising, but unless I'm doing something
wrong, it would appear they're about 12dB weaker than our current
hardware. It could be a screw-up on my part, or it could be the
difference between the 2.4GHz antennas we normally use and the PCB
antenna that Fanstel provide. Sadly there's no such thing as a USB840XE
with an external antenna.

So we're re-purposing our standard hardware. There are two limitations
that I have to contend with:

- Only comms interface to the host is via the two RS-485 ports, which I
have configured to work as full-duplex (so one is transmit, the other is
receive).
- A max limit of 250kbps: the RS-485 line transceivers don't have the
slew rate to go faster.
- No hardware flow-control signals.

I've tweaked my buffers so that my interrupt-driven UART driver has 1KiB
to play with in terms of buffering incoming frames. I'm hoping this
will make up for the lack of flow control in that it'll try to ensure
all data gets captured.

I have not made any changes to the buffer sizes that OpenThread
allocates internally (the default is 1300 for RX, 512 for TX).

I still see lots of framing errors.

> Dec 2 05:12:42 raspi-br-01 wpantund[1354]: wpantund[1354]: NCP => Framing error 6: [80 03 72 3C 00 60 05 DB DC 00 14 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 0E D6 BB 62]
> Dec 2 05:12:42 raspi-br-01 wpantund[1354]: NCP => Framing error 6: [80 03 72 3C 00 60 05 DB DC 00 14 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 0E D6 BB 62]
> Dec 2 05:12:42 raspi-br-01 wpantund[1354]: wpantund[1354]: NCP => Framing error 6: [80 03 72 4A 01 60 0D 3A 88 01 22 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 F3 CE 2B 07]
> Dec 2 05:12:42 raspi-br-01 wpantund[1354]: NCP => Framing error 6: [80 03 72 4A 01 60 0D 3A 88 01 22 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 F3 CE 2B 07]
> Dec 2 05:12:42 raspi-br-01 wpantund[1354]: wpantund[1354]: NCP => Framing error 6: [80 03 72 3C 00 60 05 DB DC 00 14 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 0E D6 BB 62]
> Dec 2 05:12:42 raspi-br-01 wpantund[1354]: NCP => Framing error 6: [80 03 72 3C 00 60 05 DB DC 00 14 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 0E D6 BB 62]
> Dec 2 05:12:43 raspi-br-01 wpantund[1354]: wpantund[1354]: NCP => Framing error 6: [80 03 72 4B 01 60 05 29 20 01 23 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 01 25 DD 42]
> Dec 2 05:12:43 raspi-br-01 wpantund[1354]: NCP => Framing error 6: [80 03 72 4B 01 60 05 29 20 01 23 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 01 25 DD 42]
> Dec 2 05:12:43 raspi-br-01 wpantund[1354]: wpantund[1354]: NCP => Framing error 6: [80 03 72 3C 00 60 05 29 20 00 14 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 01 25 DD 42 6E 56]
> Dec 2 05:12:43 raspi-br-01 wpantund[1354]: NCP => Framing error 6: [80 03 72 3C 00 60 05 29 20 00 14 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 01 25 DD 42 6E 56]
> Dec 2 05:12:44 raspi-br-01 wpantund[1354]: wpantund[1354]: NCP => Framing error 6: [80 03 72 71 00 60 02 15 7A 00 49 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 E3 F8 4A DE]
> Dec 2 05:12:44 raspi-br-01 wpantund[1354]: NCP => Framing error 6: [80 03 72 71 00 60 02 15 7A 00 49 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 E3 F8 4A DE]

Oddly enough it repeats each twice. Not sure why.

The question in my mind is in which direction was this bad frame sent?
If from the NCP to the host, it could indicate a buffering issue in
transmitting the frame from the NCP or receiving at wpantund. The other
possibility is that it's the NCP complaining that it received a bad
frame from wpantund (either because wpantund messed it up or because my
UART driver missed something).

What would be the best approach for debugging this?

Regards,
--
Stuart Longland (aka Redhatter, VK4MSL)

I haven't lost my mind...
...it's backed up on a tape somewhere.

[Stuart Longland]

On 2/12/19 3:24 pm, Stuart Longland wrote:
> I'm trying to fine-tune a NCP built around a CC2538+CC2592 to act as a
> border router.
>
> I've managed to crank the baud rate of the serial link up to 230400bps.
> Nowhere near the dizzying heights of the nRF52840 which seem to happily
> scream along at 460800, but still reasonable. We're limited in our
> hardware because we need hardware that can punch an RF signal through a
> couple of concrete floors.
>

> …

> I still see lots of framing errors.

In the interests of debugging, I tried getting a Firefly to do the same.

OpenThread changes:
> $ git diff
> diff --git a/examples/platforms/cc2538/uart.c b/examples/platforms/cc2538/uart.c
> index 992af65d5..5946c2220 100644
> --- a/examples/platforms/cc2538/uart.c
> +++ b/examples/platforms/cc2538/uart.c
> @@ -49,7 +49,7 @@
> enum
> {
> kPlatformClock = 32000000,
> - kBaudRate = 115200,
> + kBaudRate = 230400,
> kReceiveBufferSize = 128,
> };

wpantund logs (running wpantund directly rather than via systemd):
> wpantund[5727]: NCP => Framing error 6: [80 03 72 50 00 60 01 3E 7E 00 28 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 5F 96 D9 31]
> wpantund[5727]: NCP => Framing error 6: [80 03 72 4B 01 60 00 FC 1D 01 23 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 7E BB 06 83]
> wpantund[5727]: NCP => Framing error 6: [80 03 72 4B 01 60 09 72 62 01 23 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 A4 CB 64 54]
> wpantund[5727]: NCP => Framing error 6: [80 03 72 3C 00 60 05 29 20 00 14 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 01 25 DD 42]
> wpantund[5727]: NCP => Framing error 6: [80 03 72 4B 01 60 00 E9 24 01 23 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 B8 62 F8 56]

So it might not be the RS-485 side of things.

[Lukasz Duda]

Hello Stuart,

Maybe unrelated, but regarding Nordic's nRF52840, I have recently sent a patch for UART high baud rates issue:

https://github.com/openthread/openthread/pull/4350

With this PR integrated, you should be able to use 1M baud rate without any problem (if the HWFC is used).

Just remember to modify the following config: https://github.com/openthread/openthread/blob/master/examples/platforms/nrf528xx/nrf52840/platform-config.h#L110

Regards,

Łukasz Duda

[Stuart Longland]

On 3/12/19 8:49 am, Lukasz Duda wrote:
> Maybe unrelated, but regarding Nordic's nRF52840, I have recently sent a
> patch for UART high baud rates issue:
> https://github.com/openthread/openthread/pull/4350

Interesting, I've only ever tried nRF52840 using USB-CDC and never
experienced a framing error on a Nordic-based NCP.

The only Nordic board I have where I can try UART-based NCP is the
PCA10056 board I bought. Last time I tried it on OpenThread it jammed
the network even though it has worked well in the past -- maybe ESD
killed it.

The downside with the Nordic dongles (PCA10059) is the lack of external
antenna connections and the low transmit power. We're hoping to have a
NCP that can punch through a couple of concrete floors if needed, so
+22dBm isn't just a nice-to-have.

[Stuart Longland]

On 2/12/19 5:17 pm, Stuart Longland wrote:
> wpantund logs (running wpantund directly rather than via systemd):
>> wpantund[5727]: NCP => Framing error 6: [80 03 72 50 00 60 01 3E 7E 00 28 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 5F 96 D9 31]
>> wpantund[5727]: NCP => Framing error 6: [80 03 72 4B 01 60 00 FC 1D 01 23 11 3F FD 9E E3 08 E1 4C B8 77 00 00 00 00 00 00 00 FD FD 34 FE 56 78 91 00 10 7E BB 06 83]

Some sleuthing… these messages are actually tunnelled over the spinel
link from the NCP. Specifically here:

https://github.com/openthread/openthread/blob/master/src/ncp/ncp_uart.cpp#L278-L309

This is called by this block of code:
https://github.com/openthread/openthread/blob/master/src/ncp/ncp_uart.cpp#L248-L276

which in turn, is called by this function pointer reference:
https://github.com/openthread/openthread/blob/master/src/ncp/ncp_uart.cpp#L87

which leads us here:
https://github.com/openthread/openthread/blob/master/src/ncp/hdlc.cpp#L239-L261

Soon as I see HDLC mentioned, I can't help but think of AX.25 and KISS
framing. I guess SLIP, KISS and other protocols all have a common
ancestor in HDLC. Funny to think my mucking around with packet radio on
VHF has relevance here. :-)

That said, I'm trying to understand the logic in that case block:
> if (mDecodedLength > 0)
> {
> otError error = OT_ERROR_PARSE;
>
> if ((mDecodedLength >= kFcsSize)
> #ifndef FUZZING_BUILD_MODE_UNSAFE_FOR_PRODUCTION
> && (mFcs == kGoodFcs)
> #endif
> )
> {
> // Remove the FCS from the frame.
> mWritePointer.UndoLastWrites(kFcsSize);
> error = OT_ERROR_NONE;
> }
>
> mFrameHandler(mContext, error);
> }

The outer `if` is easy enough… HDLC framing says you can have any
non-zero number of "flag" bytes between frames. The inner one is a
head-scratcher.

"If decoded length is greater than the size of the FCS", that's fine,
but then "and FCS is equal to kGoodFcs (0xf0b8)"… that has me confused.
Surely one would be comparing the computed FCS (in mFcs) with the
*given* FCS at the last two bytes of the frame?

Or is that special value of 0xf0b8 chosen so that when the FCS given in
the frame is considered by `updateFcs`, that the resultant FCS should be
equal to 0xf0b8?

Is there a way I can send a test SPINEL frame to a NCP and have it echo
that frame back to me as it was received?

Regards,