pcan: usb_submit_urb() hangs in peak_usb_ndo_start_xmit()

* pcan: usb_submit_urb() hangs in peak_usb_ndo_start_xmit()
@ 2020-12-15 20:59 Stefan Tatschner
  2020-12-15 21:02 ` Stefan Tatschner
  2020-12-15 21:20 ` Marc Kleine-Budde
  0 siblings, 2 replies; 6+ messages in thread
From: Stefan Tatschner @ 2020-12-15 20:59 UTC (permalink / raw)
  To: linux-can; +Cc: ferdinand.jarisch, Tobias Specht

[-- Attachment #1: Type: text/plain, Size: 2705 bytes --]

Hi folks!

I think we spotted a problem in the pcan_usb_fd device driver. I
tracked it down but I have no idea if this is actually a device or a
driver problem. First things first. Wo do stuff with can(-fd) and iso-
tp using the pcan pro fd interface and we discovered a weird cornercase
which can be reproduced with the attached python script.

For the reproducer setup take a pcan pro fd, connect channel 1 to
channel 2 and set the device up (for both channels) like the following:

# ip link set can0 type can bitrate 500000 dbitrate 2000000 fd on
# ip link set can1 type can bitrate 500000 dbitrate 2000000 fd on

Then run isotprecv:

# isotprecv -l -d 0x650 -s 0x6f0 -L 72:64:1 can1

And start the attached poc.py script.

The very can frame which poc.py should send is:

  25 ff

But this can frame is always missing on the bus. It is missing in the
output of candump or wireshark as well. This behaviour seems to be
dependent on how many consecutive iso-tp frames are generated. In other
words, large iso-tp packets are truncated. This can not be reproduced
via the virtual vcan interface.

This cornercase unfortunately breaks our testing setups. Let's track it
down. I did a few rounds of pr_debug() debugging.

-----------------------------------------------------------------------
af_can.c

I checked if this problem originates from the isotp module by checking
the input of can_send() in af_can.c. Everything looks fine there:

[snip]
Dez 15 21:33:12 kronos kernel: 24 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  $...............
Dez 15 21:33:12 kronos kernel: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Dez 15 21:33:12 kronos kernel: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Dez 15 21:33:12 kronos kernel: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Dez 15 21:33:12 kronos kernel: can_send: calling queue xmit
Dez 15 21:33:12 kronos kernel: 25 ff                                            %.
Dez 15 21:33:12 kronos kernel: can_send: calling queue xmit

------------------------------------------------------------------------
pcan_usb_core.c

I went one layer deeper and took a look at peak_usb_ndo_start_xmit(),
especially the usb_submit_urb() call. The problem seems to be that the
very last call to usb_submit_urb() call blocks for over a minute.

Dez 15 21:33:12 kronos kernel: peak_usb_ndo_start_xmit: submitting urb
Dez 15 21:33:12 kronos kernel: peak_usb_ndo_start_xmit: urb success
Dez 15 21:33:12 kronos kernel: peak_usb_ndo_start_xmit: submitting urb
Dez 15 21:41:59 kronos kernel: peak_usb_ndo_start_xmit: urb success         <---- ??

Anybody out there who can help me tracking this down further?

Stefan

[-- Attachment #2: poc.py --]
[-- Type: text/x-python3, Size: 1339 bytes --]

#!/usr/bin/env python3

import socket
import struct
import time

# Socket Constants not available in the socket module
# https://github.com/hartkopp/can-isotp/blob/master/include/uapi/linux/can/isotp.h
SOL_CAN_ISOTP = socket.SOL_CAN_BASE + socket.CAN_ISOTP

# Valuetypes for SOL_CAN_ISOTP
CAN_ISOTP_OPTS = 1
CAN_ISOTP_RECV_FC = 2
CAN_ISOTP_TX_STMIN = 3
CAN_ISOTP_RX_STMIN = 4
CAN_ISOTP_LL_OPTS = 5

# Flags for setsockopt CAN_ISOTP_OPTS
CAN_ISOTP_LISTEN_MODE = 0x001
CAN_ISOTP_EXTEND_ADDR = 0x002
CAN_ISOTP_TX_PADDING = 0x004
CAN_ISOTP_RX_PADDING = 0x008
CAN_ISOTP_CHK_PAD_LEN = 0x010
CAN_ISOTP_CHK_PAD_DATA = 0x020
CAN_ISOTP_HALF_DUPLEX = 0x040
CAN_ISOTP_FORCE_TXSTMIN = 0x080
CAN_ISOTP_FORCE_RXSTMIN = 0x100
CAN_ISOTP_RX_EXT_ADDR = 0x200

sock = socket.socket(socket.PF_CAN, socket.SOCK_DGRAM, socket.CAN_ISOTP)
sock.bind(("can0", 0x6f0, 0x650))
# data = struct.pack("@IIBBBB", flags, frame_txtime, ext_addr,
#                    txpad_content, rxpad_content, rx_ext_address)
# sock.setsockopt(self.SOL_CAN_ISOTP, self.CAN_ISOTP_OPTS, data)
canmtu = 72
data = struct.pack("@BBB", canmtu, 64, 0)
sock.setsockopt(SOL_CAN_ISOTP, CAN_ISOTP_LL_OPTS, data)

# for i in range(0x40):
sock.send(b"\x00"*(0x529)+b"\xff")
time.sleep(0.05)
sock.send(b"\x00"*(0x52a)+b"\xff")
# time.sleep(0.05)
# sock.send(b"\xCA\xCA\xCA\xCA")
# time.sleep(0.05)

^ permalink raw reply	[flat|nested] 6+ messages in thread