wasmtime / issue #5577 Imported functions fail debug asse... · git-wasmtime

Stream: git-wasmtime

Topic: wasmtime / issue #5577 Imported functions fail debug asse...

Wasmtime GitHub notifications bot (Jan 16 2023 at 11:01):

Test Case

use anyhow::{anyhow, Result};
use wasmtime::*;

struct MyState {
}

fn main() -> Result<()> {
    let mut c = Config::default();

    c.wasm_backtrace(false);

    let engine = Engine::new(&c)?;
    let module = Module::from_file(&engine, "examples/hello.wat")?;

    let mut store = Store::new(
        &engine,
        MyState {},
    );

    let hello_func = Func::wrap(&mut store, |_: Caller<'_, MyState>| {
        Err::<(), anyhow::Error>(anyhow!("bad error"))
    });

    let imports = [hello_func.into()];
    let instance = Instance::new(&mut store, &module, &imports)?;

    let run = instance.get_typed_func::<(), ()>(&mut store, "run")?;

    run.call(&mut store, ())?;

    Ok(())
}

Steps to Reproduce

Run run --package wasmtime-cli --example repro, see the output in "Actual Results"
Run run --package wasmtime-cli --release --example repro, see the output in "Expected Results"
set wasm_backtrace(true), run --package wasmtime-cli --example repro, see the output in "Expected Results" with some more trace

Expected Results

Output like

     Running `target/release/examples/hello`
Error: bad error

Stack backtrace:
   0: anyhow::error::<impl anyhow::Error>::msg
   1: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
   2: <F as wasmtime::func::IntoFunc<T,(wasmtime::func::Caller<T>,),R>>::into_func::wasm_to_host_shim
   3: <unknown>
   4: wasmtime_runtime::traphandlers::catch_traps::call_closure
   5: wasmtime_setjmp
   6: wasmtime_runtime::traphandlers::<impl wasmtime_runtime::traphandlers::call_thread_state::CallThreadState>::with
   7: wasmtime_runtime::traphandlers::catch_traps
   8: wasmtime::func::invoke_wasm_and_catch_traps
   9: wasmtime::func::typed::TypedFunc<Params,Results>::call

Actual Results

     Running `target/debug/examples/hello`
thread 'main' panicked at 'assertion failed: needs_backtrace == backtrace.is_some()', crates/wasmtime/src/trap.rs:101:13
stack backtrace:
   0: rust_begin_unwind
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/std/src/panicking.rs:575:5
   1: core::panicking::panic_fmt
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/core/src/panicking.rs:65:14
   2: core::panicking::panic
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/core/src/panicking.rs:114:5
   3: wasmtime::trap::from_runtime_box
             at ./crates/wasmtime/src/trap.rs:101:13
   4: wasmtime::func::invoke_wasm_and_catch_traps::{{closure}}
             at ./crates/wasmtime/src/func.rs:1314:28
   5: core::result::Result<T,E>::map_err
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/core/src/result.rs:861:27
   6: wasmtime::func::invoke_wasm_and_catch_traps
             at ./crates/wasmtime/src/func.rs:1314:9
   7: wasmtime::func::typed::TypedFunc<Params,Results>::call_raw
             at ./crates/wasmtime/src/func/typed.rs:177:22
   8: wasmtime::func::typed::TypedFunc<Params,Results>::call
             at ./crates/wasmtime/src/func/typed.rs:88:18
   9: hello::main
             at ./examples/hello.rs:34:5
  10: core::ops::function::FnOnce::call_once
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/core/src/ops/function.rs:507:5

Versions and Environment

Wasmtime version or commit: * e4dc9c79443259e40f3e93b9c7815b0645ebd5c4 (main/dev head at the time of opening this issue) * As far as I can tell this became an issue after the fixes for https://github.com/bytecodealliance/wasmtime/issues/5037 were implemented (so since v0.3.0)

Operating system: Arch Linux

Architecture: amd64

Extra Info

I realize that config::wasm_backtrace is deprecated, however today there is no way (?) to tell wasmtime to not re-capture backtraces when returning errors from imported functions.

Not being able to tell wasmtime to not capture backtraces on error leads to behavior similar to https://github.com/bytecodealliance/wasmtime/issues/5037. * The (admittedly rather extreme) testcase runs a module which will:
* Recursively call a function ~380 calls deep in wasm, making the wasm stack quite big
* Then it will call an imported function, which will in turn create a new instance of the recursive module, up to 1000-recucsive module calls
* Resulting in a call-stack of 300~400k elements (this requires 64MiB native stack)
* When starting to bail-out, recording that massive backtrace is actually not that slow, takes maybe a few hundred ms.
* The issue is that currently the backtrace is recorded 1000 times, making the bail-out time in this test case ~13 minutes.

