Bug 1563554 - systemd-udevd is cotinuously eating CPU and logging to journal: "Process 'hid2hci --method=dell ....' failed with e"
Summary: systemd-udevd is cotinuously eating CPU and logging to journal: "Process 'hid...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: bluez
Version: 29
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ---
Assignee: Don Zickus
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-04-04 07:35 UTC by Ankur Sinha (FranciscoD)
Modified: 2019-08-27 16:22 UTC (History)
15 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-08-04 17:35:23 UTC
Type: Bug


Attachments (Terms of Use)
screenshot showing systemd-udevd running continuously (201.27 KB, image/png)
2018-04-04 07:35 UTC, Ankur Sinha (FranciscoD)
no flags Details
Full journal logs (15.37 MB, text/plain)
2018-04-05 08:52 UTC, Ankur Sinha (FranciscoD)
no flags Details
output of: journalctl -b0 | tail -20 (3.57 KB, text/plain)
2018-11-01 12:18 UTC, Andrew Roberts
no flags Details
First 1200 lines of "journal -b0" from affected system (135.69 KB, text/plain)
2018-11-01 12:25 UTC, Andrew Roberts
no flags Details

Description Ankur Sinha (FranciscoD) 2018-04-04 07:35:56 UTC
Created attachment 1417081 [details]
screenshot showing systemd-udevd running continuously

Description of problem:
Just upgraded to F28. systemd-udevd is continously running, and logging to journalctl.

Version-Release number of selected component (if applicable):
systemd-udev-238-7.fc28.x86_64

How reproducible:
Always

Steps to Reproduce:
1. Reboot, watch it in htop and journalctl


Additional info:
On boot, this seems to be the first mention of the message:

Apr 04 08:10:05 ankur.pc systemd-udevd[518]: Process 'hid2hci --method=dell --devpath=/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.1/1-1.1.2/1-1.1.2:1.0' failed with e>


I'm not sure what it means.

Subsequently, it continues to log these:
Apr 04 08:24:40 ankur.pc upowerd[20110]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.1/1-1.1.2/1-1.1.2:1.0
Apr 04 08:24:40 ankur.pc systemd-udevd[514]: Process 'hid2hci --method=dell --devpath=/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.1/1-1.1.2/1-1.1.2:1.0' failed with e>

$ journalctl -b --no-pager | grep hid2hci | wc -l
55901

As the screenshot shows, it's been running throughout. It's still running now.


Thanks

Comment 1 Ankur Sinha (FranciscoD) 2018-04-04 23:36:22 UTC
Supressing logging with:

sudo udevadm control -l emerg

does not help. systemd-udevd is still eating CPU. Any hints/fixes would be appreciated :)

Cheers!

Comment 2 Ankur Sinha (FranciscoD) 2018-04-05 00:18:46 UTC
Somehow, that doesn't even reduce the logging:

$ journalctl -b --no-pager | grep hid2hci | wc -l
261374

It just won't stop.

I had no trouble in F27, but I don't know if this is a regression.

Comment 3 Zbigniew Jędrzejewski-Szmek 2018-04-05 06:45:38 UTC
It seems that there's some loop in udev rule processing. /usr/lib/udev/rules.d/97-hid2hci.rules contains a call to "/sbin/udevadm trigger", so my guess would be that this rule triggers itself over and over. The call to hd2hci that would cause the loop to be broken, fails.

It would be interesting to see what the hid2hci error is. Is the log line truncated like that in the journal? How are you extracting it?

Comment 4 Ankur Sinha (FranciscoD) 2018-04-05 08:43:39 UTC
Ah, no, I think this is the complete error:

Apr 05 09:32:23 ankur.pc systemd-udevd[507]: Process 'hid2hci --method=dell --devpath=/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.1/1-1.1.2/1-1.1.2:1.0' failed with exit code 1.


I don't know much about the hw side, but lspci -vv gives me this about what i think is the hw mentioned in the error above (00:1a.0) if that helps:

00:1a.0 USB controller: Intel Corporation 5 Series/3400 Series Chipset USB2 Enhanced Host Controller (rev 06) (prog-if 20 [EHCI])
        Subsystem: Dell Device 0440
        Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
        Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
        Latency: 0
        Interrupt: pin A routed to IRQ 16
        Region 0: Memory at fb408000 (32-bit, non-prefetchable) [size=1K]
        Capabilities: [50] Power Management version 2
                Flags: PMEClk- DSI- D1- D2- AuxCurrent=375mA PME(D0+,D1-,D2-,D3hot+,D3cold+)
                Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=0 PME-
        Capabilities: [58] Debug port: BAR=1 offset=00a0
        Capabilities: [98] PCI Advanced Features
                AFCap: TP+ FLR+
                AFCtrl: FLR-
                AFStatus: TP-
        Kernel driver in use: ehci-pci


I'm happy to provide more information if you can tell me how to get it :)

Thanks,
Ankur

Comment 5 Ankur Sinha (FranciscoD) 2018-04-05 08:52:03 UTC
Created attachment 1417566 [details]
Full journal logs

I've attached the full journal logs. Lots of these lines in journalctl too, for example.

Apr 05 09:45:11 ankur.pc upowerd[20590]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.1/1-1.1.2/1-1.1.2:1.0    

Eventually, I killed systemd-udevd, and then it didn't restart:

Apr 05 09:45:11 ankur.pc systemd[1]: systemd-udevd.service: Service has no hold-off time, scheduling restart.
Apr 05 09:45:11 ankur.pc systemd[1]: systemd-udevd.service: Scheduled restart job, restart counter is at 6.
Apr 05 09:45:11 ankur.pc systemd[1]: Stopped udev Kernel Device Manager.
Apr 05 09:45:11 ankur.pc systemd[1]: systemd-udevd.service: Start request repeated too quickly.
Apr 05 09:45:11 ankur.pc systemd[1]: systemd-udevd.service: Failed with result 'start-limit-hit'.
Apr 05 09:45:11 ankur.pc systemd[1]: Failed to start udev Kernel Device Manager.

Comment 6 Zbigniew Jędrzejewski-Szmek 2018-04-05 10:17:19 UTC
And what happens if you run:
/usr/lib/udev/hid2hci --method=dell --devpath=/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.1/1-1.1.2/1-1.1.2:1.0

I'm interested in any error messages from hid2hci itself.

Comment 7 Ankur Sinha (FranciscoD) 2018-04-05 11:07:27 UTC
Not much, I'm afraid:

$ sudo /usr/lib/udev/hid2hci --method=dell --devpath=/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.1/1-1.1.2/1-1.1.2:1.0 
error: switching device '/sys//devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.1/1-1.1.2/1-1.1.2:1.0' failed.

Comment 8 Ankur Sinha (FranciscoD) 2018-09-13 14:49:13 UTC
I'm still seeing this here. It doesn't affect the machine much after I login and kill systemd-udev manually. I can restart the service and it doesn't go nuts then. However, it hangs up the boot process, which now waits for the whole 2-3 minutes before quitting on this one particular service.

Any ideas towards a workaround maybe? Is it to do with a specific device I'm using for example? (A wireless microsoft keyboard/mouse for example?)

Comment 9 Ankur Sinha (FranciscoD) 2018-09-30 15:43:14 UTC
Just upgraded to F29, and still seeing this issue.

Comment 10 Andrew Roberts 2018-11-01 12:16:50 UTC
I am as seeing this after upgrading to Fedora 29.

194232 messages relating to this in journal in uptime of 55min.

I'll attach a small sample of the output. Laptop is a dell studio 17. I'll also include start of logfile with details of system.

Comment 11 Andrew Roberts 2018-11-01 12:18:11 UTC
Created attachment 1499960 [details]
output of: journalctl -b0 | tail -20

output of: journalctl -b0 | tail -20

Comment 12 Andrew Roberts 2018-11-01 12:25:30 UTC
Created attachment 1499975 [details]
First 1200 lines of "journal -b0" from affected system

First 1200 lines of "journal -b0" from affected system

Comment 13 tonynalagan@gmail.com 2019-05-04 15:24:49 UTC
SOLVED conflict with Dell/Broadcom 370 Wireless Bluetooth half card adapter on Dell Studio 1537


