Stream: git-wasmtime

Topic: wasmtime / issue #7956 call() failing for wasm code since...

Wasmtime GitHub notifications bot (Feb 19 2024 at 15:52):

andrewdavidmackenzie opened issue #7956:

My nightly CI tests have started failing since a few nights ago with this error:

thread 'test_fibonacci_wasm_example' panicked at flowr/utilities/src/lib.rs:162:13:
Sample "fibonacci" produced output to STDERR written to 'flowr/examples/fibonacci/test.stderr'
[2024-02-19T15:46:49Z ERROR flowrlib::run_state] Error in Job #1: Error returned by WASM implementation.call() for Url { scheme: "file", cannot_be_a_base: false, username: "", password: None, host: None, port: None, path: "/Users/andrew/.flow/lib/flowstdlib/math/add/add.wasm", query: None, fragment: None } => 'error while executing at wasm backtrace:
        0: 0x104df - add.wasm!__rust_start_panic
        1: 0x104ad - add.wasm!rust_panic
        2: 0x1049f - add.wasm!_ZN3std9panicking20rust_panic_with_hook17he3f5031942851a57E
        3: 0xfbc8 - add.wasm!_ZN3std9panicking19begin_panic_handler28_$u7b$$u7b$closure$u7d$$u7d$17h2fbd6f5ef7cde01dE
        4: 0xfaf1 - add.wasm!_ZN3std10sys_common9backtrace26__rust_end_short_backtrace17h2a11135b2d55c7a5E
        5: 0x1012e - add.wasm!rust_begin_unwind
        6: 0x10c33 - add.wasm!_ZN4core9panicking9panic_fmt17hd2edc01644c13cb8E
        7: 0x110d9 - add.wasm!_ZN4core9panicking5panic17h1654f8fcddbbeba3E
        8: 0xfcde - add.wasm!__rdl_dealloc
        9: 0x8ff8 - add.wasm!__rust_dealloc
       10: 0x3353 - add.wasm!run_wasm
    note: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information'

note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

