Stream: git-wasmtime

Topic: wasmtime / issue #7606 Flaky test failure in `preview2_ud...

Wasmtime GitHub notifications bot (Nov 29 2023 at 19:37):

alexcrichton opened issue #7606:

This failure has now been seen here and here.

Currently what I've seen is:

• Both failures happen on Windows, one on MinGW and one on MSVC
• Both CI failures were trigger by failures of both the sync and async versions of the test
• All failures are this line which is acquiring the local address of a UDP socket after it's bound to a fixed port.

This all seems fishy to me, I'm not sure what's going on! cc @badeend as you're likely interested.

<details>

<summary>Failure 1</summary>

failures:

---- async_::preview2_udp_bind stdout ----
preopen: TempDir { path: "C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\wasi_components_preview2_udp_bind.component_uiQC80" }
[guest] stderr:
thread 'main' panicked at crates\test-programs\src\bin\preview2_udp_bind.rs:35:43:
called `Result::unwrap()` on an `Err` value: ErrorCode { code: 9, name: "invalid-state", message: "The operation is not valid in the socket's current state." }
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

===
thread 'async_::preview2_udp_bind' panicked at crates\wasi\tests\all\async_.rs:335:51:
called `Result::unwrap()` on an `Err` value: error while executing at wasm backtrace:
    0: 0xd3bc - <unknown>!__rust_start_panic
    1: 0xd200 - <unknown>!rust_panic
    2: 0xd133 - <unknown>!std::panicking::rust_panic_with_hook::h639672e96e0f2421
    3: 0xc545 - <unknown>!std::panicking::begin_panic_handler::{{closure}}::he2feed3b05783a82
    4: 0xc468 - <unknown>!std::sys_common::backtrace::__rust_end_short_backtrace::h2453fabad70b604e
    5: 0xcaea - <unknown>!rust_begin_unwind
    6: 0x11a8a - <unknown>!core::panicking::panic_fmt::h8d812bd208f205dc
    7: 0x13655 - <unknown>!core::result::unwrap_failed::h0c9b525dd5a26387
    8: 0x1ae8 - <unknown>!core::result::Result<T,E>::unwrap::hf03bf2ffbe46122a
    9: 0x2411 - <unknown>!preview2_udp_bind::test_udp_bind_specific_port::h457a5e69c52cafb1
   10: 0x3b5f - <unknown>!preview2_udp_bind::main::hc4fa6ed34db99c90
   11: 0x15d2 - <unknown>!core::ops::function::FnOnce::call_once::hacc676ed954b86d3
   12: 0x15a9 - <unknown>!std::sys_common::backtrace::__rust_begin_short_backtrace::h5d7b67e9a5e5af12
   13: 0x168a - <unknown>!std::rt::lang_start::{{closure}}::h5a806a5629e6b99f
   14: 0xacce - <unknown>!std::rt::lang_start_internal::h409072ad2c29d9a2
   15: 0x1635 - <unknown>!std::rt::lang_start::h776dc8db019efe49
   16: 0x410a - <unknown>!__main_void
   17: 0x1584 - <unknown>!_start
   18: 0x2e76a7 - wit-component:adapter:wasi_snapshot_preview1!wasi:cli/run@0.2.0-rc-2023-11-10#run
note: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information

Caused by:
    wasm trap: wasm `unreachable` instruction executed
stack backtrace:
   0: std::panicking::begin_panic_handler
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\std\src\panicking.rs:597
   1: core::panicking::panic_fmt
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\core\src\panicking.rs:72
   2: core::result::unwrap_failed
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\core\src\result.rs:1652
   3: core::result::Result<T,E>::unwrap
   4: all::async_::preview2_udp_bind::{{closure}}
   5: all::async_::preview2_udp_bind::{{closure}}
   6: <core::pin::Pin<P> as core::future::future::Future>::poll
   7: <F as core::future::into_future::IntoFuture>::into_future
   8: <F as core::future::into_future::IntoFuture>::into_future
   9: tokio::runtime::context::blocking::BlockingRegionGuard::block_on
  10: tokio::runtime::scheduler::multi_thread::MultiThread::block_on::{{closure}}
  11: tokio::runtime::context::runtime::enter_runtime
  12: tokio::runtime::runtime::Runtime::block_on
  13: tokio::runtime::runtime::Runtime::block_on
  14: all::async_::preview2_udp_bind::{{closure}}
  15: all::async_::preview2_udp_bind::{{closure}}
  16: core::ops::function::FnOnce::call_once
  17: core::ops::function::FnOnce::call_once
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\core\src\ops\function.rs:250
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

