After the most recent apt full-upgrade that included a kernel update, I have now twice encountered a rather strange problem, and more importantly I cannot for the life of me figure out how and why the only solution I have found actually fixes it.
Twice now, while sitting idle for 20-30 minutes while watching a video, my mouse (Logitech M510, which has been working flawlessly and I am almost certain is not where the problem lies, as I will describe below) has been disabling the pointer, yet keeping the buttons functional.
1. Batteries have been swapped, mouse has been turned off and back on several times, neither of which makes any difference.
2. Likewise, removing the usb unifying receiver does not resolve the issue.
3. dmesg does not register any errors, warnings. When the receiver gets re-plugged the output is as normal as ever:
usb 4-1.1: USB disconnect, device number 3
usb 4-1.1: new full-speed USB device number 5 using ehci-pci
usb 4-1.1: New USB device found, idVendor=046d, idProduct=c52b, bcdDevice=24.07
usb 4-1.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
usb 4-1.1: Product: USB Receiver
usb 4-1.1: Manufacturer: Logitech
logitech-djreceiver 0003:046D:C52B.0008: hiddev0,hidraw0: USB HID v1.11 Device [Logitech USB Receiver] on usb-0000:00:1d.0-1.1/input2
input: Logitech M510 as /devices/pci0000:00/0000:00:1d.0/usb4/4-1/4-1.1/4-1.1:1.2/0003:046D:C52B.0008/0003:046D:4051.0009/input/input38
logitech-hidpp-device 0003:046D:4051.0009: input,hidraw1: USB HID v1.11 Mouse [Logitech M510] on usb-0000:00:1d.0-1.1/input2:1
input: Logitech K350 as /devices/pci0000:00/0000:00:1d.0/usb4/4-1/4-1.1/4-1.1:1.2/0003:046D:C52B.0008/0003:046D:200A.000A/input/input39
logitech-hidpp-device 0003:046D:200A.000A: input,hidraw2: USB HID v1.11 Keyboard [Logitech K350] on usb-0000:00:1d.0-1.1/input2:2
4. xinput test [mouse] and xev respond to the button presses but do not register any pointer movement i.e. nothing gets recorded in the terminal.
5. Using solaar show (logitech receiver cli) when the mouse pointer is not working and when I fix it, does not show any differences except in the Device activity counters: 1=18, 2=12 line. The combined output for the receiver and mouse while its malfunctioning looks like this:
Unifying Receiver
Device path : /dev/hidraw0
USB id : 046d:c52b
Serial : AD33D9EE
Firmware : 24.07.B0030
Bootloader : 02.09
Other : AA.AC
Has 2 paired device(s) out of a maximum of 6.
Notifications: wireless, software present (0x000900)
Device activity counters: 1=18, 2=12
Wireless Mouse M510
Codename : M510v2
Kind : mouse
Wireless PID : 4051
Protocol : HID++ 4.5
Polling rate : 8 ms (125Hz)
Serial number: AD33D9EE
Firmware: RQM 62.00.B0013
The power switch is located on the base.
Supports 22 HID++ 2.0 features:
0: ROOT {0000}
1: FEATURE SET {0001}
2: DEVICE FW VERSION {0003}
3: DEVICE NAME {0005}
4: RESET {0020}
5: BATTERY STATUS {1000}
6: unknown:1802 {1802} internal, hidden
7: unknown:1810 {1810} internal, hidden
8: unknown:1830 {1830} internal, hidden
9: unknown:1862 {1862} internal, hidden
10: unknown:1890 {1890} internal, hidden
11: unknown:18A0 {18A0} internal, hidden
12: unknown:18B1 {18B1} internal, hidden
13: REPROG CONTROLS V4 {1B04}
14: WIRELESS DEVICE STATUS {1D4B}
15: unknown:1DF0 {1DF0} hidden
16: unknown:1DF3 {1DF3} internal, hidden
17: unknown:1E00 {1E00} hidden
18: unknown:1EB0 {1EB0} internal, hidden
19: unknown:1F03 {1F03} internal, hidden
20: LOWRES WHEEL {2130}
Wheel Reports: HID
21: POINTER SPEED {2205}
Pointer Speed: 1.0
Has 7 reprogrammable keys:
0: LEFT CLICK , default: LeftClick => LEFT CLICK
divertable, mse, pos:0, group:1, gmask:1
1: RIGHT CLICK , default: RightClick => RIGHT CLICK
divertable, mse, pos:0, group:1, gmask:1
2: MIDDLE BUTTON , default: MiddleMouseButton => MIDDLE BUTTON
divertable, mse, reprogrammable, pos:0, group:2, gmask:3
3: LEFT SCROLL AS AC PAN , default: HorzScrollLeftSet => LEFT SCROLL AS AC PAN
divertable, mse, reprogrammable, pos:0, group:2, gmask:3
4: RIGHT SCROLL AS AC PAN , default: HorzScrollRightSet => RIGHT SCROLL AS AC PAN
divertable, mse, reprogrammable, pos:0, group:2, gmask:3
5: BACK AS BUTTON 4 , default: BackEx => BACK AS BUTTON 4
divertable, mse, reprogrammable, pos:0, group:2, gmask:3
6: FORWARD AS BUTTON 5 , default: BrowserForwardEx => FORWARD AS BUTTON 5
divertable, mse, reprogrammable, pos:0, group:2, gmask:3
Battery: 90%, discharging.
When I use diff on the before and after solaar show outputs, the only difference I get is this:
< Device activity counters: 1=18, 2=12
---
> Device activity counters: 1=77, 2=212
7. I have not tried simply rebooting the system when the problem occurs yet, as both times this happened I was in the middle of working on things and preserving data was the priority. This being said, I would be greatly surprised if a reboot did not restore the pointer functionality.
8. And Finally, I cannot figure out why the only way I have been able to fix this mid-session, without resorting to a reboot, has been by running:
sudo modprobe -r psmouse
My original goal was to run sudo modprobe -r psmouse followed by sudo modprobe psmouse to essentially reload it, but simply removing psmouse module restored the functionality already. Running lsmod | grep -i mouse lists no psmouse or any other *mouse* modules (psmouse was the first and thus far the only mouse related module I tried reloading).
This leads me to think that there might be some sort of interference between psmouse and the hid_logitech_hidpp kernel module that controls both the wireless keyboard and the mouse, possibly related to sleep and power management (However, the /sys/device/[mouse]/power/* values appear to be the same when the error occurs and when its fixed) but I also have never heard of selective wake-up of a passive peripheral device.
Finally, while blacklisting psmouse could prevent this from happening again, I am wary of doing that as a solution, because as far as I can tell, it would ultimately disable wired mice from being recognized, without first needing to load the psmouse module.
Any ideas for what, where to look for to narrow down the cause of this behavior?
$ lsmod | grep hid
hid_logitech_hidpp 45056 0
hid_logitech_dj 28672 0
hid_generic 16384 0
usbhid 65536 1 hid_logitech_dj
hid 139264 4 usbhid,hid_generic,hid_logitech_dj,hid_logitech_hidpp
usbcore 299008 8 xhci_hcd,ehci_pci,usbhid,ehci_hcd,xhci_pci
As well as list of dpkg --list | grep -i libhid
ii libhidapi-dev:amd64 0.9.0+dfsg-1 amd64 Multi-Platform library for communication with HID devices (development files)
ii libhidapi-hidraw0:amd64 0.9.0+dfsg-1 amd64 Multi-Platform library for communication with HID devices (hidraw backend)
ii libhidapi-libusb0:amd64 0.9.0+dfsg-1 amd64 Multi-Platform library for communication with HID devices (libusb backend)
ii libhidrd0:amd64 0.2.0-11 amd64 runtime library for parsing and generating USB HID reports
ii libhidrd0-dev:amd64 0.2.0-11 amd64 development files for parsing and generating USB HID reports
Update
Here are some additional logs pulled using solaar -dd that I have been able to gather once I found a way to consistently reproduce this error.
This first one is related to the current battery state, and its corresponding notification. While unlikely, this could somehow still be related to the cause because to be honest I do not recall the battery state of the mouse being previously available, and now it can be polled. However, this error notification does repeat when the mouse is functional, so I doubt it.
WARNING [ReceiverListener:hidraw1] logitech_receiver.status: <PairedDevice(1,4051,M510v2)>: battery 70%, ALERT invalid battery
ERROR [ReceiverListener:hidraw1] logitech_receiver.listener: processing Notification(1,05,00,46050000000000000000000000000000)
Traceback (most recent call last):
File "/usr/share/solaar/lib/logitech_receiver/listener.py", line 185, in run
self._notifications_callback(n)
File "/usr/share/solaar/lib/solaar/listener.py", line 220, in _notifications_handler
_notifications.process(dev, n)
File "/usr/share/solaar/lib/logitech_receiver/notifications.py", line 54, in process
return _process_device_notification(device, status, notification)
File "/usr/share/solaar/lib/logitech_receiver/notifications.py", line 115, in _process_device_notification
return _process_feature_notification(device, status, n, feature)
File "/usr/share/solaar/lib/logitech_receiver/notifications.py", line 209, in _process_feature_notification
status.set_battery_info(discharge, _hidpp20.BATTERY_STATUS[battery_status])
File "/usr/share/solaar/lib/logitech_receiver/status.py", line 205, in set_battery_info
reason = _("Battery: %(percent)d%% (%(status)s)") % { 'percent': level, 'status': _(status) }
File "/usr/share/solaar/lib/logitech_receiver/i18n.py", line 29, in <lambda>
_ = lambda x: _gettext.gettext(x).decode('UTF-8')
AttributeError: 'NamedInt' object has no attribute 'decode'
This second log is very difficult to read for now, but I think once I decode the hexagonal hidpp communication I will have some idea what the receiver is actually trying to do to the mouse. For now it looks like the receiver is either sending or receiving (have not figured out which way it goes yet with the
w[] and the r[])the same response of r[10 01 8F00 0F0900]18:55:44,573 WARNING [ReceiverListener:hidraw1] logitech_receiver.base: timeout (4.00/4.00) on device 1 request {000F} params [2120] 18:55:44,573 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) <= w[10 01 000F 212100] 18:55:44,577 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) => r[10 01 8F00 0F0900] 18:55:44,577 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) device 0x01 error on request {000F}: 9 = resource error 18:55:44,577 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) <= w[10 01 000A 212100] 18:55:44,579 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) => r[20 02 4101 0A201A4000000400000000] 18:55:44,581 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) => r[20 00 4102 0000000000000000000000] 18:55:44,583 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) => r[10 01 8F00 0A0900] 18:55:44,583 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) device 0x01 error on request {000A}: 9 = resource error 18:55:44,583 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) <= w[10 01 000C 40A000] 18:55:44,585 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) => r[10 01 8F00 0C0900] 18:55:44,585 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) device 0x01 error on request {000C}: 9 = resource error 18:55:44,585 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) <= w[10 01 0009 40A200] 18:55:44,587 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) => r[10 01 8F00 090900] 18:55:44,587 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) device 0x01 error on request {0009}: 9 = resource error 18:55:44,587 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) <= w[10 01 0008 40A300] 18:55:44,589 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) => r[10 01 8F00 080900] 18:55:44,589 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) device 0x01 error on request {0008}: 9 = resource error 18:55:44,589 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) <= w[10 01 000C 220100] 18:55:44,591 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) => r[10 01 8F00 0C0900] 18:55:44,591 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) device 0x01 error on request {000C}: 9 = resource error 18:55:44,591 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) <= w[10 01 000C 211000] 18:55:44,593 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) => r[10 01 8F00 0C0900] 18:55:44,593 DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) device 0x01 error on request {000C}: 9 = resource errorFinally, even when I try to unpair and then pair the nouse back, it still doesn't work, and the debug log shows these lines:
INFO [ReceiverListener:hidraw1] solaar.listener: Notification(2,41,04,B10A20) triggered new device <PairedDevice(2,200A,K350)> (keyboard) INFO [ReceiverListener:hidraw1] solaar.listener: status_changed <UnifyingReceiver(/dev/hidraw1,15)>: present, 1 paired device. (0) DEBUG [ReceiverListener:hidraw1] logitech_receiver.notifications: <PairedDevice(2,200A,K350)>: unifying (eQuad DJ) connection notification: software=True, encrypted=True, link=True, payload=True INFO [ReceiverListener:hidraw1] solaar.listener: status_changed <PairedDevice(2,200A,K350)>: paired online, {'BATTERY LEVEL': NamedInt(90, 'full'), 'BATTERY CHARGING': False, 'BATTERY STATUS': NamedInt(0, 'discharging'), 'LINK ENCRYPTED': True, 'NOTIFICATION FLAGS': 1048576, 'ERROR': None} (0) WARNING [ReceiverListener:hidraw1] logitech_receiver.notifications: <PairedDevice(2,200A,K350)>: unrecognized Notification(2,42,00,0000000000000000000000) DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) <= w[10 FF 83B5 200000] DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) => r[10 FF 8F83 B50300] DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) device 0xFF error on request {83B5}: 3 = invalid value DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) <= w[10 FF 83B5 040000] DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) => r[10 FF 8F83 B50300] DEBUG [ReceiverListener:hidraw1] logitech_receiver.base: (15) device 0xFF error on request {83B5}: 3 = invalid value ERROR [ReceiverListener:hidraw1] logitech_receiver.receiver: failed to read Nano wpid for device 1 of <UnifyingReceiver(/dev/hidraw1,15)> ERROR [ReceiverListener:hidraw1] logitech_receiver.receiver: register_new_device Traceback (most recent call last): File "/usr/share/solaar/lib/logitech_receiver/receiver.py", line 415, in register_new_device dev = PairedDevice(self, number, notification) File "/usr/share/solaar/lib/logitech_receiver/receiver.py", line 103, in __init__ raise _base.NoSuchDevice(number=number, receiver=receiver, error="read Nano wpid") NoSuchDevice: {'error': u'read Nano wpid', 'number': 1, 'receiver': <UnifyingReceiver(/dev/hidraw1,15)>} WARNING [ReceiverListener:hidraw1] logitech_receiver.receiver: <UnifyingReceiver(/dev/hidraw1,15)>: looked for device 1, not found WARNING [ReceiverListener:hidraw1] solaar.listener: <UnifyingReceiver(/dev/hidraw1,15)>: received Notification(1,40,00,0000000000000000000000) for invalid device 1: None`
