Missing write readiness notifications using Child with Stdio::piped?

[adamreichold]

I have a program that among other things spawns subprocess (which are usually Python scripts) and communicates with them over pipes using a line-oriented protocol. This protocol is half-duplex, i.e. at each point in time only one of the two processes is expected to write a line and the other is expected to read one.

This seems to mostly work, but sometimes the program and its subprocess deadlock. Adding timeouts on the Rust/tokio/parent side, I found out that it was the writing which blocked indefinitely, e.g. stdin.write_all(&buf).await?. Killing a blocked Python script using SIGINT and looking at the resulting backtrace, I determined that it was blocking in sys.stdin.readline().

This does not really make sense to me as when the pipe buffer is full, the read should succeed and empty it. However, increasing the kernel's pipe buffer size to 1 MB which is larger than all lines I am trying to write so that all writes should succeed immediately did apparently resolve the issue. To me, this appears like the write readiness notifications when the pipe buffer is significantly smaller than the lines I try to write are just lost. (While the timeouts are currently set to 60s, the deadlocks really are deadlocks persisting for days if not resolved manually or via the timeouts.)

Of course, a bug in my code is much more likely, but at this point I have run out of ideas trying to diagnose it. Also due to the protocol being half-duplex, the classic case of pipe buffer deadlock involving two pipes should not happen and indeed continuously draining stdout in a separate task while writing to stdin did not affect the deadlocks. I would be glad if anyone could offer additional insight on why my writes are blocking indefinitely.

To add some context, the parent code is here and the child code is here and here. I am sorry for not having a more minimal reproducer, but I have a hard time reproducing it at all. For example, it seems to happen only on our staging VM running Ubuntu 22.04 and hence kernel 5.15, but not on our development VM currently running Ubuntu 23.04 and hence kernel 6.2. Due to the kernel version differences, I wonder if the "recent" rework of the kernel's pipe subsystem have anything to with it, but that is admittedly a long shot.

EDIT: To make this more concrete, when they deadlock, the parents waits here and the child blocks here.

EDIT: Trying a minimal reproducer which just ping-pongs 500 kB worth of line data between a Rust parent and Python child in a tight loop does not seem to trigger the issue. So at least some of the other work for the runtime seems required.

[adamreichold]

I am testing this against the 5.19 HWE kernel shipped with Ubuntu 22.04 now. Maybe the problem magically disappears that way...

[adamreichold]

But it did not so it is not some interaction with how the kernel notifies on I/O readiness of pipes. This was admittedly pretty unlikely from the start.

[adamreichold]

I fear this could be an issue in tokio or the underlying I/O stack after all: I replaced that single call to write_all by its blocking equivalent using block_in_place as in this commit and the problem has not re-appeared for a week even with the default kernel pipe buffer size of 64 kB where it would appear regularly every two to three days.

I would be grateful for any insights or advice on what I should collect to turn this into an actionable bug report.

[adamreichold]

I will deploy a more minimal change and see whether this resolves the issue. Of course, this will take a few days of observation to be reasonably sure as it was always an intermittent problem...

[adamreichold]

The above-linked minimal change has been running for a week without the issue reoccurring. I think this strongly suggests that the implementation of AsyncWrite or AsyncWriteExt has an issue when using pipes at least on Ubuntu 22.04 LTS or its HWE kernel.

As workaround for us, I will switch to std::process::Comand for now as it means I can avoid the unsafe code required for the minimal workaround and also allows me to reduce the buffering as I can use the integration of serde_json with io::{Read, Write}.

Long-term, I would be glad though to find the root cause for this to ideally provide a fix for Tokio or its underlying I/O stack or at least identify the system configuration which prevents this from working. I am willing to do more experimentation to figure this out and would be glad for any pointers on how to proceed usefully.

[Darksonn]

Unfortunately, I don't really know.

[adamreichold]

Could this be an instance of #6133 ?

[adamreichold]

I have deployed a change which does nothing but bump Tokio to 1.34 and switch back to the asynchronous version of Command this is now running without issues for week. If the problem does not resurface for another one, I would declare this as resolved as another instance of #6133.

[adamreichold]

Seemed to have been an instance of #6133 after all.