search

IntelRealSense / librealsense

Intel® RealSense™ SDK
https://www.intelrealsense.com/
Apache License 2.0
7.64k stars 4.83k forks source link

usbfs: usb_submit_urb returned -121 #7954

Open neilyoung opened 3 years ago

neilyoung commented 3 years ago
Required Info
Camera Model T265
Firmware Version 0.2.0.951
Operating System & Version Raspbian OS Buster (Dec 2020) on PI3B+
Kernel Version (Linux Only) 5.4.79-v7+
Platform Raspberry Pi
SDK Version 2.40.0
Language python
Segment Robot

Issue Description

I know, it is not an USB 3 plug, but the PI is just fitted with USB 2.1 and up to now I didn't have such an issue. Everything seems to be working fine, I get the poses (I don't care about video).

But my dmesg and journalctl is flooded with entries like these, while operational:

dmesg:

[  +0.104997] usb 1-1.3: usbfs: usb_submit_urb returned -121
[  +0.104686] usb 1-1.3: usbfs: usb_submit_urb returned -121
[  +0.105361] usb 1-1.3: usbfs: usb_submit_urb returned -121
[  +0.104992] usb 1-1.3: usbfs: usb_submit_urb returned -121
[  +0.311816] usb 1-1.3: usbfs: usb_submit_urb returned -121
[  +0.808107] usb 1-1.3: usbfs: usb_submit_urb returned -121

journalctl reveals, that the source of the evil is realsense kernel :) 

Dec 09 18:27:19 realsense kernel: usb 1-1.3: usbfs: usb_submit_urb returned -121
Dec 09 18:27:19 realsense kernel: usb 1-1.3: usbfs: usb_submit_urb returned -121
Dec 09 18:27:19 realsense kernel: usb 1-1.3: usbfs: usb_submit_urb returned -121
Dec 09 18:27:19 realsense kernel: usb 1-1.3: usbfs: usb_submit_urb returned -121
Dec 09 18:27:19 realsense kernel: usb 1-1.3: usbfs: usb_submit_urb returned -121
Dec 09 18:27:19 realsense kernel: usb 1-1.3: usbfs: usb_submit_urb returned -121

I can't even decode, what this -121 means...

I compiled the latest lib from source on the PI with these cmake flags:

cmake -D CMAKE_BUILD_TYPE="Release" -D FORCE_RSUSB_BACKEND=ON -D BUILD_PYTHON_BINDINGS=ON -D BUILD_PYTHON_DOCS=ON -D BUILD_EXAMPLES=OFF -D BUILD_GRAPHICAL_EXAMPLES=OFF ..

I'm still not sure, what to apply for the udev_rules, I applied both...

sudo ./scripts/setup_udev_rules.sh

and

sudo cp config/99-realsense-libusb.rules /etc/udev/rules.d/
sudo udevadm control --reload-rules && sudo udevadm trigger

Doesn't seem to make any difference.

I don't remember of having had these kind of issues with previous versions of the librealsense, especially not with 2.36.0.

Any pointers?

neilyoung commented 3 years ago

OK, according to https://www.kernel.org/doc/html/latest/driver-api/usb/error-codes.html and https://www-numi.fnal.gov/offline_software/srt_public_context/WebDocs/Errors/unix_system_errors.html the error could be a 

#define EREMOTEIO       121     /* Remote I/O error */

-EREMOTEIO | The data read from the endpoint did not fill the specified buffer, and URB_SHORT_NOT_OK was set in urb-transfer_flags

Does that ring a bell?

EDIT: Sounds like a firmware issue: The part, which feeds the buffer "from down under (on the cam)" is sending a package, which is short, but sets URB_SHORT_NOT_OK simultaneously. Would make sense to me.

neilyoung commented 3 years ago

Just for the files: I powered up usbmon on the PI according to the nice doc here: https://www.kernel.org/doc/Documentation/usb/usbmon.txt

sudo mount -t debugfs none_debugs /sys/kernel/debug
sudo modprobe usbmon

I literally can see the -121, but it is hard to follow the entire log... It always happens for an 8 byte package, which again points to the "short buffer, but short_not_ok theory"...


b40d9b80 3681975227 C Bi:1:015:2 0 36 = 24000000 0b100400 00000000 00000000 00000000 00000000 00000000 00000000
b40d9800 3681975339 C Ii:1:015:3 0:1 104 = 68000000 15000000 7a79b23c 50e6563b 8938153c de7c51bb 3cd90cbe bf38ddbb
b40d9800 3681976239 S Ii:1:015:3 -115:1 1024 <
b40d9b80 3681977298 S Bo:1:015:2 -115 6 = 06000000 0300
b40d9b80 3681977384 C Bo:1:015:2 0 6 >
b40d9b80 3681978714 S Bi:1:015:2 -115 16384 <
b40d9f80 3681978740 S Bi:1:015:2 -115 16384 <
b40d9b80 3681978779 C Bi:1:015:2 -121 8 = 08000000 03000000
b40d9f80 3681978798 C Bi:1:015:2 -104 0
b40d9800 3681979851 C Ii:1:015:3 0:1 104 = 68000000 15000000 ef6bb23c b575573b 5ed0143c ff4b51bb 47d80cbe 1e00ddbb
b40d9800 3681982789 S Ii:1:015:3 -115:1 1024 <
b40d9800 3681984974 C Ii:1:015:3 0:1 104 = 68000000 15000000 2057b23c 742a583b 4b86143c 568751bb 36dc0cbe eac5dcbb
b40d9800 3681985470 S Ii:1:015:3 -115:1 1024 <
b40d9800 3681989976 C Ii:1:015:3 0:1 104 = 68000000 15000000 b745b23c 82d9583b 3a2c143c 80ad51bb d8dc0cbe 6ddbdcbb

It seems also to be related to the system load: Having the usbmon running 

sudo cat /sys/kernel/debug/usb/usbmon/1u

significantly increases the -121 logs in journalctl

neilyoung commented 3 years ago

Update: Problem also present on this earlier version (launched from an older SD card):

2020-12-11 15:35:28,050 pose_pose.py INFO    : SDK: 2.33.1
2020-12-11 15:35:28,052 pose_pose.py INFO    : Firmware: 0.2.0.926
2020-12-11 15:35:28,053 pose_pose.py INFO    : USB: 2.1

This is a Raspberian OS Stretch,

pi@realsense:~/t265-realsense-poc-application/python/logs $ cat /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 9 (stretch)"
NAME="Raspbian GNU/Linux"
VERSION_ID="9"
VERSION="9 (stretch)"

while the traces above have been produced on the latest Buster. So I wouldn't blame the OS for it.