---- sync::preview2_udp_bind stdout ----
preopen: TempDir { path: "C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\wasi_components_preview2_udp_bind.component_oQBE1O" }
[guest] stderr:
thread 'main' panicked at crates\test-programs\src\bin\preview2_udp_bind.rs:35:43:
called `Result::unwrap()` on an `Err` value: ErrorCode { code: 9, name: "invalid-state", message: "The operation is not valid in the socket's current state." }
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

===
thread 'sync::preview2_udp_bind' panicked at crates\wasi\tests\all\sync.rs:278:45:
called `Result::unwrap()` on an `Err` value: error while executing at wasm backtrace:
    0: 0xd3bc - <unknown>!__rust_start_panic
    1: 0xd200 - <unknown>!rust_panic
    2: 0xd133 - <unknown>!std::panicking::rust_panic_with_hook::h639672e96e0f2421
    3: 0xc545 - <unknown>!std::panicking::begin_panic_handler::{{closure}}::he2feed3b05783a82
    4: 0xc468 - <unknown>!std::sys_common::backtrace::__rust_end_short_backtrace::h2453fabad70b604e
    5: 0xcaea - <unknown>!rust_begin_unwind
    6: 0x11a8a - <unknown>!core::panicking::panic_fmt::h8d812bd208f205dc
    7: 0x13655 - <unknown>!core::result::unwrap_failed::h0c9b525dd5a26387
    8: 0x1ae8 - <unknown>!core::result::Result<T,E>::unwrap::hf03bf2ffbe46122a
    9: 0x2411 - <unknown>!preview2_udp_bind::test_udp_bind_specific_port::h457a5e69c52cafb1
   10: 0x3b5f - <unknown>!preview2_udp_bind::main::hc4fa6ed34db99c90
   11: 0x15d2 - <unknown>!core::ops::function::FnOnce::call_once::hacc676ed954b86d3
   12: 0x15a9 - <unknown>!std::sys_common::backtrace::__rust_begin_short_backtrace::h5d7b67e9a5e5af12
   13: 0x168a - <unknown>!std::rt::lang_start::{{closure}}::h5a806a5629e6b99f
   14: 0xacce - <unknown>!std::rt::lang_start_internal::h409072ad2c29d9a2
   15: 0x1635 - <unknown>!std::rt::lang_start::h776dc8db019efe49
   16: 0x410a - <unknown>!__main_void
   17: 0x1584 - <unknown>!_start
   18: 0x2e76a7 - wit-component:adapter:wasi_snapshot_preview1!wasi:cli/run@0.2.0-rc-2023-11-10#run
note: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information

Caused by:
    wasm trap: wasm `unreachable` instruction executed
stack backtrace:
   0: std::panicking::begin_panic_handler
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\std\src\panicking.rs:597
   1: core::panicking::panic_fmt
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\core\src\panicking.rs:72
   2: core::result::unwrap_failed
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\core\src\result.rs:1652
   3: core::result::Result<T,E>::unwrap
   4: all::sync::preview2_udp_bind::{{closure}}
   5: all::sync::preview2_udp_bind::{{closure}}
   6: all::sync::preview2_udp_bind::{{closure}}
   7: core::ops::function::FnOnce::call_once
   8: core::ops::function::FnOnce::call_once
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\core\src\ops\function.rs:250
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.


failures:
    async_::preview2_udp_bind
    sync::preview2_udp_bind

</details>

<details>

<summary>Failure 2</summary>

failures:

---- async_::preview2_udp_bind stdout ----
preopen: TempDir { path: "C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\wasi_components_preview2_udp_bind.component_C7RHTg" }
[guest] stderr:
thread 'main' panicked at crates\test-programs\src\bin\preview2_udp_bind.rs:35:43:
called `Result::unwrap()` on an `Err` value: ErrorCode { code: 9, name: "invalid-state", message: "The operation is not valid in the socket's current state." }
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

