ISOTP, race condition

[Sergey1560]

Hello.
I think I found some kind of race condition in the isotp library.

What it looks like: when sending a packet larger than 7 bytes, the isotp_send function never returns. There is no return in blocking mode, and the callback is not called in non-blocking mode.

I ran several tests with different receivers on CAN BUS.
The sender in my case is an NRF52840 with a Zephyr v4.1.99-ff8f0c579eeb (Nordic SDK) .
There are two receivers (not simultaneously): a Linux host with the ISOTP kernel module and a host with STM32.

Sending data to a Linux host always worked, but on STM32 it always froze. сandump output shows that all packets were transmitted, but there was no return from the iso_send function.
For debugging, I added some messages to the isotp library code.

Here is the debug output when the Linux host receives data:

 (000.000000)  can0  783   [8]  10 5D 12 5B 3C 00 04 00
 (000.000170)  can0  784   [3]  30 00 00
 (000.001431)  can0  783   [8]  21 00 00 41 0C 48 45 52
 (000.000912)  can0  783   [8]  22 4F 31 33 20 42 6C 61
 (000.000990)  can0  783   [8]  23 63 6B 04 30 78 30 35
 (000.000872)  can0  783   [8]  24 0F 48 32 34 2E 30 31
 (000.000911)  can0  783   [8]  25 2E 30 32 2E 31 30 2E
 (000.000942)  can0  783   [8]  26 30 30 0E 43 33 35 33
 (000.000924)  can0  783   [8]  27 31 33 32 35 31 30 30
 (000.000920)  can0  783   [8]  28 36 39 39 0A 47 50 32
 (000.000925)  can0  783   [8]  29 35 31 30 30 36 39 39
 (000.000926)  can0  783   [8]  2A 0C 30 36 35 37 34 37
 (000.001030)  can0  783   [8]  2B 35 62 39 39 30 39 01
 (000.000998)  can0  783   [8]  2C 00 01 01 01 00 02 5B
 (000.000870)  can0  783   [4]  2D 5D 01 01

0x783 - sending ID
0x784 - FC ID

And log output:

[00:00:29.221,069] <dbg> isotp: send: Send 93 bytes to addr 0x783 and listen on 0x784
[00:00:29.221,130] <dbg> isotp: send: Starting work to send FF
[00:00:29.221,649] <dbg> isotp: send_state_machine: SM send FF
[00:00:29.221,862] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:29.222,564] <dbg> isotp: send_can_rx_cb: STATE: 3
[00:00:29.222,595] <dbg> isotp: send_process_fc: Got CTS. BS: 0, STmin: 0
[00:00:29.222,625] <dbg> isotp: send_process_fc: tx-backlog = 0
[00:00:29.222,717] <dbg> isotp: send_state_machine: SM send CF
[00:00:29.223,175] <dbg> isotp: send_cf: Send sn 2 ok, tx_backlog = 1
[00:00:29.223,449] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 0
[00:00:29.224,151] <dbg> isotp: send_cf: Send sn 3 ok, tx_backlog = 1
[00:00:29.224,395] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 0
[00:00:29.225,036] <dbg> isotp: send_cf: Send sn 4 ok, tx_backlog = 1
[00:00:29.225,311] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 0
[00:00:29.225,982] <dbg> isotp: send_cf: Send sn 5 ok, tx_backlog = 1
[00:00:29.226,226] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 0
[00:00:29.226,928] <dbg> isotp: send_cf: Send sn 6 ok, tx_backlog = 1
[00:00:29.227,172] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 0
[00:00:29.227,874] <dbg> isotp: send_cf: Send sn 7 ok, tx_backlog = 1
[00:00:29.228,088] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 0
[00:00:29.228,790] <dbg> isotp: send_cf: Send sn 8 ok, tx_backlog = 1
[00:00:29.229,034] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 0
[00:00:29.229,675] <dbg> isotp: send_cf: Send sn 9 ok, tx_backlog = 1
[00:00:29.229,949] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 0
[00:00:29.230,651] <dbg> isotp: send_cf: Send sn 10 ok, tx_backlog = 1
[00:00:29.230,865] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 0
[00:00:29.231,628] <dbg> isotp: send_cf: Send sn 11 ok, tx_backlog = 1
[00:00:29.231,903] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 0
[00:00:29.232,635] <dbg> isotp: send_cf: Send sn 12 ok, tx_backlog = 1
[00:00:29.232,879] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 0
[00:00:29.233,581] <dbg> isotp: send_cf: Send sn 13 ok, tx_backlog = 1
[00:00:29.233,825] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 0
[00:00:29.234,497] <dbg> isotp: send_cf: Send sn 14 ok, tx_backlog = 1
[00:00:29.234,741] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 0
[00:00:29.235,015] <dbg> isotp: send_state_machine: SM finish
[00:00:29.235,046] <dbg> canbus_isotp: isotpsend_callback: Send OK

