USB: Connection to devices is randomly interrupted with error code -1 EPIPE (Broken pipe)
#4597
Comments
|
With the newest Kernel update, this issue seems to be gone: $ dpkg -l | grep "raspberrypi-kernel"
ii raspberrypi-kernel 1:1.20210831-3~buster armhf Raspberry Pi bootloader |
|
I could reproduce the issue with my printer: $ dmesg --human --follow
[...]
[ +1.966016] usb 1-1.4: new full-speed USB device number 16 using xhci_hcd
[ +0.419968] usb 1-1.4: new low-speed USB device number 17 using xhci_hcd
[ +0.100268] usb 1-1.4: device descriptor read/64, error -32
[Sep29 12:58] usb 1-1.4: device descriptor read/64, error -32
[ +0.120278] usb 1-1-port4: attempt power cycle
[ +0.659498] usb 1-1.4: new low-speed USB device number 18 using xhci_hcd
[ +0.001040] usb 1-1.4: Device not responding to setup address.
[ +0.220002] usb 1-1.4: Device not responding to setup address.
[ +0.218969] usb 1-1.4: device not accepting address 18, error -71
[ +0.110035] usb 1-1.4: new low-speed USB device number 19 using xhci_hcd
[ +0.001022] usb 1-1.4: Device not responding to setup address.
[ +0.219569] usb 1-1.4: Device not responding to setup address.
[ +0.219379] usb 1-1.4: device not accepting address 19, error -71
[ +0.000616] usb 1-1-port4: unable to enumerate USB device |
|
What is the printer? Does it ever actually get detected correctly, or does it work then die? |
|
The behaviour is random. When I turn it on, it sometimes gets detected and works, sometimes it does not get detected and There were rare occasions, where the printer just stopped within a printing process jamming it with paper, since the USB connection suddenly cut off with above error messages. I turned on the printer again and it gets detected and it works, but for how long?: $ dmesg --human --follow
[...]
[ +3.883111] usb 1-1.3: new full-speed USB device number 8 using xhci_hcd
[ +0.137606] usb 1-1.3: New USB device found, idVendor=04e8, idProduct=3297, bcdDevice= 1.00
[ +0.000022] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ +0.000018] usb 1-1.3: Product: ML-191x 252x Series
[ +0.000018] usb 1-1.3: Manufacturer: Samsung Electronics Co., Ltd.
[ +0.000017] usb 1-1.3: SerialNumber: Z2L9BABSA03836B.
[ +0.006649] usblp 1-1.3:1.0: usblp0: USB Bidirectional printer dev 8 if 0 alt 0 proto 2 vid 0x04E8 pid 0x3297
[...]Since I installed the newest Kernel ( |
|
|
Printer: Both cables come from their respective manufacturer and the imprint says, that they are To rule the cables out, I bought different, two meter shielded USB cables, like I mentioned in my original post and the issue still remains. I have a shorter one, which is The thing is, that both devices have no issues, if I use them with my The maximium cable length for USB is The
Fortunately, I have this one from I will test the printer with the shorter cable first and then test it with the USB hub. One side note: Could the issue be related with When I print a page, it connects and disconnects: $ dmesg --human --follow
[...]
[ +25.130141] usblp0: removed
[Sep30 15:19] usblp 1-1.3:1.0: usblp0: USB Bidirectional printer dev 17 if 0 alt 0 proto 2 vid 0x04E8 pid 0x3297
[ +0.000685] usblp0: removed
[ +0.096503] usb 1-1.3: reset full-speed USB device number 17 using xhci_hcd
[ +0.139514] usblp 1-1.3:1.0: usblp0: USB Bidirectional printer dev 17 if 0 alt 0 proto 2 vid 0x04E8 pid 0x3297After each scan the USB port is resetted: $ dmesg --human --follow
[...]
[Sep30 15:23] usb 1-1.4: reset full-speed USB device number 18 using xhci_hcd |
|
I will try to capture Kernel events, while testing. Maybe this will be useful for debugging: $ cat "/sys/kernel/debug/tracing/trace_pipe" | tee --append "xhci-hcd"$ echo "1" > "/sys/kernel/debug/tracing/events/xhci-hcd/enable" |
|
I could reproduce the issue with the scanner again, but this time I have saved all Kernel events. I also used another The only time it worked, was, when I used the external USB hub: Manufacturer cable (failed) Short cable (failed) USB hub (success) But now I ask myself: Why do I need an external USB hub, when the power supply of the Raspberry Pi actually delivers And why do they just work on other devices, but not on the Raspberry Pi 4? Would this mean, that my scanner and my printer are drawing too much current from the USB ports, even, if they have their own power supply? How can I debug this? I have a multimeter here. I will test this on another Raspberry Pi 4; just to be sure. |
|
Just tested it on another Raspberry Pi 4 and the issue is still there: $ while [[ true ]]; do strace -p $(pgrep sane) 2>&1 | tee --append strace_saned.txt; sleep 1; done
[...]
ioctl(14, USBDEVFS_REAPURBNDELAY, 0xbeaef490) = -1 EAGAIN (Resource temporarily unavailable)
ioctl(14, USBDEVFS_CLEAR_HALT, 0xbeaef600) = -1 EPIPE (Broken pipe)
_newselect(17, [3], [16], NULL, {tv_sec=0, tv_usec=0}) = 1 (out [16], left {tv_sec=0, tv_usec=0})
write(16, "\0\0\37\374\272\274\272\267\267\221v\352\357\367\367\366\366\366\365\364\370\367\365\371\370\371\370\364\372\372\371\373"..., 8192) = 8192
_newselect(17, [3], [16], NULL, {tv_sec=0, tv_usec=0}) = 1 (out [16], left {tv_sec=0, tv_usec=0})
write(16, "\377\377\377\377\t", 5) = 5
close(16) = 0
read(3, "\0\0\0\10\0\0\0\0", 8192) = 8
clock_gettime(CLOCK_MONOTONIC, {tv_sec=225, tv_nsec=204484678}) = 0
timerfd_settime(10, TFD_TIMER_ABSTIME, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=255, tv_nsec=204484000}}, NULL) = 0
ioctl(14, USBDEVFS_SUBMITURB, 0x1de3058) = 0
poll([{fd=8, events=POLLIN}, {fd=10, events=POLLIN}, {fd=14, events=POLLOUT}], 3, 60000) = 1 ([{fd=14, revents=POLLOUT}])
ioctl(14, USBDEVFS_REAPURBNDELAY, 0xbeaf1810) = 0
timerfd_settime(10, 0, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}}, NULL) = 0
ioctl(14, USBDEVFS_REAPURBNDELAY, 0xbeaf1810) = -1 EAGAIN (Resource temporarily unavailable)
write(3, "\0\0\0\0", 4) = 4
read(3, "\0\0\0\5\0\0\0\0\0\0\0\10\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0\0\0", 8192) = 32
write(3, "\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0\0\0\0\0\0\0", 28) = 28
read(3, "\0\0\0\5\0\0\0\0\0\0\0\t\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0\0\0", 8192) = 32
write(3, "\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0\0\0\0\0\0\0", 28) = 28
read(3, "\0\0\0\5\0\0\0\0\0\0\0\n\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0\0\0", 8192) = 32
write(3, "\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\327\346f\0\0\0\0", 28) = 28
read(3, "\0\0\0\5\0\0\0\0\0\0\0\v\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0\0\0", 8192) = 32
write(3, "\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\1'\0\0\0\0\0\0", 28) = 28
read(3, "\0\0\0\5\0\0\0\0\0\0\0\10\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0\0\0", 8192) = 32
write(3, "\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0\0\0\0\0\0\0", 28) = 28
read(3, "\0\0\0\5\0\0\0\0\0\0\0\t\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0\0\0", 8192) = 32
write(3, "\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0\0\0\0\0\0\0", 28) = 28
read(3, "\0\0\0\5\0\0\0\0\0\0\0\n\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0\0\0", 8192) = 32
write(3, "\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\327\346f\0\0\0\0", 28) = 28
read(3, "\0\0\0\5\0\0\0\0\0\0\0\v\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\0\0\0\0", 8192) = 32
write(3, "\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\4\0\0\0\1\1'\0\0\0\0\0\0", 28) = 28
read(3, "\0\0\0\6\0\0\0\0", 8192) = 8
write(3, "\0\0\0\0\0\0\0\0\0\0\0\1\0\0\4\372\0\0\4\372\0\0\6\316\0\0\0\10", 28) = 28
[...] |
|
I just received another identical I can still reproduce this issue. Also using an universal power supply with the same voltage, but higher current ( |
|
Please dump dmesg without offset timestamps - it makes it impossible to correlate the xhci trace with the errors in dmesg. |
OK, I did not know that. "Fortunately", the issue is now constantly reproducable. This is after the connection was interruped and before exiting |
|
There is a new Kernel update available. I will upgrade it accordingly: $ apt list --upgradable
Listing... Done
firmware-atheros/testing 1:20190114-2+rpt2 all [upgradable from: 1:20190114-2+rpt1]
firmware-brcm80211/testing 1:20190114-2+rpt2 all [upgradable from: 1:20190114-2+rpt1]
firmware-libertas/testing 1:20190114-2+rpt2 all [upgradable from: 1:20190114-2+rpt1]
firmware-misc-nonfree/testing 1:20190114-2+rpt2 all [upgradable from: 1:20190114-2+rpt1]
firmware-realtek/testing 1:20190114-2+rpt2 all [upgradable from: 1:20190114-2+rpt1]
libraspberrypi-bin/testing 1:1.20210928-1~buster armhf [upgradable from: 1:1.20210831-3~buster]
libraspberrypi-dev/testing 1:1.20210928-1~buster armhf [upgradable from: 1:1.20210831-3~buster]
libraspberrypi-doc/testing 1:1.20210928-1~buster armhf [upgradable from: 1:1.20210831-3~buster]
libraspberrypi0/testing 1:1.20210928-1~buster armhf [upgradable from: 1:1.20210831-3~buster]
linux-libc-dev/testing 1:1.20210928-1~buster armhf [upgradable from: 1:1.20210831-3~buster]
raspberrypi-bootloader/testing 1:1.20210928-1~buster armhf [upgradable from: 1:1.20210831-3~buster]
raspberrypi-kernel/testing 1:1.20210928-1~buster armhf [upgradable from: 1:1.20210831-3~buster] |
|
Upgrading the Kernel did not solve the issue, but I can provide more debug information; solving this issue recently gave me the idea: Server Set debug environment variables for $ systemctl edit saned@
# custom - 20211002 - rfischer: temporarily set debug environment variables for "saned" (man 8 saned, man 5 sane-genesys)
[Service]
Environment=
Environment=SANE_CONFIG_DIR=/etc/sane.d SANE_DEBUG_DLL=255 SANE_DEBUG_GENESYS=255 SANE_DEBUG_GENESYS_LOW=255Apply the new configuration: $ systemctl daemon-reloadRestart the $ systemctl restart saned.socket && systemctl status saned.socket
● saned.socket - saned incoming socket
Loaded: loaded (/etc/systemd/system/saned.socket; enabled; vendor preset: enabled)
Active: active (listening) since Sat 2021-10-02 19:21:41 CEST; 52ms ago
Listen: [::]:6566 (Stream)
Accepted: 9; Connected: 0;
Tasks: 0 (limit: 4915)
CGroup: /system.slice/saned.socket
Oct 02 19:21:41 <some_server_hostname> systemd[1]: Listening on saned incoming socket.Client Open $ SANE_DEFAULT_DEVICE="net:<some_server_hostname>:genesys:libusb:001:005" xsaneServer Look for the newly generated $ ls -l /run/systemd/units/*sane*
lrwxrwxrwx 1 root root 32 Oct 2 19:26 /run/systemd/units/invocation:saned@10-192.168.1.80:6566-192.168.1.81:54022.service -> 04f40824f0b3454e9cfcc855b002bf82Go a temporary directory, start monitoring this particular $ cd "$(mktemp --directory)"
$ journalctl --catalog --pager-end --follow --unit="saned@10-192.168.1.80:6566-192.168.1.81:54022.service" | tee "saned@10-192.168.1.80:6566-192.168.1.81:54022.service.txt"Client Click on Server Analyse the text file Failed: scan_failed_-_saned@6-192.168.1.80:6566-192.168.1.81:53838.service.txt |
|
The I followed these instructions to $ dmesg
[...]
[ 809.448880] usb 1-1.4: new full-speed USB device number 5 using xhci_hcd
[ 809.592214] usb 1-1.4: New USB device found, idVendor=03f0, idProduct=0901, bcdDevice= 1.01
[ 809.592236] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=12
[ 809.592254] usb 1-1.4: Product: hp scanjet scanner
[ 809.592271] usb 1-1.4: Manufacturer: Hewlett-Packard
[ 809.592288] usb 1-1.4: SerialNumber: CN27QS30Q1
[...]
$ cd "/sys/bus/usb/devices/1-1.4/power/"
$ < "autosuspend_delay_ms"
2000
$ < "runtime_status"
suspended
$ < "control"
auto
$ echo "on" > "control"
$ < "control"
on
$ < "runtime_status"
activeExplanation for USB power control modes. To persist these changes, I had to write my own $ vi "/etc/udev/rules.d/90-saned.rules"
# custom - 20201003 - rfischer: add rule for the user "saned" for "hp scanjet 2300c"
ACTION=="add", SUBSYSTEM=="usb", ATTRS{idVendor}=="03f0", ATTRS{idProduct}=="0901", GROUP="scanner", MODE="0660", ENV{libsane_matched}="yes", TEST=="power/control", ATTR{power/control}="on"Adapt the new rules: $ udevadm trigger --action="change"I will give feedback, if this is the solution. |
|
Unfortunately, disabling |
|
I've looked at the last trace and it captures the time after the last spurious disconnect in dmesg. Because of the high level of activity, it's likely the trace will wrap after a few seconds. Can you repeat the test but while observing |
Sure! One thing to note: scan_successful_and_unplug_scanner_-_dmesg.txt unplug_and_plug_scanner_-_dmesg.txt The issue is not reproducible again. For now it is working. I will provide the files, when it is failing again. |
|
I could reproduce it again. This time, I kept failed_scan_and_unplug_scanner_-_dmesg.txt |
|
From the logs it looks as if the scanner (a full-speed device) is in the middle of a large bulk transfer when it randomly breaks with a "stall error". A subsequent control transfer also fails, which suggests the link between hub and device is also broken. Without a USB analyzer on the downstream (full-speed) bus it's going to be impossible to find out what the protocol breakage is. I would suggest using the intermediate hub as a workaround, since that prevents the error occuring. |
|
Thank you for your investigation! Meanwhile I was also testing, if the issue still applies for my printer and I could not reproduce it anymore. I did some research after this weird behaviour of Since the issue with my printer seems to be gone (again) and the issue still applies for the scanner, I get the impression, that the issue must be somewhere in that I will forward this to the SANE backend team. |
|
I reported it here. |
|
Ralph Little from the SANE backend issue:
Reopening this issue again. @P33M, what USB analyser would you recommend buying in order to debug this issue and could you give me exact instructions what I should do? |
|
I was able to reproduce the issue with my printer again. The first print was successful, but I could not print another document: connecting_failed_without_unplugging_the_printer_-_dmesg.txt After rebooting the Pi, it is working again, but this will only be temporary: $ dmesg --follow
[...]
[ 80.284963] usb 1-1.3: new full-speed USB device number 4 using xhci_hcd
[ 80.422623] usb 1-1.3: New USB device found, idVendor=04e8, idProduct=3297, bcdDevice= 1.00
[ 80.422645] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 80.422664] usb 1-1.3: Product: ML-191x 252x Series
[ 80.422681] usb 1-1.3: Manufacturer: Samsung Electronics Co., Ltd.
[ 80.422699] usb 1-1.3: SerialNumber: Z2L9BABSA03836B.
[ 80.559195] usblp 1-1.3:1.0: usblp0: USB Bidirectional printer dev 4 if 0 alt 0 proto 2 vid 0x04E8 pid 0x3297
[ 80.559362] usbcore: registered new interface driver usblp
[ 84.795011] usblp0: removed |
|
There is no prior indication of failure other than a random USB transaction error mid-transfer. Again this is suggestive of a protocol break between the Pi 4's integrated hub and the device. Since the device is full-speed the hub's internal transaction translator performs the actual bus transfer. My guess is that there is some incompatibility with the particular hub IP on the Pi 4 and the printer. A USB analyser of any reasonable usefullness will be much more expensive than the (already purchased) basic USB2.0 hub, so I recommend using that as a workaround. |
|
@P33M Could you please give more information as of why a hub between the two does the job, or at least how you came up with such a suggestion? I have a complete different setup (a RPI4b connected to a embedded system that behaves as a storage through serial port) and I encountered the exact same problems (-32 and -71 error codes, found using usbmon and wireshark) occurring at random times but only on the RPI4b (works perfectly on the RPI3b+ and my laptop), and I couldn't find a solution for days. I tried using a 3.0 hub (didn't have a 2.0 at hand) plugged in-between and it works (couldn't reproduce the error with tons of trials), but why ? |
|
Today, I took a quick retour on this one, when I had a flash of insight. I actually tried before in this comment, but the following looks like the most promising one:
$ < "/sys/module/usbcore/parameters/autosuspend"
2
$ echo "-1" > "/sys/module/usbcore/parameters/autosuspend"
$ < "/sys/module/usbcore/parameters/autosuspend"
-1
The $ < /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"I will report, if this worked or not. Sources:
Also somewhat related:
|
|
After seven consecutive scans and a few others with pauses inbetween, it is looking good so far! |
|
Interesting. Autosuspend should absolutely not interfere with an active device (a device node has been opened by userspace, or there are active transfers pending because a device driver submitted them, etc) and if disabling it makes the device work then either suspending the device once is enough to break it forever due to a device bug, or the kernel's incorrectly thinking the device is idle. Again, without USB analyzer traces there's little chance of finding the root cause. |
|
False alarm. It is not working again. I have removed the calibration file Also in I am going to test this in 30 minutes again. Fingers crossed. PS: If this is not working at all, I am going to try something like |
I am going to answer this with this video (loud sound warning) ExpandThat's not it... |
|
According to $ lsusb --tree
/: Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/4p, 5000M
/: Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 480M
|__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M
|__ Port 3: Dev 3, If 0, Class=Vendor Specific Class, Driver=usbfs, 12MThis is the current state of all $ for device in /sys/bus/usb/devices/*/power/{autosuspend*,control}; do echo "${device}"; cat "${device}"; done
/sys/bus/usb/devices/1-1.3/power/control
on
/sys/bus/usb/devices/1-1/power/control
auto
/sys/bus/usb/devices/usb1/power/control
auto
/sys/bus/usb/devices/usb2/power/control
auto
/sys/bus/usb/devices/1-1.3/power/autosuspend
0
/sys/bus/usb/devices/1-1.3/power/autosuspend_delay_ms
2000
/sys/bus/usb/devices/1-1/power/autosuspend
0
/sys/bus/usb/devices/1-1/power/autosuspend_delay_ms
0
/sys/bus/usb/devices/usb1/power/autosuspend
0
/sys/bus/usb/devices/usb1/power/autosuspend_delay_ms
0
/sys/bus/usb/devices/usb2/power/autosuspend
0
/sys/bus/usb/devices/usb2/power/autosuspend_delay_ms
0Interestingly, $ for device in /sys/bus/usb/devices/*/power/{autosuspend*,control}; do echo "${device}"; cat "${device}"; done | grep "1-1.3" --after-context="1"
/sys/bus/usb/devices/1-1.3/power/autosuspend
0
/sys/bus/usb/devices/1-1.3/power/autosuspend_delay_ms
2000
--
/sys/bus/usb/devices/1-1.3/power/control
onI am going to do the following:
If this is still not enough, I am going to set And, if this is still not enough, I am going to reset the USB hubs. And, if this does not work, I am going to try to force the
|
@e-scheer, I think, it has to do something with the controller of the hub itself. Maybe it periodically sends some kind of
|
|
OK, there seems to be a bug with the $ ls -l /sys/bus/pci/drivers
total 0
drwxr-xr-x 2 root root 0 Jan 1 1970 exar_serial
drwxr-xr-x 2 root root 0 Jan 1 1970 nvme
drwxr-xr-x 2 root root 0 Jan 1 1970 pcieport
drwxr-xr-x 2 root root 0 Jan 1 1970 serial
drwxr-xr-x 2 root root 0 Jan 1 1970 xhci_hcdxhci_hcd $ ls -l "/sys/bus/pci/drivers/xhci_hcd/"
total 0
lrwxrwxrwx 1 root root 0 Oct 31 00:18 0000:01:00.0 -> ../../../../devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0
--w------- 1 root root 4096 Oct 31 00:18 bind
--w------- 1 root root 4096 Oct 31 00:18 new_id
--w------- 1 root root 4096 Oct 31 00:18 remove_id
--w------- 1 root root 4096 Jan 1 1970 uevent
--w------- 1 root root 4096 Oct 31 00:18 unbind
# turn off
$ echo "0000:01:00.0" > "/sys/bus/pci/drivers/xhci_hcd/unbind"
# wait a few seconds; turn on
$ echo "0000:01:00.0" > "/sys/bus/pci/drivers/xhci_hcd/bind"The scanner is connected to the $ dmesg --follow
# echo "0000:01:00.0" > "/sys/bus/pci/drivers/xhci_hcd/unbind"
[ 1492.922457] xhci_hcd 0000:01:00.0: remove, state 4
[ 1492.922495] usb usb2: USB disconnect, device number 1
[ 1492.927619] xhci_hcd 0000:01:00.0: USB bus 2 deregistered
[ 1492.927733] xhci_hcd 0000:01:00.0: remove, state 4
[ 1492.927776] usb usb1: USB disconnect, device number 1
[ 1492.930757] xhci_hcd 0000:01:00.0: USB bus 1 deregistered
# echo "0000:01:00.0" > "/sys/bus/pci/drivers/xhci_hcd/bind"
[ 2160.320834] xhci_hcd 0000:01:00.0: xHCI Host Controller
[ 2160.320876] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[ 2160.324026] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000060000000890
[ 2160.325783] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.10
[ 2160.325805] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 2160.325823] usb usb1: Product: xHCI Host Controller
[ 2160.325840] usb usb1: Manufacturer: Linux 5.10.103-v7l+ xhci-hcd
[ 2160.325858] usb usb1: SerialNumber: 0000:01:00.0
[ 2160.326720] hub 1-0:1.0: USB hub found
[ 2160.326833] hub 1-0:1.0: 1 port detected
[ 2160.327609] xhci_hcd 0000:01:00.0: xHCI Host Controller
[ 2160.327640] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[ 2160.327668] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[ 2160.328190] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.10
[ 2160.328209] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 2160.328227] usb usb2: Product: xHCI Host Controller
[ 2160.328244] usb usb2: Manufacturer: Linux 5.10.103-v7l+ xhci-hcd
[ 2160.328261] usb usb2: SerialNumber: 0000:01:00.0
[ 2160.329119] hub 2-0:1.0: USB hub found
[ 2160.329229] hub 2-0:1.0: 4 ports detected
[ 2160.625062] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[ 2160.775277] usb 1-1: device descriptor read/64, error -71
[ 2161.045278] usb 1-1: device descriptor read/64, error -71
[ 2161.315118] usb 1-1: new high-speed USB device number 3 using xhci_hcd
[ 2161.465393] usb 1-1: device descriptor read/64, error -71
[ 2161.735356] usb 1-1: device descriptor read/64, error -71
[ 2161.855673] usb usb1-port1: attempt power cycle
[ 2162.325136] usb 1-1: new high-speed USB device number 4 using xhci_hcd
[ 2162.933068] xhci_hcd 0000:01:00.0: Setup ERROR: setup address command for slot 1.
[ 2163.145298] xhci_hcd 0000:01:00.0: Setup ERROR: setup address command for slot 1.
[ 2163.365163] usb 1-1: device not accepting address 4, error -22
[ 2163.515188] usb 1-1: new high-speed USB device number 5 using xhci_hcd
[ 2163.515343] xhci_hcd 0000:01:00.0: Setup ERROR: setup address command for slot 1.
[ 2163.735309] xhci_hcd 0000:01:00.0: Setup ERROR: setup address command for slot 1.
[ 2163.955169] usb 1-1: device not accepting address 5, error -22
[ 2163.955676] usb usb1-port1: unable to enumerate USB deviceSetting xhci_hcd $ echo "-1" > "/sys/bus/usb/devices/usb1/power/autosuspend"$ dmesg --follow
[ 3004.129273] usb 1-1: new high-speed USB device number 6 using xhci_hcd
[ 3009.309579] usb 1-1: device descriptor read/64, error -110
[ 3024.669829] usb 1-1: device descriptor read/64, error -110
[ 3024.939577] usb 1-1: new high-speed USB device number 7 using xhci_hcd
[ 3030.109887] usb 1-1: device descriptor read/64, error -110
[ 3045.470110] usb 1-1: device descriptor read/64, error -110
[ 3045.590432] usb usb1-port1: attempt power cycle
[ 3046.059885] usb 1-1: new high-speed USB device number 8 using xhci_hcd
[ 3046.060057] xhci_hcd 0000:01:00.0: Setup ERROR: setup address command for slot 1.
[ 3046.280019] xhci_hcd 0000:01:00.0: Setup ERROR: setup address command for slot 1.
[ 3046.499927] usb 1-1: device not accepting address 8, error -22
[ 3046.649930] usb 1-1: new high-speed USB device number 9 using xhci_hcd
[ 3046.650081] xhci_hcd 0000:01:00.0: Setup ERROR: setup address command for slot 1.
[ 3046.870031] xhci_hcd 0000:01:00.0: Setup ERROR: setup address command for slot 1.
[ 3047.089898] usb 1-1: device not accepting address 9, error -22
[ 3047.090404] usb usb1-port1: unable to enumerate USB deviceReconnecting the The scanner is not recognised anymore. Other USB devices are not recognised as well. In this state I am forced to do a reboot, since the ports seem to be dead. Source
|
|
Tinkering with the Trying to disable the drvier. Append the $ < "/boot/cmdline.txt"
[...] initcall_blacklist=xhci_hcd_init
$ rebootDisabling the driver (works): $ < "/boot/cmdline.txt"
[...] initcall_blacklist=xhci_pci_init
$ reboot
$ lsusb
<no_output>
$ ls -l /sys/bus/pci/drivers
total 0
drwxr-xr-x 2 root root 0 Jan 1 1970 exar_serial
drwxr-xr-x 2 root root 0 Jan 1 1970 nvme
drwxr-xr-x 2 root root 0 Jan 1 1970 pcieport
drwxr-xr-x 2 root root 0 Jan 1 1970 serialThere is no Append the $ lsusb | grep "HP"
Bus 001 Device 003: ID 03f0:0901 HP, Inc ScanJet 2300c
$ < "/boot/cmdline.txt"
[...] usb-storage.quirks=03f0:0901:u
$ rebootScanner immediately interrupts after starting the scan. Next:
Bonus:
|
There are no EHCI companion controllers on a Pi 4. A scanner with a separate power supply is unlikely to have any significant requirement for VBus current from the USB port. Has it ever been the case that using an external USB2.0 hub did not result in a working scanner? |
I see, but manually compiling the Raspberry Pi Kernel and loading the
I tested this last year, but I am not sure anymore. I am going to test the setup with the external USB hub thoroughly later on. Currently, the hub is not easyly accessible; moving heavy cardboard boxes is required... |
|
Attempt to use the Install tools to compile the $ sudo apt install raspberrypi-kernel-headers build-essential bc git wget bison flex libssl-dev make libncurses-devClone the Linux Kernel: $ uname --kernel-release
5.10.103-v7l+
$ dpkg --list | grep "raspberrypi-kernel"
ii raspberrypi-kernel 1:1.20220308~buster-1 armhf Raspberry Pi bootloader
ii raspberrypi-kernel-headers 1:1.20220308~buster-1 armhf Header files for the Raspberry Pi Linux kernel
$ cd "/home/pi/.local/src"
$ git clone --jobs="$(nproc --all)" "https://github.com/raspberrypi/linux"
$ cd "linux/"
$ git checkout "1.20220308_buster"Configure the # set default configuration for "bcm2711" and save to "./.config"
$ KERNEL="kernel7l+" make --jobs="$(nproc --all)" bcm2711_defconfig
$ make menuconfig MENUCONFIG_COLOR="blackbg"Help text: |
|
Well you are likely to be successful in getting the kernel to load your ehci_hcd module (hint: compile and install the entire tree), but I guarantee you it won't do anything useful. |
|
I made it to compile just the module, but I am stuck activating it. The only directory I can find is $ tree -FCaugp "/sys/module/ehci_hcd/"
/sys/module/ehci_hcd/
├── [-r--r--r-- root root ] coresize
├── [drwxr-xr-x root root ] holders/
├── [-r--r--r-- root root ] initsize
├── [-r--r--r-- root root ] initstate
├── [drwxr-xr-x root root ] notes/
│ ├── [-r--r--r-- root root ] .note.gnu.build-id
│ └── [-r--r--r-- root root ] .note.Linux
├── [drwxr-xr-x root root ] parameters/
│ ├── [-r--r--r-- root root ] ignore_oc
│ ├── [-r--r--r-- root root ] log2_irq_thresh
│ └── [-r--r--r-- root root ] park
├── [-r--r--r-- root root ] refcnt
├── [drwxr-xr-x root root ] sections/
│ ├── [-r-------- root root ] .alt.smp.init
│ ├── [-r-------- root root ] .bss
│ ├── [-r-------- root root ] __bug_table
│ ├── [-r-------- root root ] .data
│ ├── [-r-------- root root ] .data.once
│ ├── [-r-------- root root ] .exit.text
│ ├── [-r-------- root root ] .gnu.linkonce.this_module
│ ├── [-r-------- root root ] .init.plt
│ ├── [-r-------- root root ] .init.text
│ ├── [-r-------- root root ] __kcrctab_gpl
│ ├── [-r-------- root root ] __ksymtab_gpl
│ ├── [-r-------- root root ] __ksymtab_strings
│ ├── [-r-------- root root ] __mcount_loc
│ ├── [-r-------- root root ] .note.gnu.build-id
│ ├── [-r-------- root root ] .note.Linux
│ ├── [-r-------- root root ] __param
│ ├── [-r-------- root root ] .plt
│ ├── [-r-------- root root ] .rodata
│ ├── [-r-------- root root ] .rodata.str
│ ├── [-r-------- root root ] .rodata.str1.4
│ ├── [-r-------- root root ] .strtab
│ ├── [-r-------- root root ] .symtab
│ └── [-r-------- root root ] .text
├── [-r--r--r-- root root ] srcversion
├── [-r--r--r-- root root ] taint
└── [--w------- root root ] uevent$ modinfo ehci-hcd
filename: /lib/modules/5.10.103-v7l+/kernel/drivers/usb/host/ehci-hcd.ko
license: GPL
author: David Brownell
description: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
srcversion: 18D181C01C1C3E453846BB7
depends:
name: ehci_hcd
vermagic: 5.10.103-v7l+ SMP mod_unload modversions ARMv7 p2v8
parm: log2_irq_thresh:log2 IRQ latency, 1-64 microframes (int)
parm: park:park setting; 1-3 back-to-back async packets (uint)
parm: ignore_oc:ignore bogus hardware overcurrent indications (bool)
Of course...: $ modprobe --verbose ehci-pci
insmod /lib/modules/5.10.103-v7l+/kernel/drivers/usb/host/ehci-hcd.ko
insmod /lib/modules/5.10.103-v7l+/kernel/drivers/usb/host/ehci-pci.ko |
|
What's missing is something to tell the kernel where it will find an instance of the hardware, and that is where you will struggle - because, as @P33M has been saying, there isn't one... |
|
Well, at least I tried. :) |
|
An update: I have connected the before-mentioned USB hub to the $ dmesg --follow
[...]
[ 1027.267940] usb 1-1.3: new high-speed USB device number 6 using xhci_hcd
[ 1027.398530] usb 1-1.3: New USB device found, idVendor=1a40, idProduct=0101, bcdDevice= 1.11
[ 1027.398552] usb 1-1.3: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[ 1027.398570] usb 1-1.3: Product: USB 2.0 Hub
[ 1027.402914] hub 1-1.3:1.0: USB hub found
[ 1027.403061] hub 1-1.3:1.0: 4 ports detectedWhereas the scanner is recognised as $ dmesg --follow
[...]
[ 1034.928000] usb 1-1.3.1: new full-speed USB device number 7 using xhci_hcd
[ 1035.171436] usb 1-1.3.1: New USB device found, idVendor=03f0, idProduct=0901, bcdDevice= 1.01
[ 1035.171457] usb 1-1.3.1: New USB device strings: Mfr=1, Product=2, SerialNumber=12
[ 1035.171476] usb 1-1.3.1: Product: hp scanjet scanner
[ 1035.171493] usb 1-1.3.1: Manufacturer: Hewlett-Packard
[ 1035.171510] usb 1-1.3.1: SerialNumber: CN27QS30Q1This happens on all ports of the hub: $ dmesg --follow
[...]
[ 1749.909570] usb 1-1.3.1: new full-speed USB device number 19 using xhci_hcd
[ 1750.152921] usb 1-1.3.1: New USB device found, idVendor=03f0, idProduct=0901, bcdDevice= 1.01
[ 1750.152943] usb 1-1.3.1: New USB device strings: Mfr=1, Product=2, SerialNumber=12
[ 1750.152962] usb 1-1.3.1: Product: hp scanjet scanner
[ 1750.152979] usb 1-1.3.1: Manufacturer: Hewlett-Packard
[ 1750.152997] usb 1-1.3.1: SerialNumber: CN27QS30Q1
[ 1751.758930] usb 1-1.3.1: USB disconnect, device number 19
[ 1755.049590] usb 1-1.3.2: new full-speed USB device number 20 using xhci_hcd
[ 1755.293042] usb 1-1.3.2: New USB device found, idVendor=03f0, idProduct=0901, bcdDevice= 1.01
[ 1755.293065] usb 1-1.3.2: New USB device strings: Mfr=1, Product=2, SerialNumber=12
[ 1755.293083] usb 1-1.3.2: Product: hp scanjet scanner
[ 1755.293101] usb 1-1.3.2: Manufacturer: Hewlett-Packard
[ 1755.293118] usb 1-1.3.2: SerialNumber: CN27QS30Q1
[ 1757.922846] usb 1-1.3.2: USB disconnect, device number 20
[ 1762.379662] usb 1-1.3.4: new full-speed USB device number 21 using xhci_hcd
[ 1762.623114] usb 1-1.3.4: New USB device found, idVendor=03f0, idProduct=0901, bcdDevice= 1.01
[ 1762.623136] usb 1-1.3.4: New USB device strings: Mfr=1, Product=2, SerialNumber=12
[ 1762.623155] usb 1-1.3.4: Product: hp scanjet scanner
[ 1762.623172] usb 1-1.3.4: Manufacturer: Hewlett-Packard
[ 1762.623189] usb 1-1.3.4: SerialNumber: CN27QS30Q1
[ 1763.717673] usb 1-1.3.4: USB disconnect, device number 21
[ 1765.919694] usb 1-1.3.3: new full-speed USB device number 22 using xhci_hcd
[ 1766.163381] usb 1-1.3.3: New USB device found, idVendor=03f0, idProduct=0901, bcdDevice= 1.01
[ 1766.163403] usb 1-1.3.3: New USB device strings: Mfr=1, Product=2, SerialNumber=12
[ 1766.163422] usb 1-1.3.3: Product: hp scanjet scanner
[ 1766.163440] usb 1-1.3.3: Manufacturer: Hewlett-Packard
[ 1766.163457] usb 1-1.3.3: SerialNumber: CN27QS30Q1I will test this thoroughly. Maybe there is a way to tell the I also found some useful information how to
Next attempts: Legend
|
|
So using the external USB hub seems to be a permanent workaround. I am still wondering, why an external USB hub is necessary like I have mentioned above or why it is only working like that? I took the hub apart and scanned it. There are also some instruction manuals on the internet, which I have uploaded here. For giggles, I also measured the cristal with my newly acquired cheap oscilloscope, when the hub was passively connected to my computer doing nothing, but powering on. :) I am going to work through the task list in the above comment and will take notes.
|
|
I have a suspicion this may be the same bug as what trips up RP2040 when used with high-bandwidth full-speed endpoints. The built-in hub can cause a protocol error in certain circumstances. Can you try the following Pi 4 recovery firmware here - https://drive.google.com/file/d/1tMR1Pb7Ef0fblEV6e2hHTUDHpp9XHB0S/view?usp=sharing To revert to the official release, follow the instructions here - |
|
I have applied the firmware and it is looking good so far, but I am still skeptical. :) I will test this thoroughly, by archiving some instruction manuals and so on. |
|
I think, that fixed it; there are no issues at all! I also tested this on one of the Awesome, thank you for your help! I did a quick research about the recovery firmware and found it in the current rpi-eeprom repository as PS: Since I am scanning/archiving instruction manuals, the testing continues. :) $ rpi-eeprom-update
BOOTLOADER: up to date
CURRENT: Mon 19 Dec 11:56:47 UTC 2022 (1671451007)
LATEST: Tue 25 Jan 14:30:41 UTC 2022 (1643121041)
RELEASE: default (/lib/firmware/raspberrypi/bootloader/default)
Use raspi-config to change the release.
VL805_FW: Using bootloader EEPROM
VL805: up to date
CURRENT: 000138c0
LATEST: 000138c0 |
|
I think, this is it! I tested it thoroughly and have no issues anymore! Thank you for your efforts! -Ramon |
Describe the bug
I am using a
Raspberry Pi 4 Model B Rev 1.4 (8 GB), which I am using as network printer (cups,Samsung ML-1915) and as network scanner server (sane-utils,Hewlett Packard ScanJet 2300c flatbed scanner). Both peripheral devices are connected via the twoUSB 2.0 interfaces.Every time, when I try to scan a document from my
Gentoo client, the scanner randomly stops andxsanereturns me the error:Restarting
xsaneon theclient, which automatically connects to thesaned.socketon theserver, puts the light conductor(?) in the starting position again.For some reason, it takes a random number of failed attempts to execute one successful scan process.
The issue also occurs, when the devices are connected via the
USB 3.0 interfaces.Both devices are working on other systems via
USB 2.0 interfaces: For example my client or my oldRaspberry Pi Model B (512 MB, Debian Stretch)with some oldsane-utilversion.I also replaced the USB cables with new shielded ones, but the issue still remains.
On the
serverhowever, I could pinpoint the issue viastrace:I can only guess, that it either is hardware-related, because of the USB interfaces or it is software-related, where the issue is somewhere within the
Linux Kernel.To reproduce
Server
while loop, wherestracetries to attach to the processsanedand writes its output to the filestrace_saned.txt:Client
xsanewith correct set environment variable:SANE_DEFAULT_DEVICE="net:<some_fqdn>:genesys:libusb:001:003" xsanePreferences - Load device settingsand load this scanner configuration file for aHewlettPackard ScanJet 2300c.5.1. Optionally configure
xsanemanually5.1.1. Set
number of pages to scanto15.1.2. Set
targettomultipage5.1.3. Configure
xsane multpage project5.1.3.1. Set
multipage project directory nameto/tmp/deleteme5.1.3.2. Click on the button
Create project5.1.4. Set
scan modetoGray5.1.5. Set
source medium typetoFull color range5.1.6. Set
scan resolutionto1505.1.7. Set
gammato0.875.1.8. Set
brightnessto-8.05.1.9. Set
contrastto50.0ScanxsaneServer
while loopviaCTRL+Cstrace_saned.txtExpected behaviour
The scanner should scan without interruption or any errors.
The USB interface should work properly.
Actual behaviour
The scanning process is randomly interrupted. It takes a random number of failed attempts to scan one document without error.
The USB interfaces are not working properly.
System
System information
Server
Client
$ eix --installed sane [I] acct-user/saned Available versions: 0 Installed versions: 0(11:36:44 03/09/21) Description: User for media-gfx/sane-backends [I] media-gfx/sane-backends Available versions: 1.0.31-r2 {gphoto2 ipv6 snmp systemd threads usb v4l xinetd +zeroconf ABI_MIPS="n32 n64 o32" ABI_S390="32 64" ABI_X86="32 64 x32" SANE_BACKENDS="+abaton +agfafocus +apple +artec +artec_eplus48u +as6e +avision +bh +canon +canon630u +canon_dr +canon_lide70 canon_pp +cardscan +coolscan +coolscan2 +coolscan3 +dc25 +dc210 +dc240 +dell1600n_net +dmc +epjitsu +epson +epson2 +escl +fujitsu +genesys +gt68xx +hp +hp3500 +hp3900 +hp4200 +hp5400 +hp5590 +hpljm1005 hpsj5s +hs2p +ibm +kodak +kodakaio +kvs20xx kvs40xx +kvs1025 +leo +lexmark +ma1509 +magicolor +matsushita +microtek +microtek2 +mustek mustek_pp +mustek_usb mustek_usb2 +nec +net +niash +p5 +pie +pieusb +pixma +plustek +plustek_pp pnm +qcam +ricoh +ricoh2 +rts8891 +s9036 +sceptre +sharp +sm3600 +sm3840 +snapscan +sp15c +st400 +stv680 +tamarack +teco1 +teco2 +teco3 +test +u12 +umax +umax1220u +umax_pp +xerox_mfp"} Installed versions: 1.0.31-r2(13:54:39 14/09/21)(ipv6 usb zeroconf -gphoto2 -snmp -systemd -threads -v4l -xinetd ABI_MIPS="-n32 -n64 -o32" ABI_S390="-32 -64" ABI_X86="64 -32 -x32" SANE_BACKENDS="net -abaton -agfafocus -apple -artec -artec_eplus48u -as6e -avision -bh -canon -canon630u -canon_dr -canon_lide70 -canon_pp -cardscan -coolscan -coolscan2 -coolscan3 -dc25 -dc210 -dc240 -dell1600n_net -dmc -epjitsu -epson -epson2 -escl -fujitsu -genesys -gt68xx -hp -hp3500 -hp3900 -hp4200 -hp5400 -hp5590 -hpljm1005 -hpsj5s -hs2p -ibm -kodak -kodakaio -kvs20xx -kvs40xx -kvs1025 -leo -lexmark -ma1509 -magicolor -matsushita -microtek -microtek2 -mustek -mustek_pp -mustek_usb -mustek_usb2 -nec -niash -p5 -pie -pieusb -pixma -plustek -plustek_pp -pnm -qcam -ricoh -ricoh2 -rts8891 -s9036 -sceptre -sharp -sm3600 -sm3840 -snapscan -sp15c -st400 -stv680 -tamarack -teco1 -teco2 -teco3 -test -u12 -umax -umax1220u -umax_pp -xerox_mfp") Homepage: http://www.sane-project.org/ Description: Scanner Access Now Easy - Backends [I] media-gfx/xsane Available versions: 0.999-r3 {gimp jpeg lcms nls ocr png tiff} Installed versions: 0.999-r3(20:53:33 03/09/21)(gimp jpeg lcms png tiff -nls -ocr) Homepage: http://www.xsane.org/ Description: Graphical scanning frontend$ eix --installed cups [I] net-print/cups Available versions: 2.3.3-r4^t 2.3.3_p2-r2^t **9999*l^t {X acl dbus debug kerberos lprng-compat pam selinux +ssl static-libs systemd +threads usb xinetd zeroconf ABI_MIPS="n32 n64 o32" ABI_S390="32 64" ABI_X86="32 64 x32" KERNEL="linux"} Installed versions: 2.3.3_p2-r2^t(13:46:30 03/09/21)(X acl dbus pam ssl threads usb -debug -kerberos -selinux -static-libs -systemd -xinetd -zeroconf ABI_MIPS="-n32 -n64 -o32" ABI_S390="-32 -64" ABI_X86="64 -32 -x32" KERNEL="linux") Homepage: https://www.cups.org/ https://github.com/OpenPrinting/cups Description: The Common Unix Printing System [I] net-print/cups-filters Available versions: 1.28.3^t 1.28.7^t ~1.28.8^t ~1.28.9^t ~1.28.10^t {dbus +foomatic jpeg ldap pclm pdf perl png +postscript test tiff zeroconf} Installed versions: 1.28.7^t(16:31:53 03/09/21)(dbus foomatic jpeg png postscript -ldap -pclm -pdf -perl -test -tiff -zeroconf) Homepage: https://wiki.linuxfoundation.org/openprinting/cups-filters Description: Cups filtersLogs
strace_saned.txt
Additional context
The same behaviour of the USB interfaces applies to my printer.
When I turn it on, the Kernel cannot enumerate(?) the USB address and it fails with the USB error code
-71(Protocol Error) and then with-32(Broken Pipe).Sometimes it just works, sometimes it the above USB error codes are returned.
I will provide an output of
dmesg, if I can reproduce this similar issue; see comment.These may be also related to this issue:
/var/lib/saned/is missing RPi-Distro/repo#262The text was updated successfully, but these errors were encountered: