Bug 203741 - Wireless devices dongles (C517/Mosart) take 2-3 min to load after boot
Summary: Wireless devices dongles (C517/Mosart) take 2-3 min to load after boot
Status: RESOLVED CODE_FIX
Alias: None
Product: Drivers
Classification: Unclassified
Component: Input Devices (show other bugs)
Hardware: x86-64 Linux
: P1 normal
Assignee: drivers_input-devices
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-05-28 13:13 UTC by Mike Noe
Modified: 2019-06-18 15:47 UTC (History)
5 users (show)

See Also:
Kernel Version: 5.2rc1/rc2
Subsystem:
Regression: No
Bisected commit-id:


Attachments
dmesg (72.30 KB, text/plain)
2019-05-28 13:20 UTC, Mike Noe
Details
journalctl -b | grep -iE "kernel|udev" (95.00 KB, text/plain)
2019-05-28 13:35 UTC, Mike Noe
Details
lsmod before devs (3.43 KB, text/plain)
2019-05-28 14:05 UTC, Mike Noe
Details
lsmod after (3.54 KB, text/plain)
2019-05-28 14:06 UTC, Mike Noe
Details
dmesg after reverting two commits (72.93 KB, text/plain)
2019-06-03 13:58 UTC, Mike Noe
Details

Description Mike Noe 2019-05-28 13:13:01 UTC
I'm running Tumbleweed with the Kernel 5.2-RC2 with the following input devices:

(Logitech EX110) ID 046d:c517 Logitech, Inc. LX710 Cordless Desktop Laser
(Tecknet coreless optical mouse) ID 062a:4102 MosArt Semiconductor Corp.

I have no KVM on this machine.

If I set-default target multi-user, boot to 5.2, I have to wait anywhere from 160 to 185 seconds before these devices come on-line (I can see the msgs from dmesg), at which point, I can login, start the display server and enter Plasma.  

If I set-default target to graphical/auto-login to the Plasma DE, then the devices do not become available at all (after waiting 3mins plus) and I have to magic-key out.
Comment 1 Mike Noe 2019-05-28 13:20:45 UTC
Created attachment 282985 [details]
dmesg

See the 3 min delay for the devs coming on-line
Comment 2 Mike Noe 2019-05-28 13:35:40 UTC
Created attachment 282987 [details]
journalctl -b | grep -iE "kernel|udev"
Comment 3 Mike Noe 2019-05-28 14:05:46 UTC
Created attachment 282989 [details]
lsmod before devs

[Quote=Hans]
Can you please run lsmod *before* the devices show up in dmesg and
again after they show up and include the output of both commands in
the bug.[/quote]

I had to find an old wired keyboard to get this.  And also, my comment in the email regarding Plasma5 was incorrect.  After getting to Plasma DE, waiting for the devs to come online, they are then available to the Desktop.
Comment 4 Mike Noe 2019-05-28 14:06:11 UTC
Created attachment 282991 [details]
lsmod after
Comment 5 Hans de Goede 2019-06-03 09:29:36 UTC
Ok, so for some reason the modprobe of the 2 modules for the mouse and keyboard is taking very long, looking at the 2 lsmods:

--- Download/lsmod-before.log   2019-06-03 11:22:19.084063223 +0200
+++ Download/lsmod-after.log    2019-06-03 11:22:20.580077384 +0200
@@ -1,10 +1,13 @@
 Module                  Size  Used by
+hid_logitech_hidpp     45056  0
+joydev                 28672  0
+hid_logitech_dj        28672  0
 af_packet              53248  2
 scsi_transport_iscsi   122880  1
 msr                    16384  0

In our email exchange you said you can build your own kernels, can you try reverting these 2 commits:

git revert 4ceabaf79
git revert a025a18fe

Besides making changes to the logitech code I also submitted 2 patches to
optimize HID driver loading, but these 2 seem to be causing problems for various users.

I expect reverting these 2 to get rid of the delay.

After booting a 5.2 kernel with these 2 reverts, can you please do:

dmesg > dmesg.log

And attach the new dmesg.log here?
Comment 6 Hans de Goede 2019-06-03 10:22:57 UTC
I've another request, what is the setting of the CONFIG_RANDOM_TRUST_CPU Kconfig option in the .config file for your kernel?

If that is not set, it would also be interesting to try setting that to Y and see if that fixes the delay without needing to revert those 2 patches.
Comment 7 Mike Noe 2019-06-03 11:48:51 UTC
CONFIG_RANDOM_TRUST_CPU is set to Y for my current kernel 5.2RC2.
Comment 8 Hans de Goede 2019-06-03 12:43:31 UTC
(In reply to Mike Noe from comment #7)
> CONFIG_RANDOM_TRUST_CPU is set to Y for my current kernel 5.2RC2.

Ok, so that is not the problem then, too bad (it was a bit of a long shot anyways).
Comment 9 Mike Noe 2019-06-03 13:58:55 UTC
Created attachment 283053 [details]
dmesg after reverting two commits

Well, yes, you called it right.  I took linus/master (RC3) and reverted those two commits and now USB devs (keyboard/mouse) are all working as expected, no delay after boot.

FWIW, I'm running MSI Tomahawk/AM4/Ryzen5
Comment 10 Hans de Goede 2019-06-03 14:13:35 UTC
Thanks, the dmesg looks good, logitech-dj still loads as expected.

Can you do:

cat /proc/sys/kernel/modprobe

And paste the output?  we are still trying to find out why those 2 commits are causing problems for some users, while they work fine for others (including for both me and Benjamin who both have tested them extensively).
Comment 11 Mike Noe 2019-06-03 14:48:32 UTC
/sbin/modprobe
Comment 12 Hans de Goede 2019-06-03 14:53:47 UTC
(In reply to Mike Noe from comment #11)
> /sbin/modprobe

Ok, so nothing special there.
Comment 13 Sinisa Bandin 2019-06-03 19:39:11 UTC
Similar problem here, with kernel 5.2rc2 from opensuse HEAD, only it takes "just" 30 seconds to initialize:

[Thu May 30 08:29:20 2019] random: crng init done
[Thu May 30 08:29:20 2019] random: 7 urandom warning(s) missed due to ratelimiting
... 30 seconds wait ...
[Thu May 30 08:29:51 2019] input: Logitech USB Receiver as /devices/pci0000:00/0000:00:02.0/usb2/2-3/2-3:1.0/0003:046D:C517.0001/input/input5
[Thu May 30 08:29:51 2019] hid-generic 0003:046D:C517.0001: input,hidraw0: USB HID v1.10 Keyboard [Logitech USB Receiver] on usb-0000:00:02.0-3/input0
[Thu May 30 08:29:51 2019] input: Logitech USB Receiver Mouse as /devices/pci0000:00/0000:00:02.0/usb2/2-3/2-3:1.1/0003:046D:C517.0002/input/input6
[Thu May 30 08:29:51 2019] input: Logitech USB Receiver Consumer Control as /devices/pci0000:00/0000:00:02.0/usb2/2-3/2-3:1.1/0003:046D:C517.0002/input/input7
[Thu May 30 08:29:51 2019] input: Logitech USB Receiver System Control as /devices/pci0000:00/0000:00:02.0/usb2/2-3/2-3:1.1/0003:046D:C517.0002/input/input8
[Thu May 30 08:29:51 2019] hid-generic 0003:046D:C517.0002: input,hiddev96,hidraw1: USB HID v1.10 Mouse [Logitech USB Receiver] on usb-0000:00:02.0-3/input1
[Thu May 30 08:29:51 2019] usbcore: registered new interface driver usbhid [Thu May 30 08:29:51 2019] usbhid: USB HID core driver
[Thu May 30 08:29:51 2019] logitech-djreceiver 0003:046D:C517.0001: hidraw0:USB HID v1.10 Keyboard [Logitech USB Receiver] on usb-0000:00:02.0-3/input0
[Thu May 30 08:29:51 2019] systemd-journald[217]: Received SIGTERM from PID 1 (systemd).
[Thu May 30 08:29:51 2019] logitech-djreceiver 0003:046D:C517.0002:hiddev96,hidraw1: USB HID v1.10 Mouse [Logitech USB Receiver] on usb-0000:00:02.0-3/input1
[Thu May 30 08:29:51 2019] logitech-djreceiver 0003:046D:C517.0002: device of type 27 Mhz (0x02) connected on slot 1
[Thu May 30 08:29:51 2019] logitech-djreceiver 0003:046D:C517.0002: device of type 27 Mhz (0x02) connected on slot 3
[Thu May 30 08:29:51 2019] printk: systemd: 12 output lines suppressed due to ratelimiting
[Thu May 30 08:29:53 2019] logitech-hidpp-device 0003:046D:000A.0003: HID++ 1.0 device connected.
[Thu May 30 08:29:53 2019] input: Logitech Wireless Mouse PID:000a as /devices/pci0000:00/0000:00:02.0/usb2/2-3/2-3:1.1/0003:046D:C517.0002/0003:046D:000A.0003 input/input11
[Thu May 30 08:29:53 2019] logitech-hidpp-device 0003:046D:000A.0003: input,hidraw2: USB HID v1.11 Mouse [Logitech Wireless Mouse PID:000a] on usb-0000:00:02.0-3/input1:1
[Thu May 30 08:29:53 2019] logitech-hidpp-device 0003:046D:005E.0004: HID++ 1.0 device connected. 
[Thu May 30 08:29:53 2019] input: Logitech Wireless Keyboard PID:005e as /devices/pci0000:00/0000:00:02.0/usb2/2-3/2-3:1.1/0003:046D:C517.0002/0003:046D:005E.0004/input/input12
[Thu May 30 08:29:53 2019] logitech-hidpp-device 0003:046D:005E.0004: input,hidraw3: USB HID v1.11 Keyboard [Logitech Wireless Keyboard PID:005e] on usb-0000:00:02.0-3/input1:3


Motherboard is Gigabyte 970-GAMING, Logitech device is Cordless Desktop 650.
Comment 14 Kostiantyn Miklevskyi 2019-06-09 20:41:00 UTC
Have the same problem. My Logitech M325 mouse starts working after a delay of 2-3 minutes if hot plugged into running laptop. OR and WILL cause the 2-3 minutes delay if I turn on my laptop with a receiver plugged in. If it is not plugged kernel starts without a delay.
Comment 15 Elimar Riesebieter 2019-06-10 20:16:49 UTC
(In reply to Hans de Goede from comment #5)
> Ok, so for some reason the modprobe of the 2 modules for the mouse and
> keyboard is taking very long, looking at the 2 lsmods:
> 
> --- Download/lsmod-before.log   2019-06-03 11:22:19.084063223 +0200
> +++ Download/lsmod-after.log    2019-06-03 11:22:20.580077384 +0200
> @@ -1,10 +1,13 @@
>  Module                  Size  Used by
> +hid_logitech_hidpp     45056  0
> +joydev                 28672  0
> +hid_logitech_dj        28672  0
>  af_packet              53248  2
>  scsi_transport_iscsi   122880  1
>  msr                    16384  0
> 
> In our email exchange you said you can build your own kernels, can you try
> reverting these 2 commits:
> 
> git revert 4ceabaf79
> git revert a025a18fe
> 

I can confirm that reverting those commits solve my problem described at 
https://bugzilla.kernel.org/show_bug.cgi?id=203807
Comment 16 Hans de Goede 2019-06-11 08:43:49 UTC
The 2 reverts fixing this are queued up for merging in: https://git.kernel.org/pub/scm/linux/kernel/git/hid/hid.git/log/?h=for-5.2/fixes

So they should show up in an upcoming 5.2-rc# release.
Comment 17 Elimar Riesebieter 2019-06-17 10:18:01 UTC
(In reply to Hans de Goede from comment #16)
> The 2 reverts fixing this are queued up for merging in:
> https://git.kernel.org/pub/scm/linux/kernel/git/hid/hid.git/log/?h=for-5.2/
> fixes
> 
> So they should show up in an upcoming 5.2-rc# release.

5.2-rc5 works like a charm

Thanks for cooperation
Elimar
Comment 18 Sinisa Bandin 2019-06-18 15:47:30 UTC
Working on 5.2-rc5 too. Also, first time I can see any kind of battery status for my (old) Logitech Desktop, however inaccurate may it be (in sysfs I can find only High and Low values, while KDE battery monitor jumps from 70% when idle to 10% when typing more than a few characters, then back to 70%. I was sooooo happy when first "Low keyboard battery" notification jumped out - Windows did that back in 1990's, but after a few minutes had to reduce it's sensitivity to <10% because it was annoying. Did not have time to try new batteries, maybe tomorrow). 
I'll have to wait until one of the batteries goes dead to see what will it say then...

Thank you, and keep up the good work!

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