Tokio runtime stucks in some circumstances #4389

manio · 2022-01-08T19:16:20Z

manio
Jan 8, 2022

Hi Guys,
I have to ask you for help.
I am trying to debug one of the most irritating issue - tokio runtime stucking.
I have a project which is using an AsyncFile for reading /dev/ttyACM0 tty device (cdc-acm linux kernel driver).
I am doing this after a @Darksonn pointing this out in #3711 (comment).

Brief description of my problem:
I am using this AsyncFile implementation. It is based on official documentation example. So i believe it is now using epoll().
First of all please take a look if it is ok. Maybe I have screw something...
This is because I want to be able to read this file with timeout even when the device suddently disappear (and not leak descriptor as I have described in #3711).
I am using tokio::time::timeout on top of read future.

Most of the time my application is working perfectly fine: the device is properly read; when I disconnect the device, and reconnect, then the read future is properly terminating with the error. When there is no data to read, the future correclyt timeouts with 'deadline elapsed'. All is working perfectly great.

The problem is that occasionally (about once a week) the cdc-acm driver stuck in an weird state (this is my assumption).
When it happen, then all tokio runtime suddently stops. I mean that my main application is working but the tokio tasks, even the not related are in a 'freeze' state.

Now the interesting part:
I discovered that I can reset the /dev/ttyACM0 corresponding USB device using ioctl.
To be precise I am using this call:

ioctl(fd, USBDEVFS_RESET, 0);

from quite different C program. As the result I have in dmesg:

[Sat Jan  8 18:34:02 2022] usb 1-1.3.4: reset full-speed USB device number 10 using dwc_otg
[Sat Jan  8 18:34:02 2022] cdc_acm 1-1.3.4:1.0: ttyACM0: USB ACM device

And guess what happening for a tokio runtime... It is suddenly continuing to work! The read() call of the tty device is returning:

file read error: failed to fill whole buffer

And all tokio tasks are starting to run back again.

I'd like to confirm my assumptions - here are my questions:

Is my AsyncFile code correctly implemented?
Is it possible to create some internal tokio watchdog for detecting tokio runtime stalls?
Could the tokio hung because the polled fd magically disappears/stops signalling events?
Can I debug this epoll calls inside tokio to confirm the above?

I am open to your comments as I want to debug/confirm and solve this problem.

Answered by Darksonn

Jan 8, 2022

Your read_exact call looks wrong. Try replacing it with one that calls _read instead:

pub async fn read_exact(&self, out: &mut [u8]) -> io::Result<()> {
    while !out.is_empty() {
        let len = self._read(out).await?;
        out = &mut out[len..];
    }
    Ok(())
}

View full answer

Darksonn · 2022-01-08T19:41:26Z

Darksonn
Jan 8, 2022
Maintainer

Your read_exact call looks wrong. Try replacing it with one that calls _read instead:

pub async fn read_exact(&self, out: &mut [u8]) -> io::Result<()> {
    while !out.is_empty() {
        let len = self._read(out).await?;
        out = &mut out[len..];
    }
    Ok(())
}

12 replies

manio Jan 28, 2022
Author

Ok - so waiting for another failure...
I've also got this dmesg (+my comments) from yesterday's fail:

--this is my request (write):
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: 10 bytes from tty layer
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: writing 10 bytes
--now device is responding byte by byte:
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 0, len 1, status 0
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: submitted urb 0
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 1, len 1, status 0
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: submitted urb 1
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 2, len 1, status 0
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: submitted urb 2
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 3, len 1, status 0
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: submitted urb 3
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 4, len 1, status 0
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: submitted urb 4
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 5, len 1, status 0
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: submitted urb 5
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 6, len 1, status 0
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: submitted urb 6
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 7, len 1, status 0
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: submitted urb 7
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 8, len 1, status 0
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: submitted urb 8
---here the problem starts - usb device problem (?) and it is starting to returning errors:
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 9, len 0, status -32
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 10, len 0, status -32
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 11, len 0, status -32
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 12, len 0, status -32
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 13, len 0, status -32
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 14, len 0, status -32
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 15, len 0, status -32
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.0: acm_ctrl_irq - nonzero urb status received: -32
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.0: control resubmission terminated 0
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 0, len 0, status -32
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 1, len 0, status -32
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 2, len 0, status -32
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 3, len 0, status -2
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: acm_read_bulk_callback - urb shutting down with status: -2
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 4, len 0, status -32
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 5, len 0, status -2
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: acm_read_bulk_callback - urb shutting down with status: -2
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 6, len 0, status -2
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: acm_read_bulk_callback - urb shutting down with status: -2
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 7, len 0, status -2
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: acm_read_bulk_callback - urb shutting down with status: -2
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: got urb 8, len 0, status -2
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.1: acm_read_bulk_callback - urb shutting down with status: -2
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.0: acm_ctrl_irq - nonzero urb status received: -32
[Thu Jan 27 15:32:42 2022] cdc_acm 1-1.3.4:1.0: control resubmission terminated 0

but i still don't have the log from rust application - so still waiting for this...

manio Feb 1, 2022
Author

Hi Alice,
I have this again (not 100% sure if this is the exact kernel problem as the device has reappear, and not "stuck" but nevertheless I have something collected in my logs)...
According to your last thoughts I have my debug printing result of inner.get_ref().read(out):

--- last good read:
2022-02-01, 15:40:17.280 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:17.329 [INFO] <----------------------------- after inner_get_ref, res = Ok(2)
2022-02-01, 15:40:17.337 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:17.342 [INFO] <----------------------------- after inner_get_ref, res = Ok(14)
2022-02-01, 15:40:17.353 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:17.361 [INFO] <----------------------------- after inner_get_ref, res = Ok(15)
2022-02-01, 15:40:17.367 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:17.372 [INFO] <----------------------------- after inner_get_ref, res = Ok(14)
2022-02-01, 15:40:17.377 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:17.386 [INFO] <----------------------------- after inner_get_ref, res = Ok(11)
2022-02-01, 15:40:17.393 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:17.400 [INFO] <----------------------------- after inner_get_ref, res = Ok(15)
2022-02-01, 15:40:17.404 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:17.408 [INFO] <----------------------------- after inner_get_ref, res = Ok(3)
--- here the problem start, USB device disconnect and reconnects, and the endless loop has started with:
2022-02-01, 15:40:22.296 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:22.363 [INFO] <----------------------------- after inner_get_ref, res = Ok(0)
2022-02-01, 15:40:22.364 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:22.365 [INFO] <----------------------------- after inner_get_ref, res = Ok(0)
2022-02-01, 15:40:22.366 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:22.366 [INFO] <----------------------------- after inner_get_ref, res = Ok(0)
2022-02-01, 15:40:22.367 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:22.368 [INFO] <----------------------------- after inner_get_ref, res = Ok(0)
2022-02-01, 15:40:22.368 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:22.369 [INFO] <----------------------------- after inner_get_ref, res = Ok(0)
2022-02-01, 15:40:22.370 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:22.370 [INFO] <----------------------------- after inner_get_ref, res = Ok(0)
2022-02-01, 15:40:22.371 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:22.399 [INFO] <----------------------------- after inner_get_ref, res = Ok(0)
2022-02-01, 15:40:22.405 [INFO] <----------------------------- before inner_get_ref
2022-02-01, 15:40:22.410 [INFO] <----------------------------- after inner_get_ref, res = Ok(0)

Code is the same: https://github.com/manio/hard/blob/master/src/asyncfile.rs#L28

Darksonn Feb 1, 2022
Maintainer

Ah, it returns Ok(0). That more or less means that your connection has closed. Your read_exact method should probably panic or return an error in this situation.

manio Feb 4, 2022
Author

@Darksonn
Thank you very much for all your help - I've made a change to address the Ok(0) case and it seems it is now correctly handled (tested in real situation, where it properly bails out with error and continue working). I believe that this was my main source of problems and tokio runtime blocking.
I am marking this lengthy discussion as resolved.

Did you maybe think about including such a generic AsyncFile to the tokio itself? This way one could avoid all this problems I had if a generic AsyncFile would be available from tokio out of the box. Even the AsyncTcpStream is only mentioned in the documentation (https://docs.rs/tokio/latest/tokio/io/unix/struct.AsyncFd.html#examples) and not available for use...

Darksonn Feb 4, 2022
Maintainer

It could make sense, but it needs to be clear that it doesn't work with ordinary files.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Tokio runtime stucks in some circumstances #4389

{{title}}

Replies: 1 comment 12 replies

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Tokio runtime stucks in some circumstances #4389

manio Jan 8, 2022

Replies: 1 comment · 12 replies

Darksonn Jan 8, 2022 Maintainer

manio Jan 28, 2022 Author

manio Feb 1, 2022 Author

Darksonn Feb 1, 2022 Maintainer

manio Feb 4, 2022 Author

Darksonn Feb 4, 2022 Maintainer

manio
Jan 8, 2022

Replies: 1 comment 12 replies

Darksonn
Jan 8, 2022
Maintainer

manio Jan 28, 2022
Author

manio Feb 1, 2022
Author

Darksonn Feb 1, 2022
Maintainer

manio Feb 4, 2022
Author

Darksonn Feb 4, 2022
Maintainer