Closed keks24 closed 1 year ago
keks24
commented
2 years ago 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 bootloaderI 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
JamesH65
commented
2 years ago What is the printer? Does it ever actually get detected correctly, or does it work then die?
keks24
commented
2 years ago The behaviour is random.
When I turn it on, it sometimes gets detected and works, sometimes it does not get detected and dmesg outputs the above error messages.
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 (1:1.20210831-3~buster) for Buster, the scanner (HP ScanJet 2300c) works without any issues, which I described previously, but the issue with the printer still remains.
P33M
commented
2 years ago -71 indicates a protocol error most commonly caused by poor signal integrity.
keks24
commented
2 years ago
- How long is the USB cable between the printer/scanner and the Pi?
Printer: Estimated 1.53m
Scanner: Estimated 1.80m
Both cables come from their respective manufacturer and the imprint says, that they are shielded.
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 shielded as well and estimated 1.23m long. I will try this cable first for while and see, if I can reproduce the issue once again.
The thing is, that both devices have no issues, if I use them with my Gentoo client or my Raspberry Pi Model B+ (512MB, Debian Stretch). Both with manufacturer cables or the new ones. The latter is powered with a small power supply with 5V and 2A.
The maximium cable length for USB is 5m, so I can only guess, that something must have been changed with the USB ports on the Raspberry Pi 4 (8GB) or the Kernel handling them.
The Raspberry Pi 4 is powered via an official power supply with 5.1V and 3A.
- What happens if you insert a powered USB2.0 hub between the Pi and the device(s)?
Fortunately, I have this one from i-tec, which I can use.
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 connecting to and disconnecting from the USB port?
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_hcdI 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 5.1V 3A power supply to rule that out as well.
The only time it worked, was, when I used the external USB hub:
Manufacturer cable (failed) scanner_manufacturercable-_dmesg_usb.txt scanner_manufacturercable-_trace_xhci-hcd.txt
Short cable (failed) scanner_shortcable-_dmesg_usb.txt scanner_shortcable-_trace_xhci-hcd.txt
USB hub (success) scanner_usb_hubdmesg_usb.txt scanner_usb_hubtrace_xhci-hcd.txt
But now I ask myself:
Why do I need an external USB hub, when the power supply of the Raspberry Pi actually delivers 15.3W? The USB ports are actually capable of powering an external 2.5" hard drive...
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.
keks24
commented
2 years ago 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 HP ScanJet 2300c, which came with another power supply, but with the same voltage (12V) and current strength (1.25A).
I can still reproduce this issue.
Also using an universal power supply with the same voltage, but higher current (3A) does not work as well. The servo motor quits working and hums in an unhealthy way.
P33M
commented
2 years ago Please dump dmesg without offset timestamps - it makes it impossible to correlate the xhci trace with the errors in dmesg.
keks24
commented
2 years ago 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 xsane:
[...]
saned-23664 [003] .... 75194.109875: xhci_urb_enqueue: ep0out-control: urb 8b39963f pipe 2147485952 slot 2 length 0/1 sgs 0/0 stream 0 flags 00000000
saned-23664 [003] d... 75194.109901: xhci_queue_trb: CTRL: bRequestType 40 bRequest 0c wValue 0083 wIndex 0000 wLength 1 length 8 TD size 0 intr 0 type 'Setup Stage' flags I:i:C
saned-23664 [003] d... 75194.109903: xhci_inc_enq: CTRL cf1c8c00: enq 0x000000041a5c5ef0(0x000000041a5c5000) deq 0x000000041a5c5ee0(0x000000041a5c5000) segs 2 stream 0 free_trbs 508 bounce 0 cycle 0
saned-23664 [003] d... 75194.109905: xhci_queue_trb: CTRL: Buffer c020cb1cc032f201 length 1 TD size 0 intr 0 type 'Data Stage' flags I:i:c:s:i:e:c
saned-23664 [003] d... 75194.109907: xhci_inc_enq: CTRL cf1c8c00: enq 0x000000041a5c5f00(0x000000041a5c5000) deq 0x000000041a5c5ee0(0x000000041a5c5000) segs 2 stream 0 free_trbs 507 bounce 0 cycle 0
saned-23664 [003] d... 75194.109909: xhci_queue_trb: CTRL: Buffer 0000000000000000 length 0 TD size 0 intr 0 type 'Status Stage' flags I:c:e:c
saned-23664 [003] d... 75194.109911: xhci_inc_enq: CTRL cf1c8c00: enq 0x000000041a5c5f10(0x000000041a5c5000) deq 0x000000041a5c5ee0(0x000000041a5c5000) segs 2 stream 0 free_trbs 506 bounce 0 cycle 0
saned-23664 [003] d... 75194.109913: xhci_ring_ep_doorbell: Ring doorbell for Slot 2 ep0in
<idle>-0 [000] d.h. 75194.110146: xhci_handle_event: EVENT: TRB 000000041a5c5ee0 status 'Stall Error' len 8 slot 2 ep 1 type 'Transfer Event' flags e:C
<idle>-0 [000] d.h. 75194.110151: xhci_handle_transfer: CTRL: bRequestType 40 bRequest 0c wValue 0083 wIndex 0000 wLength 1 length 8 TD size 0 intr 0 type 'Setup Stage' flags I:i:c
<idle>-0 [000] d.h. 75194.110160: xhci_queue_trb: CMD: Reset Endpoint Command: ctx 0000000000000000 slot 2 ep 1 flags t:C
<idle>-0 [000] d.h. 75194.110164: xhci_inc_enq: CMD b9f7a832: enq 0x000000041a501920(0x000000041a501000) deq 0x000000041a501910(0x000000041a501000) segs 1 stream 0 free_trbs 253 bounce 0 cycle 1
<idle>-0 [000] d.h. 75194.110167: xhci_dbg_reset_ep: Cleaning up stalled endpoint ring
<idle>-0 [000] d.h. 75194.110170: xhci_dbg_cancel_urb: Finding endpoint context
<idle>-0 [000] d.h. 75194.110173: xhci_dbg_cancel_urb: Cycle state = 0x0
<idle>-0 [000] d.h. 75194.110176: xhci_dbg_cancel_urb: New dequeue segment = 5420925b (virtual)
<idle>-0 [000] d.h. 75194.110179: xhci_dbg_cancel_urb: New dequeue pointer = 0x41a5c5f10 (DMA)
<idle>-0 [000] d.h. 75194.110182: xhci_dbg_reset_ep: Queueing new dequeue state
<idle>-0 [000] d.h. 75194.110184: xhci_dbg_cancel_urb: Set TR Deq Ptr cmd, new deq seg = 5420925b (0x41a5c5000 dma), new deq ptr = c19ece3c (0x41a5c5f10 dma), new cycle = 0
<idle>-0 [000] d.h. 75194.110190: xhci_queue_trb: CMD: Set TR Dequeue Pointer Command: deq 000000041a5c5f10 stream 0 slot 2 ep 1 flags C
<idle>-0 [000] d.h. 75194.110192: xhci_inc_enq: CMD b9f7a832: enq 0x000000041a501930(0x000000041a501000) deq 0x000000041a501910(0x000000041a501000) segs 1 stream 0 free_trbs 252 bounce 0 cycle 1
<idle>-0 [000] d.h. 75194.110194: xhci_ring_host_doorbell: Ring doorbell for Command Ring 0
<idle>-0 [000] d.h. 75194.110198: xhci_urb_giveback: ep0out-control: urb 8b39963f pipe 2147485952 slot 2 length 0/1 sgs 0/0 stream 0 flags 00000000
<idle>-0 [000] d.h. 75194.110200: xhci_inc_deq: EVENT bc050dc9: enq 0x000000041a503000(0x000000041a503000) deq 0x000000041a507260(0x000000041a507000) segs 8 stream 0 free_trbs 2039 bounce 0 cycle 1
<idle>-0 [000] d.h. 75194.110247: xhci_handle_event: EVENT: TRB 000000041a501910 status 'Success' len 0 slot 2 ep 0 type 'Command Completion Event' flags e:C
<idle>-0 [000] d.h. 75194.110249: xhci_handle_command: CMD: Reset Endpoint Command: ctx 0000000000000000 slot 2 ep 1 flags t:C
<idle>-0 [000] d.h. 75194.110253: xhci_handle_cmd_reset_ep: State stopped mult 1 max P. Streams 0 interval 125 us max ESIT payload 0 CErr 3 Type Ctrl burst 0 maxp 8 deq 000000041a5c5ee0 avg trb len 0
<idle>-0 [000] d.h. 75194.110257: xhci_dbg_reset_ep: Ignoring reset ep completion code of 1
<idle>-0 [000] d.h. 75194.110263: xhci_inc_deq: CMD b9f7a832: enq 0x000000041a501930(0x000000041a501000) deq 0x000000041a501920(0x000000041a501000) segs 1 stream 0 free_trbs 253 bounce 0 cycle 1
<idle>-0 [000] d.h. 75194.110264: xhci_inc_deq: EVENT bc050dc9: enq 0x000000041a503000(0x000000041a503000) deq 0x000000041a507270(0x000000041a507000) segs 8 stream 0 free_trbs 2039 bounce 0 cycle 1
<idle>-0 [000] d.h. 75194.110294: xhci_handle_event: EVENT: TRB 000000041a501920 status 'Success' len 0 slot 2 ep 0 type 'Command Completion Event' flags e:C
<idle>-0 [000] d.h. 75194.110295: xhci_handle_command: CMD: Set TR Dequeue Pointer Command: deq 000000041a5c5f10 stream 0 slot 2 ep 1 flags C
<idle>-0 [000] d.h. 75194.110299: xhci_handle_cmd_set_deq: RS 00004 full-speed Ctx Entries 7 MEL 0 us Port# 1/0 [TT Slot 1 Port# 4 TTT 0 Intr 0] Addr 2 State configured
<idle>-0 [000] d.h. 75194.110301: xhci_handle_cmd_set_deq_ep: State stopped mult 1 max P. Streams 0 interval 125 us max ESIT payload 0 CErr 3 Type Ctrl burst 0 maxp 8 deq 000000041a5c5f10 avg trb len 0
<idle>-0 [000] d.h. 75194.110303: xhci_dbg_cancel_urb: Successful Set TR Deq Ptr cmd, deq = @41a5c5f10
<idle>-0 [000] d.h. 75194.110308: xhci_inc_deq: CMD b9f7a832: enq 0x000000041a501930(0x000000041a501000) deq 0x000000041a501930(0x000000041a501000) segs 1 stream 0 free_trbs 254 bounce 0 cycle 1
<idle>-0 [000] d.h. 75194.110309: xhci_inc_deq: EVENT bc050dc9: enq 0x000000041a503000(0x000000041a503000) deq 0x000000041a507280(0x000000041a507000) segs 8 stream 0 free_trbs 2039 bounce 0 cycle 1There 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 saned:
$ 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 systemd socket unit saned.socket, even, if it is actually not necessary:
$ 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 xsane with the correct default device. This will connect to the listening socket, which then generates a systemd service unit on the server:
$ SANE_DEFAULT_DEVICE="net:<some_server_hostname>:genesys:libusb:001:005" xsaneServer
Look for the newly generated service unit:
$ 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 service unit and write its output to a text file:
$ 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 Scan and wait for the process to end. Close it afterwards.
Server
Analyse the text file saned@10-192.168.1.80:6566-192.168.1.81:54022.service.txt.
Failed: scanfailed-_saned@6-192.168.1.80:6566-192.168.1.81:53838.service.txt Successful: scansuccessful-_saned@3-192.168.1.80:6566-192.168.1.81:53710.service.txt
keks24
commented
2 years ago I might have found the solution, where the culprit might be (See below comment).USB autosuspending.
The udev rule file /lib/udev/rules.d/60-libsane.rules pointed that out:
[...]
# The following rule will disable USB autosuspend for the device
ENV{DEVTYPE}=="usb_device", ENV{libsane_matched}=="yes", TEST=="power/control", ATTR{power/control}="on"
[...]I followed these instructions to disable USB autosuspending:
$ 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 udev rules:
$ 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.
keks24
commented
2 years ago Unfortunately, disabling USB autosuspend is not the solution.
P33M
commented
2 years ago 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 dmesg --follow, and as soon as you get a disconnect event unplug the printer/scanner? Note that other devices such as mice will cause more tracelog clutter, so consider unplugging those before the scan starts and capturing the dmesg/trace via SSH.
keks24
commented
2 years ago Can you repeat the test but while observing dmesg --follow, and as soon as you get a disconnect event unplug the printer/scanner?
Sure!
One thing to note: saned gets triggered as soon as the scanner is unplugged and plugged into the USB port. I will provide these files as well.
scan_successful_and_unplugscanner-_dmesg.txt scan_successful_and_unplugscanner-_strace_saned.txt scan_successful_and_unplugscanner-_xhci-hcd.txt
unplug_and_plugscanner-_dmesg.txt unplug_and_plugscanner-_strace_saned.txt unplug_and_plugscanner-_trace_xhci-hcd.txt
The issue is not reproducible again. For now it is working.
I will provide the files, when it is failing again.
keks24
commented
2 years ago I could reproduce it again. This time, I kept xsane open and just unplugged the scanner after the issue occurred. Also, xsane did not return any error.
failed_scan_and_unplugscanner-_dmesg.txt failed_scan_and_unplugscanner-_strace_saned.txt failed_scan_and_unplugscanner-_xhci-hcd.txt
P33M
commented
2 years ago 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.
keks24
commented
2 years ago 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 saned and figured out, that the SANE project provides their own USB implementation (genesys is the driver of my scanner).
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 custom USB implementation and not the Linux Kernel.
I will forward this to the SANE backend team.
keks24
commented
2 years ago Ralph Little from the SANE backend issue:
I read the accompanying issue. SANE doesn't provide its own USB implementation. We have a sanei_* wrapper around libusb.
I have a suspicion that a lot of this has to do with USB chipset and the Linux kernel driver xhci.
I feel that quite a few people are experiencing similar issues including myself on my AM4 platform.
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?
keks24
commented
2 years ago 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_theprinter-_dmesg.txt connecting_failed_without_unplugging_theprinter-_trace_xhci-hcd.txt connecting_failed_with_unplugging_theprinter-_dmesg.txt connecting_failed_with_unplugging_theprinter-_trace_xhci-hcd.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: removedThere 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.
e-scheer
commented
2 years ago @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 ?
keks24
commented
1 year ago Today, I took a quick retour on this one, when I had a flash of insight. Disable USB autosuspend.
I actually tried before in this comment, but the following looks like the most promising one:
I don't know if it is the problem you have, but I have recently met some troubles using USB scanners on recent hardware with USB3. I eventually cured it by disabling USB powersaving with this kernel module option: modprobe usbcore autosuspend=-1
$ < "/sys/module/usbcore/parameters/autosuspend"
2
$ echo "-1" > "/sys/module/usbcore/parameters/autosuspend"
$ < "/sys/module/usbcore/parameters/autosuspend"
-1/etc/modprobe.d/usbcore.confusbcore is compiled with the kernel and not a module; see here)
# custom - 20221028 - rfischer: disable autosuspend
options usbcore autosuspend="-1"The Raspberry Pi OS is still Debian 10 (Buster):
$ < /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:
keks24
commented
1 year ago After seven consecutive scans and a few others with pauses inbetween, it is looking good so far!
P33M
commented
1 year ago 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.
keks24
commented
1 year ago False alarm. It is not working again.
I have removed the calibration file /var/lib/saned/.sane/Hewlett_Packard_Scanjet_2300c.cal before doing another scan and it worked; for now at least.
Also in /sys/bus/usb/devices/ I have set every [...]/power/autosuspend to -1 and [...]/power/control to on.
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 turning on and off individual USB ports or the entire hub.
keks24
commented
1 year ago Fingers crossed
I am going to answer this with this video (loud sound warning)
That's not it...
keks24
commented
1 year ago According to lsusb, device 1-1.3 is my scanner:
$ 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 USB devices after booting:
$ 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, /sys/bus/usb/devices/1-1.3/power/autosuspend_delay_ms, is set to 2000, which is two seconds and autosuspend is set to 0:
$ 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:
autosuspend_delay_ms to 0.If this is still not enough, I am going to set autosuspend_delay_ms to -1 and repeat steps 1 to 8.
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 USB 2.0 port to operate in USB 1.1 mode:
keks24
commented
1 year ago 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 ?
@e-scheer, I think, it has to do something with the controller of the hub itself. Maybe it periodically sends some kind of keep alive signal to the connected port to circumvent bugs?
Use a cheap USB 1.1 (or 2.0) hub and connect it to the USB3 port. Connect your device to the USB 1.1/2.0 hub. This will force the connection to be USB1.1/2.0. Since the hub has a different USB controller, it will workaround some protocol bugs. A USB 1.1 hub is a good choice for a "low speed" device like a mouse, keyboard etc. A USB 2.0 hub may well be necessary for a "full speed" device like a scanner that won't downgrade to USB 1.1.
keks24
commented
1 year ago OK, there seems to be a bug with the xhci_hcd driver, which controls the USB 3.0 and USB 2.0 ports. There is no ehci_hcd, which actually controls USB 2.0 ports:
$ 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 USB 2.0 port and does not want to come back:
$ 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 autosuspend to -1 connects the scanner, but the driver fails after a short period of time; ending in a loop, which stops at unable to enumerate USB device:
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 USB cable does nothing; reconnecting the electric plug also does nothing.
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
2. For Ubuntu 12.04 and Older Versions: https://www.ubuntubuzz.com/2016/06/reset-usb-20-ehci-usb-30-xhci-without-reboot-linux.htmlkeks24
commented
1 year ago Tinkering with the xhci_hcd driver:
Trying to disable the drvier. Append the kernel parameter initcall_blacklist (does not work):
$ < "/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 ehci_hcd or other drivers as fallback.
Append the kernel parameter usb-storage.quirks (does no good):
$ 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:
xhci_hcd driverehci_hcd drivermodprobeBonus:
companion file in order to downgrade a selected port to USB 1.1P33M
commented
1 year ago OK, there seems to be a bug with the
xhci_hcddriver, which controls theUSB 3.0andUSB 2.0ports. There is noehci_hcd, which actually controlsUSB 2.0ports:
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?
keks24
commented
1 year ago There are no EHCI companion controllers on a Pi 4.
I see, but manually compiling the Raspberry Pi Kernel and loading the ehci-hcd driver should be possible/compatible, shouldn't it?
Has it ever been the case that using an external USB2.0 hub did not result in a working scanner?
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...
keks24
commented
1 year ago Attempt to use the ehci_hcd driver:
Install tools to compile the Linux Kernel:
$ 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 ehci_hcd driver as module:
# set default configuration for "bcm2711" and save to "./.config"
$ KERNEL="kernel7l+" make --jobs="$(nproc --all)" bcm2711_defconfig
$ make menuconfig MENUCONFIG_COLOR="blackbg"Device Drivers --->
[*] USB support --->
<M> EHCI HCD (USB 2.0) support
[*] Root Hub Transaction Translators
[*] Improved Transaction Translator schedulingEHCI HCD (USB 2.0) support
```no-highlight
CONFIG_USB_EHCI_HCD:
The Enhanced Host Controller Interface (EHCI) is standard for USB 2.0
"high speed" (480 Mbit/sec, 60 Mbyte/sec) host controller hardware.
If your USB host controller supports USB 2.0, you will likely want to
configure this Host Controller Driver.
EHCI controllers are packaged with "companion" host controllers (OHCI
or UHCI) to handle USB 1.1 devices connected to root hub ports. Ports
will connect to EHCI if the device is high speed, otherwise they
connect to a companion controller. If you configure EHCI, you should
probably configure the OHCI (for NEC and some other vendors) USB Host
Controller Driver or UHCI (for Via motherboards) Host Controller
Driver too.
You may want to read
Root Hub Transaction Translators```no-highlight CONFIG_USB_EHCI_ROOT_HUB_TT: Some EHCI chips have vendor-specific extensions to integrate transaction translators, so that no OHCI or UHCI companion controller is needed. It's safe to say "y" even if your controller doesn't support this feature. This supports the EHCI implementation that's originally from ARC, and has since changed hands a few times. Symbol: USB_EHCI_ROOT_HUB_TT [=y] Type : bool Defined at drivers/usb/host/Kconfig:151 Prompt: Root Hub Transaction Translators Depends on: USB_SUPPORT [=y] && USB [=y] && USB_EHCI_HCD [=m] Location: -> Device Drivers -> USB support (USB_SUPPORT [=y]) -> EHCI HCD (USB 2.0) support (USB_EHCI_HCD [=m]) Selected by [n]: - USB_EHCI_FSL [=n] && USB_SUPPORT [=y] && USB [=y] && USB_EHCI_HCD [=m] - USB_EHCI_MV [=n] && USB_SUPPORT [=y] && USB [=y] && USB_EHCI_HCD [=m] && (ARCH_PXA [=n] || ARCH_MMP [=n] || COMPILE_TEST [=n]) - USB_CHIPIDEA_HOST [=n] && USB_SUPPORT [=y] && USB_CHIPIDEA [=n] && USB_EHCI_HCD [=m] ```
Improved Transaction Translator scheduling```no-highlight CONFIG_USB_EHCI_TT_NEWSCHED: This changes the periodic scheduling code to fill more of the low and full speed bandwidth available from the Transaction Translator (TT) in USB 2.0 hubs. Without this, only one transfer will be issued in each microframe, significantly reducing the number of periodic low/fullspeed transfers possible. If you have multiple periodic low/fullspeed devices connected to a highspeed USB hub which is connected to a highspeed USB Host Controller, and some of those devices will not work correctly (possibly due to "ENOSPC" or "-28" errors), say Y. Conversely, if you have only one such device and it doesn't work, you could try saying N. If unsure, say Y. Symbol: USB_EHCI_TT_NEWSCHED [=y] Type : bool Defined at drivers/usb/host/Kconfig:163 Prompt: Improved Transaction Translator scheduling Depends on: USB_SUPPORT [=y] && USB [=y] && USB_EHCI_HCD [=m] Location: -> Device Drivers -> USB support (USB_SUPPORT [=y]) -> EHCI HCD (USB 2.0) support (USB_EHCI_HCD [=m]) ```
P33M
commented
1 year ago 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.
keks24
commented
1 year ago I made it to compile just the module, but I am stuck activating it.
The only directory I can find is /sys/module/ehci_hcd/:
$ 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)What am I missing here?
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
pelwell
commented
1 year ago 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...
keks24
commented
1 year ago An update:
I have connected the before-mentioned USB hub to the USB 2.0 port passively, where I connected the scanner to. The hub is recognised as high-speed USB device (2.0):
$ 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 full-speed USB device (1.1):
$ 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 xhci driver, that it should always recognise the scanner as high-speed USB device.
I also found some useful information how to force the Raspberry Pi to use the ehci driver:
Next attempts:
Legend
[:heavy_plus_sign:] - Open Task
[:heavy_minus_sign:] - Currently testing
[:white_check_mark:] - Seems to work, needs more testing
[:heavy_check_mark:] - It works and task completed
[:x:] - Does not work and task completed
[:heavy_minus_sign:] Try to reproduce the issue with the scanner...
[:heavy_plus_sign:] Try to force the xhci driver to recognise the scanner as full-speed USB device.
[:heavy_plus_sign:] Try to use the ehci driver
[:heavy_plus_sign:] Install the newest 32bit Raspberry Pi OS
[:heavy_plus_sign:] Install the newest 64bit Raspberry Pi OS
keks24
commented
1 year ago 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.
| USB 2.0 hub (top view) | USB 2.0 hub (bottom view) |
|---|---|
 |
 |
