Why does it synchronously wait?

[Arniiiii]

I wasted several hours of my life investigation this issue.

And I want an explanation not to why a simple rearrangement fixed the issue, but why proc.async_wait() is a blocking wait.

Background

In spare time, I try to write a CI for my Gentoo repo, i.e. a git repo with recipes how to build packages using Gentoo Linux's package manager called Portage.

The idea of next code is to call Portage's ebuild utility in format like ebuild /path/to/repo_with_recipes/package-category/package-name/package-name-version.ebuild manifest , in the official way according to man ebuild . This is for (re-)generating hashes of tarballs of recipe's sources, so that user of a recipe could download a tarball independently and check its hash before proceeding building.

And I wrote something like this:
https://github.com/Arniiiii/gyou/blob/afb35829c94e69a4e07c3451ebfc402a3c22203d/source/bash_ebuild_manifest.cpp#L81-L108

        auto proc = boost::process::process(
            ioc, path_to_ebuild_py_exe.string(),
            {path_to_ebuild_file.string(), "manifest"},
            boost::process::process_stdio{.in = {/* in to default */},
                                          .out = rp_stdout,
                                          .err = rp_stderr},
            boost::process::process_environment{env_for_ebuild});

        LOG_DEBUG("Doing sth in python, probably");

        auto [proc_tuple, stdout_s, stderr_s] = co_await corral::allOf(
            proc.async_wait(corral::asio_nothrow_awaitable),
            gyou::read_loop(fmt::format("manifest_{}_out", pkg_full_name),
                            rp_stdout),
            gyou::read_loop(fmt::format("manifest_{}_err", pkg_full_name),
                            rp_stderr));
        auto&& [_, status_code_proc] = proc_tuple;

The same code structure used to work for many other processes.

But here was one that broke everything.

It was wget.

Or to be precise boost.process.v2 -> portage -> wget

How does it look like?

Let me show you read_loop first, to be sure that everything is logged. The function basically repeats boost::asio::async_read(io_context, sth, boost::dynamic_buffer(a_string), corral::asio_nothrow_awaitable), but does logging of all intermediary receivings via boost::asio::async_read_some.

https://github.com/Arniiiii/gyou/blob/afb35829c94e69a4e07c3451ebfc402a3c22203d/source/async_read_with_custom_log.cpp

    corral::Task<std::string> read_loop(std::string const& logger_name,
                                        boost::asio::readable_pipe& a_pipe)
    {
        std::string res;
        std::array<char, 4096> buf;
        quill::Logger* logger_with_custom_name
            = quill::Frontend::create_or_get_logger(logger_name,
                                                    global_logger_a);
        logger_with_custom_name->set_log_level(
            global_logger_a->get_log_level());

        for (;;)
            {
                auto [error_code, received_size]
                    = co_await a_pipe.async_read_some(
                        boost::asio::buffer(buf),
                        corral::asio_nothrow_awaitable);
                if (received_size != 0U)
                    {
                        QUILL_LOG_TRACE_L2(
                            logger_with_custom_name, "{}",
                            std::string_view(buf.data(), received_size));
                        res.append(buf.data(), received_size);
                    }
                if (error_code == boost::asio::error::eof)
                    {
                        co_return res;
                    }
                if (error_code)
                    {
                        QUILL_LOG_WARNING(
                            logger_with_custom_name,
                            "A pipe has been broken not via eof.");
                    }
            }
    };

As it is prominently featured, everything received from a_pipe.async_read_some is logged.

So, how does it look like?

It does not print anything until cancelled. And then it prints some 4KB or IDK how many bytes of logs of typical wget invocation. It also allows wget to download around 30 MB of real file before hanging. By "hanging" I mean wget does not do anything and does not accomplishes its downloading purpose.

Why?

Let me show you how wget just hangs itself via showing the only output of hanged wget via strace -p <wget_pid>:

strace -p <wget_pid>

strace: Process 3262575 attached
write(2, ".", 1

At the same time ebuild, the Portage's utility that created wget process, just waits in loop and await its completion:

strace -p <ebuild_pid>

...
getpid()                                = 3262245
poll([{fd=9, events=POLLIN}], 1, 0)     = 1 ([{fd=9, revents=POLLHUP}])
wait4(3262575, 0x7ffd81f9ba54, WNOHANG, NULL) = 0
wait4(3262575, 0x7ffd81f9ba54, WNOHANG, NULL) = 0
epoll_wait(5, [], 1, 100)               = 0
epoll_wait(5, [], 1, 0)                 = 0
getpid()                                = 3262245
poll([{fd=9, events=POLLIN}], 1, 0)     = 1 ([{fd=9, revents=POLLHUP}])
wait4(3262575, 0x7ffd81f9ba54, WNOHANG, NULL) = 0
wait4(3262575, 0x7ffd81f9ba54, WNOHANG, NULL) = 0

After looking two hours at Portage's code, I guess there are also many skeletons of ancient python era with no async, but it seems that it forces wget's stderr to the same pipe as stdout, which seems to be true, because I get next logs after cancelling:

Details

06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out Resolving release-assets.githubusercontent.com... 185.199.109.133, 185.199.110.133, 185.199.108.133, ...
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out Connecting to release-assets.githubusercontent.com|185.199.109.133|:443... connected.
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out HTTP request sent, awaiting response... 200 OK
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out Length: 107878596 (103M) [application/octet-stream]
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out Saving to: ‘/tmp/tmp_gyou/distfiles/boost-1.92.0-cmake.tar.xz.__download__’
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out      0K .......... .......... .......... .......... ..........  0% 1.06M 97s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out     50K .......... .......... .......... .......... ..........  0% 1.19M 91s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    100K .......... .......... .......... .......... ..........  0% 1.95M 78s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    150K .......... .......... .......... .......... ..........  0% 2.25M 70s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    200K .......... .......... .......... .......... ..........  0% 1.60M 69s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    250K .......... .......... .......... .......... ..........  0% 5.09M 61s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    300K .......... .......... .......... .......... ..........  0% 2.52M 58s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    350K .......... .......... .......... .......... ..........  0% 1.14M 62s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    400K .......... .......... .......... .......... ..........  0% 3.20M 59s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    450K .......... .......... .......... .......... ..........  0% 8.61M 54s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    500K .......... .......... .......... .......... ..........  0% 1.57M 55s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    550K .......... .......... .......... .......... ..........  0% 7.91M 51s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    600K .......... .......... .......... .......... ..........  0% 1.36M 53s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    650K .......... .......... .......... .......... ..........  0% 3.21M 52s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    700K .......... .......... .......... .......... ..........  0% 2.34M 51s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    750K .......... .......... .......... .......... ..........  0% 2.20M 51s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    800K .......... .......... .......... .......... ..........  0% 2.66M 50s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    850K .......... .......... .......... .......... ..........  0% 2.60M 49s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    900K .......... .......... .......... .......... ..........  0% 15.1M 47s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out    950K .......... .......... .......... .......... ..........  0% 1.84M 47s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1000K .......... .......... .......... .......... ..........  0% 3.89M 46s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1050K .......... .......... .......... .......... ..........  1% 3.06M 46s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1100K .......... .......... .......... .......... ..........  1% 7.09M 44s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1150K .......... .......... .......... .......... ..........  1% 2.23M 44s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1200K .......... .......... .......... .......... ..........  1% 2.19M 45s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1250K .......... .......... .......... .......... ..........  1% 8.60M 43s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1300K .......... .......... .......... .......... ..........  1% 3.68M 43s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1350K .......... .......... .......... .......... ..........  1% 1.85M 43s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1400K .......... .......... .......... .......... ..........  1% 4.09M 42s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1450K .......... .......... .......... .......... ..........  1% 5.97M 42s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1500K .......... .......... .......... .......... ..........  1% 4.22M 41s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1550K .......... .......... .......... .......... ..........  1% 2.21M 41s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1600K .......... .......... .......... .......... ..........  1% 3.06M 41s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1650K .......... .......... .......... .......... ..........  1% 4.36M 40s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1700K .......... .......... .......... .......... ..........  1% 7.21M 40s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1750K .......... .......... .......... .......... ..........  1% 3.29M 39s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1800K .......... .......... .......... .......... ..........  1% 3.16M 39s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1850K .......... .......... .......... .......... ..........  1% 2.93M 39s
06:37:34.043652352 [151007] async_read_with_custom_log.cpp:40 LOG_TRACE_L2  manifest_boost-1.92.0_out   1900K .......... .......... .......... .......

Notice manifest_boost-1.92.0_out. The out part, which means it was logged from pipe denoted as for stdout, not stderr.

Also notice that it flashes in one moment.

Maybe it is not boost process?

1. I have tested original wget command via wget | echo to emulate pipes. Issue does not appear.

• BUT if add -q to wget while calling the ebuild command via boost process, then it writes nothing and therefore the issue resolves.

2. Testing the ebuild command that calls wget. Issue does not appear.

Maybe something between wget and Portage?

I have tried overriding some variables, which do make effect:

RESUMECOMMAND="stdbuf -oL -eL wget --progress=dot:force -t 5 --read-timeout=15 -T 60 --passive-ftp -U \"Portage (Gentoo, https://www.gentoo.org) distfile-fetch\" -O \"\${DISTDIR}/\${FILE}\" \"\${URI}\"" 
FETCHCOMMAND="stdbuf -oL -eL wget --progress=dot:force -t 5 --read-timeout=15 -T 60 --passive-ftp -U \"Portage (Gentoo, https://www.gentoo.org) distfile-fetch\" -O \"\${DISTDIR}/\${FILE}\" \"\${URI}\""
PYTHONUNBUFFERED=1

But the issue still persisted.

Then I saw stacktrace of my program.

gdb -p <pid_of_my_program> -ex "bt"

#0  __syscall_cancel_arch () at ../sysdeps/unix/sysv/linux/x86_64/syscall_cancel.S:56
#1  0x00007f3eedea6ed8 in __internal_syscall_cancel (a1=<optimized out>, a2=<optimized out>, a3=<optimized out>, a4=<optimized out>, a5=0x0, a6=0x0, nr=0x3d) at cancellation.c:49
#2  __syscall_cancel (a1=<optimized out>, a2=<optimized out>, a3=<optimized out>, a4=<optimized out>, a5=a5@entry=0x0, a6=a6@entry=0x0, nr=0x3d) at cancellation.c:75
#3  0x00007f3eedf329bb in __GI___wait4 (pid=<optimized out>, stat_loc=<optimized out>, options=<optimized out>, usage=<optimized out>) at ../sysdeps/unix/sysv/linux/wait4.c:30
#4  0x000055725aa95174 in ___interceptor_waitpid ()
    at /var/tmp/portage/llvm-runtimes/compiler-rt-sanitizers-22.1.8/work/compiler-rt/lib/asan/../sanitizer_common/sanitizer_common_interceptors.inc:2765
#5  0x000055725b0d77d3 in boost::process::v2::detail::basic_process_handle_fd<boost::asio::any_io_executor>::async_wait_op_::operator()<boost::asio::detail::composed_op<boost::process::v2::detail::basic_process_handle_fd<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, boost::asio::detail::composed_op<boost::process::v2::basic_process<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, corral::detail::AsioAwaiterBase<corral::detail::BoostAsioImpl, int>::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)>&> (this=0x7b3eec089a78, self=..., ec=...)
    at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/process/v2/detail/process_handle_fd.hpp:332
#6  0x000055725b0d7488 in boost::asio::detail::composed_op<boost::process::v2::detail::basic_process_handle_fd<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, boost::asio::detail::composed_op<boost::process::v2::basic_process<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, corral::detail::AsioAwaiterBase<corral::detail::BoostAsioImpl, int>::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)>::operator()<boost::system::error_code const&> (this=0x7b3eec089a70, t=...) at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/composed.hpp:150
#7  0x000055725b0d7080 in boost::asio::detail::binder1<boost::asio::detail::composed_op<boost::process::v2::detail::basic_process_handle_fd<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, boost::asio::detail::composed_op<boost::process::v2::basic_process<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, corral::detail::AsioAwaiterBase<corral::detail::BoostAsioImpl, int>::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)>, boost::system::error_code>::operator() (this=0x7b3eec089a70) at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/detail/bind_handler.hpp:116
#8  0x000055725b0d99d5 in boost::asio::detail::executor_function::complete<boost::asio::detail::binder1<boost::asio::detail::composed_op<boost::process::v2::detail::basic_process_handle_fd<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, boost::asio::detail::composed_op<boost::process::v2::basic_process<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, corral::detail::AsioAwaiterBase<corral::detail::BoostAsioImpl, int>::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)>, boost::system::error_code>, std::allocator<void> > (base=0x7c4eed1f9f40, call=0x1)
    at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/detail/executor_function.hpp:114
#9  0x000055725aef4f16 in boost::asio::detail::executor_function::operator() (this=0x7b3eebf79320) at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/detail/executor_function.hpp:62
#10 0x000055725aefd092 in boost::asio::io_context::basic_executor_type<std::allocator<void>, 4ul>::execute<boost::asio::detail::executor_function> (this=0x7b3eec1a9098, f=...)
    at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/impl/io_context.hpp:218
#11 0x000055725aefc850 in boost::asio::execution::detail::any_executor_base::execute_ex<boost::asio::io_context::basic_executor_type<std::allocator<void>, 4ul> > (ex=..., f=...)
    at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/execution/any_executor.hpp:901
#12 0x000055725b0d8a26 in boost::asio::execution::detail::any_executor_base::execute<boost::asio::detail::binder1<boost::asio::detail::composed_op<boost::process::v2::detail::basic_process_handle_fd<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, boost::asio::detail::composed_op<boost::process::v2::basic_process<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, corral::detail::AsioAwaiterBase<corral::detail::BoostAsioImpl, int>::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)>, boost::system::error_code> > (this=0x7b3eec1a9098, f=...)
    at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/execution/any_executor.hpp:682
#13 0x000055725b0d715f in boost::asio::detail::handler_work_base<boost::asio::any_io_executor, boost::asio::any_io_executor, boost::asio::io_context, boost::asio::executor, void>::dispatch<boost::asio::detail::binder1<boost::asio::detail::composed_op<boost::process::v2::detail::basic_process_handle_fd<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, boost::asio::detail::composed_op<boost::process::v2::basic_process<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, corral::detail::AsioAwaiterBase<corral::detail::BoostAsioImpl, int>::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)>, boost::system::error_code>, boost::asio::detail::composed_op<boost::process::v2::detail::basic_process_handle_fd<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, boost::asio::detail::composed_op<boost::process::v2::basic_process<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, corral::detail::AsioAwaiterBase<corral::detail::BoostAsioImpl, int>::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)> > (this=0x7b3eec1a9098, function=...)
    at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/detail/handler_work.hpp:400
#14 0x000055725b0d6d0b in boost::asio::detail::handler_work<boost::asio::detail::composed_op<boost::process::v2::detail::basic_process_handle_fd<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, boost::asio::detail::composed_op<boost::process::v2::basic_process<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, corral::detail::AsioAwaiterBase<corral::detail::BoostAsioImpl, int>::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)>, boost::asio::any_io_executor, void>::complete<boost::asio::detail::binder1<boost::asio::detail::composed_op<boost::process::v2::detail::basic_process_handle_fd<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, boost::asio::detail::composed_op<boost::process::v2::basic_process<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, corral::detail::AsioAwaiterBase<corral::detail::BoostAsioImpl, int>::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)>, boost::system::error_code> > (this=0x7b3eec1a9060, function=..., handler=...) at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/detail/handler_work.hpp:438
#15 0x000055725b0d5f87 in boost::asio::detail::reactive_wait_op<boost::asio::detail::composed_op<boost::process::v2::detail::basic_process_handle_fd<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, boost::asio::detail::composed_op<boost::process::v2::basic_process<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, corral::detail::AsioAwaiterBase<corral::detail::BoostAsioImpl, int>::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)>, boost::asio::any_io_executor>::do_complete (owner=0x7c5eed1e0340, base=0x7c7eed262440) at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/detail/reactive_wait_op.hpp:88
#16 0x000055725adfd6ff in boost::asio::detail::scheduler_operation::complete (this=0x7c7eed262440, owner=0x7c5eed1e0340, ec=..., bytes_transferred=0x0)
    at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/detail/scheduler_operation.hpp:41
#17 0x000055725adfc660 in boost::asio::detail::epoll_reactor::descriptor_state::do_complete (owner=0x7c5eed1e0340, base=0x7c0eed1ee080, ec=..., bytes_transferred=0x11)
    at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/detail/impl/epoll_reactor.ipp:833
#18 0x000055725adfd6ff in boost::asio::detail::scheduler_operation::complete (this=0x7c0eed1ee080, owner=0x7c5eed1e0340, ec=..., bytes_transferred=0x11)
    at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/detail/scheduler_operation.hpp:41
#19 0x000055725ae0e755 in boost::asio::detail::scheduler::do_run_one (this=0x7c5eed1e0340, lock=..., this_thread=..., ec=...)
    at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/detail/impl/scheduler.ipp:502
#20 0x000055725ae0d345 in boost::asio::detail::scheduler::run (this=0x7c5eed1e0340, ec=...) at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/detail/impl/scheduler.ipp:218
#21 0x000055725ae5414d in boost::asio::io_context::run (this=0x7b3eec3f17b0) at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/impl/io_context.ipp:64
#22 0x000055725ae15609 in corral::detail::AsioEventLoopTraitsImpl<corral::detail::BoostAsioImpl>::run (io=...) at /home/paxu/.conan2/p/b/corra5b846b3c50e05/p/include/corral/detail/asio.h:264
#23 0x000055725ae142c8 in corral::detail::Runner<boost::asio::io_context>::run<corral::detail::AwaiterMaker<corral::detail::AnyOf<corral::UseExceptions, corral::Task<gyou::ReturnCode>, corral::detail::AsioAwaitable<corral::detail::BoostAsioImpl, true, boost::asio::basic_signal_set<boost::asio::any_io_executor>::initiate_async_wait, std::tuple<>, int>, corral::Task<void> >, corral::Task<gyou::ReturnCode>, corral::detail::AsioAwaitable<corral::detail::BoostAsioImpl, true, boost::asio::basic_signal_set<boost::asio::any_io_executor>::initiate_async_wait, std::tuple<>, int>, corral::Task<void> > >(corral::detail::AwaiterMaker<corral::detail::AnyOf<corral::UseExceptions, corral::Task<gyou::ReturnCode>, corral::detail::AsioAwaitable<corral::detail::BoostAsioImpl, true, boost::asio::basic_signal_set<boost::asio::any_io_executor>::initiate_async_wait, std::tuple<>, int>, corral::Task<void> >, corral::Task<gyou::ReturnCode>, corral::detail::AsioAwaitable<corral::detail::BoostAsioImpl, true, boost::asio::basic_signal_set<boost::asio::any_io_executor>::initiate_async_wait, std::tuple<>, int>, corral::Task<void> >&&) && (this=0x7b3eebea46a0, awaitable=...)
    at /home/paxu/.conan2/p/b/corra5b846b3c50e05/p/include/corral/run.h:86
#24 0x000055725ac789a4 in corral::run<boost::asio::io_context, corral::detail::AwaiterMaker<corral::detail::AnyOf<corral::UseExceptions, corral::Task<gyou::ReturnCode>, corral::detail::AsioAwaitable<corral::detail::BoostAsioImpl, true, boost::asio::basic_signal_set<boost::asio::any_io_executor>::initiate_async_wait, std::tuple<>, int>, corral::Task<void> >, corral::Task<gyou::ReturnCode>, corral::detail::AsioAwaitable<corral::detail::BoostAsioImpl, true, boost::asio::basic_signal_set<boost::asio::any_io_executor>::initiate_async_wait, std::tuple<>, int>, corral::Task<void> > >(boost::asio::io_context&, corral::detail::AwaiterMaker<corral::detail::AnyOf<corral::UseExceptions, corral::Task<gyou::ReturnCode>, corral::detail::AsioAwaitable<corral::detail::BoostAsioImpl, true, boost::asio::basic_signal_set<boost::asio::any_io_executor>::initiate_async_wait, std::tuple<>, int>, corral::Task<void> >, corral::Task<gyou::ReturnCode>, corral::detail::AsioAwaitable<corral::detail::BoostAsioImpl, true, boost::asio::basic_signal_set<boost::asio::any_io_executor>::initiate_async_wait, std::tuple<>, int>, corral::Task<void> >&&) (eventLoop=..., awaitable=...)
    at /home/paxu/.conan2/p/b/corra5b846b3c50e05/p/include/corral/run.h:138
#25 0x000055725abed59a in main (argc=0xf, argv=0x7ffcba4c1ef8) at /home/paxu/data/code/my_projects/gyou/main.cpp:682

I ask you to notice #3 0x00007f3eedf329bb in __GI___wait4 (pid=<optimized out>, stat_loc=<optimized out>, options=<optimized out>, usage=<optimized out>) at ../sysdeps/unix/sysv/linux/wait4.c:30

wait4

One of the blocking waits.

And I use corral, a single-threaded coroutine-async structured-concurrency framework.

Explanation: making sense out of logs

wget tries to write to a stderr pipe a character . for showing a progress which by default interprets 10KB worth of bytes, but pipe has been filled and not flashed, because I got a deadlock using Boost Process: I was waiting concurrently for output from pipes and for process completion. Apparently, waiting for process completion is not async, therefore, I got deadlock, pipe was not flashed, wget has filled it and failed to continue executing because there's no place to put more logs of wget.

Epiphany

What if rearrange to wait until pipes end and then wait until the process ends?

Arniiiii/gyou@3256de2

        auto [stdout_s, stderr_s] = co_await corral::allOf(
            gyou::read_loop(fmt::format("manifest_{}_out", pkg_full_name),
                            rp_stdout),
            gyou::read_loop(fmt::format("manifest_{}_err", pkg_full_name),
                            rp_stderr));

        auto&& [_, status_code_proc]
            = co_await proc.async_wait(corral::asio_nothrow_awaitable);

And it fixed the hanging and wget finishes successfully, and therefore current version of my program.

The question

Why is a process waited for synchronously when it is async awaited in user's code?
What should happen so that boost process waits asynchronously for completion of its processes?
Does Linux provide any API for that?

Additional details

Details

Boost version: 1.91.0 from conan.io

https://github.com/Arniiiii/gyou/blob/afb35829c94e69a4e07c3451ebfc402a3c22203d/CMakeLists.txt#L33-L40

target_compile_definitions(${PROJECT_NAME}_lib
    ...
    PUBLIC BOOST_PROCESS_V2_DISABLE_NOTIFY_FORK=1
    PUBLIC BOOST_PROCESS_USE_STD_FS=1
    ...
)

Kernel: Linux 6.18.43-gentoo-dist

a clang++-22, gcc-15's libstdc++ , glibc 2.43, mold 2.41.0

app-misc/pax-utils:        1.3.10::gentoo
app-shells/bash:           5.3_p15::gentoo
dev-build/autoconf:        2.72-r7::gentoo
dev-build/automake:        1.18.1-r1::gentoo
dev-build/cmake:           4.3.4::gentoo
dev-build/libtool:         2.5.4::gentoo
dev-build/make:            4.4.1-r102::gentoo
dev-build/meson:           1.11.1::gentoo
dev-java/java-config:      2.3.4::gentoo
dev-lang/perl:             5.42.2::gentoo
dev-lang/python:           3.13.14::gentoo, 3.14.6_p1::gentoo
dev-lang/rust-bin:         1.94.1::gentoo, 1.95.0::gentoo
llvm-core/clang:           20.1.8::gentoo, 21.1.8::gentoo, 22.1.8::gentoo, 23.0.0.9999::gentoo
llvm-core/lld:             20.1.8::gentoo, 21.1.8-r1::gentoo, 22.1.8-r1::gentoo, 23.0.0.9999::gentoo
llvm-core/llvm:            20.1.8::gentoo, 21.1.8::gentoo, 22.1.8::gentoo, 23.0.0.9999::gentoo
sys-apps/baselayout:       2.18-r1::gentoo
sys-apps/openrc:           0.63.3::gentoo
sys-apps/sandbox:          2.49::gentoo
sys-devel/binutils:        2.46.0::gentoo
sys-devel/binutils-config: 5.6::gentoo
sys-devel/gcc:             14.3.1_p20260604::gentoo, 15.3.0::gentoo
sys-devel/gcc-config:      2.12.2::gentoo
sys-kernel/linux-headers:  6.18::gentoo (virtual/os-headers)
sys-libs/glibc:            2.43-r2::gentoo

Additional CMake generate options I used for my project:

    -DCMAKE_CXX_FLAGS='-Wnrvo -Wpessimizing-move -pipe -march=native -ggdb3  -Werror=odr -Werror=lto-type-mismatch -Werror=strict-aliasing -fdiagnostics-color=always -fdiagnostics-color -fsanitize=address,leak,undefined',
    -DCMAKE_EXE_LINKER_FLAGS='-fuse-ld=mold -fsanitize=address,leak,undefined'

conan's profile . I had to lie to conan that it is clang-20, because conan is stupid and thinks that clang-22 does not exist in nature.

[settings]
arch=x86_64
build_type=Debug
compiler=clang
compiler.cppstd=gnu23
compiler.libcxx=libstdc++11
compiler.version=21
os=Linux

[conf]
tools.cmake.cmaketoolchain:generator=Ninja
tools.build:compiler_executables={"c": "clang-22", "cpp": "clang++-22"}

[buildenv]
CFLAGS=-ggdb3
CXXFLAGS=-ggdb3

[klemens-morgenstern]

I honestly have no idea.

Why is a process waited for synchronously when it is async awaited in user's code?

Does the async_wait block the event loop or just the allOf? Does the read_loop task get resumed at all? What happens if you change the order in the allOf call?

[Arniiiii]

Does the async_wait block the event loop or just the allOf?

I do not know how to definitively test it, but it looks like there's no progress in logs, once it waits for the process. Also, the gdb -p <pid> -ex "bt" shows only one stacktrace 6 / 6 times.

Does the read_loop task get resumed at all?

Yeah, because otherwise I would not see change of logger name at logs when cancelling or something.

What happens if you change the order in the allOf call?

It does not matter. In theory and in practice: I have just tested it. It is structured asynchronous programming. Similar to python's trio

[Arniiiii]

#5 0x000055725b0d77d3 in boost::process::v2::detail::basic_process_handle_fd<boost::asio::any_io_executor>::async_wait_op_::operator()<boost::asio::detail::composed_op<boost::process::v2::detail::basic_process_handle_fd<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, boost::asio::detail::composed_op<boost::process::v2::basic_process<boost::asio::any_io_executor>::async_wait_op_, boost::asio::detail::composed_work<void(boost::asio::any_io_executor)>, corral::detail::AsioAwaiterBase<corral::detail::BoostAsioImpl, int>::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)>&> (this=0x7b3eec089a78, self=..., ec=...)
at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/process/v2/detail/process_handle_fd.hpp:332

process/include/boost/process/v2/detail/process_handle_fd.hpp

Lines 328 to 335 in cfbaf1f

	template<typename Self>
	void operator()(Self &&self, error_code ec, int = 0)
	{
	if (!ec && process_is_running(exit_code))
	if (::waitpid(pid_, &exit_code, 0) == -1)
	ec = get_last_error();
	std::move(self).complete(ec);
	}

process/include/boost/process/v2/detail/process_handle_fd.hpp

Line 332 in cfbaf1f

if (::waitpid(pid_, &exit_code, 0) == -1)

no options -> blocking wait.

[Arniiiii]

Does the async_wait block the event loop or just the allOf?

It stalls event_loop.

full trace inside of the `process_handle_fd.hpp`:

sth.gdb.gz

[klemens-morgenstern]

OK, this is odd - this call should reap the pid of a process that already exited.

At least that's how i read the docs - EPOLLIN means the process exited: https://man7.org/linux/man-pages/man2/pidfd_open.2.html

I'll look into it, maybe just a defensive asynchronous wait until it's reaped would solve your issue.

[Arniiiii]

OK, this is odd - this call should reap the pid of a process that already exited.

At least that's how i read the docs - EPOLLIN means the process exited: https://man7.org/linux/man-pages/man2/pidfd_open.2.html

I'll look into it, maybe just a defensive asynchronous wait until it's reaped would solve your issue.

The issue is that it has not exited. It is actively running in fact. I hit it when only started downloading via wget.

I suspect that

process/include/boost/process/v2/detail/process_handle_fd.hpp

Line 308 in cfbaf1f

descriptor.async_wait(net::posix::descriptor_base::wait_read, std::move(self));

signals that it is ready to read the process's file descriptor immediately, for some reason.

[Arniiiii]

It seems that asio thinks that after approx. 800ms that descriptor is ready.

I have recompiled my program with BOOST_ASIO_ENABLE_HANDLER_TRACKING=1

I've got next logs when I have reached the deadlock:

@asio|1788902396.178708|894*911|descriptor@0x555d54bad250.async_wait
@asio|1788902396.178730|894*912|descriptor@0x555d54bad360.async_read_some
@asio|1788902396.178734|.912|non_blocking_read,ec=system:11,bytes_transferred=0
@asio|1788902396.178747|894*913|descriptor@0x555d54bad3b0.async_read_some
@asio|1788902396.178750|.913|non_blocking_read,ec=system:11,bytes_transferred=0
@asio|1788902396.178754|<894|
@asio|1788902396.178757|>895|
@asio|1788902396.178768|895|descriptor@0x555d54a88c00.close
@asio|1788902396.178776|895|descriptor@0x555d54a88ca8.close
@asio|1788902396.178782|895|descriptor@0x555d54a88c58.close
@asio|1788902396.178851|895^914|in 'async_read' (/home/paxu/.conan2/p/b/boost11309c33f93d9/p/include/boost/asio/impl/read.hpp:781)
@asio|1788902396.178851|895*914|descriptor@0x555d54a3b4f8.async_read_some
@asio|1788902396.178859|<895|
@asio|1788902396.178864|>896|
@asio|1788902396.178874|896|descriptor@0x555d54ba35b0.close
@asio|1788902396.178880|896|descriptor@0x555d54ba3658.close
@asio|1788902396.178885|896|descriptor@0x555d54ba3608.close
@asio|1788902396.178930|896^915|in 'async_read' (/home/paxu/.conan2/p/b/boost11309c33f93d9/p/include/boost/asio/impl/read.hpp:781)
@asio|1788902396.178930|896*915|descriptor@0x555d54a34ca8.async_read_some
@asio|1788902396.178936|<896|
@asio|1788902396.178938|>897|ec=asio.misc:2,bytes_transferred=0
@asio|1788902396.178969|897|descriptor@0x555d549f1b10.close
@asio|1788902396.178976|897|descriptor@0x555d549f1c70.close
@asio|1788902396.178983|897|descriptor@0x555d549f1c20.close
@asio|1788902396.179066|<897|
@asio|1788902396.179072|>898|ec=system:0
@asio|1788902396.939565|<898|
@asio|1788902396.939592|>904|ec=system:0
@asio|1788902396.950953|<904|
@asio|1788902396.950976|>907|ec=system:0
@asio|1788902396.951003|<907|
@asio|1788902396.951006|>911|ec=system:0

I even dare to say that probably the 800ms is waiting for a previous process to end in the blocking manner, and it is probably was marked to be ready to read immediately.

[Arniiiii]

It seems that asio spuriously try to call the handler, without waiting for the event.

`strace -v -tt -e trace=pidfd_open,epoll_ctl,epoll_wait,wait4 ./build/gyou ... `

22:05:20.886376 wait4(1484387, NULL, WNOHANG, NULL) = -1 ECHILD (No child processes)
@asio|1788905120.886397|1013|descriptor@0x55cd8bcb7370.close
22:05:20.886416 epoll_ctl(5, EPOLL_CTL_DEL, 18, 0x7ffc5da1cd2c) = 0
@asio|1788905120.886457|1013|descriptor@0x55cd8bcb74d0.close
22:05:20.886475 epoll_ctl(5, EPOLL_CTL_DEL, 15, 0x7ffc5da1cd8c) = 0
@asio|1788905120.886520|1013|descriptor@0x55cd8bcb7480.close
22:05:20.886537 epoll_ctl(5, EPOLL_CTL_DEL, 11, 0x7ffc5da1cd8c) = 0
@asio|1788905120.886642|<1013|
22:05:20.886660 epoll_wait(5, [{events=EPOLLIN, data=0x55cd8bb8f450}, {events=EPOLLIN|EPOLLHUP, data=0x55cd8bbdb040}, {events=EPOLLIN|EPOLLHUP, data=0x55cd8bc12240}, {events=EPOLLIN|EPOLLHUP, data=0x55cd8bbe9310}, {events=EPOLLIN|EPOLLHUP, data=0x55cd8bc0b1f0}, {events=EPOLLIN|EPOLLHUP, data=0x55cd8bb439f0}, {events=EPOLLIN|EPOLLHUP, data=0x55cd8bc05250}, {events=EPOLLIN|EPOLLHUP, data=0x55cd8bbd4460}], 128, 0) = 8
@asio|1788905120.886704|>1014|
22:05:20.886727 wait4(1484362, NULL, WNOHANG, NULL) = -1 ECHILD (No child processes)
@asio|1788905120.886745|1014|descriptor@0x55cd8bceaba0.close
22:05:20.886762 epoll_ctl(5, EPOLL_CTL_DEL, 24, 0x7ffc5da1d2dc) = 0
@asio|1788905120.886792|1014|descriptor@0x55cd8bceac48.close
22:05:20.886809 epoll_ctl(5, EPOLL_CTL_DEL, 22, 0x7ffc5da1d33c) = 0
@asio|1788905120.886838|1014|descriptor@0x55cd8bceabf8.close
22:05:20.886856 epoll_ctl(5, EPOLL_CTL_DEL, 17, 0x7ffc5da1d33c) = 0
22:05:20.887140 epoll_ctl(5, EPOLL_CTL_ADD, 11, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bbf7270}) = 0
22:05:20.887191 epoll_ctl(5, EPOLL_CTL_ADD, 15, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bbdb0e0}) = 0
22:05:20.888698 pidfd_open(1484500, 0)  = 17
22:05:20.888729 epoll_ctl(5, EPOLL_CTL_ADD, 17, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bbdb040}) = 0
22:05:20.888831 wait4(1484500, 0x55cd8bcb73b8, WNOHANG, NULL) = 0
@asio|1788905120.888857|1014*1021|descriptor@0x55cd8bcb7370.async_wait
22:05:20.888882 epoll_ctl(5, EPOLL_CTL_MOD, 17, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bbdb040}) = 0
@asio|1788905120.888929|1014*1022|descriptor@0x55cd8bcb7480.async_read_some
@asio|1788905120.888978|.1022|non_blocking_read,ec=system:11,bytes_transferred=0
@asio|1788905120.889002|1014*1023|descriptor@0x55cd8bcb74d0.async_read_some
@asio|1788905120.889048|.1023|non_blocking_read,ec=system:11,bytes_transferred=0
@asio|1788905120.889063|<1014|
@asio|1788905120.889078|>1015|
22:05:20.889108 wait4(1484364, NULL, WNOHANG, NULL) = -1 ECHILD (No child processes)
@asio|1788905120.889125|1015|descriptor@0x55cd8bc6f330.close
22:05:20.889143 epoll_ctl(5, EPOLL_CTL_DEL, 27, 0x7ffc5da1d2dc) = 0
@asio|1788905120.889175|1015|descriptor@0x55cd8bc6f3d8.close
22:05:20.889192 epoll_ctl(5, EPOLL_CTL_DEL, 25, 0x7ffc5da1d33c) = 0
@asio|1788905120.889222|1015|descriptor@0x55cd8bc6f388.close
22:05:20.889239 epoll_ctl(5, EPOLL_CTL_DEL, 20, 0x7ffc5da1d33c) = 0
22:05:20.889574 epoll_ctl(5, EPOLL_CTL_ADD, 13, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bbf7440}) = 0
22:05:20.889621 epoll_ctl(5, EPOLL_CTL_ADD, 18, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bc121a0}) = 0
22:05:20.891453 pidfd_open(1484501, 0)  = 20
22:05:20.891513 epoll_ctl(5, EPOLL_CTL_ADD, 20, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bc12240}) = 0
22:05:20.891607 wait4(1484501, 0x55cd8bc02888, WNOHANG, NULL) = 0
@asio|1788905120.891631|1015*1024|descriptor@0x55cd8bc02840.async_wait
22:05:20.891651 epoll_ctl(5, EPOLL_CTL_MOD, 20, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bc12240}) = 0
@asio|1788905120.891695|1015*1025|descriptor@0x55cd8bc02950.async_read_some
@asio|1788905120.891744|.1025|non_blocking_read,ec=system:11,bytes_transferred=0
@asio|1788905120.891764|1015*1026|descriptor@0x55cd8bc029a0.async_read_some
@asio|1788905120.891810|.1026|non_blocking_read,ec=system:11,bytes_transferred=0
@asio|1788905120.891825|<1015|
@asio|1788905120.891841|>1016|
22:05:20.891867 wait4(1484380, NULL, WNOHANG, NULL) = -1 ECHILD (No child processes)
@asio|1788905120.891906|1016|descriptor@0x55cd8bb932b0.close
22:05:20.891926 epoll_ctl(5, EPOLL_CTL_DEL, 42, 0x7ffc5da1d2dc) = 0
@asio|1788905120.891975|1016|descriptor@0x55cd8bb93358.close
22:05:20.891996 epoll_ctl(5, EPOLL_CTL_DEL, 40, 0x7ffc5da1d33c) = 0
@asio|1788905120.892035|1016|descriptor@0x55cd8bb93308.close
22:05:20.892052 epoll_ctl(5, EPOLL_CTL_DEL, 35, 0x7ffc5da1d33c) = 0
22:05:20.892378 epoll_ctl(5, EPOLL_CTL_ADD, 16, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bbe9080}) = 0
22:05:20.892434 epoll_ctl(5, EPOLL_CTL_ADD, 21, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bbe9120}) = 0
22:05:20.893737 pidfd_open(1484502, 0)  = 24
22:05:20.893767 epoll_ctl(5, EPOLL_CTL_ADD, 24, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bbe9310}) = 0
22:05:20.893857 wait4(1484502, 0x55cd8bb4ed48, WNOHANG, NULL) = 0
@asio|1788905120.893880|1016*1027|descriptor@0x55cd8bb4ed00.async_wait
22:05:20.893901 epoll_ctl(5, EPOLL_CTL_MOD, 24, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bbe9310}) = 0
22:05:20.894114 epoll_ctl(5, EPOLL_CTL_ADD, 19, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bb40370}) = 0
22:05:20.894173 epoll_ctl(5, EPOLL_CTL_ADD, 25, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bb44cf0}) = 0
22:05:20.895394 pidfd_open(1484503, 0)  = 35
22:05:20.895425 epoll_ctl(5, EPOLL_CTL_ADD, 35, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bbbf250}) = 0
22:05:20.895512 wait4(1484503, 0x55cd8bcac4a8, WNOHANG, NULL) = 0
@asio|1788905120.895532|1016*1028|descriptor@0x55cd8bcac460.async_wait
22:05:20.895553 epoll_ctl(5, EPOLL_CTL_MOD, 35, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bbbf250}) = 0
@asio|1788905120.895600|1016*1029|descriptor@0x55cd8bb4ee10.async_read_some
@asio|1788905120.895651|.1029|non_blocking_read,ec=system:11,bytes_transferred=0
@asio|1788905120.895676|1016*1030|descriptor@0x55cd8bb4ee60.async_read_some
@asio|1788905120.895723|.1030|non_blocking_read,ec=system:11,bytes_transferred=0
@asio|1788905120.895745|1016*1031|descriptor@0x55cd8bcac570.async_read_some
@asio|1788905120.895795|.1031|non_blocking_read,ec=system:11,bytes_transferred=0
@asio|1788905120.895819|1016*1032|descriptor@0x55cd8bcac5c0.async_read_some
@asio|1788905120.895865|.1032|non_blocking_read,ec=system:11,bytes_transferred=0
@asio|1788905120.895880|<1016|
@asio|1788905120.895896|>1017|
22:05:20.895932 wait4(1484369, NULL, WNOHANG, NULL) = -1 ECHILD (No child processes)
@asio|1788905120.895950|1017|descriptor@0x55cd8bcacf80.close
22:05:20.895969 epoll_ctl(5, EPOLL_CTL_DEL, 30, 0x7ffc5da1d2dc) = 0
@asio|1788905120.896001|1017|descriptor@0x55cd8bcad028.close
22:05:20.896018 epoll_ctl(5, EPOLL_CTL_DEL, 28, 0x7ffc5da1d33c) = 0
@asio|1788905120.896048|1017|descriptor@0x55cd8bcacfd8.close
22:05:20.896066 epoll_ctl(5, EPOLL_CTL_DEL, 23, 0x7ffc5da1d33c) = 0
@asio|1788905120.896222|1017^1033|in 'async_read' (/home/paxu/.conan2/p/b/boost11309c33f93d9/p/include/boost/asio/impl/read.hpp:781)
@asio|1788905120.896222|1017*1033|descriptor@0x55cd8bb71628.async_read_some
@asio|1788905120.896253|<1017|
@asio|1788905120.896268|>1018|
22:05:20.896295 wait4(1484375, NULL, WNOHANG, NULL) = -1 ECHILD (No child processes)
@asio|1788905120.896314|1018|descriptor@0x55cd8bcf4f20.close
22:05:20.896331 epoll_ctl(5, EPOLL_CTL_DEL, 36, 0x7ffc5da1d2dc) = 0
@asio|1788905120.896370|1018|descriptor@0x55cd8bcf4fc8.close
22:05:20.896390 epoll_ctl(5, EPOLL_CTL_DEL, 34, 0x7ffc5da1d33c) = 0
@asio|1788905120.896427|1018|descriptor@0x55cd8bcf4f78.close
22:05:20.896444 epoll_ctl(5, EPOLL_CTL_DEL, 29, 0x7ffc5da1d33c) = 0
22:05:20.896839 epoll_ctl(5, EPOLL_CTL_ADD, 23, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bc05410}) = 0
22:05:20.896890 epoll_ctl(5, EPOLL_CTL_ADD, 28, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bb42cd0}) = 0
22:05:20.898113 pidfd_open(1484504, 0)  = 30
22:05:20.898139 epoll_ctl(5, EPOLL_CTL_ADD, 30, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bb439f0}) = 0
22:05:20.898228 wait4(1484504, 0x55cd8bd01268, WNOHANG, NULL) = 0
@asio|1788905120.898250|1018*1034|descriptor@0x55cd8bd01220.async_wait
22:05:20.898270 epoll_ctl(5, EPOLL_CTL_MOD, 30, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bb439f0}) = 0
@asio|1788905120.898308|1018*1035|descriptor@0x55cd8bd01330.async_read_some
@asio|1788905120.898634|.1035|non_blocking_read,ec=system:11,bytes_transferred=0
@asio|1788905120.898666|1018*1036|descriptor@0x55cd8bd01380.async_read_some
@asio|1788905120.898711|.1036|non_blocking_read,ec=system:11,bytes_transferred=0
@asio|1788905120.898726|<1018|
@asio|1788905120.898743|>1019|
22:05:20.898771 wait4(1484373, NULL, WNOHANG, NULL) = -1 ECHILD (No child processes)
@asio|1788905120.898794|1019|descriptor@0x55cd8bcb7de0.close
22:05:20.898811 epoll_ctl(5, EPOLL_CTL_DEL, 33, 0x7ffc5da1d2dc) = 0
@asio|1788905120.898843|1019|descriptor@0x55cd8bcb7e88.close
22:05:20.898860 epoll_ctl(5, EPOLL_CTL_DEL, 31, 0x7ffc5da1d33c) = 0
@asio|1788905120.898891|1019|descriptor@0x55cd8bcb7e38.close
22:05:20.898908 epoll_ctl(5, EPOLL_CTL_DEL, 26, 0x7ffc5da1d33c) = 0
@asio|1788905120.899039|1019^1037|in 'async_read' (/home/paxu/.conan2/p/b/boost11309c33f93d9/p/include/boost/asio/impl/read.hpp:781)
@asio|1788905120.899039|1019*1037|descriptor@0x55cd8bb841b8.async_read_some
@asio|1788905120.899070|<1019|
@asio|1788905120.899083|>1020|
22:05:20.899110 wait4(1484378, NULL, WNOHANG, NULL) = -1 ECHILD (No child processes)
@asio|1788905120.899127|1020|descriptor@0x55cd8bd03870.close
22:05:20.899144 epoll_ctl(5, EPOLL_CTL_DEL, 39, 0x7ffc5da1d2dc) = 0
@asio|1788905120.899176|1020|descriptor@0x55cd8bd03918.close
22:05:20.899193 epoll_ctl(5, EPOLL_CTL_DEL, 37, 0x7ffc5da1d33c) = 0
@asio|1788905120.899222|1020|descriptor@0x55cd8bd038c8.close
22:05:20.899239 epoll_ctl(5, EPOLL_CTL_DEL, 32, 0x7ffc5da1d33c) = 0
22:05:20.899496 epoll_ctl(5, EPOLL_CTL_ADD, 27, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bb43ac0}) = 0
22:05:20.899545 epoll_ctl(5, EPOLL_CTL_ADD, 31, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bbd4200}) = 0
22:05:20.900852 pidfd_open(1484505, 0)  = 33
22:05:20.900878 epoll_ctl(5, EPOLL_CTL_ADD, 33, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bbd4460}) = 0
22:05:20.900961 wait4(1484505, 0x55cd8bb62fc8, WNOHANG, NULL) = 0
@asio|1788905120.900982|1020*1038|descriptor@0x55cd8bb62f80.async_wait
22:05:20.901001 epoll_ctl(5, EPOLL_CTL_MOD, 33, {events=EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP|EPOLLET, data=0x55cd8bbd4460}) = 0
@asio|1788905120.901040|1020*1039|descriptor@0x55cd8bb63090.async_read_some
@asio|1788905120.901088|.1039|non_blocking_read,ec=system:11,bytes_transferred=0
@asio|1788905120.901109|1020*1040|descriptor@0x55cd8bb630e0.async_read_some
@asio|1788905120.901155|.1040|non_blocking_read,ec=system:11,bytes_transferred=0
@asio|1788905120.901170|<1020|
@asio|1788905120.901206|>1021|ec=system:0
22:05:20.901227 wait4(1484500, 0x55cd8bcb73b8, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
22:05:21.644485 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=1484502, si_uid=1000, si_status=0, si_utime=61 /* 0.61 s */, si_stime=4 /* 0.04 s */} ---
22:05:21.644534 wait4(1484500, 0x55cd8bcb73b8, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
22:05:21.652978 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=1484504, si_uid=1000, si_status=0, si_utime=62 /* 0.62 s */, si_stime=4 /* 0.04 s */} ---
22:05:21.653023 wait4(1484500, 0x55cd8bcb73b8, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
22:05:21.667513 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=1484503, si_uid=1000, si_status=0, si_utime=60 /* 0.60 s */, si_stime=7 /* 0.07 s */} ---
22:05:21.667686 wait4(1484500, 0x55cd8bcb73b8, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
22:05:21.671383 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=1484505, si_uid=1000, si_status=0, si_utime=63 /* 0.63 s */, si_stime=3 /* 0.03 s */} ---
22:05:21.671534 wait4(1484500, 0x55cd8bcb73b8, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
22:05:21.693729 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=1484501, si_uid=1000, si_status=0, si_utime=62 /* 0.62 s */, si_stime=6 /* 0.06 s */} ---
22:05:21.693855 wait4(1484500

Probably, making the functor overload like this would fix the issue:

template<typename Self>
void operator()(Self &&self, error_code ec, int = 0)
{
    if (!ec && process_is_running(exit_code))
    {
        int res = ::waitpid(pid_, &exit_code, WNOHANG);
        if (res == 0) 
        {
            // Process hasn't actually exited yet! 
            descriptor.async_wait(
                boost::asio::posix::descriptor_base::wait_read, 
                std::move(self)
            );
            return;
        }
        else if (res == -1)
        {
            ec = get_last_error();
        }
    }
    std::move(self).complete(ec);
}

But I am not sure. I am in process of finding a way to patch boost process within conan and testing for real.

[klemens-morgenstern]

The problem I see here is this: if the wake-up is spurious but EPOLLIN is set, we'll just be looping the same call over and over again. I guess that's better than blocking, but not by much.

I really would like to know why the fd becomes readable, I found two ML discussions

https://lore.kernel.org/lkml/20240131141204.GA24130@redhat.com/T/
https://lwn.net/Articles/954095/

but haven't had the time yet to look deeply into that.