To fix issues please consider modifying  /lib/udev/rules.d/97-hid2hci.rules files from:

ATTR{bInterfaceClass}=="03", ATTR{bInterfaceSubClass}=="01", ATTR{bInterfaceProtocol}=="02", \
  ATTRS{bDeviceClass}=="00", ATTRS{idVendor}=="413c", ATTRS{bmAttributes}=="e0", \
  RUN+="hid2hci --method=dell --devpath=%p", ENV{HID2HCI_SWITCH}="1"

to:

ACTION=="add", ATTR{bInterfaceClass}=="03", ATTR{bInterfaceSubClass}=="01", ATTR{bInterfaceProtocol}=="02", \
  ATTRS{bDeviceClass}=="00", ATTRS{idVendor}=="413c", ATTRS{bmAttributes}=="e0", \
  RUN+="hid2hci --method=dell --devpath=%p", ENV{HID2HCI_SWITCH}="1"

Adding:

the ACTION=="add",

to the line fixed my issues with the Dell/Broadcom 370 Wireless Bluetooth half card adapter in my Dell Studio 1537.
Hopefully this fix will be helpful to others.

Comment 14 Zbigniew Jędrzejewski-Szmek 2019-05-04 17:03:28 UTC
/lib/udev/rules.d/97-hid2hci.rules is owned by bluez-hid2hci-5.50-6.fc30.x86_64.
Let's reassign.

Comment 15 Felipe Bessa Coelho 2019-05-24 12:53:33 UTC
> To fix issues please consider modifying  /lib/udev/rules.d/97-hid2hci.rules
> files from:
> 
> ATTR{bInterfaceClass}=="03", ATTR{bInterfaceSubClass}=="01",
> ATTR{bInterfaceProtocol}=="02", \
>   ATTRS{bDeviceClass}=="00", ATTRS{idVendor}=="413c",
> ATTRS{bmAttributes}=="e0", \
>   RUN+="hid2hci --method=dell --devpath=%p", ENV{HID2HCI_SWITCH}="1"
> 
> to:
> 
> ACTION=="add", ATTR{bInterfaceClass}=="03", ATTR{bInterfaceSubClass}=="01",
> ATTR{bInterfaceProtocol}=="02", \
>   ATTRS{bDeviceClass}=="00", ATTRS{idVendor}=="413c",
> ATTRS{bmAttributes}=="e0", \
>   RUN+="hid2hci --method=dell --devpath=%p", ENV{HID2HCI_SWITCH}="1"
> 
> Adding:
> 
> the ACTION=="add",
> 
> to the line fixed my issues with the Dell/Broadcom 370 Wireless Bluetooth
> half card adapter in my Dell Studio 1537.

This has fixed the issue for me too on my Dell Vostro 3500. My bluetooth devices:

$ lsusb | grep -i blue
Bus 001 Device 007: ID 413c:8160 Dell Computer Corp. Wireless 365 Bluetooth
Bus 001 Device 003: ID 0a5c:4500 Broadcom Corp. BCM2046B1 USB 2.0 Hub (part of BCM2046 Bluetooth)

Comment 16 Ankur Sinha (FranciscoD) 2019-08-04 17:35:23 UTC
I no longer have this hardware and cannot reproduce this issue, so I'll close this bug now. If someone else is seeing it too, please re-open.

Comment 17 tonynalagan@gmail.com 2019-08-21 03:48:47 UTC
bluez-hid2hci still hasn't been updated to reflect the fix as outlined in comment 13, 14, 15. This is a big problem with SilverBlue, since /lib/udev/rules.d/97-hid2hci.rules is on an immutable file system. I really like SilverBlue, but I can't fix this issue anymore. Also documentation on SilverBlue is lacking because it is new. Do I have to create a new RPM and install with rpm-ostree install. Please advise.

Comment 18 Rémi G. 2019-08-27 16:22:39 UTC
Same issue on a Dell Vostro 3300 with Fedora 30... And comment #13 solved my problem again.


Note You need to log in before you can comment on or make changes to this bug.