tokio 1.39/mio 1.0 appears to be dropping waker notifications on illumos

[sunshowers]

(filing this here for now just to put down notes)

Tokio 1.39.2's test suite consistently hangs on illumos while 1.38.0 doesn't. Via a git bisect we traced it down to this being an issue in mio 1.0, with (in the mio repo) cargo nextest run --all-features --test waker waker_multiple_wakeups_different_thread:

        FAIL [   0.111s] mio::waker waker_multiple_wakeups_different_thread

--- STDOUT:              mio::waker waker_multiple_wakeups_different_thread ---

running 1 test
test waker_multiple_wakeups_different_thread ... FAILED

failures:

failures:
    waker_multiple_wakeups_different_thread

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 6 filtered out; finished in 0.10s


--- STDERR:              mio::waker waker_multiple_wakeups_different_thread ---
thread 'waker_multiple_wakeups_different_thread' panicked at tests/waker.rs:157:5:
assertion failed: !events.is_empty()
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

Via another bisect we found that this pair of commits is to blame, and the pair looks relevant:

• tokio-rs/mio@f3863f1
• tokio-rs/mio@1133ed0

The second commit is a child of the first, and the first commit doesn't build on illumos, so consider the pair of commits as a unit.

Combined diff of the two commits in case it's helpful: https://gist.github.com/sunshowers/c573ae448d2c1eb028216c3f3d644719

cc @jclulow who first noticed the issue

[sunshowers]

In tokio-rs/mio@1133ed0 it looks like the waker impl on illumos (unintentionally?) got switched from pipe-based to eventfd.

[sunshowers]

PR to switch the impl back to being pipe-based: tokio-rs/mio#1824

For the eventfd impls, there might be some bug-incompatibility between Linux and illumos here -- might be worth figuring out what it is.

[sunshowers]

I looked at the eventfd impl, as well as the Linux and illumos man pages, and to be honest the code is really simple and looks like it should work. Suggests possibly a bug in the illumos eventfd impl.

Too tired to continue but at least we have a good workaround :)

[sunshowers]

Repro:

git clone https://github.com/tokio-rs/mio
cd mio
git checkout 4a5114e518b982f49ce093be6d0d2a2ab86472d1
cargo test --all-features --test waker -- waker_multiple_wakeups_different_thread

@rmustacc has expressed an interest in looking at the issue.

[sunshowers]

