5

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'
  1. 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 error 
    
  2. Finally, 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`
    
7
  • Do you know what your last working kernel was, and what your current kernel is? Aug 26 '19 at 16:11
  • A yes, sorry. I forgot to include that very important detail. Before I was running linux kernel 4.19.28 and now I am running 5.2.9 synced with Debian. I also have a copy of apt list --upgradable right before this error began occuring (it is a rather long list of over 200 packages) if that might be of use. I can however tell you that that the recent full-upgrade did not touch libinput as far as I can tell.
    – Neticegear
    Aug 26 '19 at 17:49
  • 1
    BTW: psmouse is for PS/2 mice; USB mice generally use usbhid. So blacklisting it (which should do nothing if it isn't being loaded anyway) shouldn't be an issue. And modprobe -r on a module that isn't loaded shouldn't do anything at all. It's very confusing that fixed the problem, if indeed lsmod | grep -i mouse showed nothing before running it!
    – derobert
    Aug 26 '19 at 17:58
  • @derobert, psmouse cannot be strictly for PS/2 mice as on another one of my systems (a laptop with synaptic touchpad) psmouse is actually responsible for the touchpad operation (in that case unloading and reloading it does typically fix all touchpad related issues and/or reload configuration). In this case however, there is no touchpad and the machine is not a laptop. Nevertheless, I upvoted because unloading a module that appears to play no role, shouldn't as you said, do anything at all.
    – Neticegear
    Aug 26 '19 at 18:06
  • I added lsmod | grep -i hid to the post for reference.
    – Neticegear
    Aug 26 '19 at 18:08

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.