===
thread 'async_::preview2_udp_bind' panicked at crates\wasi\tests\all\async_.rs:335:51:
called `Result::unwrap()` on an `Err` value: error while executing at wasm backtrace:
    0: 0xc363 - <unknown>!__rust_start_panic
    1: 0xc1a7 - <unknown>!rust_panic
    2: 0xc0da - <unknown>!std::panicking::rust_panic_with_hook::h639672e96e0f2421
    3: 0xb4ec - <unknown>!std::panicking::begin_panic_handler::{{closure}}::he2feed3b05783a82
    4: 0xb40f - <unknown>!std::sys_common::backtrace::__rust_end_short_backtrace::h2453fabad70b604e
    5: 0xba91 - <unknown>!rust_begin_unwind
    6: 0x10a31 - <unknown>!core::panicking::panic_fmt::h8d812bd208f205dc
    7: 0x125fc - <unknown>!core::result::unwrap_failed::h0c9b525dd5a26387
    8: 0x1b45 - <unknown>!core::result::Result<T,E>::unwrap::hba05ad71650d65eb
    9: 0x246e - <unknown>!preview2_udp_bind::test_udp_bind_specific_port::h7df0afeb18519e70
   10: 0x3bbc - <unknown>!preview2_udp_bind::main::h3b5389890cf6c15d
   11: 0x162f - <unknown>!core::ops::function::FnOnce::call_once::he547435657136ad8
   12: 0x1606 - <unknown>!std::sys_common::backtrace::__rust_begin_short_backtrace::h99201b78ada4a42e
   13: 0x16e7 - <unknown>!std::rt::lang_start::{{closure}}::h856cf0990f321ac7
   14: 0x9c75 - <unknown>!std::rt::lang_start_internal::h409072ad2c29d9a2
   15: 0x1692 - <unknown>!std::rt::lang_start::h9ee8d16b8e164ff4
   16: 0x4167 - <unknown>!__main_void
   17: 0x15e1 - <unknown>!_start
   18: 0x2e7076 - wit-component:adapter:wasi_snap
[message truncated]

Wasmtime GitHub notifications bot (Nov 29 2023 at 19:41):

alexcrichton commented on issue #7606:

One possible clue, we don't know at this time which of these four functions triggered the failure:

    test_udp_bind_specific_port(&net, IpAddress::IPV4_LOOPBACK);
    test_udp_bind_specific_port(&net, IpAddress::IPV6_LOOPBACK);
    test_udp_bind_specific_port(&net, IpAddress::IPV4_UNSPECIFIED);
    test_udp_bind_specific_port(&net, IpAddress::IPV6_UNSPECIFIED);

This may perhaps be an ipv4-vs-ipv6 thing on a specific github actions builder, unsure!

Wasmtime GitHub notifications bot (Nov 29 2023 at 19:59):

badeend commented on issue #7606:

I think this is (yet again :) ) the same issue as in https://github.com/bytecodealliance/wasmtime/issues/7429 and https://github.com/bytecodealliance/wasmtime/pull/7339. If bind fails, we fall through instead of short circuiting the test case... :grimacing: Line 35 just happens to be the first thing to execute after bind failed, but other than that I don;t think it's actually related.


Wasmtime GitHub notifications bot (Nov 29 2023 at 20:00):

badeend commented on issue #7606:

I'll submit a fix

Wasmtime GitHub notifications bot (Nov 29 2023 at 20:05):

alexcrichton commented on issue #7606:

Oh oops, and good catch! Here I was looking for a more complicated answer when the obvious one was staring me in the face...

Wasmtime GitHub notifications bot (Nov 29 2023 at 21:41):

alexcrichton closed issue #7606:

This failure has now been seen here and here.

Currently what I've seen is:

• Both failures happen on Windows, one on MinGW and one on MSVC
• Both CI failures were trigger by failures of both the sync and async versions of the test
• All failures are this line which is acquiring the local address of a UDP socket after it's bound to a fixed port.

This all seems fishy to me, I'm not sure what's going on! cc @badeend as you're likely interested.

<details>

<summary>Failure 1</summary>

failures:

---- async_::preview2_udp_bind stdout ----
preopen: TempDir { path: "C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\wasi_components_preview2_udp_bind.component_uiQC80" }
[guest] stderr:
thread 'main' panicked at crates\test-programs\src\bin\preview2_udp_bind.rs:35:43:
called `Result::unwrap()` on an `Err` value: ErrorCode { code: 9, name: "invalid-state", message: "The operation is not valid in the socket's current state." }
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

