socketcan sometimes not receiving frame send using isotpsend #113

hfn92 · 2018-12-08T16:25:52Z

Sporadically frames send using isoptsend seem to be not correctly received by applications using raw can sockets. I'm unsure whether this because of isotpsend, socketcan or simply because of misuse on my part.

I was able to reproduce this on different machines using vcan like this:

Set up vcan0
Open terminal and candump -d -e -t a vcan0
Open second terminal and repeatedly send:

echo 3E 80 | isotpsend -s 7DF -d 0 vcan0 ; \
echo 10 01 | isotpsend -s 700 -d 600 vcan0 ; \
echo 50 01 00 00 00 00 00 | isotpsend -s 600 -d 700 vcan0  ; \
echo 10 01 | isotpsend -s 700 -d 600 vcan0  ; \
echo 50 01 FF FF FF FF FF | isotpsend -s 600 -d 700 vcan0

Eventually a frame (always 50 01 FF FF FF FF FF) will not show up (isoptsend didn't fail)

$ candump -d -e -t a vcan0
[...] 
 (1544280665.838845)  vcan0  7DF   [3]  02 3E 80
 (1544280665.840640)  vcan0  700   [3]  02 10 01
 (1544280665.842494)  vcan0  600   [8]  07 50 01 00 00 00 00 00
 (1544280665.844340)  vcan0  700   [3]  02 10 01
 (1544280684.626579)  vcan0  7DF   [3]  02 3E 80
 (1544280684.628394)  vcan0  700   [3]  02 10 01
 (1544280684.630246)  vcan0  600   [8]  07 50 01 00 00 00 00 00
 (1544280684.632036)  vcan0  700   [3]  02 10 01
 (1544280684.633857)  vcan0  600   [8]  07 50 01 FF FF FF FF FF

This does not just happen for this single candump instance. Every raw can socket misses this frame.

Interestingly it will show up for isotprecv and isotpsniffer

$ isotpsniffer -s 700 -d 600 -t a vcan0
[...]
(1544280665.840640)  vcan0  700  [2]  10 01  - '..'
(1544280665.842494)  vcan0  600  [7]  50 01 00 00 00 00 00  - 'P......'
(1544280665.844340)  vcan0  700  [2]  10 01  - '..'
(1544280665.846159)  vcan0  600  [7]  50 01 FF FF FF FF FF  - 'P......'
(1544280684.628394)  vcan0  700  [2]  10 01  - '..'
(1544280684.630246)  vcan0  600  [7]  50 01 00 00 00 00 00  - 'P......'
(1544280684.632036)  vcan0  700  [2]  10 01  - '..'
(1544280684.633857)  vcan0  600  [7]  50 01 FF FF FF FF FF  - 'P......'

Additionally I set up vcan1 and a gateway from vcan0 to vcan1. And vcan1 receives the frame.

$  candump -d -e -t a vcan1
 (1544280665.838862)  vcan1  7DF   [3]  02 3E 80
 (1544280665.840654)  vcan1  700   [3]  02 10 01
 (1544280665.842508)  vcan1  600   [8]  07 50 01 00 00 00 00 00
 (1544280665.844355)  vcan1  700   [3]  02 10 01
 (1544280665.846170)  vcan1  600   [8]  07 50 01 FF FF FF FF FF
 (1544280684.626596)  vcan1  7DF   [3]  02 3E 80
 (1544280684.628407)  vcan1  700   [3]  02 10 01
 (1544280684.630258)  vcan1  600   [8]  07 50 01 00 00 00 00 00
 (1544280684.632050)  vcan1  700   [3]  02 10 01
 (1544280684.633870)  vcan1  600   [8]  07 50 01 FF FF FF FF FF

Weirdly enough the any interface also receives the frame.

$ candump -d -e -t a any
 (1544280665.840640)  vcan0  700   [3]  02 10 01
 (1544280665.840654)  vcan1  700   [3]  02 10 01
 (1544280665.842494)  vcan0  600   [8]  07 50 01 00 00 00 00 00
 (1544280665.842508)  vcan1  600   [8]  07 50 01 00 00 00 00 00
 (1544280665.844340)  vcan0  700   [3]  02 10 01
 (1544280665.844355)  vcan1  700   [3]  02 10 01
 (1544280665.846159)  vcan0  600   [8]  07 50 01 FF FF FF FF FF
 (1544280665.846170)  vcan1  600   [8]  07 50 01 FF FF FF FF FF
 (1544280684.626579)  vcan0  7DF   [3]  02 3E 80
 (1544280684.626596)  vcan1  7DF   [3]  02 3E 80
 (1544280684.628394)  vcan0  700   [3]  02 10 01
 (1544280684.628407)  vcan1  700   [3]  02 10 01

To Sum up:

I try to send a can message using isotpsend on vcan0
Application listening directly on vcan0 using a raw can socket sporadically don't receive a frame
Other isotp* tools such isotprecv and isotpsniffer receive everything correctly
It's always the same frame that doesn't show up (not because of the data but the order)
raw can socket applications using a different interface through a gateway or any receive the message (although they sometimes also drop other frames)

Things I tried:

80ms pause between request/response
Send request on vcan0 and send response on vcan1 (through gateway)
Use cansend to send frames (never failed -> couldn't reproduce)
increase txqueuelen of vcan0 to 1000

The text was updated successfully, but these errors were encountered:

hartkopp · 2018-12-09T21:13:23Z

Hm. In fact I was not able to reproduce your reported issue. Neither when invoking

nor when I put one or many of this sequence in a script.

I always get

(1544389520.733203) vcan0 7DF [3] 02 3E 80 (1544389520.739302) vcan0 700 [3] 02 10 01 (1544389520.742488) vcan0 600 [8] 07 50 01 00 00 00 00 00 (1544389520.746663) vcan0 700 [3] 02 10 01 (1544389520.750430) vcan0 600 [8] 07 50 01 FF FF FF FF FF
as expected.

Have you ever tried isotpdump which uses the raw-socket too?

hfn92 · 2018-12-10T05:53:07Z

I just tried isotpdump and it shows the same behavior as candump.

Sometimes it happens immediately but sometimes I need to repeat it as many as over 100 times.

EDIT: I was wrong about the specific frame dropping. It can be any frame. Also the behavior seem to change when you host another vcan

hartkopp · 2018-12-11T20:04:35Z

Can you tell me, what kind of hardware you are using?
I have a rough idea what could cause these sporadic drops when reading this patch from Oleksij:
https://marc.info/?l=linux-can&m=154399010212260&w=2
There is some wait mechanic in isotp.c - but I'm not sure whether it takes care of these single frame transmissions. Will take a look and come back soon. Tnx!

hfn92 · 2018-12-12T06:18:07Z

I tested on a Win10 Notebook inside a VM with a i7-6920Q and a Arch Linux desktop PC with an i7-5830K

hartkopp · 2018-12-12T10:32:11Z

I moved the wait check - can you try this patch?

diff --git a/net/can/isotp.c b/net/can/isotp.c
index 22b7ad2..8f174f0 100644
--- a/net/can/isotp.c
+++ b/net/can/isotp.c
@@ -936,8 +936,8 @@ static int isotp_sendmsg(struct kiocb *iocb, struct socket *sock,
else
cf->data[ae] |= size;

          /* we are done after this single frame transmission */
          so->tx.state = ISOTP_IDLE;

          wake_up_interruptible(&so->wait);
  } else {
          /* send first frame and wait for FC */

@@ -956,6 +956,10 @@ static int isotp_sendmsg(struct kiocb *iocb, struct socket *sock,
skb->sk = sk;
err = can_send(skb, 1);
dev_put(dev);
+

```
  if (so->tx.state == ISOTP_IDLE)
```

          wake_up_interruptible(&so->wait);

```
  if (err)
          return err;
```

hartkopp · 2018-12-12T10:32:49Z

` diff --git a/net/can/isotp.c b/net/can/isotp.c
index 22b7ad2..8f174f0 100644
--- a/net/can/isotp.c
+++ b/net/can/isotp.c
@@ -936,8 +936,8 @@ static int isotp_sendmsg(struct kiocb *iocb, struct socket *sock,
else
cf->data[ae] |= size;

          /* we are done after this single frame transmission */
          so->tx.state = ISOTP_IDLE;

          wake_up_interruptible(&so->wait);
  } else {
          /* send first frame and wait for FC */

@@ -956,6 +956,10 @@ static int isotp_sendmsg(struct kiocb *iocb, struct socket *sock,
skb->sk = sk;
err = can_send(skb, 1);
dev_put(dev);
+

```
  if (so->tx.state == ISOTP_IDLE)
```

          wake_up_interruptible(&so->wait);

```
  if (err)
          return err;
```

`

hfn92 · 2018-12-12T11:57:21Z

The patch doesn't show correctly for me (I think you need to put the patch in between three quotes each like this: ```

But I assume you just removed the line 940: wake_up_interruptible(&so->wait); and added

  if (so->tx.state == ISOTP_IDLE)
          wake_up_interruptible(&so->wait);

after line 958 (after dev_put(dev);).

If that is correct it didn't help. I can't measure it but it may have even gotten worse.

hartkopp · 2018-12-12T13:23:17Z

ok. That was the idea. Thanks for testing!
Will dig deeper then ...

hartkopp · 2018-12-15T18:44:06Z

I'm not able to reproduce the problem. Can you tell what Linux kernels you are using? (uname -a)

hfn92 · 2018-12-16T07:25:53Z

My physical machine has 4.19.6
The VM on my notebook has 4.9.140

I can't really confirm but it seems to get worse on faster machines

hartkopp · 2018-12-16T16:19:37Z

I've simplified the kernel version dependent stuff and also added the reserved skb space and some debug info in a branch for Linux 4.17+
https://github.com/hartkopp/can-isotp/tree/4.17+
Can you please test this version on your physical machine with the 4.19.6 kernel?

hfn92 · 2018-12-16T19:15:42Z

I tested it with approximately 5000 message and every single one was received (with rev 20181216 alpha)

I switched back to rev 20170725 alpha and got a message drop after about 50 messages.

I will do further tests next week but so far rev 20181216 alpha seems to be working. Thank you!

hartkopp · 2018-12-16T19:28:42Z

Thanks for testing! Even if I wasn't able to reproduce the problem, I assume this patch to be missing in <rev 20170725 alpha> :
hartkopp/can-isotp@f9cd4c1
I'll port this one back to the master branch tomorrow then.
Regards,
Oliver

Since Linux 3.9 outgoing skbuffs with CAN frames contain a reserved area with CAN specific content which is not stored in common skbuff structures. The changes accidently have not been applied to the out-of-tree isotp.c . See GitHub issues: linux-can/can-utils#113 #12 Reported-by: https://github.com/hfn92 Reported-by: https://github.com/pylessard Signed-off-by: Oliver Hartkopp <socketcan@hartkopp.net>

hartkopp · 2018-12-17T18:05:43Z

Closed due to applied fix hartkopp/can-isotp@3852256

hartkopp mentioned this issue Dec 17, 2018

CAN frames lost when stmin > 0 hartkopp/can-isotp#12

Closed

hartkopp closed this as completed Dec 17, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

socketcan sometimes not receiving frame send using isotpsend #113

socketcan sometimes not receiving frame send using isotpsend #113

hfn92 commented Dec 8, 2018

hartkopp commented Dec 9, 2018

hfn92 commented Dec 10, 2018 •

edited

Loading

hartkopp commented Dec 11, 2018

hfn92 commented Dec 12, 2018

hartkopp commented Dec 12, 2018

hartkopp commented Dec 12, 2018

hfn92 commented Dec 12, 2018

hartkopp commented Dec 12, 2018

hartkopp commented Dec 15, 2018

hfn92 commented Dec 16, 2018

hartkopp commented Dec 16, 2018

hfn92 commented Dec 16, 2018

hartkopp commented Dec 16, 2018

hartkopp commented Dec 17, 2018

socketcan sometimes not receiving frame send using isotpsend #113

socketcan sometimes not receiving frame send using isotpsend #113

Comments

hfn92 commented Dec 8, 2018

hartkopp commented Dec 9, 2018

hfn92 commented Dec 10, 2018 • edited Loading

hartkopp commented Dec 11, 2018

hfn92 commented Dec 12, 2018

hartkopp commented Dec 12, 2018

hartkopp commented Dec 12, 2018

hfn92 commented Dec 12, 2018

hartkopp commented Dec 12, 2018

hartkopp commented Dec 15, 2018

hfn92 commented Dec 16, 2018

hartkopp commented Dec 16, 2018

hfn92 commented Dec 16, 2018

hartkopp commented Dec 16, 2018

hartkopp commented Dec 17, 2018

hfn92 commented Dec 10, 2018 •

edited

Loading