Here is the debug output when data is received by the host with stm32:

 (000.000000)  can0  783   [8]  10 5D 12 5B 3C 00 04 00
 (000.000041)  can0  784   [3]  30 00 00
 (000.001375)  can0  783   [8]  21 00 00 41 0C 48 45 52
 (000.001023)  can0  783   [8]  22 4F 31 33 20 42 6C 61
 (000.000994)  can0  783   [8]  23 63 6B 04 30 78 30 35
 (000.001026)  can0  783   [8]  24 0F 48 32 34 2E 30 31
 (000.001006)  can0  783   [8]  25 2E 30 32 2E 31 30 2E
 (000.001021)  can0  783   [8]  26 30 30 0E 43 33 35 33
 (000.001026)  can0  783   [8]  27 31 33 32 35 31 30 30
 (000.001031)  can0  783   [8]  28 36 39 39 0A 47 50 32
 (000.001032)  can0  783   [8]  29 35 31 30 30 36 39 39
 (000.001023)  can0  783   [8]  2A 0C 30 36 35 37 34 37
 (000.000998)  can0  783   [8]  2B 35 62 39 39 30 39 01
 (000.001050)  can0  783   [8]  2C 00 01 01 01 00 02 5B
 (000.000876)  can0  783   [4]  2D 5D 01 01

Log output:

[00:00:21.742,797] <dbg> isotp: send: Send 93 bytes to addr 0x783 and listen on 0x784
[00:00:21.742,858] <dbg> isotp: send: Starting work to send FF
[00:00:21.743,438] <dbg> isotp: send_state_machine: SM send FF
[00:00:21.743,957] <dbg> isotp: send_can_rx_cb: STATE: 3
[00:00:21.744,018] <dbg> isotp: send_process_fc: Got CTS. BS: 0, STmin: 0
[00:00:21.744,049] <dbg> isotp: send_process_fc: tx-backlog = 0
[00:00:21.744,110] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:21.744,354] <dbg> isotp: send_state_machine: SM send CF
[00:00:21.744,934] <dbg> isotp: send_cf: Send sn 2 ok, tx_backlog = 0
[00:00:21.745,208] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:21.745,941] <dbg> isotp: send_cf: Send sn 3 ok, tx_backlog = 0
[00:00:21.746,246] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:21.746,948] <dbg> isotp: send_cf: Send sn 4 ok, tx_backlog = 0
[00:00:21.747,253] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:21.747,985] <dbg> isotp: send_cf: Send sn 5 ok, tx_backlog = 0
[00:00:21.748,260] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:21.748,992] <dbg> isotp: send_cf: Send sn 6 ok, tx_backlog = 0
[00:00:21.749,267] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:21.750,000] <dbg> isotp: send_cf: Send sn 7 ok, tx_backlog = 0
[00:00:21.750,305] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:21.751,007] <dbg> isotp: send_cf: Send sn 8 ok, tx_backlog = 0
[00:00:21.751,312] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:21.752,014] <dbg> isotp: send_cf: Send sn 9 ok, tx_backlog = 0
[00:00:21.752,319] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:21.753,051] <dbg> isotp: send_cf: Send sn 10 ok, tx_backlog = 0
[00:00:21.753,326] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:21.754,058] <dbg> isotp: send_cf: Send sn 11 ok, tx_backlog = 0
[00:00:21.754,333] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:21.755,065] <dbg> isotp: send_cf: Send sn 12 ok, tx_backlog = 0
[00:00:21.755,371] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:21.756,072] <dbg> isotp: send_cf: Send sn 13 ok, tx_backlog = 0
[00:00:21.756,378] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:21.757,049] <dbg> isotp: send_cf: Send sn 14 ok, tx_backlog = 0
[00:00:21.757,293] <dbg> isotp: send_can_tx_cb: TX_CB: tx_backlog = 255
[00:00:21.757,354] <dbg> isotp: send_can_tx_cb: backlog > 0

As you can see, all the data has been transferred, but the transfer hasn't completed.

The difference is in the sctx->tx_backlog variable, which is declared as uint8_t. In the case of stm32, the FC packet arrives significantly faster than from the Linux host, and the rx-callback function (send_can_rx_cb and send_process_fc) is called before send_can_tx_cb. As a result of the "sctx->tx_backlog--;" operation, sctx->tx_backlog becomes 255, and everything breaks.

Candump output shows that Linux responds with an FC packet in about 170 uS, while stm32 responds about 40 uS.

To fix the problem, I think it's enough to add a check before decrementing sctx->tx_backlog.

In the send_can_tx_cb (zephyr/subsys/canbus/isotp/isotp.c, line 765) function, replace the code:

sctx->tx_backlog--;

with this:

if(sctx->tx_backlog > 0 ){
	sctx->tx_backlog--;
};

In my case, this solved the problem.

It would be great if someone more experienced could take a look at this.