===
thread 'async_::preview2_udp_bind' panicked at crates\wasi\tests\all\async_.rs:335:51:
called `Result::unwrap()` on an `Err` value: error while executing at wasm backtrace:
    0: 0xd3bc - <unknown>!__rust_start_panic
    1: 0xd200 - <unknown>!rust_panic
    2: 0xd133 - <unknown>!std::panicking::rust_panic_with_hook::h639672e96e0f2421
    3: 0xc545 - <unknown>!std::panicking::begin_panic_handler::{{closure}}::he2feed3b05783a82
    4: 0xc468 - <unknown>!std::sys_common::backtrace::__rust_end_short_backtrace::h2453fabad70b604e
    5: 0xcaea - <unknown>!rust_begin_unwind
    6: 0x11a8a - <unknown>!core::panicking::panic_fmt::h8d812bd208f205dc
    7: 0x13655 - <unknown>!core::result::unwrap_failed::h0c9b525dd5a26387
    8: 0x1ae8 - <unknown>!core::result::Result<T,E>::unwrap::hf03bf2ffbe46122a
    9: 0x2411 - <unknown>!preview2_udp_bind::test_udp_bind_specific_port::h457a5e69c52cafb1
   10: 0x3b5f - <unknown>!preview2_udp_bind::main::hc4fa6ed34db99c90
   11: 0x15d2 - <unknown>!core::ops::function::FnOnce::call_once::hacc676ed954b86d3
   12: 0x15a9 - <unknown>!std::sys_common::backtrace::__rust_begin_short_backtrace::h5d7b67e9a5e5af12
   13: 0x168a - <unknown>!std::rt::lang_start::{{closure}}::h5a806a5629e6b99f
   14: 0xacce - <unknown>!std::rt::lang_start_internal::h409072ad2c29d9a2
   15: 0x1635 - <unknown>!std::rt::lang_start::h776dc8db019efe49
   16: 0x410a - <unknown>!__main_void
   17: 0x1584 - <unknown>!_start
   18: 0x2e76a7 - wit-component:adapter:wasi_snapshot_preview1!wasi:cli/run@0.2.0-rc-2023-11-10#run
note: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information

Caused by:
    wasm trap: wasm `unreachable` instruction executed
stack backtrace:
   0: std::panicking::begin_panic_handler
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\std\src\panicking.rs:597
   1: core::panicking::panic_fmt
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\core\src\panicking.rs:72
   2: core::result::unwrap_failed
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\core\src\result.rs:1652
   3: core::result::Result<T,E>::unwrap
   4: all::async_::preview2_udp_bind::{{closure}}
   5: all::async_::preview2_udp_bind::{{closure}}
   6: <core::pin::Pin<P> as core::future::future::Future>::poll
   7: <F as core::future::into_future::IntoFuture>::into_future
   8: <F as core::future::into_future::IntoFuture>::into_future
   9: tokio::runtime::context::blocking::BlockingRegionGuard::block_on
  10: tokio::runtime::scheduler::multi_thread::MultiThread::block_on::{{closure}}
  11: tokio::runtime::context::runtime::enter_runtime
  12: tokio::runtime::runtime::Runtime::block_on
  13: tokio::runtime::runtime::Runtime::block_on
  14: all::async_::preview2_udp_bind::{{closure}}
  15: all::async_::preview2_udp_bind::{{closure}}
  16: core::ops::function::FnOnce::call_once
  17: core::ops::function::FnOnce::call_once
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\core\src\ops\function.rs:250
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

---- sync::preview2_udp_bind stdout ----
preopen: TempDir { path: "C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\wasi_components_preview2_udp_bind.component_oQBE1O" }
[guest] stderr:
thread 'main' panicked at crates\test-programs\src\bin\preview2_udp_bind.rs:35:43:
called `Result::unwrap()` on an `Err` value: ErrorCode { code: 9, name: "invalid-state", message: "The operation is not valid in the socket's current state." }
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

===
thread 'sync::preview2_udp_bind' panicked at crates\wasi\tests\all\sync.rs:278:45:
called `Result::unwrap()` on an `Err` value: error while executing at wasm backtrace:
    0: 0xd3bc - <unknown>!__rust_start_panic
    1: 0xd200 - <unknown>!rust_panic
    2: 0xd133 - <unknown>!std::panicking::rust_panic_with_hook::h639672e96e0f2421
    3: 0xc545 - <unknown>!std::panicking::begin_panic_handler::{{closure}}::he2feed3b05783a82
    4: 0xc468 - <unknown>!std::sys_common::backtrace::__rust_end_short_backtrace::h2453fabad70b604e
    5: 0xcaea - <unknown>!rust_begin_unwind
    6: 0x11a8a - <unknown>!core::panicking::panic_fmt::h8d812bd208f205dc
    7: 0x13655 - <unknown>!core::result::unwrap_failed::h0c9b525dd5a26387
    8: 0x1ae8 - <unknown>!core::result::Result<T,E>::unwrap::hf03bf2ffbe46122a
    9: 0x2411 - <unknown>!preview2_udp_bind::test_udp_bind_specific_port::h457a5e69c52cafb1
   10: 0x3b5f - <unknown>!preview2_udp_bind::main::hc4fa6ed34db99c90
   11: 0x15d2 - <unknown>!core::ops::function::FnOnce::call_once::hacc676ed954b86d3
   12: 0x15a9 - <unknown>!std::sys_common::backtrace::__rust_begin_short_backtrace::h5d7b67e9a5e5af12
   13: 0x168a - <unknown>!std::rt::lang_start::{{closure}}::h5a806a5629e6b99f
   14: 0xacce - <unknown>!std::rt::lang_start_internal::h409072ad2c29d9a2
   15: 0x1635 - <unknown>!std::rt::lang_start::h776dc8db019efe49
   16: 0x410a - <unknown>!__main_void
   17: 0x1584 - <unknown>!_start
   18: 0x2e76a7 - wit-component:adapter:wasi_snapshot_preview1!wasi:cli/run@0.2.0-rc-2023-11-10#run
note: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information

Caused by:
    wasm trap: wasm `unreachable` instruction executed
stack backtrace:
   0: std::panicking::begin_panic_handler
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\std\src\panicking.rs:597
   1: core::panicking::panic_fmt
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\core\src\panicking.rs:72
   2: core::result::unwrap_failed
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\core\src\result.rs:1652
   3: core::result::Result<T,E>::unwrap
   4: all::sync::preview2_udp_bind::{{closure}}
   5: all::sync::preview2_udp_bind::{{closure}}
   6: all::sync::preview2_udp_bind::{{closure}}
   7: core::ops::function::FnOnce::call_once
   8: core::ops::function::FnOnce::call_once
             at /rustc/79e9716c980570bfd1f666e3b16ac583f0168962/library\core\src\ops\function.rs:250
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.


failures:
    async_::preview2_udp_bind
    sync::preview2_udp_bind

</details>

<details>

<summary>Failure 2</summary>

failures:

---- async_::preview2_udp_bind stdout ----
preopen: TempDir { path: "C:\\Users\\RUNNER~1\\AppData\\Local\\Temp\\wasi_components_preview2_udp_bind.component_C7RHTg" }
[guest] stderr:
thread 'main' panicked at crates\test-programs\src\bin\preview2_udp_bind.rs:35:43:
called `Result::unwrap()` on an `Err` value: ErrorCode { code: 9, name: "invalid-state", message: "The operation is not valid in the socket's current state." }
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

===
thread 'async_::preview2_udp_bind' panicked at crates\wasi\tests\all\async_.rs:335:51:
called `Result::unwrap()` on an `Err` value: error while executing at wasm backtrace:
    0: 0xc363 - <unknown>!__rust_start_panic
    1: 0xc1a7 - <unknown>!rust_panic
    2: 0xc0da - <unknown>!std::panicking::rust_panic_with_hook::h639672e96e0f2421
    3: 0xb4ec - <unknown>!std::panicking::begin_panic_handler::{{closure}}::he2feed3b05783a82
    4: 0xb40f - <unknown>!std::sys_common::backtrace::__rust_end_short_backtrace::h2453fabad70b604e
    5: 0xba91 - <unknown>!rust_begin_unwind
    6: 0x10a31 - <unknown>!core::panicking::panic_fmt::h8d812bd208f205dc
    7: 0x125fc - <unknown>!core::result::unwrap_failed::h0c9b525dd5a26387
    8: 0x1b45 - <unknown>!core::result::Result<T,E>::unwrap::hba05ad71650d65eb
    9: 0x246e - <unknown>!preview2_udp_bind::test_udp_bind_specific_port::h7df0afeb18519e70
   10: 0x3bbc - <unknown>!preview2_udp_bind::main::h3b5389890cf6c15d
   11: 0x162f - <unknown>!core::ops::function::FnOnce::call_once::he547435657136ad8
   12: 0x1606 - <unknown>!std::sys_common::backtrace::__rust_begin_short_backtrace::h99201b78ada4a42e
   13: 0x16e7 - <unknown>!std::rt::lang_start::{{closure}}::h856cf0990f321ac7
   14: 0x9c75 - <unknown>!std::rt::lang_start_internal::h409072ad2c29d9a2
   15: 0x1692 - <unknown>!std::rt::lang_start::h9ee8d16b8e164ff4
   16: 0x4167 - <unknown>!__main_void
   17: 0x15e1 - <unknown>!_start
   18: 0x2e7076 - wit-component:adapter:wasi_snap
[message truncated]

Last updated: Nov 22 2024 at 17:03 UTC