Wasmtime GitHub notifications bot (Jan 16 2023 at 11:01):

magik6k labeled issue #5577:

Test Case

use anyhow::{anyhow, Result};
use wasmtime::*;

struct MyState {
}

fn main() -> Result<()> {
    let mut c = Config::default();

    c.wasm_backtrace(false);

    let engine = Engine::new(&c)?;
    let module = Module::from_file(&engine, "examples/hello.wat")?;

    let mut store = Store::new(
        &engine,
        MyState {},
    );

    let hello_func = Func::wrap(&mut store, |_: Caller<'_, MyState>| {
        Err::<(), anyhow::Error>(anyhow!("bad error"))
    });

    let imports = [hello_func.into()];
    let instance = Instance::new(&mut store, &module, &imports)?;

    let run = instance.get_typed_func::<(), ()>(&mut store, "run")?;

    run.call(&mut store, ())?;

    Ok(())
}

Steps to Reproduce

Run run --package wasmtime-cli --example repro, see the output in "Actual Results"
Run run --package wasmtime-cli --release --example repro, see the output in "Expected Results"
set wasm_backtrace(true), run --package wasmtime-cli --example repro, see the output in "Expected Results" with some more trace

Expected Results

Output like

     Running `target/release/examples/hello`
Error: bad error

Stack backtrace:
   0: anyhow::error::<impl anyhow::Error>::msg
   1: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
   2: <F as wasmtime::func::IntoFunc<T,(wasmtime::func::Caller<T>,),R>>::into_func::wasm_to_host_shim
   3: <unknown>
   4: wasmtime_runtime::traphandlers::catch_traps::call_closure
   5: wasmtime_setjmp
   6: wasmtime_runtime::traphandlers::<impl wasmtime_runtime::traphandlers::call_thread_state::CallThreadState>::with
   7: wasmtime_runtime::traphandlers::catch_traps
   8: wasmtime::func::invoke_wasm_and_catch_traps
   9: wasmtime::func::typed::TypedFunc<Params,Results>::call

Actual Results

     Running `target/debug/examples/hello`
thread 'main' panicked at 'assertion failed: needs_backtrace == backtrace.is_some()', crates/wasmtime/src/trap.rs:101:13
stack backtrace:
   0: rust_begin_unwind
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/std/src/panicking.rs:575:5
   1: core::panicking::panic_fmt
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/core/src/panicking.rs:65:14
   2: core::panicking::panic
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/core/src/panicking.rs:114:5
   3: wasmtime::trap::from_runtime_box
             at ./crates/wasmtime/src/trap.rs:101:13
   4: wasmtime::func::invoke_wasm_and_catch_traps::{{closure}}
             at ./crates/wasmtime/src/func.rs:1314:28
   5: core::result::Result<T,E>::map_err
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/core/src/result.rs:861:27
   6: wasmtime::func::invoke_wasm_and_catch_traps
             at ./crates/wasmtime/src/func.rs:1314:9
   7: wasmtime::func::typed::TypedFunc<Params,Results>::call_raw
             at ./crates/wasmtime/src/func/typed.rs:177:22
   8: wasmtime::func::typed::TypedFunc<Params,Results>::call
             at ./crates/wasmtime/src/func/typed.rs:88:18
   9: hello::main
             at ./examples/hello.rs:34:5
  10: core::ops::function::FnOnce::call_once
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/core/src/ops/function.rs:507:5

Versions and Environment

Operating system: Arch Linux

Architecture: amd64

Extra Info

I realize that config::wasm_backtrace is deprecated, however today there is no way (?) to tell wasmtime to not re-capture backtraces when returning errors from imported functions.

Wasmtime GitHub notifications bot (Jan 17 2023 at 02:25):

alexcrichton commented on issue #5577:

Thanks for the detailed report! I've opened https://github.com/bytecodealliance/wasmtime/pull/5580 to fix the debug_assert! and I've gone ahead and remove the #[deprecated] notice in the PR as well since I think at this point it's reasonable to just keep the config option.

Note that for your use case if you were to thread through the original error, with the WasmBacktrace context on it, through all the calls on the stack then it should prevent the backtrace from being recaptured. I presume, though, that you're not doing this which would explain the quadratic behavior.

