Events were blocked while poll next

[RolandMa1986]

While using Tokio-udev to monitor usb disk plugin events, We found that not all the events can be polled at sametime, but until plugin/unplugin a usb disk next time.

This issuse can be easily reproduced by partition a usb disk to 4 or more partitions.

[jeandudey]

Do you have some example code? So I can reproduce and track it down. Thanks for reporting!

[ajanon]

Hi,

I think we faced the same issue (or a very similar one) in swhkd.
This was reported on our side in waycrate/swhkd#162.

The test setup is rather simple: run the code below and connect/disconnect an input device (a keyboard or a mouse should do). Notice how some events are delayed. This may take more than one connect/disconnect.

Here is the MWE from the above issue to make it easier to track here.

use std::error::Error;
use std::time::{SystemTime, UNIX_EPOCH};
use tokio::select;
use tokio_stream::StreamExt;
use tokio_udev::{AsyncMonitorSocket, MonitorBuilder};

#[tokio::main]
async fn main() -> Result<(), Box<dyn Error>> {
    let mut udev = AsyncMonitorSocket::new(MonitorBuilder::new()?.match_subsystem("input")?.listen()?)?;
    loop {
        select! {
            Some(Ok(event)) = udev.next() => {
                println!("[{:?}] '{:?}' event - devnode: {:?}",
                         SystemTime::now().duration_since(UNIX_EPOCH)?.as_secs(),
                         event.event_type(),
                         event.devnode());
            }
        }
    }
}

For two disconnections/reconnections, this gives me (late events in bold):

[1663146903] 'Remove' event - devnode: Some("/dev/input/event3")
[1663146903] 'Remove' event - devnode: None
[1663146903] 'Remove' event - devnode: Some("/dev/input/event5")
[1663146903] 'Remove' event - devnode: None
[1663146903] 'Remove' event - devnode: Some("/dev/input/event6")
[1663146903] 'Remove' event - devnode: None
[1663146903] 'Remove' event - devnode: Some("/dev/input/event7")
[1663146903] 'Remove' event - devnode: Some("/dev/input/event8")
[1663146903] 'Remove' event - devnode: None
[1663146919] 'Remove' event - devnode: None
[1663146919] 'Add' event - devnode: None
[1663146919] 'Add' event - devnode: None
[1663146919] 'Add' event - devnode: None
[1663146919] 'Add' event - devnode: None
[1663146919] 'Add' event - devnode: None
[1663146919] 'Add' event - devnode: Some("/dev/input/event6")
[1663146919] 'Add' event - devnode: Some("/dev/input/event8")
[1663146919] 'Add' event - devnode: Some("/dev/input/event5")
[1663146919] 'Add' event - devnode: Some("/dev/input/event7")
[1663146925] 'Add' event - devnode: Some("/dev/input/event3")
[1663146925] 'Remove' event - devnode: Some("/dev/input/event3")
[1663146925] 'Remove' event - devnode: None
[1663146925] 'Remove' event - devnode: Some("/dev/input/event5")
[1663146925] 'Remove' event - devnode: None
[1663146925] 'Remove' event - devnode: Some("/dev/input/event6")
[1663146925] 'Remove' event - devnode: None
[1663146925] 'Remove' event - devnode: Some("/dev/input/event7")
[1663146925] 'Remove' event - devnode: None
[1663146925] 'Remove' event - devnode: Some("/dev/input/event8")
[1663146932] 'Remove' event - devnode: None
[1663146932] 'Add' event - devnode: None
[1663146932] 'Add' event - devnode: None
[1663146932] 'Add' event - devnode: None
[1663146932] 'Add' event - devnode: None
[1663146932] 'Add' event - devnode: None
[1663146932] 'Add' event - devnode: Some("/dev/input/event6")
[1663146932] 'Add' event - devnode: Some("/dev/input/event8")
[1663146932] 'Add' event - devnode: Some("/dev/input/event5")

Please note that here, the input which is the actual keyboard is /dev/input/event3 but it is passed to the application only after it has been removed again.

I do not understand why this happens. The most I was able to understand was that the stream sometimes got 'stuck' on Poll::Pending as if no new events were available (but there actually was).

Running udevadm monitor -s input at the same time shows events in real time with no lag.

Sample Cargo.toml used for this test:

[package]
name = "test_udev"
version = "0.1.0"
edition = "2021"

[dependencies]
tokio = { version = "1.23.0", features = ["full"] }
tokio-stream = "0.1.11"
tokio-udev = "0.8.0

[jeandudey]

I can reproduce it, I'll look into it, thanks for reporting

[CluelessTechnologist]

I've added a bounty to get this issue solved. Need it solved in order to fix another an issue in swhkd project.

[ghost]

• [CRITICAL] Bountysource is Insolvent, do not use! bountysource/core#1586

[jeandudey]

@CluelessTechnologist could you try reproducing on the recent master branch?

I've pushed @sjoerdsimons changes and it seems to be working as it essentially tries to drain the events before polling again which should be the right thing to do.

Let me know before pushing a 0.8 release.

[CluelessTechnologist]

I'm just a user. I'm not competent enough in Rust to be able to test this. Sorry. But I asked in swhkd matrix channel if there was someone from the dev team that could take a look. I don't know if @ajanon is able to test again perhaps?

Many thanks for fixing it though! Appreciate it!

[sjoerdsimons]

@jeandudey Mind that there is already a tokio-udev 0.8 on crates.io for some reason ; So for a new relese you probably want to bump to version 0.9 :)

[ajanon]

This solves the issue on swhkd's end perfectly, thanks a lot!

@jeandudey Unless the original reporter still has issues, I think you can close this. Could you push a new release with the latest changes?

@CluelessTechnologist Thanks for pinging me on this! You can test it on the udev_async branch on swhkd if you want to!

[jeandudey]

I've released v0.9.0 on crates.io.

Will close this issue as it appears solved, if not please reopen and let me know what needs to be done/fixed. Thanks guys!