Why does it synchronously wait?
- Dominant language
- C++
- Stars
- 145
- Forks
- 151
- PR merge metrics
- No merged PRs in 30d
Description
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](https://github.com/Arniiiii/gyou), 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`](https://github.com/Arniiiii/portage/blob/master/bin/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`](https://dev.gentoo.org/~zmedico/portage/doc/man/ebuild.1.html) . 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
```cpp
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
```cpp
corral::Task read_loop(std::string const& logger_name,
boost::asio::readable_pipe& a_pipe)
{
std::string res;
std::array 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 `:
`strace -p `
```
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 `
```
...
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](https://github.com/Arniiiii/portage/blob/master/lib/_emerge/SpawnProcess.py), I guess there are also [many skeletons of ancient python era with no `async`,](https://github.com/gentoo/portage/blob/master/lib/portage/util/_async/PipeLogger.py) but it seems that it forces `wget`'s [stderr to the same pipe as stdout](https://github.com/gentoo/portage/blob/15b0835c7c44d8a41746e1f441b486e8ee609826/lib/_emerge/SpawnProcess.py#L110-L112), which seems to be true, because I get next logs after cancelling:
```
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:
```shell
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 -ex "bt"`
```
#0 __syscall_cancel_arch () at ../sysdeps/unix/sysv/linux/x86_64/syscall_cancel.S:56
#1 0x00007f3eedea6ed8 in __internal_syscall_cancel (a1=, a2=, a3=, a4=, a5=0x0, a6=0x0, nr=0x3d) at cancellation.c:49
#2 __syscall_cancel (a1=, a2=, a3=, a4=, a5=a5@entry=0x0, a6=a6@entry=0x0, nr=0x3d) at cancellation.c:75
#3 0x00007f3eedf329bb in __GI___wait4 (pid=, stat_loc=, options=, usage=) 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::async_wait_op_::operator()::async_wait_op_, boost::asio::detail::composed_work, boost::asio::detail::composed_op::async_wait_op_, boost::asio::detail::composed_work, corral::detail::AsioAwaiterBase::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::async_wait_op_, boost::asio::detail::composed_work, boost::asio::detail::composed_op::async_wait_op_, boost::asio::detail::composed_work, corral::detail::AsioAwaiterBase::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)>::operator() (this=0x7b3eec089a70, t=...) at /home/paxu/.conan2/p/b/boost34fa1e20831c2/p/include/boost/asio/composed.hpp:150
#7 0x000055725b0d7080 in boost::asio::detail::binder1::async_wait_op_, boost::asio::detail::composed_work, boost::asio::detail::composed_op::async_wait_op_, boost::asio::detail::composed_work, corral::detail::AsioAwaiterBase::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::async_wait_op_, boost::asio::detail::composed_work, boost::asio::detail::composed_op::async_wait_op_, boost::asio::detail::composed_work, corral::detail::AsioAwaiterBase::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)>, boost::system::error_code>, std::allocator > (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, 4ul>::execute (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, 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::async_wait_op_, boost::asio::detail::composed_work, boost::asio::detail::composed_op::async_wait_op_, boost::asio::detail::composed_work, corral::detail::AsioAwaiterBase::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::dispatch::async_wait_op_, boost::asio::detail::composed_work, boost::asio::detail::composed_op::async_wait_op_, boost::asio::detail::composed_work, corral::detail::AsioAwaiterBase::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)>, boost::system::error_code>, boost::asio::detail::composed_op::async_wait_op_, boost::asio::detail::composed_work, boost::asio::detail::composed_op::async_wait_op_, boost::asio::detail::composed_work, corral::detail::AsioAwaiterBase::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::async_wait_op_, boost::asio::detail::composed_work, boost::asio::detail::composed_op::async_wait_op_, boost::asio::detail::composed_work, corral::detail::AsioAwaiterBase::DoneCB, void(boost::system::error_code, int)>, void(boost::system::error_code)>, boost::asio::any_io_executor, void>::complete::async_wait_op_, boost::asio::detail::composed_work, boost::asio::detail::composed_op::async_wait_op_, boost::asio::detail::composed_work, corral::detail::AsioAwaiterBase::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::async_wait_op_, boost::asio::detail::composed_work, boost::asio::detail::composed_op::async_wait_op_, boost::asio::detail::composed_work, corral::detail::AsioAwaiterBase::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::run (io=...) at /home/paxu/.conan2/p/b/corra5b846b3c50e05/p/include/corral/detail/asio.h:264
#23 0x000055725ae142c8 in corral::detail::Runner::run, corral::detail::AsioAwaitable::initiate_async_wait, std::tuple<>, int>, corral::Task >, corral::Task, corral::detail::AsioAwaitable::initiate_async_wait, std::tuple<>, int>, corral::Task > >(corral::detail::AwaiterMaker, corral::detail::AsioAwaitable::initiate_async_wait, std::tuple<>, int>, corral::Task >, corral::Task, corral::detail::AsioAwaitable::initiate_async_wait, std::tuple<>, int>, corral::Task >&&) && (this=0x7b3eebea46a0, awaitable=...)
at /home/paxu/.conan2/p/b/corra5b846b3c50e05/p/include/corral/run.h:86
#24 0x000055725ac789a4 in corral::run, corral::detail::AsioAwaitable::initiate_async_wait, std::tuple<>, int>, corral::Task >, corral::Task, corral::detail::AsioAwaitable::initiate_async_wait, std::tuple<>, int>, corral::Task > >(boost::asio::io_context&, corral::detail::AwaiterMaker, corral::detail::AsioAwaitable::initiate_async_wait, std::tuple<>, int>, corral::Task >, corral::Task, corral::detail::AsioAwaitable::initiate_async_wait, std::tuple<>, int>, corral::Task >&&) (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=, stat_loc=, options=, usage=) at ../sysdeps/unix/sysv/linux/wait4.c:30`
**`wait4`**
[One of the blocking waits.](https://www.man7.org/linux/man-pages/man2/wait4.2.html)
And I use [`corral`](https://github.com/hudson-trading/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?
https://github.com/Arniiiii/gyou/commit/3256de28deb1e0561dc4536cc4bf4e68f8fa0260
```cpp
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 a 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
Boost version: 1.91.0 from [conan.io](https://github.com/conan-io/conan-center-index/blob/master/recipes/boost/all/conanfile.py)
https://github.com/Arniiiii/gyou/blob/afb35829c94e69a4e07c3451ebfc402a3c22203d/CMakeLists.txt#L33-L40
```cmake
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-21, 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
```
Contributor guide
No contributing guide indexed for this repository
Research direction
Start with the proc.async_wait call in source/bash_ebuild_manifest.cpp and the read_loop implementation in async_read_with_custom_log.cpp. Reproduce the wget-through-ebuild case and inspect the strace behavior described in the issue. Done means documenting why the wait appears blocking and how the pipe interaction leads to the observed hang.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- cpp
- Domain
- operating-systems
- Issue type
- Documentation
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Active
- Clarity
- Needs clarification
- Newbie friendliness
- 45/100