Wasmtime GitHub notifications bot (Jan 17 2023 at 15:17):

magik6k commented on issue #5577:

Thanks a lot for the quick response / fix!

Note that for your use case if you were to thread through the original error, with the WasmBacktrace context on it, through all the calls on the stack then it should prevent the backtrace from being recaptured.

We unfortunately can't do that, because is our case it's up to user (wasm) code to handle the error coming from the sub-call, so we don't really control how bailing-out happens.

Wasmtime GitHub notifications bot (Jan 17 2023 at 15:31):

alexcrichton commented on issue #5577:

Ok makes sense! To me that highlights the need to be able to preserve this option instead of deprecating it.

Wasmtime GitHub notifications bot (Jan 17 2023 at 19:14):

alexcrichton closed issue #5577:

Test Case

use anyhow::{anyhow, Result};
use wasmtime::*;

struct MyState {
}

fn main() -> Result<()> {
    let mut c = Config::default();

    c.wasm_backtrace(false);

    let engine = Engine::new(&c)?;
    let module = Module::from_file(&engine, "examples/hello.wat")?;

    let mut store = Store::new(
        &engine,
        MyState {},
    );

    let hello_func = Func::wrap(&mut store, |_: Caller<'_, MyState>| {
        Err::<(), anyhow::Error>(anyhow!("bad error"))
    });

    let imports = [hello_func.into()];
    let instance = Instance::new(&mut store, &module, &imports)?;

    let run = instance.get_typed_func::<(), ()>(&mut store, "run")?;

    run.call(&mut store, ())?;

    Ok(())
}

Steps to Reproduce

Run run --package wasmtime-cli --example repro, see the output in "Actual Results"
Run run --package wasmtime-cli --release --example repro, see the output in "Expected Results"
set wasm_backtrace(true), run --package wasmtime-cli --example repro, see the output in "Expected Results" with some more trace

Expected Results

Output like

     Running `target/release/examples/hello`
Error: bad error

Stack backtrace:
   0: anyhow::error::<impl anyhow::Error>::msg
   1: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
   2: <F as wasmtime::func::IntoFunc<T,(wasmtime::func::Caller<T>,),R>>::into_func::wasm_to_host_shim
   3: <unknown>
   4: wasmtime_runtime::traphandlers::catch_traps::call_closure
   5: wasmtime_setjmp
   6: wasmtime_runtime::traphandlers::<impl wasmtime_runtime::traphandlers::call_thread_state::CallThreadState>::with
   7: wasmtime_runtime::traphandlers::catch_traps
   8: wasmtime::func::invoke_wasm_and_catch_traps
   9: wasmtime::func::typed::TypedFunc<Params,Results>::call

Actual Results

     Running `target/debug/examples/hello`
thread 'main' panicked at 'assertion failed: needs_backtrace == backtrace.is_some()', crates/wasmtime/src/trap.rs:101:13
stack backtrace:
   0: rust_begin_unwind
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/std/src/panicking.rs:575:5
   1: core::panicking::panic_fmt
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/core/src/panicking.rs:65:14
   2: core::panicking::panic
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/core/src/panicking.rs:114:5
   3: wasmtime::trap::from_runtime_box
             at ./crates/wasmtime/src/trap.rs:101:13
   4: wasmtime::func::invoke_wasm_and_catch_traps::{{closure}}
             at ./crates/wasmtime/src/func.rs:1314:28
   5: core::result::Result<T,E>::map_err
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/core/src/result.rs:861:27
   6: wasmtime::func::invoke_wasm_and_catch_traps
             at ./crates/wasmtime/src/func.rs:1314:9
   7: wasmtime::func::typed::TypedFunc<Params,Results>::call_raw
             at ./crates/wasmtime/src/func/typed.rs:177:22
   8: wasmtime::func::typed::TypedFunc<Params,Results>::call
             at ./crates/wasmtime/src/func/typed.rs:88:18
   9: hello::main
             at ./examples/hello.rs:34:5
  10: core::ops::function::FnOnce::call_once
             at /rustc/ff8c8dfbe66701531e3e5e335c28c544d0fbc945/library/core/src/ops/function.rs:507:5

Versions and Environment

Operating system: Arch Linux

Architecture: amd64

Extra Info

I realize that config::wasm_backtrace is deprecated, however today there is no way (?) to tell wasmtime to not re-capture backtraces when returning errors from imported functions.

Last updated: Oct 23 2024 at 20:03 UTC