I compile some rust code to wasm with rustc, and then invoke it from my binary that links wasmtime using this function:

    fn call(&self, offset: i32, length: i32, store: &mut Store<()>) -> Result<i32> {
        let mut results: [Val;1] = [Val::I32(0)];
        let params = [Val::I32(offset), Val::I32(length)];
        self.implementation
            .call(store, &params, &mut results)
            .map_err(|e| format!("Error returned by WASM implementation.call() for {:?} => '{}'",
            self.source_url, e))?;
...

I thought it might be some wasmtime upgrade, but fails the same on 16.0.0, 17.0.0, and 17.0.1
I thought it might be rustc, so I went back to the last one that worked ("nightly-2024-2-13") but it fails there too.

Given the difficulty of finding where it fails I'm kind of stuck, so any ideas as to what to try next or what I can add here to help debug it, would be appreciated.

This function (_add()) is the code being compiled and executed (with some wrapper code to format params etc):
https://github.com/andrewdavidmackenzie/flow/blob/6723be519fbeeeb2b8dcfbe2d1421609adef5f13/flowstdlib/src/math/add/add.rs#L4

Wasmtime GitHub notifications bot (Feb 19 2024 at 16:41):

andrewdavidmackenzie edited issue #7956:

My nightly CI tests have started failing since a few nights ago with this error:

thread 'test_fibonacci_wasm_example' panicked at flowr/utilities/src/lib.rs:162:13:
Sample "fibonacci" produced output to STDERR written to 'flowr/examples/fibonacci/test.stderr'
[2024-02-19T15:46:49Z ERROR flowrlib::run_state] Error in Job #1: Error returned by WASM implementation.call() for Url { scheme: "file", cannot_be_a_base: false, username: "", password: None, host: None, port: None, path: "/Users/andrew/.flow/lib/flowstdlib/math/add/add.wasm", query: None, fragment: None } => 'error while executing at wasm backtrace:
        0: 0x104df - add.wasm!__rust_start_panic
        1: 0x104ad - add.wasm!rust_panic
        2: 0x1049f - add.wasm!_ZN3std9panicking20rust_panic_with_hook17he3f5031942851a57E
        3: 0xfbc8 - add.wasm!_ZN3std9panicking19begin_panic_handler28_$u7b$$u7b$closure$u7d$$u7d$17h2fbd6f5ef7cde01dE
        4: 0xfaf1 - add.wasm!_ZN3std10sys_common9backtrace26__rust_end_short_backtrace17h2a11135b2d55c7a5E
        5: 0x1012e - add.wasm!rust_begin_unwind
        6: 0x10c33 - add.wasm!_ZN4core9panicking9panic_fmt17hd2edc01644c13cb8E
        7: 0x110d9 - add.wasm!_ZN4core9panicking5panic17h1654f8fcddbbeba3E
        8: 0xfcde - add.wasm!__rdl_dealloc
        9: 0x8ff8 - add.wasm!__rust_dealloc
       10: 0x3353 - add.wasm!run_wasm
    note: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information'

note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

I compile some rust code to wasm with rustc, and then invoke it from my binary that links wasmtime using this function:

    fn call(&self, offset: i32, length: i32, store: &mut Store<()>) -> Result<i32> {
        let mut results: [Val;1] = [Val::I32(0)];
        let params = [Val::I32(offset), Val::I32(length)];
        self.implementation
            .call(store, &params, &mut results)
            .map_err(|e| format!("Error returned by WASM implementation.call() for {:?} => '{}'",
            self.source_url, e))?;
...

I thought it might be some wasmtime upgrade, but fails the same on 16.0.0, 17.0.0, and 17.0.1
I thought it might be rustc, so I went back to the last one that worked ("nightly-2024-2-13") but it fails there too.

Given the difficulty of finding where it fails I'm kind of stuck, so any ideas as to what to try next or what I can add here to help debug it, would be appreciated.

This function (_add()) is the code being compiled and executed (with some wrapper code to format params etc):
https://github.com/andrewdavidmackenzie/flow/blob/6723be519fbeeeb2b8dcfbe2d1421609adef5f13/flowstdlib/src/math/add/add.rs#L4
But in fact it seems to fail on any/all of my wasm functions/files, that worked until a few days ago - and I haven't changed, so I think it's something generic, and not related to that code.

Could it be that rustc is emitting some wasm instruction that is not yet supported?

Wasmtime GitHub notifications bot (Feb 19 2024 at 17:09):

andrewdavidmackenzie edited issue #7956:

add.wasm.txt
My nightly CI tests have started failing since a few nights ago with this error:

thread 'test_fibonacci_wasm_example' panicked at flowr/utilities/src/lib.rs:162:13:
Sample "fibonacci" produced output to STDERR written to 'flowr/examples/fibonacci/test.stderr'
[2024-02-19T15:46:49Z ERROR flowrlib::run_state] Error in Job #1: Error returned by WASM implementation.call() for Url { scheme: "file", cannot_be_a_base: false, username: "", password: None, host: None, port: None, path: "/Users/andrew/.flow/lib/flowstdlib/math/add/add.wasm", query: None, fragment: None } => 'error while executing at wasm backtrace:
        0: 0x104df - add.wasm!__rust_start_panic
        1: 0x104ad - add.wasm!rust_panic
        2: 0x1049f - add.wasm!_ZN3std9panicking20rust_panic_with_hook17he3f5031942851a57E
        3: 0xfbc8 - add.wasm!_ZN3std9panicking19begin_panic_handler28_$u7b$$u7b$closure$u7d$$u7d$17h2fbd6f5ef7cde01dE
        4: 0xfaf1 - add.wasm!_ZN3std10sys_common9backtrace26__rust_end_short_backtrace17h2a11135b2d55c7a5E
        5: 0x1012e - add.wasm!rust_begin_unwind
        6: 0x10c33 - add.wasm!_ZN4core9panicking9panic_fmt17hd2edc01644c13cb8E
        7: 0x110d9 - add.wasm!_ZN4core9panicking5panic17h1654f8fcddbbeba3E
        8: 0xfcde - add.wasm!__rdl_dealloc
        9: 0x8ff8 - add.wasm!__rust_dealloc
       10: 0x3353 - add.wasm!run_wasm
    note: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information'

note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

I compile some rust code to wasm with rustc, and then invoke it from my binary that links wasmtime using this function:

    fn call(&self, offset: i32, length: i32, store: &mut Store<()>) -> Result<i32> {
        let mut results: [Val;1] = [Val::I32(0)];
        let params = [Val::I32(offset), Val::I32(length)];
        self.implementation
            .call(store, &params, &mut results)
            .map_err(|e| format!("Error returned by WASM implementation.call() for {:?} => '{}'",
            self.source_url, e))?;
...

I thought it might be some wasmtime upgrade, but fails the same on 16.0.0, 17.0.0, and 17.0.1
I thought it might be rustc, so I went back to the last one that worked ("nightly-2024-2-13") but it fails there too.

Given the difficulty of finding where it fails I'm kind of stuck, so any ideas as to what to try next or what I can add here to help debug it, would be appreciated.

This function (_add()) is the code being compiled and executed (with some wrapper code to format params etc):
https://github.com/andrewdavidmackenzie/flow/blob/6723be519fbeeeb2b8dcfbe2d1421609adef5f13/flowstdlib/src/math/add/add.rs#L4
But in fact it seems to fail on any/all of my wasm functions/files, that worked until a few days ago - and I haven't changed, so I think it's something generic, and not related to that code.

Could it be that rustc is emitting some wasm instruction that is not yet supported?

Wasmtime GitHub notifications bot (Feb 19 2024 at 17:10):

andrewdavidmackenzie edited issue #7956:

My nightly CI tests have started failing since a few nights ago with this error:

thread 'test_fibonacci_wasm_example' panicked at flowr/utilities/src/lib.rs:162:13:
Sample "fibonacci" produced output to STDERR written to 'flowr/examples/fibonacci/test.stderr'
[2024-02-19T15:46:49Z ERROR flowrlib::run_state] Error in Job #1: Error returned by WASM implementation.call() for Url { scheme: "file", cannot_be_a_base: false, username: "", password: None, host: None, port: None, path: "/Users/andrew/.flow/lib/flowstdlib/math/add/add.wasm", query: None, fragment: None } => 'error while executing at wasm backtrace:
        0: 0x104df - add.wasm!__rust_start_panic
        1: 0x104ad - add.wasm!rust_panic
        2: 0x1049f - add.wasm!_ZN3std9panicking20rust_panic_with_hook17he3f5031942851a57E
        3: 0xfbc8 - add.wasm!_ZN3std9panicking19begin_panic_handler28_$u7b$$u7b$closure$u7d$$u7d$17h2fbd6f5ef7cde01dE
        4: 0xfaf1 - add.wasm!_ZN3std10sys_common9backtrace26__rust_end_short_backtrace17h2a11135b2d55c7a5E
        5: 0x1012e - add.wasm!rust_begin_unwind
        6: 0x10c33 - add.wasm!_ZN4core9panicking9panic_fmt17hd2edc01644c13cb8E
        7: 0x110d9 - add.wasm!_ZN4core9panicking5panic17h1654f8fcddbbeba3E
        8: 0xfcde - add.wasm!__rdl_dealloc
        9: 0x8ff8 - add.wasm!__rust_dealloc
       10: 0x3353 - add.wasm!run_wasm
    note: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information'

note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

I compile some rust code to wasm with rustc, and then invoke it from my binary that links wasmtime using this function:

    fn call(&self, offset: i32, length: i32, store: &mut Store<()>) -> Result<i32> {
        let mut results: [Val;1] = [Val::I32(0)];
        let params = [Val::I32(offset), Val::I32(length)];
        self.implementation
            .call(store, &params, &mut results)
            .map_err(|e| format!("Error returned by WASM implementation.call() for {:?} => '{}'",
            self.source_url, e))?;
...

I thought it might be some wasmtime upgrade, but fails the same on 16.0.0, 17.0.0, and 17.0.1
I thought it might be rustc, so I went back to the last one that worked ("nightly-2024-2-13") but it fails there too.

Given the difficulty of finding where it fails I'm kind of stuck, so any ideas as to what to try next or what I can add here to help debug it, would be appreciated.

This function (_add()) is the code being compiled and executed (with some wrapper code to format params etc):
https://github.com/andrewdavidmackenzie/flow/blob/6723be519fbeeeb2b8dcfbe2d1421609adef5f13/flowstdlib/src/math/add/add.rs#L4
But in fact it seems to fail on any/all of my wasm functions/files, that worked until a few days ago - and I haven't changed, so I think it's something generic, and not related to that code.

Could it be that rustc is emitting some wasm instruction that is not yet supported?

Here is the add.wasm binary file, with txt extension to allow upload
add.wasm.txt

Wasmtime GitHub notifications bot (Feb 20 2024 at 15:57):

alexcrichton commented on issue #7956:

This looks like it's probably a Rust panic happening, are you able to capture the stdout or stderr of the wasm guest to see what it's saying? Rust nightly is adding some more debug checks recently so you might be tripping over an assertion in the guest.

Wasmtime GitHub notifications bot (Feb 20 2024 at 16:04):

bjorn3 commented on issue #7956:

What if the return data is bigger than the input data at https://github.com/andrewdavidmackenzie/flow/blob/e6a2244a35f025e6bf822df6ea9686d5e9159def/flowmacro/src/lib.rs#L172? You did write out-of-bounds of the allocated vector. Also you are calling Vec::from_raw_parts without forgetting the vector again, which means that the allocation to which you write the return data using will be dropped before returning. Maybe you wanted to use std::slice::from_raw_parts instead?

Wasmtime GitHub notifications bot (Feb 20 2024 at 17:42):

andrewdavidmackenzie commented on issue #7956:

@bjorn3 I'll check the points you make. I wrote that a long time ago - and knew little....so there's quite possibly bugs in it.
I'm not sure why it's started failing lately though, as it hasn't changed in a long time...

I'm trying to go back to the older code and older rustc nightly to the last working version and figure out what change caused it.

Wasmtime GitHub notifications bot (Feb 20 2024 at 17:49):

andrewdavidmackenzie commented on issue #7956:

On the memory size point.
I think I always use the same fixed size alloc (hopefully larger than ever needed!) for input and output.
So, providing output is smaller than the memory size, it doesn't matter if it is longer than the input data part.

    fn send_inputs(&self, store: &mut Store<()>, inputs: &[Value]) -> Result<(i32, i32)> {
        let input_data = serde_json::to_vec(&inputs)?;
        let alloc_size = max(input_data.len() as i32, MAX_RESULT_SIZE);
        let offset = self.alloc(alloc_size, store)?;
        self.memory
            .write(store, offset as usize, &input_data)
            .map_err(|_| "Could not write to WASM Linear Memory")?;
        Ok((offset, input_data.len() as i32))
    }

(I could add an assert to that to fail if not big enough...)

Wasmtime GitHub notifications bot (Feb 20 2024 at 17:54):

andrewdavidmackenzie commented on issue #7956:

On the vector lifetime. That function ("run_wasm") is the one that calls the wasm ("object.run()" and the input_data vec should still be in scope when I do the copy to return_data ... I think.... can hardly remember this code...

Wasmtime GitHub notifications bot (Feb 20 2024 at 17:58):

andrewdavidmackenzie deleted a comment on issue #7956:

On the vector lifetime. That function ("run_wasm") is the one that calls the wasm ("object.run()" and the input_data vec should still be in scope when I do the copy to return_data ... I think.... can hardly remember this code...

Wasmtime GitHub notifications bot (Feb 20 2024 at 17:58):

bjorn3 commented on issue #7956:

You aren't copying to return_data, you are copying from return_data to input_data and then immediately freeing both return_data and input_data through their drop impls.

Wasmtime GitHub notifications bot (Feb 20 2024 at 17:58):

andrewdavidmackenzie commented on issue #7956:

yes. mistake there - sorry, I deleted that wrong comment.

Wasmtime GitHub notifications bot (Feb 20 2024 at 17:59):

andrewdavidmackenzie edited a comment on issue #7956:

yes. mistake there - sorry, I deleted that wrong comment.
But I'm copying to input_data_ptr which is passed in, not input data - so should be OK?

Wasmtime GitHub notifications bot (Feb 20 2024 at 18:01):

andrewdavidmackenzie edited a comment on issue #7956:

yes. mistake there - sorry, I deleted that wrong comment.
But I'm copying to input_data_ptr which is passed in, not input data - so should be OK?
As you say, input_data and return_data are freed - but the memory behind input_data_ptr outlives this function?

Wasmtime GitHub notifications bot (Feb 20 2024 at 18:08):

bjorn3 commented on issue #7956:

This is the steps that happen when running your code as far as I can tell:

• WasmExecutor::run (host)
  * WasmExecutor::send_inputs (host) -> allocate "the buffer" on the guest
  * WasmExecutor::call (host)
  * run_wasm (guest)
  * input_data = Vec::from_raw_parts(the buffer) (guest)
  * Process data and create return value
  * Copy return value into "the buffer"
  * Implicit mem::drop(input_data) => frees "the buffer" <-- BUG IS HERE
  * WasmExecutor::get_returns (host) => use after free of "the buffer"

I've marked the source of the UB here with "BUG IS HERE". Replacing input_data = Vec::from_raw_parts(the buffer) with input_data = slice::from_raw_parts_mut(the buffer) would fix this by preventing the implicit drop of input_data from freeing the backing storage.

Wasmtime GitHub notifications bot (Feb 20 2024 at 18:09):

andrewdavidmackenzie commented on issue #7956:

I'm trying slide::from_raw_parts already (slow build!), so let's see! :-)

Wasmtime GitHub notifications bot (Feb 20 2024 at 18:09):

andrewdavidmackenzie edited a comment on issue #7956:

I'm trying slice::from_raw_parts already (slow build!), so let's see! :-)

Wasmtime GitHub notifications bot (Feb 20 2024 at 18:10):

andrewdavidmackenzie edited a comment on issue #7956:

I'm trying slice::from_raw_parts already (slow build!), so let's see! :-)
Since some is running native, and other parts are running in wasm in the wasm runtime - I've always struggled to reason about allow/free with this code to be honest!

Wasmtime GitHub notifications bot (Feb 20 2024 at 18:13):

andrewdavidmackenzie edited a comment on issue #7956:

I'm trying slice::from_raw_parts already (slow build!), so let's see! :-)
Since some is running native, and other parts are running in wasm in the wasm runtime - I've always struggled to reason about alloc/free with this code to be honest!

Wasmtime GitHub notifications bot (Feb 20 2024 at 18:13):

andrewdavidmackenzie commented on issue #7956:

I think that indeed has fixed it. @bjorn3 you are a godsend! I would never have found that!
Thanks so much for your help and patience!
I'll now go back to latest code and latest rustc and confirm - but I'm confident that is indeed the fix!

Wasmtime GitHub notifications bot (Feb 20 2024 at 18:16):

bjorn3 commented on issue #7956:

Happy to help!

Wasmtime GitHub notifications bot (Feb 20 2024 at 18:18):

andrewdavidmackenzie closed issue #7956:

My nightly CI tests have started failing since a few nights ago with this error:

thread 'test_fibonacci_wasm_example' panicked at flowr/utilities/src/lib.rs:162:13:
Sample "fibonacci" produced output to STDERR written to 'flowr/examples/fibonacci/test.stderr'
[2024-02-19T15:46:49Z ERROR flowrlib::run_state] Error in Job #1: Error returned by WASM implementation.call() for Url { scheme: "file", cannot_be_a_base: false, username: "", password: None, host: None, port: None, path: "/Users/andrew/.flow/lib/flowstdlib/math/add/add.wasm", query: None, fragment: None } => 'error while executing at wasm backtrace:
        0: 0x104df - add.wasm!__rust_start_panic
        1: 0x104ad - add.wasm!rust_panic
        2: 0x1049f - add.wasm!_ZN3std9panicking20rust_panic_with_hook17he3f5031942851a57E
        3: 0xfbc8 - add.wasm!_ZN3std9panicking19begin_panic_handler28_$u7b$$u7b$closure$u7d$$u7d$17h2fbd6f5ef7cde01dE
        4: 0xfaf1 - add.wasm!_ZN3std10sys_common9backtrace26__rust_end_short_backtrace17h2a11135b2d55c7a5E
        5: 0x1012e - add.wasm!rust_begin_unwind
        6: 0x10c33 - add.wasm!_ZN4core9panicking9panic_fmt17hd2edc01644c13cb8E
        7: 0x110d9 - add.wasm!_ZN4core9panicking5panic17h1654f8fcddbbeba3E
        8: 0xfcde - add.wasm!__rdl_dealloc
        9: 0x8ff8 - add.wasm!__rust_dealloc
       10: 0x3353 - add.wasm!run_wasm
    note: using the `WASMTIME_BACKTRACE_DETAILS=1` environment variable may show more debugging information'

note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

I compile some rust code to wasm with rustc, and then invoke it from my binary that links wasmtime using this function:

    fn call(&self, offset: i32, length: i32, store: &mut Store<()>) -> Result<i32> {
        let mut results: [Val;1] = [Val::I32(0)];
        let params = [Val::I32(offset), Val::I32(length)];
        self.implementation
            .call(store, &params, &mut results)
            .map_err(|e| format!("Error returned by WASM implementation.call() for {:?} => '{}'",
            self.source_url, e))?;
...

I thought it might be some wasmtime upgrade, but fails the same on 16.0.0, 17.0.0, and 17.0.1
I thought it might be rustc, so I went back to the last one that worked ("nightly-2024-2-13") but it fails there too.

Given the difficulty of finding where it fails I'm kind of stuck, so any ideas as to what to try next or what I can add here to help debug it, would be appreciated.

This function (_add()) is the code being compiled and executed (with some wrapper code to format params etc):
https://github.com/andrewdavidmackenzie/flow/blob/6723be519fbeeeb2b8dcfbe2d1421609adef5f13/flowstdlib/src/math/add/add.rs#L4
But in fact it seems to fail on any/all of my wasm functions/files, that worked until a few days ago - and I haven't changed, so I think it's something generic, and not related to that code.

Could it be that rustc is emitting some wasm instruction that is not yet supported?

Here is the add.wasm binary file, with txt extension to allow upload
add.wasm.txt

Wasmtime GitHub notifications bot (Feb 20 2024 at 18:18):

andrewdavidmackenzie commented on issue #7956:

Given my level of expertise, I'm surprised I ever got that code working, so having it break was a real concern - that I could never fix it! Back on track.

Thanks again, closing.

Last updated: Nov 22 2024 at 16:03 UTC