Workaround is to set RUSTFLAGS="--cfg mio_unsupported_force_waker_pipe". (But note that rustflags settings do not compose: if someone has RUSTFLAGS set in the environment, then that will override build.rustflags set in .cargo/config.toml.

[citrus-it]

This appears to be a similar problem to https://www.illumos.org/issues/13436 in that the epoll wakeup appears to occur only on an eventfd transition from zero to non-zero. Resetting to zero before waking up results in the test passing.

diff --git a/src/sys/unix/waker/eventfd.rs b/src/sys/unix/waker/eventfd.rs
index c0086fc..3a1e6bf 100644
--- a/src/sys/unix/waker/eventfd.rs
+++ b/src/sys/unix/waker/eventfd.rs
@@ -42,6 +42,11 @@ impl Waker {

     #[allow(clippy::unused_io_amount)] // Don't care about partial writes.
     pub(crate) fn wake(&self) -> io::Result<()> {
+        // The epoll emulation on some illumos systems currently requires the
+        // eventfd to transition from zero for an edge-triggered wakeup.
+        #[cfg(target_os = "illumos")]
+        self.reset()?;
+
         let buf: [u8; 8] = 1u64.to_ne_bytes();
         match (&self.fd).write(&buf) {
             Ok(_) => Ok(()),

bloody:mio:HEAD% cargo test --all-features --test waker -- waker_multiple_wakeups_different_thread
    Finished `test` profile [unoptimized + debuginfo] target(s) in 0.08s
     Running tests/waker.rs (target/debug/deps/waker-1f848cdbed8b9273)

running 1 test
test waker_multiple_wakeups_different_thread ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 6 filtered out; finished in 0.05s

And in fact all tests pass with this change

bloody:mio:HEAD% cargo test --all-features
  Downloaded hermit-abi v0.3.9
  Downloaded 1 crate (16.2 KB) in 1.34s
   Compiling mio v1.0.1 (/data/omnios-build/mio)
    Finished `test` profile [unoptimized + debuginfo] target(s) in 4.28s
     Running unittests src/lib.rs (target/debug/deps/mio-b7460c5ba3de9e3f)

running 2 tests
test sys::unix::uds::tests::pathname_address ... ok
test poll::as_raw_fd ... ok

test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Running tests/aio.rs (target/debug/deps/aio-f6ab7b622ddfa7eb)

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Running tests/close_on_drop.rs (target/debug/deps/close_on_drop-bbbaaeec16e0962d)

running 1 test
test close_on_drop ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Running tests/events.rs (target/debug/deps/events-06fb0c87ad1f7bdf)

running 2 tests
test assert_event_source_implemented_for ... ok
test events_all ... ok

test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Running tests/interest.rs (target/debug/deps/interest-f8c17705b1758c36)

running 4 tests
test add ... ok
test fmt_debug ... ok
test is_tests ... ok
test bit_or ... ok

test result: ok. 4 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

     Running tests/poll.rs (target/debug/deps/poll-15f7f69ae28e7ac9)

running 16 tests
test is_send_and_sync ... ok
test deregister_without_register ... ok
test poll_erroneous_registration ... ok
test poll_registration ... ok
test double_register_different_token ... ok
test drop_cancels_interest_and_shuts_down ... ok
test reregister_interest_token_usage ... ok
test reregister_without_register ... ok
test poll_ok_after_cancelling_pending_ops ... ok
test registry_behind_arc ... ok
test registry_operations_are_thread_safe ... ok
test zero_duration_polls_events ... ok
test poll_closes_fd ... ok
test add_then_drop ... ok
test run_once_with_nothing ... ok
test register_during_poll ... ok

test result: ok. 16 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.20s

     Running tests/registering.rs (target/debug/deps/registering-b2b1d422215e0cf4)

running 5 tests
test udp_register_multiple_event_loops ... ok
test tcp_register_multiple_event_loops ... ok
test registering_after_deregistering ... ok
test register_deregister ... ok
test reregister_different_interest_without_poll ... ok

test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.40s

     Running tests/regressions.rs (target/debug/deps/regressions-dcebfd43d6086c38)

running 3 tests
test issue_1403 ... ok
test issue_776 ... ok
test issue_1205 ... ok

test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.50s

     Running tests/tcp.rs (target/debug/deps/tcp-acd28c7132a9b122)

running 18 tests
test is_send_and_sync ... ok
test connect_error ... ok
test connect_then_close ... ok
test bind_twice_bad ... ok
test local_addr_ready ... ok
test accept ... ok
test write_then_deregister ... ok
test write_error ... ok
test connect ... ok
test write_then_drop ... ok
test multiple_writes_immediate_success ... ok
test peek ... ok
test write ... ok
test read ... ok
test listen_then_close ... ok
test connection_reset_by_peer ... ok
test write_shutdown ... ok
test tcp_no_events_after_deregister ... ok

test result: ok. 18 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.35s

     Running tests/tcp_listener.rs (target/debug/deps/tcp_listener-83e78c9c6dd69786)

running 11 tests
test is_send_and_sync ... ok
test get_ttl_without_previous_set ... ok
test raw_fd ... ok
test set_get_ttl ... ok
test tcp_listener_std ... ok
test reregister ... ok
test tcp_listener ... ok
test tcp_listener_ipv6 ... ok
test registering ... ok
test no_events_after_deregister ... ok
test tcp_listener_two_streams ... ok

test result: ok. 11 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.05s

     Running tests/tcp_stream.rs (target/debug/deps/tcp_stream-8f876d58468376dc)

running 21 tests
test is_send_and_sync ... ok
test hup_event_on_disconnect ... ok
test raw_fd ... ok
test get_nodelay_without_previous_set ... ok
test shutdown_write ... ignored, This test is flaky, it doesn't always receive an event after shutting down the write side
test tcp_shutdown_client_both_close_event ... ignored, fails; client write_closed events are not found
test reregistering ... ok
test get_ttl_without_previous_set ... ok
test set_get_ttl ... ok
test tcp_shutdown_client_write_close_event ... ignored, fails; client write_closed events are not found
test set_get_nodelay ... ok
test shutdown_both ... ok
test tcp_shutdown_client_read_close_event ... ok
test shutdown_read ... ok
test tcp_shutdown_server_write_close_event ... ok
test tcp_stream_ipv6 ... ok
test tcp_stream_std ... ok
test tcp_stream_ipv4 ... ok
test registering ... ok
test no_events_after_deregister ... ok
test tcp_reset_close_event ... ok

test result: ok. 18 passed; 0 failed; 3 ignored; 0 measured; 0 filtered out; finished in 0.10s

     Running tests/udp_socket.rs (target/debug/deps/udp_socket-fe449bf38f831726)

running 32 tests
test get_multicast_loop_v4_without_previous_set ... ok
test is_send_and_sync ... ok
test get_multicast_loop_v6_without_previous_set ... ok
test get_multicast_ttl_v4_without_previous_set ... ok
test get_ttl_without_previous_set ... ok
test get_broadcast_without_previous_set ... ok
test connected_udp_socket_std ... ok
test empty_datagram ... ok
test et_behavior_recv ... ok
test et_behavior_recv_from ... ok
test connected_udp_socket_ipv6 ... ok
test connected_udp_socket_ipv4 ... ok
test connected_udp_socket_unconnected_methods ... ok
test multicast ... ok
test reconnect_udp_socket_receiving ... ok
test reconnect_udp_socket_sending ... ok
test set_get_broadcast ... ok
test set_get_multicast_loop_v4 ... ok
test set_get_multicast_loop_v6 ... ok
test set_get_multicast_ttl_v4 ... ok
test set_get_ttl ... ok
test udp_socket ... ok
test udp_socket_discard ... ok
test udp_socket_raw_fd ... ok
test unconnected_udp_socket_connected_methods ... ok
test udp_socket_send_recv ... ok
test unconnected_udp_socket_ipv4 ... ok
test udp_socket_reregister ... ok
test unconnected_udp_socket_ipv6 ... ok
test unconnected_udp_socket_std ... ok
test udp_socket_register ... ok
test udp_socket_no_events_after_deregister ... ok

test result: ok. 32 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.06s

     Running tests/unix_datagram.rs (target/debug/deps/unix_datagram-bd72435bfea8f0a6)

running 11 tests
test is_send_and_sync ... ok
test unix_datagram_pair ... ok
test unix_datagram_smoke_connected_from_std ... ok
test unix_datagram_connect ... ok
test unix_datagram_smoke_connected ... ok
test unix_datagram_smoke_unconnected ... ok
test unix_datagram_reregister ... ok
test unix_datagram_smoke_unconnected_from_std ... ok
test unix_datagram_shutdown ... ok
test unix_datagram_register ... ok
test unix_datagram_deregister ... ok

test result: ok. 11 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.05s

     Running tests/unix_listener.rs (target/debug/deps/unix_listener-8c549d6e522714c0)

running 7 tests
test unix_listener_send_and_sync ... ok
test unix_listener_local_addr ... ok
test unix_listener_register ... ok
test unix_listener_deregister ... ok
test unix_listener_reregister ... ok
test unix_listener_from_std ... ok
test unix_listener_smoke ... ok

test result: ok. 7 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.05s

     Running tests/unix_pipe.rs (target/debug/deps/unix_pipe-a19e7a75dad0f7db)

running 5 tests
test event_when_receiver_is_dropped ... ok
test smoke ... ok
test event_when_sender_is_dropped ... ok
test nonblocking_child_process_io ... ok
test from_child_process_io ... ok

test result: ok. 5 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.02s

     Running tests/unix_stream.rs (target/debug/deps/unix_stream-c07e6c36b50d7df0)

running 14 tests
test unix_stream_send_and_sync ... ok
test unix_stream_pair ... ok
test unix_stream_connect ... ok
test unix_stream_connect_addr ... ok
test unix_stream_from_std ... ok
test unix_stream_shutdown_write ... ok
test unix_stream_peer_addr ... ok
test unix_stream_shutdown_listener_write ... ok
test unix_stream_shutdown_both ... ok
test unix_stream_shutdown_read ... ok
test unix_stream_smoke ... ok
test unix_stream_reregister ... ok
test unix_stream_register ... ok
test unix_stream_deregister ... ok

test result: ok. 14 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.06s

     Running tests/waker.rs (target/debug/deps/waker-1f848cdbed8b9273)

running 7 tests
test is_send_and_sync ... ok
test waker ... ok
test waker_multiple_wakeups_same_thread ... ok
test using_multiple_wakers_panics_different_cloned_registries - should panic ... ok
test using_multiple_wakers_panics - should panic ... ok
test waker_multiple_wakeups_different_thread ... ok
test waker_wakeup_different_thread ... ok

test result: ok. 7 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.05s

     Running tests/win_named_pipe.rs (target/debug/deps/win_named_pipe-093ebaabb9a36e34)

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

   Doc-tests mio

running 45 tests
test src/net/tcp/stream.rs - net::tcp::stream::TcpStream::try_io (line 229) - compile ... ok
test src/event/source.rs - event::source::Source (line 41) ... ok
test src/interest.rs - interest::Interest::add (line 59) ... ok
test src/event/events.rs - event::events::Events::is_empty (line 114) ... ok
test src/event/events.rs - event::events::Events::with_capacity (line 86) ... ok
test src/event/events.rs - event::events::Events::capacity (line 100) ... ok
test src/interest.rs - interest::Interest::remove (line 76) ... ok
test src/lib.rs - guide (line 151) ... ok
test src/lib.rs - guide (line 185) ... ok
test src/net/udp.rs - net::udp::UdpSocket::peek_from (line 266) - compile ... ok
test src/net/tcp/stream.rs - net::tcp::stream::TcpStream (line 24) ... ok
test src/event/events.rs - event::events::Iter (line 55) ... ok
test src/event/events.rs - event::events::Events (line 20) ... ok
test src/event/events.rs - event::events::Events::clear (line 164) ... ok
test src/event/events.rs - event::events::Events::iter (line 128) ... ok
test src/net/udp.rs - net::udp::UdpSocket::recv_from (line 230) - compile ... ok
test src/net/udp.rs - net::udp::UdpSocket::send_to (line 197) - compile ... ok
test src/net/tcp/listener.rs - net::tcp::listener::TcpListener (line 24) ... ok
test src/lib.rs - guide (line 223) ... ok
test src/net/udp.rs - net::udp::UdpSocket::try_io (line 571) - compile ... ok
test src/net/udp.rs - net::udp::UdpSocket (line 32) ... ok
test src/net/udp.rs - net::udp::UdpSocket::bind (line 102) ... ok
test src/net/udp.rs - net::udp::UdpSocket::broadcast (line 370) ... ok
test src/net/udp.rs - net::udp::UdpSocket::local_addr (line 143) ... ok
test src/net/udp.rs - net::udp::UdpSocket::peer_addr (line 170) ... ok
test src/net/udp.rs - net::udp::UdpSocket::set_ttl (line 451) ... ok
test src/net/udp.rs - net::udp::UdpSocket::set_broadcast (line 340) ... ok
test src/net/udp.rs - net::udp::UdpSocket::ttl (line 480) ... ok
test src/net/uds/datagram.rs - net::uds::datagram::UnixDatagram::try_io (line 133) ... ok
test src/net/uds/stream.rs - net::uds::stream::UnixStream::try_io (line 98) ... ok
test src/poll.rs - poll::Poll (line 50) ... ok
test src/sys/unix/pipe.rs - sys::unix::pipe::Receiver::try_io (line 414) ... ok
test src/poll.rs - poll::Registry::reregister (line 597) ... ok
test src/sys/unix/pipe.rs - sys::unix::pipe::new (line 116) ... ok
test src/poll.rs - poll::Registry::register (line 519) ... ok
test src/sys/unix/pipe.rs - sys::unix::pipe::Sender::try_io (line 243) ... ok
test src/sys/unix/pipe.rs - sys::unix::pipe::new (line 171) ... ok
test src/sys/unix/sourcefd.rs - sys::unix::sourcefd::SourceFd (line 58) ... ok
test src/poll.rs - poll::Poll::poll (line 384) ... ok
test src/sys/unix/sourcefd.rs - sys::unix::sourcefd::SourceFd (line 33) ... ok
test src/poll.rs - poll::Poll::new (line 299) ... ok
test src/token.rs - token::Token (line 20) ... ok
test src/poll.rs - poll::Poll (line 146) ... ok
test src/poll.rs - poll::Registry::deregister (line 664) ... ok
test src/waker.rs - waker::Waker (line 37) ... ok

test result: ok. 45 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 2.37s

[citrus-it]

This behaviour seems to be intentional in the illumos implementation:

static int
eventfd_write(dev_t dev, struct uio *uio, cred_t *credp)
{
...
        /*
         * Notify pollers as well if the eventfd is now readable.
         */
        if (oval == 0) {
                pollwakeup(&state->efd_pollhd, POLLRDNORM | POLLIN);
        }

        return (0);
}

[citrus-it]

I have opened https://www.illumos.org/issues/16700 upstream for this, and also opened illumos/epoll-test-suite#2 to add a test to the illumos epoll test suite.