lots of logging to /var/log/warn "Could not process a mouse event: receiving on a closed channel"

[ensonic]

Please describe the bug Since a kernel update the mounse is not detected at boot-up. This can be fixed with unplug/plug. Until that eruption logs repeadetly the same unactionable error message.:

2023-03-27T21:17:29.535014+02:00 locky locky eruption[982]: Could not process a mouse event: receiving on a closed channel
2023-03-27T21:17:29.535021+02:00 locky locky eruption[982]: An error occurred while closing the device
2023-03-27T21:17:29.535029+02:00 locky locky eruption[982]: Could not process a mouse event: receiving on a closed channel
2023-03-27T21:17:29.535080+02:00 locky locky eruption[982]: An error occurred while closing the device

Logs Please provide full logs: sudo journalctl -u eruption.service -b

Mär 27 21:18:05 locky systemd[1]: Starting Realtime RGB LED Driver for Linux...
Mär 27 21:18:05 locky eruption[958]: locky eruption[958]: ** EXPERIMENTAL DRIVERS are ENABLED, this may expose serious bugs! **
Mär 27 21:18:05 locky systemd[1]: Started Realtime RGB LED Driver for Linux.
Mär 27 21:18:07 locky.lan eruption[958]: locky eruption[958]: Step 1: Invalid result
Mär 27 21:18:18 locky.lan eruption[958]: locky eruption[958]: Socket error: Audio proxy disconnected
Mär 27 21:25:05 locky.lan eruption[958]: locky eruption[958]: More than 82 milliseconds of jitter detected!
Mär 27 21:25:05 locky.lan eruption[958]: locky eruption[958]: This means that we dropped at least one frame
Mär 27 21:25:05 locky.lan eruption[958]: locky eruption[958]: Loop took: 141 milliseconds, goal: 41
Mär 27 21:49:29 locky.lan eruption[958]: locky eruption[958]: Mouse device went away: No such device (os error 19)
Mär 27 21:49:29 locky.lan eruption[958]: locky eruption[958]: Error sending LED map to a device: Device not opened
Mär 27 21:49:29 locky.lan eruption[958]: locky eruption[958]: More than 82 milliseconds of jitter detected!
Mär 27 21:49:29 locky.lan eruption[958]: locky eruption[958]: This means that we dropped at least one frame
Mär 27 21:49:29 locky.lan eruption[958]: locky eruption[958]: Loop took: 181 milliseconds, goal: 41
Mär 27 21:49:29 locky.lan eruption[958]: locky eruption[958]: Error sending LED map to a device: Device not opened
Mär 27 21:49:29 locky.lan eruption[958]: locky eruption[958]: Could not process a mouse event: receiving on a closed channel
Mär 27 21:49:29 locky.lan eruption[958]: locky eruption[958]: An error occurred while closing the device
Mär 27 21:49:29 locky.lan eruption[958]: locky eruption[958]: Could not process a mouse event: receiving on a closed channel
Mär 27 21:49:29 locky.lan eruption[958]: locky eruption[958]: An error occurred while closing the device
Mär 27 21:49:29 locky.lan eruption[958]: locky eruption[958]: Could not process a mouse event: receiving on a closed channel
Mär 27 21:49:29 locky.lan eruption[958]: locky eruption[958]: An error occurred while closing the device
...

sudo journalctl -u eruption.service -b | wc -l
205021

Please complete the following information:

> eruption --version
Eruption 0.3.2 (0.3.2.r0.g35cce455) (release build)

> lsusb
Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 002 Device 003: ID 05e3:0716 Genesys Logic, Inc. Multislot Card Reader/Writer
Bus 002 Device 004: ID 046d:c077 Logitech, Inc. Mouse
Bus 002 Device 002: ID 05e3:0608 Genesys Logic, Inc. Hub
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 006 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 005 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 003 Device 003: ID 1e7d:30f7 ROCCAT ROCCAT Vulcan Pro
Bus 003 Device 004: ID 1e7d:2e2c ROCCAT ROCCAT Kone Aimo 16K
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

> uname -a
Linux locky.lan 6.2.8-1-default #1 SMP PREEMPT_DYNAMIC Wed Mar 22 18:56:06 UTC 2023 (221c28f) x86_64 x86_64 x86_64 GNU/Linux

[ensonic]

I had to stop/uininstall it, it was logging sooo much that m,y disk went full.

[ensonic]

Hmm, this is basically here: https://github.com/X3n0m0rph59/eruption/blob/master/eruption/src/main.rs#L745 I think it would be helpful to add more data to the error (e.g. which device) and then exit. Definitely don't log this repeatedly from the main loop. Computers are fast these days :)

[ensonic]

I have no experience with rust yet. I figured that there is a get_usb_path(), but have not tried how to call it. Anyway, I also have more details on how to trigger it.

1. When I start my computer the mouse works
2. When I log in the mouse stops working
3. When I unplug and re-plug it, it moves again, but then this error logging starts

Sounds like some issue with hotplug handling? Any pointers?

[derEremit]

I have the same problem I have a switch to use the mouse on a different pc. everytime I switch away the logging starts to fill up my disc

I am still on 0.3.0 btw. last version from ubuntu ppa

[X3n0m0rph59]

@ensonic @derEremit Thanks for reporting this issue!

I have implemented the following mitigations regarding the underlying problem of this issue:

• Implemented a simple rate-limiting functionality for log messages
• Provide better error messages; thanks to @ensonic for opening up a pull request
• Made the device handling code somewhat more resilient against device failures

The code has been pushed to the develop branch

[ensonic]

@X3n0m0rph59 thanks! I'll rebuild in a bit. Do you have any idea wrt the root-cause. I suspect something changed on the kernel side. Eruption was working fine for month.

[X3n0m0rph59]

@ensonic I am not inclined to blame the kernel for the issue... Maybe some external change triggered the problem, but I believe that the code for handling failed devices (inside the eruption daemon) was not as resilient as it should have been. There has been a problem with device hot-plug too, that contributed to the issue even further.

I believe that the new code is much more resilient in the presence of failed USB devices... And device hot-plug now works completely stable on my test hardware as well.

[X3n0m0rph59]

@ensonic I just switched the HIDAPI backend from libusb to hidraw. This may improve device interoperability in the presence of other drivers that try to access the USB devices. If you encounter spurious keypresses or other problems that could relate to the USB device layer, then please compile from this commit 3dcf521f52801d6b62c1e7c869fabd846eb2b70a That is the commit right before the one that introduces the switch of the HIDAPI backend.

[ensonic]

I've build and installed from 'develop' at 3dcf521f52801d6b62c1e7c869fabd846eb2b70a and it is looking good. Should I open a new ticket to discuss what it would take to get the ROCCAT Vulcan Pro series keyboard out of experimental (its working fine with all features as far as I can tell).

[X3n0m0rph59]

@ensonic Glad to hear that it seems to work now!

[X3n0m0rph59]

@ensonic Yes, please create a new issue for tracking progress on stabilizing the ROCCAT Vulcan Pro