| Oscilloscope images | ||
|---|---|---|
 |
 |
 |
P33M
commented
1 year ago 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 This adds a VL805 update on top of the latest bootloader release. Copy to a blank FAT-formatted SD card and power up the Pi 4 with it inserted. HDMI should display a green screen and the ACT LED will flash rapidly once the update is complete.
To revert to the official release, follow the instructions here - https://www.raspberrypi.com/documentation/computers/raspberry-pi.html#raspberry-pi-4-boot-eeprom
keks24
commented
1 year ago 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.
keks24
commented
1 year ago @P33M
I think, that fixed it; there are no issues at all! I also tested this on one of the USB 3.0 ports.
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 rpi-boot-eeprom-recovery-2022-12-07-vl805-000138a1-sd.zip.
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: 000138c0I 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:Preferences - Load device settingsand load this scanner configuration file for aHewlettPackard ScanJet 2300c. 5.1. Optionally configurexsanemanually 5.1.1. Setnumber of pages to scanto15.1.2. Settargettomultipage5.1.3. Configurexsane multpage project5.1.3.1. Setmultipage project directory nameto/tmp/deleteme5.1.3.2. Click on the buttonCreate project5.1.4. Setscan modetoGray5.1.5. Setsource medium typetoFull color range5.1.6. Setscan resolutionto1505.1.7. Setgammato0.875.1.8. Setbrightnessto-8.05.1.9. Setcontrastto50.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* ```bash $ uname -a Linux 5.10.60-v7l+ #1449 SMP Wed Aug 25 15:00:44 BST 2021 armv7l GNU/Linux
```
```bash
$ grep "Model" "/proc/cpuinfo"
Model : Raspberry Pi 4 Model B Rev 1.4
```
```bash
$ vcgencmd version
Aug 31 2021 14:52:47
Copyright (c) 2012 Broadcom
version 67615e950e1e28b92dfae6303cf7a8b879a8908f (clean) (release) (start)
```
```bash
$ < "/etc/rpi-issue"
Raspberry Pi reference 2021-01-11
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 21090519d85bdaa1615d5d5057d37b09368ea5d2, stage2
```
```bash
$ < "/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"
```
```bash
$ dpkg --list | grep "sane-utils"
ii sane-utils 1.0.27-3.2 armhf API library for scanners -- utilities
```
```bash
$ dpkg --list | grep "cups"
ii cups 2.2.10-6+deb10u4 armhf Common UNIX Printing System(tm) - PPD/driver support, web interface
ii cups-browsed 1.21.6-5+rpt1 armhf OpenPrinting CUPS Filters - cups-browsed
ii cups-client 2.2.10-6+deb10u4 armhf Common UNIX Printing System(tm) - client programs (SysV)
ii cups-common 2.2.10-6+deb10u4 all Common UNIX Printing System(tm) - common files
ii cups-core-drivers 2.2.10-6+deb10u4 armhf Common UNIX Printing System(tm) - driverless printing
ii cups-daemon 2.2.10-6+deb10u4 armhf Common UNIX Printing System(tm) - daemon
ii cups-filters 1.21.6-5+rpt1 armhf OpenPrinting CUPS Filters - Main Package
ii cups-filters-core-drivers 1.21.6-5+rpt1 armhf OpenPrinting CUPS Filters - Driverless printing
ii cups-ipp-utils 2.2.10-6+deb10u4 armhf Common UNIX Printing System(tm) - IPP developer/admin utilities
ii cups-ppdc 2.2.10-6+deb10u4 armhf Common UNIX Printing System(tm) - PPD manipulation utilities
ii cups-server-common 2.2.10-6+deb10u4 all Common UNIX Printing System(tm) - server common files
ii libcups2:armhf 2.2.10-6+deb10u4 armhf Common UNIX Printing System(tm) - Core library
ii libcupsfilters1:armhf 1.21.6-5+rpt1 armhf OpenPrinting CUPS Filters - Shared library
ii libcupsimage2:armhf 2.2.10-6+deb10u4 armhf Common UNIX Printing System(tm) - Raster image library
```
```bash
$ lsusb | grep "HP\|Samsung"
Bus 001 Device 003: ID 03f0:0901 HP, Inc ScanJet 2300c
Bus 001 Device 004: ID 04e8:3297 Samsung Electronics Co., Ltd ML-191x/ML-252x Laser Printer
$ lsusb -t
/: 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 4, If 0, Class=Printer, Driver=usblp, 12M
|__ Port 4: Dev 3, If 0, Class=Vendor Specific Class, Driver=, 12M
```
*Client*
```bash
$ uname --all
Linux 5.10.61-gentoo #1 SMP Fri Sep 3 08:57:37 CEST 2021 x86_64 Intel(R) Core(TM) i5-3450 CPU @ 3.10GHz GenuineIntel GNU/Linux
```
```bash
$ grep "SANE_BACKENDS" "/etc/portage/make.conf"
SANE_BACKENDS="net"
```
```bash
$ 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
```
```bash
$ 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 filters
```
Logs 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: